SAPup broke during phase STARTSAP_PUPG

Am Ende der Execution Phase während eines SAP Upgrades (oder Support Stack Installation) versucht der Software Update Manager (SUM) die SAP Instanz(en) zu starten.

Nach mehreren Minuten bricht die Phase ab, ein SUM Troubleticket wird erstellt mit folgendem Eintrag:

Foto: SAPBASIS.CH

Foto: SAPBASIS.CH

////////////////////////////////////////////////////////////

Einträge aus dem SAPup_troubleticket.log:

////////////////////////////////////////////////////////////

This trouble ticket was created by SAPup on 20150305160537
————————————————————-
SAPup broke during phase STARTSAP_PUPG in module MAIN_UPTRANS / Transition to uptime
Error Message: RFC login to system SID ashost saphost nr 00 gwhost saphost gwservice sapgw00 failed with code 1 key RFC_COMMUNICATION_FAILURE:
LOCATION    CPIC (TCP/IP) on local host with Unicode
ERROR       partner ‚10.5.0.213:3300‘ not reached
TIME        Thu Mar 05 16:05:17 2015
RELEASE     721
COMPONENT   NI (network interface)
VERSION     40
RC          -10
MODULE      nixxi.cpp
LINE        3283
DETAIL      NiPConnect2: 10.5.0.213:3300
SYSTEM CALL connect
ERRNO       10061
ERRNO TEXT  WSAECONNREFUSED: Connection refused
COUNTER     50

System start failed
————————————————————-
————————————————————-
Summary of SAPup:
————————————————————-
SAPehpi Release: lmt_008
SAPehpi Version: SAPup release lmt_008 version 53.000
Start Release:  731
Target Release:  731
————————————————————-
Summary of host system details:
————————————————————-
SID:   SID
Host:   saphost
MS Host:  saphost
GW Host:  saphost
Start Path:  E:\usr\sap\SID\DVEBMGS00\exe
Kernel Path:  E:\usr\sap\SID\DVEBMGS00\exe
————————————————————-
Summary of operating system details:
————————————————————-
OS Type:  Windows NT X86_64
OS Version:  6.0
————————————————————-
Summary of database details:
————————————————————-
Database Type:  mss
Database Version: 10.00.5848.00
————————————————————-
Summary of RFC details:
————————————————————-
Host:   saphost
GW Host:  saphost
Client:   000
Destination:  SID
Language:  E
System No.:  00
————————————————————-
————————————————————-

 

////////////////////////////////////////////////////////////

Alle Workprozesse brechen ab mit folgender Meldung z.B. Einträge aus dev_disp, aus wp_0

////////////////////////////////////////////////////////////
Logs vom SAP Dispatcher „DEV_DISP“ – folgende Einträge:

—————————————————
trc file: „dev_disp“, trc level: 1, release: „721“
—————————————————
sysno      00
sid        SID
systemid   562 (PC with Windows NT)
relno      7210
patchlevel 0
patchno    300
intno      20020600
make       multithreaded, ASCII, 64 bit, optimized
profile    \\saphost\sapmnt\SID\SYS\profile\SID_DVEBMGS00_saphost
pid        3260

