Error in START_SHDI_FIRST... RFC logon fails

Former Member · ‎08-02-2010

Hello All,

I cannot get past a step in the enhancement package 4 installation. The step is called: START_SHDI_FIRST. The error says to troubleshoot by looking at 2 logs, STARTSFI.LOG and DEVTRACE.log. extracted below.

The problem can be described this way. The step begins as the installer tries to start the shadow system. The first attempt stopped and I could see that the shadow was not started. I used the information in note 525677 to manually start the shadow and could verify that it was starting.

The screen says to retry until I can logon to the shadow. I am able to logon as user SAP* with password pass in client 000. I am not able to logon as myself and receive the message: Logon not possible (error in license check).

As SAP* I use the transaction SLICENSE, and could see that the maintenance certificate had expired. I loaded that certificate without an error.

I also see that the hardware key information is missing. SAP* is not allowed to update that information.

I believe that no other user will be able to logon as long as the license is an issue. The installer is trying to do a remote logon to verify that the system is up (my interpretation) .

I also see this information in the shadow system dev_W1 log.

M *** ERROR => ThMsGetHardwareId: ThOpcodeToMsg failed (1) [thxxmsg.c 3095]

M ***LOG Q16=> ThGetMsHwId, DpMBufHwIdGet (HWID_PENDING) [thxxmbuf.c 511]

M *** ERROR => SlicLikeyGetHardwareKey: no hwid from MSG server: -1 [sliclikey.c 1301]

M *** ERROR => likey_get_validity_dates: Error getting the hardware key. You might find some information in file "dev_ms" on the message server

M

M Thu Jul 29 15:18:28 2010

M *** ERROR => ThCheckReqInfo: message send/receive failed [thxxhead.c 17580]

M

M Modeinfo for User T8/M1

So, am I correct in seeing that the missing hardware key is the problem in the shadow system? Any ideas would be appreciated, otherwise I will clear the systems out and start over. Thanks.

Pat.

Below is the DEVTRACE (extract)

Directory: /usr/sap/TEH/EHPI/abap/log

Name: DEVTRACE.LOG

-

trc file: "dev_disp.new", trc level: 1, release: "701"

-

sysno 15

sid TEH

systemid 324 (IBM iSeries with OS400)

relno 7010

patchlevel 0

patchno 69

intno 20020600

make: single threaded, ASCII, 64 bit, optimized

pid 103802

Thu Jul 29 14:54:58 2010

kernel runs with dp version 243(ext=110) (@(#) DPLIB-INT-VERSION-243)

length of sys_adm_ext is 364 bytes

SWITCH TRC-HIDE on ***

***LOG Q00=> DpSapEnvInit, DPStart (15 103802) [dpxxdisp.c 1287]

shared lib "dw_xml.so" version 69 successfully loaded

shared lib "dw_xtc.so" version 69 successfully loaded

shared lib "dw_stl.so" version 69 successfully loaded

shared lib "dw_gui.so" version 69 successfully loaded

shared lib "dw_mdm.so" version 69 successfully loaded

rdisp/softcancel_sequence : -> 0,5,-1

use internal message server connection to port 3615

MtxInit: 30000 0 0

Thu Jul 29 14:54:59 2010

MBUF state OFF

DpCommInitTable: init table for 500 entries

rdisp/queue_size_check_value : -> off

ThTaskStatus: rdisp/reset_online_during_debug 0

EmInit: MmSetImplementation( 2 ).

MM global diagnostic options set: 0

<ES> client 0 initializing ....

<ES> InitFreeList

<ES> block size is 4096 kByte.

Using implementation std

<ES> Info: use normal pages (no huge table support available)

EsStdUnamFileMapInit: ES base = 0x7000000b0000000

EsStdInit: Extended Memory 4096 MB allocated

<ES> 1023 blocks reserved for free list.

ES initialized.

mm.dump: set maximum dump mem to 96 MB

Thu Jul 29 14:55:00 2010

WARNING => System running without ICM - check rdisp/start_icman [dpxxdisp.c 13279]

DpSetProcessPriority: Run priority for work process startup adjusted to 20

Thu Jul 29 14:55:01 2010

rdisp/http_min_wait_dia_wp : 1 -> 1

***LOG Q0I=> NiPConnect: connect (79: Connection refused) [nixxi.cpp 2519]

ERROR => NiPConnect: SiConnect failed for hdl 2 / sock 9

(SI_ECONN_REFUSE/79; I4; ST; 10.127.0.100:3615) [nixxi.cpp 2519]

ERROR => MsIAttachEx: NiBufConnect to omni/3615 failed (rc=NIECONN_REFUSED) [msxxi.c 652]

***LOG Q0L=> DpLoopInit, nomscon () [dpxxdisp.c 1816]

Thu Jul 29 14:55:19 2010

CCMS: AlInitGlobals : alert/use_sema_lock = TRUE.

Thu Jul 29 14:55:53 2010

***LOG Q0I=> NiPConnect: connect (79: Connection refused) [nixxi.cpp 2519]

ERROR => NiPConnect: SiConnect failed for hdl 3 / sock 10

(SI_ECONN_REFUSE/79; I4; ST; 10.127.0.100:3615) [nixxi.cpp 2519]

ERROR => MsIAttachEx: NiBufConnect to omni/3615 failed (rc=NIECONN_REFUSED) [msxxi.c 652]

Thu Jul 29 14:56:34 2010

ERROR => MsISnd2: not_attached [msxxi.c 1321]

***LOG Q0N=> DpRqNoWpHandle, MsSndName () [dpxxdisp.c 5007]

trc file: "dev_ms", trc level: 1, release: "701"

-

[Thr 01] Thu Jul 29 14:54:56 2010

[Thr 01] MsSOsPrivInit: Run priority adjusted to 12

[Thr 01] MsSSetTrcLog: trc logging active, max size = 20971520 bytes

systemid 324 (IBM iSeries with OS400)

relno 7010

patchlevel 0

patchno 63

intno 20020600

make: multithreaded, ASCII, 64 bit, optimized

pid 103801

[Thr 01] ***LOG Q01=> MsSInit, MSStart (Msg Server 1 103801) [msxxserv_mt. 1853]

[Thr 01] Thu Jul 29 14:54:57 2010

[Thr 01] SigISetDefaultAction : default handling for signal 20

[Thr 01] ***LOG Q0I=> NiIBindSocket: bind (67: Address already in use) [nixxi.cpp 3239]

[Thr 01] *** ERROR => NiIBindSocket: SiBind failed for hdl 1 / sock 7

(SI_EPORT_INUSE/67; I4; ST; 0.0.0.0:3615) [nixxi.cpp 3239]

[Thr 01] *** ERROR => MsSCommInit: NiBufListen(3615) (rc=NIESERV_USED) [msxxserv_mt. 10222]

[Thr 01] *** ERROR => MsSInit: MsSCommInit (internal) [msxxserv_mt. 1903]

[Thr 01] *** ERROR => main: MsSInit [msxxserv_mt. 5983]

[Thr 01] ***LOG Q02=> MsSHalt, MSStop (Msg Server 103801) [msxxserv_mt. 6030]

-

trc file: "dev_rd", trc level: 1, release: "701"

-

Thu Jul 29 14:55:00 2010

Shared memory semaphore administration area size = 10608

Thu Jul 29 14:55:06 2010

***LOG S00=> GwInitReader, gateway started ( 103807) [gwxxrd.c 1758]

systemid 324 (IBM iSeries with OS400)

relno 7010

patchlevel 0

patchno 68

intno 20020600

make: single threaded, ASCII, 64 bit, optimized

pid 103807

gateway runs with dp version 243(ext=110) (@(#) DPLIB-INT-VERSION-243)

gateway (version=701.2009.09.28)

gw/local_addr : 0.0.0.0

CCMS: AlInitGlobals : alert/use_sema_lock = TRUE.

CCMS: Initalizing shared memory of size 40000000 for monitoring segment.

Thu Jul 29 14:55:09 2010

CCMS: Checking Downtime Configuration of Monitoring Segment.

Bind service sapgw15 (socket) to port 3315

GwPrintMyHostAddr: my host addresses are :

1 : [10.127.0.100] omni (HOSTNAME)

2 : [127.0.0.1] LOOPBACK (LOCALHOST)

Full qualified hostname = omni.plastekgroup.com

DpSysAdmExtCreate: ABAP is active

DpSysAdmExtCreate: VMC (JAVA VM in WP) is not active

MtxInit: -2 0 0

Thu Jul 29 14:55:47 2010

GwDpInit: attached to gw_adm at 700000080599e90

Thu Jul 29 14:55:48 2010

DpSetProcessPriority: Run priority for gwrd adjusted to 12

AN EXTRACT OF STARTSFI_LOG

Directory: /usr/sap/TEH/EHPI/abap/log

Name: STARTSFI.LOG

-

1 ETQ201 Entering upgrade-phase "START_SHDI_FIRST" ("20100729145436")

2 ETQ367 Connect variables are set for standard instance access

4 ETQ399 System-nr = '14', GwService = 'sapgw14'

4 ETQ399 Environment variables:

4 ETQ399 dbs_db4_schema=<null>

4 ETQ399 auth_shadow_upgrade=<null>

4 ETQ399 Set environment for standard connect:

4 ETQ399 ENV: dbs_db4_schema=SAPR3

4 ETQ399 ENV: auth_shadow_upgrade=0

4 ETQ399 Set RFC variables for standard connect:

4 ETQ399 System-nr = '14', GwService = 'sapgw14'

4 ETQ399 Set tool parameters for standard connect:

4 ETQ399 default TPPARAM: DEFAULT.TPP

1 ETQ206 Executing pre-phase DB specific actions.

1 ETQ200 Executing actual phase 'MAIN_SHADOW/START_SHDI_FIRST'.

1 ETQ399 Phase arguments:

2 ETQ399 Arg[0] = 'DEVTRACE.LOG'

4 ETQ399 Set environment for shadow connect:

4 ETQ399 ENV: dbs_db4_schema=SAPR3

4 ETQ399 ENV: auth_shadow_upgrade=1

4 ETQ399 Set RFC variables for shadow connect:

4 ETQ399 System-nr = '15', GwService = 'sapgw15'

4 ETQ399 Set tool parameters for shadow connect:

4 ETQ380 computing toolpath for request "TP_SHADOW_CONNECT"

4 ETQ381 request "TP_SHADOW_CONNECT" means "tp needs to connect to shadow system"

4 ETQ382 translates to group "R3UP_TOOL_GROUP_NEW"

4 ETQ383 translates to path "exe"

4 ETQ399 default TPPARAM: SHADOW.TPP

4 ETQ380 computing toolpath for request "TP_ALWAYS_NEW"

4 ETQ381 request "TP_ALWAYS_NEW" means "always tp from DIR_PUT/exe, for phase KX_SWITCH"

4 ETQ382 translates to group "R3UP_TOOL_GROUP_NEW"

4 ETQ383 translates to path "exe"

2 ETQ399 Starting shadow instance