kernel runs with dp version 139(ext=121) (@(#) DPLIB-INT-VERSION-139)
length of sys_adm_ext is 380 bytes
*** SWITCH TRC-HIDE on ***
***LOG Q00=> DpSapEnvInit, DPStart (00 3260) [dpxxdisp.c   1321]
shared lib „dw_xml.dll“ version 300 successfully loaded
shared lib „dw_xtc.dll“ version 300 successfully loaded
shared lib „dw_stl.dll“ version 300 successfully loaded
shared lib „dw_gui.dll“ version 300 successfully loaded
shared lib „dw_mdm.dll“ version 300 successfully loaded
shared lib „dw_rndrt.dll“ version 300 successfully loaded
shared lib „dw_abp.dll“ version 300 successfully loaded
shared lib „dw_sym.dll“ version 300 successfully loaded
shared lib „dw_aci.dll“ version 300 successfully loaded
rdisp/softcancel_sequence :  -> 0,5,-1
use internal message server connection to port 3900
rdisp/dynamic_wp_check : 1
rdisp/calculateLoadAverage : 1

Thu Mar 05 16:46:07 2015
*** WARNING => DpNetCheck: NiAddrToHost(1.0.0.0) took 5 seconds
***LOG GZZ=> 1 possible network problems detected – check tracefile and adjust the DNS settings [dpxxtool2.c  6485]
MtxInit: 30000 0 0
DpSysAdmExtInit: ABAP is active
DpSysAdmExtInit: VMC (JAVA VM in WP) is not active
display_tcp_ip: 0
DpIPCInit2: write dp-profile-values into sys_adm_ext
DpIPCInit2: start server >saphost_SID_00                             <
DpShMCreate: sizeof(wp_adm)  38720 (1760)
DpShMCreate: sizeof(tm_adm)  4976768 (24760)
DpShMCreate: sizeof(wp_ca_adm)  56000 (56)
DpShMCreate: sizeof(appc_ca_adm) 56000 (56)
DpCommTableSize: max/headSize/ftSize/tableSize=500/16/776048/776064
DpShMCreate: sizeof(comm_adm)  776064 (1528)
DpSlockTableSize: max/headSize/ftSize/fiSize/tableSize=0/0/0/0/0
DpShMCreate: sizeof(slock_adm)  0 (232)
DpFileTableSize: max/headSize/ftSize/tableSize=0/0/0/0
DpShMCreate: sizeof(file_adm)  0 (80)
DpShMCreate: sizeof(vmc_adm)  0 (1864)
DpShMCreate: sizeof(wall_adm)  (25648/42880/64/104)
DpShMCreate: sizeof(gw_adm) 48
DpShMCreate: sizeof(j2ee_adm) 2032
DpShMCreate: SHM_DP_ADM_KEY  (addr: 0000000003B70050, size: 5986736)
DpShMCreate: allocated sys_adm at 0000000003B70060
DpShMCreate: allocated wp_adm_list at 0000000003B72A20
DpShMCreate: allocated wp_adm at 0000000003B72C10
DpShMCreate: allocated tm_adm_list at 0000000003B7C360
DpShMCreate: allocated tm_adm at 0000000003B7C3B0
DpShMCreate: allocated wp_ca_adm at 000000000403B440
DpShMCreate: allocated appc_ca_adm at 0000000004048F10
DpShMCreate: allocated comm_adm at 00000000040569E0
DpShMCreate: system runs without slock table
DpShMCreate: system runs without file table
DpShMCreate: allocated vmc_adm_list at 0000000004114170
DpShMCreate: system runs without vmc_adm
DpShMCreate: allocated gw_adm at 0000000004114220
DpShMCreate: allocated j2ee_adm at 0000000004114260
DpShMCreate: allocated ca_info at 0000000004114A60
DpShMCreate: allocated wall_adm at 0000000004114AE0
DpCommAttachTable: attached comm table (header=00000000040569E0/ft=00000000040569F0)
DpSysAdmIntInit: initialize sys_adm
rdisp/test_roll : roll strategy is DP_NORMAL_ROLL
dia token check not active (10 token)
MBUF state OFF
DpCommInitTable: init table for 500 entries
DpRqQInit: keep protect_queue / slots_per_queue 0 / 2001 in sys_adm
rdisp/queue_size_check_value :  -> on,50,30,40,500,50,500,80
EmInit: MmSetImplementation( 2 ).
MM global diagnostic options set: 0
<ES> client 0 initializing ….
<ES> EsILock: use Mutex for locking
<ES> InitFreeList
<ES> block size is 4096 kByte.
<ES> Info: em/initial_size_MB( 20478MB) not multiple of em/blocksize_KB( 4096KB)
<ES> Info: em/initial_size_MB rounded up to 20480MB
Using implementation view
<EsNT> Using memory model view.
<EsNT> Memory Reset disabled as NT default
<ES> 5119 blocks reserved for free list.
ES initialized.
mm.dump: set maximum dump mem to 192 MB
mm.dump: set global maximum dump mem to 192 MB
EsRegisterEmCheck: Register EmGetEsHandles at 0000000140F198C0
DpVmcSetActive: set vmc state DP_VMC_NOT_ACTIVE
MPI: dynamic quotas disabled.
MPI init: pipes=4000 buffers=1279 reserved=383 quota=10%
rdisp/http_min_wait_dia_wp : 1 -> 1
***LOG Q0K=> DpMsAttach, mscon ( saphost) [dpxxdisp.c   12808]
MBUF state LOADING
DpStartStopMsg: send start message (myname is >saphost_SID_00                             <)
DpStartStopMsg: start msg sent
CCMS: Initialized monitoring segment of size 60000000.
CCMS: Initialized CCMS Headers in the shared monitoring segment.
CCMS: Checking Downtime Configuration of Monitoring Segment.
CCMS: AlMsUpload called by wp 1024.

Thu Mar 05 16:46:11 2015
CCMS: AlMsUpload successful for E:\usr\sap\SID\DVEBMGS00\log\ALMTTREE.DAT (6419 MTEs).
CCMS: start to initalize 3.X shared alert area (first segment).
DpAppcBlksLow: max appc blocks in queue is 500 (50 %)
DpWpBlksLow: max wp blocks in queue is 800 (80 %)
DpMBufHwIdSet: set Hardware-ID
***LOG Q1C=> DpMBufHwIdSet [dpxxmbuf.c   1296]
MBUF state ACTIVE
MBUF component UP
DpMsgProcess: 1 server in MBUF

Thu Mar 05 16:46:14 2015
DpModState: change server state from STARTING to ACTIVE
*** WARNING => DpRqServiceQueue: timeout of HIGH PRIO msg, return DP_CANT_HANDLE_REQ

Thu Mar 05 16:46:16 2015
*** WARNING => DpRqServiceQueue: timeout of HIGH PRIO msg, return DP_CANT_HANDLE_REQ
*** WARNING => DpRqServiceQueue: timeout of HIGH PRIO msg, return DP_CANT_HANDLE_REQ
*** WARNING => DpRqServiceQueue: timeout of HIGH PRIO msg, return DP_CANT_HANDLE_REQ

Thu Mar 05 16:46:20 2015
*** WARNING => DpRqServiceQueue: timeout of HIGH PRIO msg, return DP_CANT_HANDLE_REQ
*** WARNING => DpRqServiceQueue: timeout of HIGH PRIO msg, return DP_CANT_HANDLE_REQ

Thu Mar 05 16:46:29 2015
*** WARNING => DpRqServiceQueue: timeout of HIGH PRIO msg, return DP_CANT_HANDLE_REQ

Thu Mar 05 16:48:18 2015
*** WARNING => DpRqServiceQueue: timeout of HIGH PRIO msg, return DP_CANT_HANDLE_REQ

Thu Mar 05 16:49:39 2015
DpWpConf: requested operation mode switch:
DIA 10->10 BTC 6->6 UPD 1->1 UP2 1->1 ENQ 1->1 SPO 1->1 RESTR 0->0 DYN 2->2
DpWpConf: operation mode switch complete

Thu Mar 05 17:28:12 2015
DpSigInt: caught signal 2
DpHalt: shutdown server >saphost_SID_00                             < (normal)
DpModState: change server state from ACTIVE to SHUTDOWN
DpHalt: stop work processes

Thu Mar 05 17:28:13 2015
DpHalt: stop gateway
DpHalt: stop icman
DpHalt: terminate gui connections
DpHalt: wait for end of work processes
DpHalt: wait for end of gateway
DpHalt: waiting for termination of gateway …

Thu Mar 05 17:28:14 2015
*** ERROR => [DpProcDied] Process died  (PID:5448  HANDLE:792  rc:0x0) [dpnttool2.c  147]
DpHalt: wait for end of icman
DpHalt: waiting for termination of icman …

Thu Mar 05 17:28:15 2015
DpHalt: waiting for termination of icman …

Thu Mar 05 17:28:16 2015
DpHalt: waiting for termination of icman …

Thu Mar 05 17:28:17 2015
DpHalt: waiting for termination of icman …

Thu Mar 05 17:28:18 2015
DpHalt: waiting for termination of icman …

Thu Mar 05 17:28:19 2015
DpHalt: waiting for termination of icman …

Thu Mar 05 17:28:20 2015
DpHalt: waiting for termination of icman …

Thu Mar 05 17:28:21 2015
*** ERROR => [DpProcDied] Process died  (PID:3636  HANDLE:800  rc:0x0) [dpnttool2.c  147]
DpStartStopMsg: send stop message (myname is >saphost_SID_00                             <)
DpStartStopMsg: stop msg sent

Thu Mar 05 17:28:22 2015
DpHalt: sync with message server o.k.
DpHalt: detach from message server
***LOG Q0M=> DpMsDetach, ms_detach () [dpxxdisp.c   13208]
MBUF state OFF
MBUF component DOWN
DpHalt: cleanup EM
***LOG Q05=> DpHalt, DPStop ( 3260) [dpxxdisp.c   11688]
////////////////////////////////////////////////////////////

Logs vom Workprozess 0 [dev_w0] mit den folgenden Einträgen:

////////////////////////////////////////////////////////////
M  *** WARNING => ThCallDbBreak: db_sqlbreak failed (16388), caller=ThIErrHandle
M  ThIErrHandle: don’t try rollback again
M  ThShutDownServer: shutdown server
M  ThExecShutDown: perform exclusive shutdown actions
M  ThCheckComOrRb (event=1, full_commit=1)

M  *** WARNING => ThCallDbBreak: db_sqlbreak failed (16388), caller=ThIErrHandle
M  ThIErrHandle: don’t try rollback again
M  ThShutDownServer: shutdown server

B  Disconnected from connection 1
B  statistics db_con_commit (com_total=1330, com_tx=599)
B  statistics db_con_rollback (roll_total=36, roll_tx=0)
M  ***LOG Q02=> wp_halt, WPStop (Workp. 0 864) [dpnttool.c   339]

DpHdlDeadWp:  died (severity=0, status=0) [dpxxwp.c     1746]

Steht man zum erstenmal vor dieser Fehlermeldung wird wie üblich im SAP Basis Bereich erstmal eine 1/2 Stunde in die Lösungssuche anhand der Logfile Einträge investiert 😉
Letztendlich war die Lösung den vom SUM installierten neuen Kernel (aus dem Stack) manuell in den Kernel Verzeichnissen zu löschen und ein Kernelbackup vor der Installation zurück zu kopieren.
Anschließend folgt die Prozedur wie bei einem normalen Kernelpatch, d.h. alle SAP Services stoppen (+diablen), die neuen Kernel Archive in dieser Reihenfolge mit sapcar -xvf entpacken ( zuerste SAPEXe…SAR danach SAPEXEDB…SAR)
und die entpackten Kernel-Dateien über das zuvor zurückgesicherte Kernelbackup kopieren.

Foto: SAPBASIS.CH

Foto: SAPBASIS.CH

Dieses manuell durchgeführte Kernel Update hat die Lösung gebracht und SAP konnte erfolgreich gestartet werden über die MMC. Danach weiter im SUM Prozess zur Phase Finalization!

Tags: , , , , , ,