on 04-21-2015 11:17 AM
Hi,
we are struggling to set up the connection from C4C to ECC using a reverse proxy (apache).
Thank you for any help!
Best Regards
Florian
Our apache config is as follows:
<VirtualHost *:443>
ServerName customer.reverseproxy.com
SSLEngine On
SSLProxyEngine On
ErrorLog /var/www/customer/log/error.log
Customlog /var/www/customer/log/access.log "common"
# TransferLog "<Apache_home>/logs/access.log"
# Offical SSL Certificate for customer.reverseproxy.com
SSLCertificateFile "/etc/apache2/ssl/customer/customer_cert.pem"
SSLCertificateKeyFile "/etc/apache2/ssl/customer/customer_key_np.pem"
SSLCACertificateFile "/etc/apache2/ssl/customer/SSL123_CA_Bundle.pem"
# SSLCertificateChainFile "<Apache_home>/conf/proxy-server-ca.crt" # activate the client certificate authentication
#SSLCertificateChainFile "/etc/apache2/ssl/customer/SAP-CA.crt"
# Signing CA's for SAP client certificate (Baltimore CyberTrust Root & Verizon Public SureServer CA G14-SHA2 + more)
SSLCertificateChainFile "/etc/apache2/ssl/customer/SAPClientCA.pem"
SSLVerifyClient require
SSLVerifyDepth 10
SSLOptions +ExportCertData +StdEnvVars
# CA's from SAP and customer for backend connections between Proxy and SAP system (Baltimore CyberTrust Root & Verizon Public SureServer CA G14-SHA2 + more)
SSLProxyCACertificateFile "/etc/apache2/ssl/customer/SAP-CA.crt"
# SSLProxyMachineCertificateFile <Apache_home>/conf/proxy-client.pem
# initialize the special headers to a blank value to avoid http header forgeries
RequestHeader set SSL_CLIENT_CERT ""
<Location />
# add SSL_CLIENT_CERT header to forward real client certificate
RequestHeader set SSL_CLIENT_CERT "%{SSL_CLIENT_CERT}s"
ProxyPass https://sap.internal.com:8300/
ProxyPassReverse https://sap.internal.com:8300/
</Location>
</VirtualHost>
On the HCI we get the following error shown
Message Processing Log{
ContextName = com.sap.scenarios.cod2erp.customermaster.replicate
IntermediateError = true
MessageGuid = AFU2MVOblsS5yIwpSvYiCt7XnLaT
Node = vsaxxxxxx.od.sap.biz
OverallStatus = FAILED
ReceiverId = Q47_
StartTime = Tue Apr 21 11:15:31 UTC 2015
StopTime = Tue Apr 21 11:15:31 UTC 2015
Children [
Invoked endpoint{
Cxf.EndpointAddress = https://HCI.intaas.hana.ondemand.com/cxf/COD/ERP/BP_MASTER_REPLICATION
Error = Inbound processing in endpoint at https://HCI.intaas.hana.ondemand.com/cxf/COD/ERP/BP_MASTER_REPLICATION failed with message "Sequential processing failed for number 0. Exchange[Message: [Body is not logged]]. Caused by: [org.apache.cxf.interceptor.Fault - Could not send Message.]", caused by "SunCertPathBuilderException:unable to find valid certification path to requested target"
StartTime = Tue Apr 21 11:15:31 UTC 2015
Status = FAILED
StopTime = Tue Apr 21 11:15:31 UTC 2015
Children [
Entering Camel route route52{
StartTime = Tue Apr 21 11:15:31 UTC 2015
Children [
Exchange ID-vsaxxxxxx-od-sap-biz-40387-1427614280233-51-38 created in Endpoint[cxf://bean:my308416_]{
StartTime = Tue Apr 21 11:15:31 UTC 2015
Children [
Processing exchange ID-vsaxxxxxx-od-sap-biz-40387-1427614280233-51-38 in ref:encodingProcessor{
StartTime = Tue Apr 21 11:15:31 UTC 2015
StepId = process151
StopTime = Tue Apr 21 11:15:31 UTC 2015
Children [
Processing exchange ID-vsaxxxxxx-od-sap-biz-40387-1427614280233-51-38 in removeHeaders[*]{
StartTime = Tue Apr 21 11:15:31 UTC 2015
StepId = removeHeaders52
StopTime = Tue Apr 21 11:15:31 UTC 2015
Children [
Processing exchange ID-vsaxxxxxx-od-sap-biz-40387-1427614280233-51-38 in setHeader[MessageId]{
StartTime = Tue Apr 21 11:15:31 UTC 2015
StepId = setHeader76
StopTime = Tue Apr 21 11:15:31 UTC 2015
Children [
Processing exchange ID-vsaxxxxxx-od-sap-biz-40387-1427614280233-51-38 in sap-map-pi:COD_ERP_BusinessPartnerERPBulkReplicateRequest{
Sent To URI = sap-map-pi://COD_ERP_BusinessPartnerERPBulkReplicateRequest
StartTime = Tue Apr 21 11:15:31 UTC 2015
StepId = CallActivity_1
StopTime = Tue Apr 21 11:15:31 UTC 2015
Time Taken = 11
Children [
Processing exchange ID-vsaxxxxxx-od-sap-biz-40387-1427614280233-51-38 in ref:idocOutboundRequest{
StartTime = Tue Apr 21 11:15:31 UTC 2015
StepId = process152
StopTime = Tue Apr 21 11:15:31 UTC 2015
com.sap.sod.utils.idoc.soap.messageid= 00163E0CB1A01EE4BA82F713C72AD65B
Children [
Processing exchange ID-vsaxxxxxx-od-sap-biz-40387-1427614280233-51-38 in split[bean{idocPackageSplitter, method=split}]{
Error = org.apache.camel.CamelExchangeException: Sequential processing failed for number 0. Exchange[Message: [Body is not logged]]. Caused by: [org.apache.cxf.interceptor.Fault - Could not send Message.], cause: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
StartTime = Tue Apr 21 11:15:31 UTC 2015
StepId = CallActivity_2
StopTime = Tue Apr 21 11:15:31 UTC 2015
Children [
Successor Exchange ID-vsaxxxxxx-od-sap-biz-40387-1427614280233-51-39 created with reference to Exchange ID-vsaxxxxxx-od-sap-biz-40387-1427614280233-51-38{
StartTime = Tue Apr 21 11:15:31 UTC 2015
StopTime = Tue Apr 21 11:15:31 UTC 2015
Children [
Processing exchange ID-vsaxxxxxx-od-sap-biz-40387-1427614280233-51-39 in setHeader[SapIDocContentType]{
StartTime = Tue Apr 21 11:15:31 UTC 2015
StepId = setHeader77
StopTime = Tue Apr 21 11:15:31 UTC 2015
Children [
Processing exchange ID-vsaxxxxxx-od-sap-biz-40387-1427614280233-51-39 in removeHeader[ssl_client_cert]{
StartTime = Tue Apr 21 11:15:31 UTC 2015
StepId = removeHeader197
StopTime = Tue Apr 21 11:15:31 UTC 2015
Children [
Processing exchange ID-vsaxxxxxx-od-sap-biz-40387-1427614280233-51-39 in removeHeader[ssl_client_user]{
StartTime = Tue Apr 21 11:15:31 UTC 2015
StepId = removeHeader198
StopTime = Tue Apr 21 11:15:31 UTC 2015
Children [
Processing exchange ID-vsaxxxxxx-od-sap-biz-40387-1427614280233-51-39 in removeHeader[operationName]{
StartTime = Tue Apr 21 11:15:31 UTC 2015
StepId = removeHeader199
StopTime = Tue Apr 21 11:15:31 UTC 2015
Children [
Processing exchange ID-vsaxxxxxx-od-sap-biz-40387-1427614280233-51-39 in removeHeader[operationNamespace]{
StartTime = Tue Apr 21 11:15:31 UTC 2015
StepId = removeHeader200
StopTime = Tue Apr 21 11:15:31 UTC 2015
Children [
Processing exchange ID-vsaxxxxxx-od-sap-biz-40387-1427614280233-51-39 in cxf:bean:Q47_{
Error = org.apache.cxf.interceptor.Fault: Could not send Message., cause: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
Sent To URI = cxf://bean:Q47_
StartTime = Tue Apr 21 11:15:31 UTC 2015
StepId = MessageFlow_2
StopTime = Tue Apr 21 11:15:31 UTC 2015
Time Taken = 123
Children [
Sent message to endpoint{
Cxf.EndpointAddress = https://customer.reverseproxy.com:443/sap/bc/srt/idoc?sap-client=310
Error = Outbound processing in endpoint at https://customer.reverseproxy.com:443/sap/bc/srt/idoc?sap-client=310 failed with message "Could not send Message.", caused by "SunCertPathBuilderException:unable to find valid certification path to requested target"
StartTime = Tue Apr 21 11:15:31 UTC 2015
Status = FAILED
StopTime = Tue Apr 21 11:15:31 UTC 2015
}
Exchange ID-vsaxxxxxx-od-sap-biz-40387-1427614280233-51-39 failed{
StartTime = Tue Apr 21 11:15:31 UTC 2015
Status = FAILED
} ] } ] } ] } ] } ] } ] } ] }
Exchange ID-vsaxxxxxx-od-sap-biz-40387-1427614280233-51-38 failed{
StartTime = Tue Apr 21 11:15:31 UTC 2015
Status = FAILED
Children [
Exiting Camel route route52{
StartTime = Tue Apr 21 11:15:31 UTC 2015
} ] } ] } ] } ] } ] } ] } ] } ] } ] } ] } ]
ReceiverIds [
Q47_
] }
Hi Florian,
u (SAP) must import the reverse proxy root certificate into the key store (system.jks) of the HCI.
Can u please check this!
best regards,
fabian
You must be a registered user to add a comment. If you've already registered, sign in. Otherwise, register and sign in.
Dear Fabian,
Please check the list of trusted issuers in the section 5.3.2 of the security guide available in SMP.
You will need a certificate isused by one of these. Alternately, you can raise an incident to SAP to include the issuers that you have int he trusted list for the HCI tenant you are using.
Best Regards,
Pragya
Hello Florian,
Did you get the guide section?
Which direction communication is raising an issue HCI->ECC or ECC->HCI?
security guide -
Best Regards,
Pragya
Hello Florian,
Please check this link :
This has the latest list as well.
Best Regards,
Pragya
Hi Pragya,
right now we are working on C4C --> HCI --> ECC.
if I compare both lists, there are some differences in the trusted CAs. Which is now the correct one to have a proper signed reverse proxy certificate?
The one from the C4C security Guide (chapter 5.3.2) or the ones mentioned in the chapter "Load Balancer Root Certificates Supported by SAP" of the Hana Cloud Integration documentation.
Best Regards
Florian
Dear Florian,
Go with the ones mentioned in the HANA documentation chapter. I will cross check with the guide.
If you are looking at HCI->ECC then the you need a certificate issued by one of these trusted ones for the ECC(or the proxy if there is one before ECC) and upload the certificate in HCI.
Else if customer has already bought a certificate then raise an incident to SAP to get the issuer included in the trusted list for the HCI tenant.
Best Regards,
pragya
HI Florian
You might want to open a connectivity ticket - LOD-CRM-INT-NET component. Soemone will walk through each step.
I see you sent this to Former Member - he and are the experts here.
-ginger
Hello Florian,
"The HCI of our customer is SAP operated. So I would expect that these the reverse proxy root certificate is trusted automatically or am I wrong?" -
By default HCI Key store contains only a private key pair. So you need to add the issuer certificate chain of your reverse proxy to the HCI key store.
Best regards, Abinash
Hello Florian,
Then I would request to create an Incident as we need to look into the HCI key store and the reverse proxy URL.
By the way do you have a IP whitelisting in place? When I try to reach the URL
https://customer.reverseproxy.com:443/sap/bc/srt/idoc?sap-client=310 I get a 404 error
Best regards, Abinash
Hi Abinash,
the URL ist not the ture one. I have changed the URL to a generic one.
The reverse proxy is configured to require a client certificate in order to go through which is sent from HCI to ECC.
If we disable the client certificate requirement, we are able to properly connect directly to the SAP system via the reverse proxy. But HCI still doesn't.
The tickets our customer raised via OSS are:
322306 / 2015
345098 / 2015
Best Regards
Florian
Hi Abinash,
now we are one step further and receive a HTTP 401 on the reverse proxy. It looks like the client cert from HCI is not handled correctly. Can you help?
Best Regards
Florian
HCI log
Sent message to endpoint{
Cxf.EndpointAddress = https://customer.reverse.com:443/sap/bc/srt/idoc?sap-client=310
Error = Outbound processing in endpoint at https://customer.reverse.com:443/sap/bc/srt/idoc?sap-client=310 failed with message "HTTP response '401: Unauthorized' when communicating with https://customer.reverse.com:443/sap/bc/srt/idoc?sap-client=310"
StartTime = Fri Apr 24 11:03:12 UTC 2015
Status = FAILED
StopTime = Fri Apr 24 11:03:12 UTC 2015
}
Apache config
<VirtualHost *:443>
ServerName cuscrm.webmail.cus.com
SSLEngine On
SSLProxyEngine On
ErrorLog /var/www/cuscrm/log/error.log
Customlog /var/www/cuscrm/log/access.log "common"
# TransferLog "<Apache_home>/logs/access.log"
# Offical SSL Certificate for cuscrm.webmail.cus.com
SSLCertificateFile "/etc/apache2/ssl/cuscrm/cuscrm_cert.pem"
SSLCertificateKeyFile "/etc/apache2/ssl/cuscrm/cuscrm_key_np.pem"
SSLCertificateChainFile "/etc/apache2/ssl/cuscrm/ThawteCAChain.pem"
# SAP Baltimore Cybertrust Chain for Client authentication
SSLCACertificateFile "/etc/apache2/ssl/cuscrm/SAPCybertrust.pem"
SSLVerifyClient require
SSLVerifyDepth 10
SSLOptions +ExportCertData +StdEnvVars
# CA's from SAP and Schunk for backend connections between Proxy and SAP system
#SSLProxyCACertificateFile "/etc/apache2/ssl/cuscrm/SAP-CA.crt"
SSLProxyCACertificateFile "/etc/apache2/ssl/cuscrm/SAPCHAIN.pem"
# SSLProxyMachineCertificateFile <Apache_home>/conf/proxy-client.pem
# initialize the special headers to a blank value to avoid http header forgeries
RequestHeader set SSL_CLIENT_CERT ""
<Location />
# add SSL_CLIENT_CERT header to forward real client certificate
RequestHeader set SSL_CLIENT_CERT "%{SSL_CLIENT_CERT}s"
ProxyPass https://internal.sap:8300/
ProxyPassReverse https://internal.sap:8300/
</Location>
</VirtualHost>
Hello Florian,
I am not very much aware of apache configuration. But for 401 we can get more information from the SMICM trace of your backend system.
Can you please set the ICM trace level to 3, reset the trace and send a fresh message from HCI to ERP and then set the trace level to 1. Send me the trace.
Best regards, Abinash
Hello Florian,
In the ICM trace it clearly says No Client certificate
This usually means either of the two
1. Your reverse proxy is not forwarding the client certificate to ICM (because of wrong configuration)
or
2. Your backend system does not trust the incoming SSL request (For this you need to add the issuer certificate of the client to STRUST). Please note incase connection between your reverse proxy and backend system(ICM) is SSL based then you need to add the issuer certificate of apache client to Server PSE in the backend system. Only incase the reverse proxy is acting as a router you need to add the HCI issuer certificate to STRUST (this certificate you can get from HCI key store).
Best regards, Abinash
Hello Florian,
Additionally could you please check if you have set the following parameters in ICM
The configuration of the Web AS ABAP of PI System is described
under section “ICM Configuration”. As you intend to use SSL offloading
(scenario 3) the certificates need to be accepted using http.
icm/accept_forwarded_cert_via_http =
TRUE
In addition if you want to setup HTTPS connection between web
dispatcher and SAP Web AS make sure the ICM parameter is set to request for a
client certificate in the instance profile parameter
icm/HTTPS/verify_client =1
In addition to accept client
certificate from web dispatcher over SSL ICM must be configured to trust the
web dispatcher. This can be achieved using the following two parameters
icm/HTTPS/trust_client_with_subject =
CN=SWD,*
icm/HTTPS/trust_client_with_issuer =
CN=Server CA,*
Where SWD is the subject name of web dispatcher and Server CA is the issuer name.
The statements above are for SAP web dispatcher but should be similar of Apache as well.
Best regards, Abinash
Hello Florian,
You can find this information at the link below
X.509-Based Logon to NetWeaver AS from SAP Web Dispatcher - SAP Web Dispatcher - SAP Library
Best regards, Abinash
HI Abinash,
thank you. In the meanwhile we got it working. The issue were not properly set up parameters in the profile.
We added the following knowing that we have to restrict the "trust client" parameters.
icm/HTTPS/verify_client = 1
icm/HTTPS/trust_client_with_issuer = *
icm/HTTPS/trust_client_with_subject = *
Best Regards
Florian
Hi ,
I have similar issue. We are trying to connect HCI-ECC using basic authentication and we have the following error. Our security experts say that they could see the traffic flowing in and being sent to ECC. However in ECC , I dont have any thing on ICM trace.
Do we need to have the ECC signed Server Certificate in HCI keystore , if we want to use basic authentication?
Message Processing Log{
ContextName = com.sap.scenarios.cod2erp.customermaster.replicate_QE0400
ID = 00163E0CB1A01EE5A2B0198D5974DCEF
IntermediateError = true
MessageGuid = AFZFBewTUFFJhcspHteF_eDaOr7X
Node = vsa679811
OverallStatus = FAILED
ReceiverId = QE0CLNT400_
StartTime = Thu Nov 12 21:34:36 UTC 2015
StopTime = Thu Nov 12 21:34:37 UTC 2015
Children [
Invoked endpoint{
Cxf.EndpointAddress = /COD/ERP/BP_MASTER_REPLICATION_QE0400
Error = Inbound processing in endpoint at /COD/ERP/BP_MASTER_REPLICATION_QE0400 failed with message "Fault:Sequential processing failed for number 0. Exchange[Message: [Body is not logged]]. Caused by: [org.apache.cxf.interceptor.Fault - Response was of unexpected text/html ContentType. Incoming portion of HTML stream: (none)]", caused by "Fault:Response was of unexpected text/html ContentType. Incoming portion of HTML stream: (none)"
StartTime = Thu Nov 12 21:34:36 UTC 2015
Status = FAILED
StopTime = Thu Nov 12 21:34:37 UTC 2015
Children [
Entering Camel route route33{
StartTime = Thu Nov 12 21:34:36 UTC 2015
Children [
Exchange ID-vsa679811-52589-1446908913708-30-18 created in Endpoint[cxf://bean:COD_]{
StartTime = Thu Nov 12 21:34:36 UTC 2015
Children [
Processing exchange ID-vsa679811-52589-1446908913708-30-18 in ref:encodingProcessor{
StartTime = Thu Nov 12 21:34:36 UTC 2015
StepId = process105
StopTime = Thu Nov 12 21:34:36 UTC 2015
Children [
Processing exchange ID-vsa679811-52589-1446908913708-30-18 in removeHeaders[*]{
StartTime = Thu Nov 12 21:34:36 UTC 2015
StepId = removeHeaders30
StopTime = Thu Nov 12 21:34:36 UTC 2015
Children [
Processing exchange ID-vsa679811-52589-1446908913708-30-18 in setHeader[MessageId]{
StartTime = Thu Nov 12 21:34:36 UTC 2015
StepId = setHeader54
StopTime = Thu Nov 12 21:34:36 UTC 2015
Children [
Processing exchange ID-vsa679811-52589-1446908913708-30-18 in sap-map-pi:COD_ERP_BusinessPartnerERPBulkReplicateRequest{
Sent To URI = sap-map-pi://COD_ERP_BusinessPartnerERPBulkReplicateRequest
StartTime = Thu Nov 12 21:34:36 UTC 2015
StepId = CallActivity_1
StopTime = Thu Nov 12 21:34:36 UTC 2015
Time Taken = 4
Children [
Processing exchange ID-vsa679811-52589-1446908913708-30-18 in ref:idocOutboundRequest{
StartTime = Thu Nov 12 21:34:36 UTC 2015
StepId = process106
StopTime = Thu Nov 12 21:34:36 UTC 2015
com.sap.sod.utils.idoc.soap.messageid= 00163E0CB1A01EE5A2B0198D5974DCEF
Children [
Processing exchange ID-vsa679811-52589-1446908913708-30-18 in split[bean{idocPackageSplitter, method=split}]{
Error = org.apache.camel.CamelExchangeException: Sequential processing failed for number 0. Exchange[Message: [Body is not logged]]. Caused by: [org.apache.cxf.interceptor.Fault - Response was of unexpected text/html ContentType. Incoming portion of HTML stream: (none)], cause: org.apache.cxf.interceptor.Fault: Response was of unexpected text/html ContentType. Incoming portion of HTML stream: (none)
StartTime = Thu Nov 12 21:34:36 UTC 2015
StepId = CallActivity_2
StopTime = Thu Nov 12 21:34:37 UTC 2015
Children [
Successor Exchange ID-vsa679811-52589-1446908913708-30-19 created with reference to Exchange ID-vsa679811-52589-1446908913708-30-18{
StartTime = Thu Nov 12 21:34:36 UTC 2015
StopTime = Thu Nov 12 21:34:37 UTC 2015
Children [
Processing exchange ID-vsa679811-52589-1446908913708-30-19 in setHeader[SAP_ApplicationID]{
StartTime = Thu Nov 12 21:34:36 UTC 2015
StepId = CallActivity_3
StopTime = Thu Nov 12 21:34:36 UTC 2015
Children [
Processing exchange ID-vsa679811-52589-1446908913708-30-19 in setHeader[SapIDocContentType]{
StartTime = Thu Nov 12 21:34:36 UTC 2015
StepId = setHeader55
StopTime = Thu Nov 12 21:34:36 UTC 2015
Children [
Processing exchange ID-vsa679811-52589-1446908913708-30-19 in removeHeader[operationName]{
StartTime = Thu Nov 12 21:34:36 UTC 2015
StepId = removeHeader61
StopTime = Thu Nov 12 21:34:36 UTC 2015
Children [
Processing exchange ID-vsa679811-52589-1446908913708-30-19 in removeHeader[operationNamespace]{
StartTime = Thu Nov 12 21:34:36 UTC 2015
StepId = removeHeader62
StopTime = Thu Nov 12 21:34:36 UTC 2015
Children [
Processing exchange ID-vsa679811-52589-1446908913708-30-19 in cxf:bean:QE0CLNT400_{
Error = org.apache.cxf.interceptor.Fault: Response was of unexpected text/html ContentType. Incoming portion of HTML stream: (none)
Sent To URI = cxf://bean:QE0CLNT400_
StartTime = Thu Nov 12 21:34:36 UTC 2015
Status = FAILED
StepId = MessageFlow_2
StopTime = Thu Nov 12 21:34:37 UTC 2015
Time Taken = 360
Children [
Sent message to endpoint{
Cxf.EndpointAddress = https://ecc-q-nl.xxxxxxxx.eu/sap/bc/srt/idoc?sap-client=400
StartTime = Thu Nov 12 21:34:36 UTC 2015
Status = COMPLETED
StopTime = Thu Nov 12 21:34:37 UTC 2015
}
Exchange ID-vsa679811-52589-1446908913708-30-19 failed{
StartTime = Thu Nov 12 21:34:37 UTC 2015
Status = FAILED
} ] } ] } ] } ] } ] } ] }
Exchange ID-vsa679811-52589-1446908913708-30-18 failed{
StartTime = Thu Nov 12 21:34:37 UTC 2015
Status = FAILED
Children [
Exiting Camel route route33{
StartTime = Thu Nov 12 21:34:37 UTC 2015
} ] } ] } ] } ] } ] } ] } ] } ] } ] } ] } ]
ReceiverIds [
QE0CLNT400_
] }
Hi,
ICM is the entry point for HTTP request, if you don't see any trace in ICM then I am afraid data is not coming in to your ERP system. I would suggest set the trace level to 3 and check the ICM trace.
Make sure to reset the trace before you do the connection test.
You can attach the trace to his thread
Best regards, Abinash
Hi Amber,
did you set up the correct credentials in HCI and also use them in you iflows to ECC?
First, create the credentials in HCI using the ECC user and password.
Second, change the iflow to use basic authentication
Third, change the artifact name to the credential name.
This should do it as the credential stored in HCI is required for login to ECC.
The ECC server certificate or reverse proxy certificate (depending against what HCI connects directly) has to be signed with the officially accepted CAs defined in the HCI documentation in order to establish the connection.
Best Regards
Florian
Thank you for the responses. I have increased the ICM level to 3 as suggested and made a fresh test out of C4C system. Settings suggested by Florian are maintained properly. One question still remains unclear to me is that , is it really mandatory to have the ECC Server Certificate signed?? because we are now using basic authenciation and we only have a signed certificate.
--------------------------------------------------------------------------------
| ICM Trace File (dev_icm) |
--------------------------------------------------------------------------------
---------------------------------------------------
trc file: "dev_icm", trc level: 3, release: "722"
---------------------------------------------------
sysno 35
sid QE0
systemid 329 (IBM i with OS400)
relno 7220
patchlevel 0
patchno 12
intno 20020600
make multithreaded, ASCII, 64 bit, optimized
profile /usr/sap/QE0/SYS/profile/QE0_DVEBMGS35_SRVSAP01
pid 20040732
[Thr 01] Fri Nov 13 13:39:48 2015
[Thr 01] TRACE FILE TRUNCATED
[Thr 01] <<- SapSSLSetTraceFile()==SAP_O_K
[Thr 01] NiBufIAlloc: malloc ICM_EXT, to 104 bytes
[Thr 01]
[Thr 01] NiBufSend starting
[Thr 01] NiIWrite: hdl 33 sent data (wrt=104,pac=1,MESG_IO)
[Thr 01] MAIN TRACE END
[Thr 01] SiSelPSelect: start select (timeout=-1)
[Thr 3599] Fri Nov 13 13:39:49 2015
[Thr 3599] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 3599] WATCHDOG TRACE BEGIN
[Thr 3599] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 3599] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 3599] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 3599] MPI<cf06>0#22578 WriteOOB 00000001 00000002 00000001 801BCC10 09001000 A0003DF8 000000
[Thr 3599] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 3599] WATCHDOG TRACE END
[Thr 3342] MPI<cf06>0#22579 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 3599] SiSelPSelect: start select (timeout=10000)
[Thr 3342] MpiSelSelect( 8 -1 ) -> MPI_OK
[Thr 3342] MPI WATCHDOG TRACE BEGIN
[Thr 3342] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 3342] MPI<cf06>0#22580 ReadOOB 00000001 00000002 00000001 801BCC10 09001000 A0003DF8 000000 -> MPI_OK
[Thr 3342] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 3342] MPI WATCHDOG TRACE END
[Thr 3342] MPI<cf06>0#22581: GetInbuf: check avail. buffers 0 0
[Thr 3342] MPI<cf06>0#22581 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 3342] MpiSelect: 0 waiting for events
[Thr 01] Fri Nov 13 13:39:55 2015
[Thr 01] SiSelPNext: sock 16 selected (pos=3; revt=r--)
[Thr 01] NiBufISelProcess: hdl 25 process r-
[Thr 01] NiBufIAlloc: malloc NIBUF-IN, to 96 bytes
[Thr 01] NiIRead: hdl 25 received data (rcd=96,pac=1,MESG_IO)
[Thr 01] NiBufIIn: NIBUF len=96
[Thr 01] NiBufIIn: packet complete for hdl 25
[Thr 01] NiBufISelUpdate: new MODE -- (r-) for hdl 25 in set0
[Thr 01] SiSelPSet: set events of sock 16 to: ---
[Thr 01] NiBufISelUpdate: new STAT r-- (---) for hdl 25 in set0
[Thr 01] NiSelIListInsert: add hdl 25 [3] to buf-list (0) of set0
[Thr 01] SiSelPNext: sock 17 selected (pos=4; revt=r--)
[Thr 01] NiBufISelProcess: hdl 33 process r-
[Thr 01] NiBufIAlloc: malloc NIBUF-IN, to 8416 bytes
[Thr 01] NiIRead: hdl 33 received data (rcd=8416,pac=1,MESG_IO)
[Thr 01] NiBufIIn: NIBUF len=8416
[Thr 01] NiBufIIn: packet complete for hdl 33
[Thr 01] NiBufISelUpdate: new MODE -- (r-) for hdl 33 in set0
[Thr 01] SiSelPSet: set events of sock 17 to: ---
[Thr 01] NiBufISelUpdate: new STAT r-- (---) for hdl 33 in set0
[Thr 01] NiSelIListInsert: add hdl 33 [4] to buf-list (1) of set0
[Thr 01] NiSelISelectInt: 2 handles selected (2 buffered)
[Thr 01] MAIN TRACE BEGIN
[Thr 01] IcmMsgProcess: Receive data from partner: DP(1), wp_no: 0
[Thr 01]
[Thr 01] NiBufReceive starting
[Thr 01] NiBufISelUpdate: new MODE r- (--) for hdl 33 in set0
[Thr 01] SiSelPSet: set events of sock 17 to: rp-
[Thr 01] NiBufISelUpdate: new STAT --- (r--) for hdl 33 in set0
[Thr 01] NiSelIListRemove: remove hdl 33 [4] from buf-list (2) of set0
[Thr 01] IcmRecMsg: received 8416 bytes
[Thr 01] ============================================
[Thr 01] | COM_DATA:
[Thr 01] | Offset: 0 | Version: 7210
[Thr 01] | MsgNo: 97792 | Opcode: ICM_COM_OP_SET_PARAM (11)
[Thr 01] ============================================
[Thr 01] IcmHandleAdmMsg: op: 11, auth: 1
[Thr 01] IcmHandleAdmMsg: set param -> icm/OP_SET_ABAP_RELEASE
[Thr 01] NiBufIAlloc: malloc ICM_EXT, to 104 bytes
[Thr 01]
[Thr 01] NiBufSend starting
[Thr 01] NiIWrite: hdl 33 sent data (wrt=104,pac=1,MESG_IO)
[Thr 01] IcmMsgProcess: Receive data from partner: WP(2), wp_no: 3
[Thr 01]
[Thr 01] NiBufReceive starting
[Thr 01] NiBufISelUpdate: new MODE r- (--) for hdl 25 in set0
[Thr 01] SiSelPSet: set events of sock 16 to: rp-
[Thr 01] NiBufISelUpdate: new STAT --- (r--) for hdl 25 in set0
[Thr 01] NiSelIListRemove: remove hdl 25 [3] from buf-list (1) of set0
[Thr 01] IcmRecMsg: received 96 bytes
[Thr 01] ============================================
[Thr 01] | COM_DATA:
[Thr 01] | Offset: 0 | Version: 7210
[Thr 01] | MsgNo: 27492 | Opcode: ICM_COM_OP_ICM_MONITOR (66)
[Thr 01] ============================================
[Thr 01] IcmHandleAdmMsg: op: 66, auth: 1
[Thr 01] NiBufIAlloc: malloc NiBufadm, to 0 bytes
[Thr 01] NiBufDup: ref 1 for buf 1875ce9f0
[Thr 01] IcmCreateRequest: Append request 11839
[Thr 01] IcmQueueAppend: queuelen: 1
[Thr 01] NiBufIAlloc: malloc ICM_EXT, to 104 bytes
[Thr 2571] IcmWorkerThread: worker 7 got the semaphore
[Thr 01]
[Thr 01] NiBufSend starting
[Thr 2571] REQUEST:
Type: ADMMSG Index = 11839
[Thr 01] NiIWrite: hdl 25 sent data (wrt=104,pac=1,MESG_IO)
[Thr 2571] NiBufFree: ref 1 for buf 1875ce9f0
[Thr 01] MAIN TRACE END
[Thr 2571] MPI<f830>16#5 GetInbuf -1 1e60a0 1160 (1) -> MPI_EOS: End Of Stream
[Thr 01] SiSelPSelect: start select (timeout=-1)
[Thr 2571] IcmHandleMonitorMessage: called with opcode: ICM_COM_OP_MON_INFO (100)
[Thr 2571] MPI<f82f>15#4 GetOutbuf -1 1f60e0 65536 (0) -> 7000000901f6100 73400320 MPI_OK
[Thr 2571] MPI<f830>16#6 FreeInbuf#2 0 1e60a0 0 -> MPI_OK
[Thr 2571] MPI<f82f>15#5 FlushOutbuf -1 1 1 1f60e0 4325 6 -> 7000000901f60e0 MPI_OK
[Thr 2571] IcmWorkerThread: Thread 7: Waiting for event
[Thr 515] Fri Nov 13 13:39:58 2015
[Thr 515] SiSelPSelect: of 1 sockets 0 selected
[Thr 515] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 515] SiSelPSelect: start select (timeout=10000)
[Thr 3599] Fri Nov 13 13:39:59 2015
[Thr 3599] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 3599] WATCHDOG TRACE BEGIN
[Thr 3599] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 3599] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 3599] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 3599] MPI<cf06>0#22582 WriteOOB 00000001 00000002 00000001 801BCC10 09001000 A0003DF8 000000
[Thr 3599] IcmWatchDogThread: call schedules, last t: 1447418369, next t: 1447418399, cur t: 1447418399
[Thr 3342] MPI<cf06>0#22583 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 3599] IcmCreateRequest: Append request 11840
[Thr 3342] MpiSelSelect( 8 -1 ) -> MPI_OK
[Thr 3599] IcmQueueAppend: queuelen: 0
[Thr 1029] IcmWorkerThread: worker 1 got the semaphore
[Thr 3599] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1029] REQUEST:
Type: SCHEDULER Index = 11840
[Thr 3599] WATCHDOG TRACE END
[Thr 1029] IcmGetSchedule: found slot 0
[Thr 3599] SiSelPSelect: start select (timeout=10000)
[Thr 3342] MPI WATCHDOG TRACE BEGIN
[Thr 1029] IcmAlReportData: Reporting data to CCMS Alerting Infrastructure
[Thr 3342] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 3342] MPI<cf06>0#22584 ReadOOB 00000001 00000002 00000001 801BCC10 09001000 A0003DF8 000000 -> MPI_OK
[Thr 3342] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 3342] MPI WATCHDOG TRACE END
[Thr 3342] MPI<cf06>0#22585: GetInbuf: check avail. buffers 0 0
[Thr 3342] MPI<cf06>0#22585 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 3342] MpiSelect: 0 waiting for events
[Thr 1029] IcmConnCheckStoredClientConn: check for client conn timeout
[Thr 1029] IcmConnCheckStoredClientConn: next client timeout check in 10 sec
[Thr 1029] IcmGetServicePtr: SRVSAP01.FORFARMERS.local:8035 - new serv_ref_count: 1
[Thr 1029] PlugInHandleAdmMessage: request received:
[Thr 1029] PlugInHandleAdmMessage: opcode: ICM_COM_OP_CACHE_STAT (136), len: 272, dest_type: 2, subhdlkey: 262145
[Thr 1029] HttpISubHandlerItCreate: add reference to table 182a5a3f0, now 2 references, 1 tables used
[Thr 1029] HttpSubHandlerCall: Call Handler: HttpCacheHandler (182adbe50/182a5a3f0), task=TASK_ADM_MSG(4), header_len=0
[Thr 1029] HttpCacheHandler: 4 0 182adbe50 0
[Thr 1029] SCACHE: adm request received:
[Thr 1029] SCACHE: opcode: 136, len: 272, dest_type: 2, dest:
[Thr 1029] MTX_LOCK 3184 182adc030
[Thr 1029] MTX_UNLOCK 3197 182adc030
[Thr 1029] IctCmGetCacheInfo#1874 -> 0
[Thr 1029] IcmNetBufWrapBuf: allocated netbuf: 180a77350, blocks used: 1
[Thr 1029] IcmNetBufWrapBuf: allocated netbuf: 180a77350
[Thr 1029] HttpSubHandlerItDelete: remove reference to table 182a5a3f0, now 1 references, 1 tables used
[Thr 1029] IcmNetBufFree: free netbuf: 180a77350 out of 1 used
[Thr 1029] IcmConnFreeContext: context 1 released
[Thr 1029] IcmServDecrRefCount: SRVSAP01.FORFARMERS.local:8035 - new serv_ref_count: 0
[Thr 1029] IcmGetSchedule: next schedule in 30 secs
[Thr 1029] IcmWorkerThread: Thread 1: Waiting for event
[Thr 515] Fri Nov 13 13:40:08 2015
[Thr 515] SiSelPSelect: of 1 sockets 0 selected
[Thr 515] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 515] SiSelPSelect: start select (timeout=10000)
[Thr 3599] Fri Nov 13 13:40:09 2015
[Thr 3599] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 3599] WATCHDOG TRACE BEGIN
[Thr 3599] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 3599] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 3599] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 3599] MPI<cf06>0#22586 WriteOOB 00000001 00000002 00000001 801BCC10 09001000 A0003DF8 000000
[Thr 3599] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 3342] MPI<cf06>0#22587 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 3599] WATCHDOG TRACE END
[Thr 3342] MpiSelSelect( 8 -1 ) -> MPI_OK
[Thr 3599] SiSelPSelect: start select (timeout=10000)
[Thr 3342] MPI WATCHDOG TRACE BEGIN
[Thr 3342] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 3342] MPI<cf06>0#22588 ReadOOB 00000001 00000002 00000001 801BCC10 09001000 A0003DF8 000000 -> MPI_OK
[Thr 3342] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 3342] MPI WATCHDOG TRACE END
[Thr 3342] MPI<cf06>0#22589: GetInbuf: check avail. buffers 0 0
[Thr 3342] MPI<cf06>0#22589 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 3342] MpiSelect: 0 waiting for events
[Thr 01] Fri Nov 13 13:40:10 2015
[Thr 01] SiSelPNext: sock 26 selected (pos=8; revt=r--)
[Thr 01] NiSelIListInsert: add hdl 73 [8] to sel-list (0) of set0
[Thr 01] NiSelISelectInt: 1 handles selected (0 buffered)
[Thr 01] MAIN TRACE BEGIN
[Thr 01] IcmAcceptClient: Connection request from Client received
[Thr 01] NiIPeekListen: peek successful for hdl 73
[Thr 01] NiIAccept: hdl 73 accepted connection
[Thr 01] NiICreateHandle: hdl 145 state NI_INITIAL_CON
[Thr 01] NiIInitSocket: set default settings for hdl 145/sock 37 (I4; ST)
[Thr 01] NiIBlockMode: set blockmode for hdl 145 FALSE
[Thr 01] NiIAccept: state of hdl 145 NI_ACCEPTED
[Thr 01] NiIAccept: hdl 73 accepted hdl 145 from 192.168.102.72:50943
[Thr 01] NiIAccept: hdl 145 took local address 172.20.1.202:8235
[Thr 01] IcmConnCheckStoredClientConn: check for client conn timeout
[Thr 01] IcmConnCheckStoredClientConn: next client timeout check in 10 sec
[Thr 01] MAIN TRACE REQ: 0/3396/1
[Thr 01] IcmServIncrRefCount: SRVSAP01.FORFARMERS.local:8235 - new serv_ref_count: 1
[Thr 01] IcmCreateRequest: Append request 11841
[Thr 01] IcmQueueAppend: queuelen: 1
[Thr 01] IcmConnIntegrateServer: accepted connection from 192.168.102.72 on service 8235
[Thr 3085] IcmWorkerThread: worker 9 got the semaphore
[Thr 01] MAIN TRACE END
[Thr 3085] REQ TRACE BEGIN: 0/3396/1
[Thr 01] SiSelPSelect: start select (timeout=-1)
[Thr 3085] REQUEST:
Type: ACCEPT_CONNECTION Index = 11841
[Thr 3085] CONNECTION (id=0/3396):
used: 1, type: default, role: Server(1), stateful: 0
NI_HDL: 145, protocol: HTTPS(2)
local host: 172.20.1.202:8235 ()
remote host: 192.168.102.72:50943 ()
status: NOP
connect time: 13.11.2015 13:40:10
MPI request: <0> MPI response: <0>
request_buf_size: 0 response_buf_size: 0
request_buf_used: 0 response_buf_used: 0
request_buf_offset: 0 response_buf_offset: 0
[Thr 3085] MPI 21: event flag already open:7949 key=16949
[Thr 3085] MPI 21: event flag already open:7948 key=16948
[Thr 3085] MPI:21 create pipe 7000000900024e0 1
[Thr 3085] MPI<f831>15#1 Open( ANONYMOUS 21 1 ) -> 21
[Thr 3085] MPI<f831>15#2 Open( ANONYMOUS 21 0 ) -> 21
[Thr 3085] MPI 22: event flag already open:7947 key=16947
[Thr 3085] MPI 22: event flag already open:7946 key=16946
[Thr 3085] MPI:22 create pipe 700000090002690 1
[Thr 3085] MPI<f832>16#1 Open( ANONYMOUS 22 0 ) -> 22
[Thr 3085] MPI<f832>16#2 Open( ANONYMOUS 22 1 ) -> 22
[Thr 3085] ->> SapSSLSessionInit(&sssl_hdl=180c6be08, role=2 (SERVER), auth_type=1 (ASK_CLIENT_CERT))
[Thr 3085] <<- SapSSLSessionInit()==SAP_O_K
[Thr 3085] in: args = "role=2 (SERVER), auth_type=1 (ASK_CLIENT_CERT)"
[Thr 3085] out: sssl_hdl = 1875ce9f0
[Thr 3085] ->> SapSSLSetNiHdl(sssl_hdl=1875ce9f0, ni_hdl=145)
[Thr 3085] NiIBlockMode: set blockmode for hdl 145 TRUE
[Thr 3085] SSL NI-sock: local=172.20.1.202:8235 peer=192.168.102.72:50943
[Thr 3085] <<- SapSSLSetNiHdl(sssl_hdl=1875ce9f0, ni_hdl=145)==SAP_O_K
[Thr 3085] ->> SapSSLSessionStart(sssl_hdl=1875ce9f0)
[Thr 3085] SapISSLServerCacheExpiration(): Calling ServerCacheCleanup() (lifetime=1440)
[Thr 3085] SapISSLServerCacheExpiration(srv,"/usr/sap/QE0/DVEBMGS35/sec/SAPSSLS.pse"): Cache max/before/now = 5000/1/1
[Thr 3085] Server-configured Ciphersuites: "TLS_RSA_WITH_AES128_GCM_SHA256:TLS_RSA_WITH_AES256_GCM_SHA384:TLS_RSA_WITH_AES128_
[Thr 3085] Client-offered Ciphersuites: "TLS_RSA_WITH_RC4_128_MD5:TLS_RSA_WITH_RC4_128_SHA:TLS_RSA_EXPORT_WITH_RC4_40_MD5:TLS_
[Thr 3085] No Client Certificate
[Thr 3085] Cached session resumed (TLSv1.0)
[Thr 3085] HexDump of native SSL session ID { &buf= 1875cebe4, buf_len= 32 }
[Thr 3085] 00000: 64 1d d2 9d d5 e4 62 b7 79 55 78 da a9 36 51 97 d.....b. yUx..6Q.
[Thr 3085] 00010: 13 b3 83 85 a6 1e a1 94 ba 66 ee c5 12 f3 b5 c1 ........ .f......
[Thr 3085] <<- SapSSLSessionStart(sssl_hdl=1875ce9f0)==SAP_O_K
[Thr 3085] status = "resumed SSL session, NO client cert"
[Thr 3085] IcmPlCheckRetVal: Next status: READ_REQUEST(1)
[Thr 3085] IcmReadFromConn(id=0/3396): request new MPI (0/0)
[Thr 3085] IcmLowOnBlocks: mpi buffer space free (cur/limit/unreserved): 0/2507/3134)
[Thr 3085] MPI<f831>15#3 GetOutbuf 0 1f60e0 65536 (0) -> 7000000901f6100 73400320 MPI_OK
[Thr 3085] ->> SapSSLReadPending(sssl_hdl=1875ce9f0, &pendlen=18268e370)
[Thr 3085] <<- SapSSLReadPending(sssl_hdl=1875ce9f0)==SAP_O_K
[Thr 3085] out: pendlen = 0
[Thr 3085] NiIPeek: peek successful for hdl 145 (r)
[Thr 3085] ->> SapSSLRead(sssl_hdl=1875ce9f0, buf=7000000901f6148, maxlen=65463, timeout=500, &readlen=18268e374)
[Thr 3085] <<- SapSSLRead(sssl_hdl=1875ce9f0)==SAP_O_K
[Thr 3085] ... = "buf= 7000000901f6148, max=65463, received=874"
[Thr 3085] ->> SapSSLReadPending(sssl_hdl=1875ce9f0, &pendlen=18268e370)
[Thr 3085] <<- SapSSLReadPending(sssl_hdl=1875ce9f0)==SAP_O_K
[Thr 3085] out: pendlen = 0
[Thr 3085] NiIPeek: peek successful for hdl 145 (r)
[Thr 3085] ->> SapSSLRead(sssl_hdl=1875ce9f0, buf=7000000901f64b2, maxlen=64589, timeout=0, &readlen=18268e374)
[Thr 3085] <<- SapSSLRead(sssl_hdl=1875ce9f0)==SAP_O_K
[Thr 3085] ... = "buf= 7000000901f64b2, max=64589, received=2468"
[Thr 3085] ->> SapSSLReadPending(sssl_hdl=1875ce9f0, &pendlen=18268e370)
[Thr 3085] <<- SapSSLReadPending(sssl_hdl=1875ce9f0)==SAP_O_K
[Thr 3085] out: pendlen = 0
[Thr 3085] NiIPeek: peek for hdl 145 timed out (r; 0ms)
[Thr 3085] IcmReadFromConn(id=0/3396): no SSL data available
[Thr 3085] IcmReadFromConn(id=0/3396): read 3342 bytes, 2 readops (timeout 0)
[Thr 3085] BINDUMP of content denied
[Thr 3085] HttpPlugInHandleNetData(rqid=0/3396/1): role: Server(1), status: 1
[Thr 3085] content-length: 0/0, buf_len: 3342, buf_offset: 0, buf_status: 0
[Thr 3085] ICT: IctIHttpOpenMessage: 188352f70 typ=1
[Thr 3085] HttpParseRequestHeader: content length: 2468
[Thr 3085] HttpParseRequestHeader: no transfer-encoding set
[Thr 3085] HttpParseRequestHeader: Version: 1001
[Thr 3085] HttpParseRequestHeader: Keep-Alive: 1
[Thr 3085] HttpParseRequestHeader: no server port set
[Thr 3085] DpPlgGetVirtHost: search virt host for 2/ecc-q-nl.forfarmers.eu/8235
[Thr 3085] DpPlgGetVirtHost: no server defined, use default
[Thr 3085] HttpGetVirtHost: use virt_host_idx 0 for ecc-q-nl.forfarmers.eu:8235
[Thr 3085] HttpSrvHdlRequest: method: 2; path: /sap/bc/srt/idoc
[Thr 3085] Handler 0: HttpLogHandler matches url: /sap/bc/srt/idoc
[Thr 3085] Handler 1: HttpAuthHandler matches url: /sap/bc/srt/idoc
[Thr 3085] Handler 2: HttpModHandler matches url: /sap/bc/srt/idoc
[Thr 3085] Handler 4: HttpCacheHandler matches url: /sap/bc/srt/idoc
[Thr 3085] Handler 6: HttpSAPR3Handler matches url: /sap/bc/srt/idoc
[Thr 3085] HttpSubHandlerMatch: add reference to table 182a5a3f0, now 2 references, 1 tables used
[Thr 3085] HttpSubHandlerCall: Call Handler: HttpLogHandler (1836b44f0/182a5a3f0), task=TASK_REQUEST(1), header_len=874
[Thr 3085] HttpLogHandler called: task=1
[Thr 3085] HttpSubHandlerItDeactivate: handler 0: HttpLogHandler
[Thr 3085] HttpSubHandlerCall: Call Handler: HttpAuthHandler (1836b4910/182a5a3f0), task=TASK_REQUEST(1), header_len=874
[Thr 3085] >> start >> CsiGetInstance(1836b50d0)
[Thr 3085] << end << CsiGetInstance(1836b50d0) returned inst=1875e3f30
[Thr 3085] >> start >> CsiExecute(1875e3f30,182689e70,31,1,182689e60,182689e10,0)
[Thr 3085] >> VsaScan(1875e4010,1875e3190,1875e3c30,1875e32f0,NULL) >>
[Thr 3085] << VsaScan(1875e4010,1875e3190,1875e3c30,1875e32f0,NULL) = 0 <<
[Thr 3085] << end << CsiExecute(CSI_RC==VSI_OK)
[Thr 3085] >> start >> CsiFreeInstance(1875e3f30)
[Thr 3085] << end << CsiFreeInstance(CSI_RC==VSI_OK)
[Thr 3085] ->> SapSSLGetPeerInfo(sssl_hdl=1875ce9f0, &cert=18268c070, &cert_len=18268c050,
[Thr 3085] &subject_dn=18268c088, &issuer_dn=18268c080, &cipher=18268c078)
[Thr 3085] Current Cipher: TLS_RSA_WITH_AES128_CBC_SHA
[Thr 3085] <<- SapSSLGetPeerInfo(sssl_hdl=1875ce9f0)==SAP_O_K
[Thr 3085] out: cert_len = <no cert>
[Thr 3085] out: cipher = "TLS_RSA_WITH_AES128_CBC_SHA"
[Thr 3085] HttpSubHandlerItDeactivate: handler 1: HttpAuthHandler
[Thr 3085] HttpSubHandlerCall: Call Handler: HttpModHandler (1836b47f0/182a5a3f0), task=TASK_REQUEST(1), header_len=874
[Thr 3085] ->> SapSSLGetPeerInfo(sssl_hdl=1875ce9f0, &cert=18267d760, &cert_len=18267d740,
[Thr 3085] &subject_dn=18267d758, &issuer_dn=18267d750, &cipher=18267d748)
[Thr 3085] <<- SapSSLGetPeerInfo(sssl_hdl=1875ce9f0)==SAP_O_K
[Thr 3085] out: cert_len = <no cert>
[Thr 3085] out: cipher = "TLS_RSA_WITH_AES128_CBC_SHA"
[Thr 3085] HttpModGetDefRules: determined the defactions: NOTHING (0)
[Thr 3085] HttpSubHandlerItDeactivate: handler 2: HttpModHandler
[Thr 3085] HttpSubHandlerCall: Call Handler: HttpCacheHandler (182adbe50/182a5a3f0), task=TASK_REQUEST(1), header_len=874
[Thr 3085] HttpCacheHandler: 1 874 182adbe50 0
[Thr 3085] ISC: uncacheable request method 2
[Thr 3085] HttpCacheHandler: cache miss.
[Thr 3085] HttpSubHandlerItDeactivate: handler 3: HttpCacheHandler
[Thr 3085] HttpSubHandlerCall: Call Handler: HttpSAPR3Handler (1875f5b90/182a5a3f0), task=TASK_REQUEST(1), header_len=874
[Thr 3085] HttpSAPR3Handler: url_tab_init: 1, force_dest: 0
[Thr 3085] ICT: IctLookupPathTable() -> 0
[Thr 3085] HttpSAPR3Handler: Call SAP AppServer for URI: /, java: 0
[Thr 3085] DTRACE(0/3396/1): {root-id=56441E69FE6FCC1CE1008000AC1401CA}_{conn-id=56441E6AFE6FCC1CE1008000AC1401CA}_1
[Thr 3085] IcmFlushBuf: Flushing 3342 Bytes, buf_status: 6
[Thr 3085] flush buffer with mpi buffer id 5
[Thr 3085] MPI<f831>15#4 FlushOutbuf 5 1 0 1f60e0 3414 6 -> 7000000901f60e0 MPI_OK
[Thr 3085] IcmCreateDpRequest: Send request to AppServer
[Thr 3085] DpCheckContextUsage: check for plugin 2: 2000/90 against 0 used
[Thr 3085] -OUT- sender_id IC_MAN tid -1 wp_ca_blk -1 wp_id -1
[Thr 3085] -OUT- action SEND_TO_WP uid -1 appc_ca_blk -1 type DIA
[Thr 3085] -OUT- new_stat NO_CHANGE mode 0 len 0 rq_id 60938
[Thr 3085] -OUT- req_info LOGIN,DP_ICM_EVENT
[Thr 3085] -OUT- mpi read <f831> mpi write <f832> prot 2 obj fd -1 rq_id 0
[Thr 3085] -OUT- icm_opcode: ICM_PLUGIN_REQUEST virt_host_idx: 0
[Thr 3085] -OUT- dtrace {root-id=56441E69FE6FCC1CE1008000AC1401CA}_{conn-id=56441E6AFE6FCC1CE1008000AC1401CA}_1
[Thr 3085] SemRq( 2, 1, -1) enter
[Thr 3085] SemRq( 2, 1, -1) exit rtc=0, 0us
[Thr 3085] SemRel( 2, 1 ) enter
[Thr 3085] SemRel( 2, 1 ) exit rtc=0, 0us
[Thr 3085] DpRqIPutIntoQ: put elem in queue DIA, elems=1
[Thr 3085] DpRqPutIntoQueue: put request into queue (reqtype 1, prio LOW, rq_id 60938)
[Thr 3085] IcmConnRollInWP: rolled in WP -old roll reason was: ICM_ROLL_NONE(0)
[Thr 3085] HttpSrvHdlRequest: Subhandler rc=704
[Thr 3085] IcmPlCheckRetVal: Next status: WRITE_RESPONSE(4)
[Thr 3085] IcmHandleNetRead(id=0/3396): read_len: 3342, HandleNetData returned: 4
[Thr 3085] IcmHandleNetRead(id=0/3396): status 1 -> 4
[Thr 3085] IcmReadFromPartner(id=0/3396): read with maximum timeout 500
[Thr 3085] IcmConnRollInWP: no need to roll in WP status: ROLLED IN
[Thr 3085] IcmMpiWatchInsert: MPI watch entry <f832>, number 0 inserted.
[Thr 3085] MPI<f832>16#3: GetInbuf: waiting for new buffer 0 0
[Thr 3085] MPI<f832>16#5 GetInbuf -1 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 3085] IcmMpiWatchRemove: MPI watch entry <f832>, number 0 removed (wakeup was not sent).
[Thr 3085] IcmReadFromPartner: IcmMpiGetInbuf returned rc=MPI_EOUTOFBAND: out-of-band message/12, wakeup not sent
[Thr 3085] MPI<f832>16#6 ReadOOB 00000001 00000006 00000021 00DD1DDF 0039322E 3136382E 313032 -> MPI_OK
[Thr 3085] IcmHandleOOBData: Received data on 1st MPI (seqno: 1, type=6, reason=Request processed in wp(3)): 33/7647/0
[Thr 3085] IcmHandleOOBData: request will be processed in wp 3
[Thr 3085] IcmConnRollInWP: no need to roll in WP status: ROLLED IN
[Thr 3085] IcmMpiWatchInsert: MPI watch entry <f832>, number 0 inserted.
[Thr 3085] MPI<f832>16#7: GetInbuf: waiting for new buffer 0 0
[Thr 01] SiSelPNext: sock 17 selected (pos=4; revt=r--)
[Thr 01] NiBufISelProcess: hdl 33 process r-
[Thr 01] NiBufIAlloc: malloc NIBUF-IN, to 8416 bytes
[Thr 01] NiIRead: hdl 33 received data (rcd=8416,pac=1,MESG_IO)
[Thr 01] NiBufIIn: NIBUF len=8416
[Thr 01] NiBufIIn: packet complete for hdl 33
[Thr 01] NiBufISelUpdate: new MODE -- (r-) for hdl 33 in set0
[Thr 01] SiSelPSet: set events of sock 17 to: ---
[Thr 01] NiBufISelUpdate: new STAT r-- (---) for hdl 33 in set0
[Thr 01] NiSelIListInsert: add hdl 33 [4] to buf-list (0) of set0
[Thr 01] NiSelISelectInt: 1 handles selected (1 buffered)
[Thr 01] MAIN TRACE BEGIN
[Thr 01] IcmMsgProcess: Receive data from partner: DP(1), wp_no: 0
[Thr 01]
[Thr 01] NiBufReceive starting
[Thr 01] NiBufISelUpdate: new MODE r- (--) for hdl 33 in set0
[Thr 01] SiSelPSet: set events of sock 17 to: rp-
[Thr 01] NiBufISelUpdate: new STAT --- (r--) for hdl 33 in set0
[Thr 01] NiSelIListRemove: remove hdl 33 [4] from buf-list (1) of set0
[Thr 01] IcmRecMsg: received 8416 bytes
[Thr 01] ============================================
[Thr 01] | COM_DATA:
[Thr 01] | Offset: 0 | Version: 7210
[Thr 01] | MsgNo: 98052 | Opcode: ICM_COM_OP_SET_PARAM (11)
[Thr 01] ============================================
[Thr 01] IcmHandleAdmMsg: op: 11, auth: 1
[Thr 01] IcmHandleAdmMsg: set param -> icm/OP_SET_ABAP_RELEASE
[Thr 01] NiBufIAlloc: malloc ICM_EXT, to 104 bytes
[Thr 01]
[Thr 01] NiBufSend starting
[Thr 01] NiIWrite: hdl 33 sent data (wrt=104,pac=1,MESG_IO)
[Thr 01] MAIN TRACE END
[Thr 01] SiSelPSelect: start select (timeout=-1)
[Thr 01] SiSelPNext: sock 32 selected (pos=12; revt=r--)
[Thr 01] NiBufISelProcess: hdl 105 process r-
[Thr 01] NiBufIAlloc: malloc NIBUF-IN, to 96 bytes
[Thr 01] NiIRead: hdl 105 received data (rcd=96,pac=1,MESG_IO)
[Thr 01] NiBufIIn: NIBUF len=96
[Thr 01] NiBufIIn: packet complete for hdl 105
[Thr 01] NiBufISelUpdate: new MODE -- (r-) for hdl 105 in set0
[Thr 01] SiSelPSet: set events of sock 32 to: ---
[Thr 01] NiBufISelUpdate: new STAT r-- (---) for hdl 105 in set0
[Thr 01] NiSelIListInsert: add hdl 105 [12] to buf-list (0) of set0
[Thr 01] NiSelISelectInt: 1 handles selected (1 buffered)
[Thr 01] MAIN TRACE BEGIN
[Thr 01] IcmMsgProcess: Receive data from partner: WP(2), wp_no: 0
[Thr 01]
[Thr 01] NiBufReceive starting
[Thr 01] NiBufISelUpdate: new MODE r- (--) for hdl 105 in set0
[Thr 01] SiSelPSet: set events of sock 32 to: rp-
[Thr 01] NiBufISelUpdate: new STAT --- (r--) for hdl 105 in set0
[Thr 01] NiSelIListRemove: remove hdl 105 [12] from buf-list (1) of set0
[Thr 01] IcmRecMsg: received 96 bytes
[Thr 01] ============================================
[Thr 01] | COM_DATA:
[Thr 01] | Offset: 0 | Version: 7210
[Thr 01] | MsgNo: 25604 | Opcode: ICM_COM_OP_ICM_MONITOR (66)
[Thr 01] ============================================
[Thr 01] IcmHandleAdmMsg: op: 66, auth: 1
[Thr 01] NiBufIAlloc: malloc NiBufadm, to 0 bytes
[Thr 01] NiBufDup: ref 1 for buf 1875d22b0
[Thr 01] IcmCreateRequest: Append request 11842
[Thr 01] IcmQueueAppend: queuelen: 1
[Thr 01] NiBufIAlloc: malloc ICM_EXT, to 104 bytes
[Thr 2828] IcmWorkerThread: worker 8 got the semaphore
[Thr 01]
[Thr 01] NiBufSend starting
[Thr 2828] REQUEST:
Type: ADMMSG Index = 11842
[Thr 01] NiIWrite: hdl 105 sent data (wrt=104,pac=1,MESG_IO)
[Thr 2828] NiBufFree: ref 1 for buf 1875d22b0
[Thr 01] MAIN TRACE END
[Thr 2828] MPI<f834>12#5 GetInbuf -1 1f60e0 1160 (1) -> MPI_EOS: End Of Stream
[Thr 01] SiSelPSelect: start select (timeout=-1)
[Thr 2828] IcmHandleMonitorMessage: called with opcode: ICM_COM_OP_MON_INFO (100)
[Thr 2828] MPI<f833>11#4 GetOutbuf -1 1e60a0 65536 (0) -> 7000000901e60c0 73400320 MPI_OK
[Thr 2828] MPI<f834>12#6 FreeInbuf#2 0 1f60e0 0 -> MPI_OK
[Thr 2828] MPI<f833>11#5 FlushOutbuf -1 1 1 1e60a0 4325 6 -> 7000000901e60a0 MPI_OK
[Thr 2828] IcmWorkerThread: Thread 8: Waiting for event
[Thr 3085] MPI<f832>16#10 GetInbuf -1 1e60a0 971 (1) -> MPI_EOS: End Of Stream
[Thr 3085] IcmMpiWatchRemove: MPI watch entry <f832>, number 0 removed (wakeup was not sent).
[Thr 3085] IcmReadFromPartner: IcmMpiGetInbuf returned rc=MPI_EOS: End Of Stream/6, wakeup not sent
[Thr 3085] BINDUMP of content denied
[Thr 3085] PlugInHandleServData(rqid=0/3396/1): role: Server(1), status: 3
[Thr 3085] content-length: 0/-1, buf_len: 899, buf_offset: 0, buf_status: 6
[Thr 3085] ICT: IctIHttpOpenMessage: 188365530 typ=2
[Thr 3085] HttpParseResponseHeader: no transfer-encoding set
[Thr 3085] HttpParseResponseHeader: no connection value set
[Thr 3085] HttpParseResponseHeader: Version: 1001
[Thr 3085] HttpParseResponseHeader: Keep-Alive: 0
[Thr 3085] HttpSrvHdlResponse: body_complete: 1, native: 1, follow_up: 0
[Thr 3085] HttpSrvHdlResponse: flags: 1052677, handle_resp: 0
[Thr 3085] HttpSrvHdlResponse: native: 1, flags & NATIVE: 0
[Thr 3085] HttpSubHandlerCall: Call Handler: HttpSAPR3Handler (1875f5b90/182a5a3f0), task=TASK_RESPONSE(2), header_len=899
[Thr 3085] HttpSAPR3Handler: Response from AppServer
[Thr 3085] HttpSrvHdlResponse: flags: 12293, handle_resp: 8192
[Thr 3085] HttpSubHandlerItActivate: handler 3: HttpCacheHandler
[Thr 3085] HttpSrvHdlResponse: native: 1, flags & NATIVE: 0
[Thr 3085] HttpSubHandlerCall: Call Handler: HttpCacheHandler (182adbe50/182a5a3f0), task=TASK_RESPONSE(2), header_len=899
[Thr 3085] HttpCacheHandler: 2 899 182adbe50 188357130
[Thr 3085] ISC: don't cache response (no valid cache key).
[Thr 3085] ICC: don't cache response. scc=0 status=0 len=0 meth=2
[Thr 3085] HttpSrvHdlResponse: flags: 12293, handle_resp: 8192
[Thr 3085] HttpSubHandlerItActivate: handler 2: HttpModHandler
[Thr 3085] HttpSrvHdlResponse: native: 1, flags & NATIVE: 0
[Thr 3085] HttpSubHandlerCall: Call Handler: HttpModHandler (1836b47f0/182a5a3f0), task=TASK_RESPONSE(2), header_len=899
[Thr 3085] HttpSrvHdlResponse: flags: 12293, handle_resp: 8192
[Thr 3085] HttpSubHandlerItActivate: handler 1: HttpAuthHandler
[Thr 3085] HttpSrvHdlResponse: native: 1, flags & NATIVE: 0
[Thr 3085] HttpSubHandlerCall: Call Handler: HttpAuthHandler (1836b4910/182a5a3f0), task=TASK_RESPONSE(2), header_len=899
[Thr 3085] HttpSrvHdlResponse: flags: 12293, handle_resp: 8192
[Thr 3085] HttpSubHandlerItActivate: handler 0: HttpLogHandler
[Thr 3085] HttpSrvHdlResponse: native: 1, flags & NATIVE: 0
[Thr 3085] HttpSubHandlerCall: Call Handler: HttpLogHandler (1836b44f0/182a5a3f0), task=TASK_RESPONSE(2), header_len=899
[Thr 3085] HttpLogHandler called: task=2
[Thr 3085] IcmNetBufWrapBuf: allocated netbuf: 180a77350, blocks used: 1
[Thr 3085] IcmNetBufWrapBuf: allocated netbuf: 180a77350
[Thr 3085] HttpSubHandlerClose: Call Handler: HttpLogHandler (1836b44f0/182a5a3f0), task=TASK_CLOSE(3)
[Thr 3085] HttpLogHandler called: task=3
[Thr 3085] HttpSubHandlerClose: Call Handler: HttpAuthHandler (1836b4910/182a5a3f0), task=TASK_CLOSE(3)
[Thr 3085] HttpSubHandlerClose: Call Handler: HttpModHandler (1836b47f0/182a5a3f0), task=TASK_CLOSE(3)
[Thr 3085] HttpSubHandlerClose: Call Handler: HttpCacheHandler (182adbe50/182a5a3f0), task=TASK_CLOSE(3)
[Thr 3085] HttpCacheHandler: 3 0 182adbe50 188357130
[Thr 3085] HttpSubHandlerClose: Call Handler: HttpSAPR3Handler (1875f5b90/182a5a3f0), task=TASK_CLOSE(3)
[Thr 3085] HttpSubHandlerClose: remove reference to table 182a5a3f0, now 1 references, 1 tables used
[Thr 3085] PlugInHandleServData: HttpSrvHdlResponse returned: 702
[Thr 3085] IcmPlCheckRetVal: Plugin retval: PLUGIN_RET_CLOSE (702)
[Thr 3085] IcmHandleNetWrite(id=0/3396): HandleServData returned: 702
[Thr 3085] BINDUMP of content denied
[Thr 3085] IcmWriteToConn(id=0/3396): prepared to write data to partner (len = 899)
[Thr 3085] ->> SapSSLWrite(sssl_hdl=1875ce9f0, buf=7000000901e6108, len=899, timeout=2000, &writelen=18268e3e0)
[Thr 3085] <<- SapSSLWrite(sssl_hdl=1875ce9f0)==SAP_O_K
[Thr 3085] ... = "buf= 7000000901e6108, written= 899 of 899 (all)"
[Thr 3085] IcmWriteToConn(id=0/3396): wrote data to partner (len = 899)
[Thr 3085] IcmNetBufFree: free netbuf: 180a77350 out of 1 used
[Thr 3085] MPI<f832>16#12 FreeInbuf#1 0 1e60a0 0 -> MPI_OK
[Thr 3085] MPI<f831>15#8 ReadOOB 00000002 00000001 00000021 00521DDF 00000001 80005320 0FFFFF -> MPI_OK
[Thr 3085] IcmHandleOOBData: Received data on 1st MPI (seqno: 2, type=1, reason=ICM_ROLL_APPL_REL_CONTEXT(4)): 33/7647/0
[Thr 3085] MPI<f832>16#13 ReadOOB 00000002 00000001 00000021 00521DDF 00000001 80005320 0FFFFF -> MPI_OK
[Thr 3085] IcmHandleOOBData: Received data on 2nd MPI (seqno: 2, type=1, reason=ICM_ROLL_APPL_REL_CONTEXT(4)): 33/7647/0
[Thr 3085] IcmHandleOOBData: Received context key (type=1, reason=ICM_ROLL_APPL_REL_CONTEXT(4)): 33/7647/0
[Thr 3085] PlugInStopConn: role: Server(1), error: 0, write_err: 0
[Thr 3085] ICT: IctHttpCloseMessage( 188352f70 ) -> u=0 rc=0
[Thr 3085] ICT: IctHttpCloseMessage( 188365530 ) -> u=0 rc=0
[Thr 3085] ->> SapSSLSessionDone(&sssl_hdl=180c6be08)
[Thr 3085] <<- SapSSLSessionDone()==SAP_O_K
[Thr 3085] in: sssl_hdl = 1875ce9f0
[Thr 3085] ... ni_hdl = 145
[Thr 3085] MPI<f831>15#9 Close( 15 ) opt=4 del=0( 1 0 ) wakeup=0-> MPI_OK
[Thr 3085] MPI<f831>15#11 Delete( 15 ) -> MPI_OK
[Thr 3085] MPI<f831>15#10 Close( 15 ) opt=4 del=1( 0 0 ) wakeup=0-> MPI_OK
[Thr 3085] MPI<f832>16#14 Close( 16 ) opt=4 del=0( 0 1 ) wakeup=0-> MPI_OK
[Thr 3085] MPI<f832>16#16 Delete( 16 ) -> MPI_OK
[Thr 3085] MPI<f832>16#15 Close( 16 ) opt=4 del=1( 0 0 ) wakeup=0-> MPI_OK
[Thr 3085] NiICloseHandle: shutdown and close hdl 145/sock 37
[Thr 3085] IcmConnClose: Connection 0/3396 closed
[Thr 3085] IcmConnFreeContext: context 1 released
[Thr 3085] IcmServDecrRefCount: SRVSAP01.FORFARMERS.local:8235 - new serv_ref_count: 0
[Thr 3085] REQ TRACE END: 0/3396/1
[Thr 3085] IcmWorkerThread: Thread 9: Waiting for event
[Thr 515] Fri Nov 13 13:40:18 2015
[Thr 515] SiSelPSelect: of 1 sockets 0 selected
[Thr 515] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 515] SiSelPSelect: start select (timeout=10000)
[Thr 3599] Fri Nov 13 13:40:19 2015
[Thr 3599] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 3599] WATCHDOG TRACE BEGIN
[Thr 3599] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 3599] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 3599] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 3599] MPI<cf06>0#22590 WriteOOB 00000001 00000002 00000001 801BCC10 09001000 A0003DF8 000000
[Thr 3599] IcmConnPoolNiWatchCheck: Check Ni Watch List with 0 entries
[Thr 3342] MPI<cf06>0#22591 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 3599] IcmCheckForBlockedThreads: check for blocked SSL-threads
[Thr 3342] MpiSelSelect( 8 -1 ) -> MPI_OK
[Thr 3599] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 3342] MPI WATCHDOG TRACE BEGIN
[Thr 3599] WATCHDOG TRACE END
[Thr 3342] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 3599] SiSelPSelect: start select (timeout=10000)
[Thr 3342] MPI<cf06>0#22592 ReadOOB 00000001 00000002 00000001 801BCC10 09001000 A0003DF8 000000 -> MPI_OK
[Thr 3342] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 3342] MPI WATCHDOG TRACE END
[Thr 3342] MPI<cf06>0#22593: GetInbuf: check avail. buffers 0 0
[Thr 3342] MPI<cf06>0#22593 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 3342] MpiSelect: 0 waiting for events
[Thr 01] Fri Nov 13 13:40:25 2015
[Thr 01] SiSelPNext: sock 17 selected (pos=4; revt=r--)
[Thr 01] NiBufISelProcess: hdl 33 process r-
[Thr 01] NiBufIAlloc: malloc NIBUF-IN, to 8416 bytes
[Thr 01] NiIRead: hdl 33 received data (rcd=8416,pac=1,MESG_IO)
[Thr 01] NiBufIIn: NIBUF len=8416
[Thr 01] NiBufIIn: packet complete for hdl 33
[Thr 01] NiBufISelUpdate: new MODE -- (r-) for hdl 33 in set0
[Thr 01] SiSelPSet: set events of sock 17 to: ---
[Thr 01] NiBufISelUpdate: new STAT r-- (---) for hdl 33 in set0
[Thr 01] NiSelIListInsert: add hdl 33 [4] to buf-list (0) of set0
[Thr 01] SiSelPNext: sock 32 selected (pos=12; revt=r--)
[Thr 01] NiBufISelProcess: hdl 105 process r-
[Thr 01] NiBufIAlloc: malloc NIBUF-IN, to 96 bytes
[Thr 01] NiIRead: hdl 105 received data (rcd=96,pac=1,MESG_IO)
[Thr 01] NiBufIIn: NIBUF len=96
[Thr 01] NiBufIIn: packet complete for hdl 105
[Thr 01] NiBufISelUpdate: new MODE -- (r-) for hdl 105 in set0
[Thr 01] SiSelPSet: set events of sock 32 to: ---
[Thr 01] NiBufISelUpdate: new STAT r-- (---) for hdl 105 in set0
[Thr 01] NiSelIListInsert: add hdl 105 [12] to buf-list (1) of set0
[Thr 01] NiSelISelectInt: 2 handles selected (2 buffered)
[Thr 01] MAIN TRACE BEGIN
[Thr 01] IcmMsgProcess: Receive data from partner: WP(2), wp_no: 0
[Thr 01]
[Thr 01] NiBufReceive starting
[Thr 01] NiBufISelUpdate: new MODE r- (--) for hdl 105 in set0
[Thr 01] SiSelPSet: set events of sock 32 to: rp-
[Thr 01] NiBufISelUpdate: new STAT --- (r--) for hdl 105 in set0
[Thr 01] NiSelIListRemove: remove hdl 105 [12] from buf-list (2) of set0
[Thr 01] IcmRecMsg: received 96 bytes
[Thr 01] ============================================
[Thr 01] | COM_DATA:
[Thr 01] | Offset: 0 | Version: 7210
[Thr 01] | MsgNo: 25608 | Opcode: ICM_COM_OP_ICM_MONITOR (66)
[Thr 01] ============================================
[Thr 01] IcmHandleAdmMsg: op: 66, auth: 1
[Thr 01] NiBufIAlloc: malloc NiBufadm, to 0 bytes
[Thr 01] NiBufDup: ref 1 for buf 1875ce9f0
[Thr 01] IcmCreateRequest: Append request 11843
[Thr 01] IcmQueueAppend: queuelen: 1
[Thr 772] IcmWorkerThread: worker 0 got the semaphore
[Thr 01] NiBufIAlloc: malloc ICM_EXT, to 104 bytes
[Thr 772] REQUEST:
Type: ADMMSG Index = 11843
[Thr 01]
[Thr 01] NiBufSend starting
[Thr 772] NiBufFree: ref 1 for buf 1875ce9f0
[Thr 01] NiIWrite: hdl 105 sent data (wrt=104,pac=1,MESG_IO)
[Thr 772] MPI<f836>15#5 GetInbuf -1 1e60a0 1160 (1) -> MPI_EOS: End Of Stream
[Thr 01] IcmMsgProcess: Receive data from partner: DP(1), wp_no: 0
[Thr 772] IcmHandleMonitorMessage: called with opcode: ICM_COM_OP_MON_INFO (100)
[Thr 01]
[Thr 01] NiBufReceive starting
[Thr 772] MPI<f835>16#4 GetOutbuf -1 1f60e0 65536 (0) -> 7000000901f6100 73400320 MPI_OK
[Thr 01] NiBufISelUpdate: new MODE r- (--) for hdl 33 in set0
[Thr 772] MPI<f836>15#6 FreeInbuf#2 0 1e60a0 0 -> MPI_OK
[Thr 01] SiSelPSet: set events of sock 17 to: rp-
[Thr 772] MPI<f835>16#5 FlushOutbuf -1 1 1 1f60e0 4325 6 -> 7000000901f60e0 MPI_OK
[Thr 01] NiBufISelUpdate: new STAT --- (r--) for hdl 33 in set0
[Thr 772] IcmWorkerThread: Thread 0: Waiting for event
[Thr 01] NiSelIListRemove: remove hdl 33 [4] from buf-list (1) of set0
[Thr 01] IcmRecMsg: received 8416 bytes
[Thr 01] ============================================
[Thr 01] | COM_DATA:
[Thr 01] | Offset: 0 | Version: 7210
[Thr 01] | MsgNo: 98056 | Opcode: ICM_COM_OP_SET_PARAM (11)
[Thr 01] ============================================
[Thr 01] IcmHandleAdmMsg: op: 11, auth: 1
[Thr 01] IcmHandleAdmMsg: set param -> icm/OP_SET_ABAP_RELEASE
[Thr 01] NiBufIAlloc: malloc ICM_EXT, to 104 bytes
[Thr 01]
[Thr 01] NiBufSend starting
[Thr 01] NiIWrite: hdl 33 sent data (wrt=104,pac=1,MESG_IO)
[Thr 01] MAIN TRACE END
[Thr 01] SiSelPSelect: start select (timeout=-1)
[Thr 515] Fri Nov 13 13:40:28 2015
[Thr 515] SiSelPSelect: of 1 sockets 0 selected
[Thr 515] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 515] SiSelPSelect: start select (timeout=10000)
Florian,.
Thanks for the tip. I have activated all the traces I could think of
Error message in SOAMANAGAER says as follows :
CL_SOAP_TRANSPORT_EXTENSN_ROOT HANDLE_REQUEST SOAP Transport Binding A SOAP Runtime Core Exception occurred in method CREATE_FROM_HTTP_SERVER of class CL_SRT_WSP_RT_CONFIG at position id 2 with internal error id 1001 and error text SRT: Unexpected failure in SOAP processing occurred: ("Keine Web-Service-Konfiguration für diesen Zugriffspfad: """) (fault location is 1 ).
I further checked in SRTUTIL. It complains about the SICF Idoc inbound service not active. however it is active.
One minor thing I notice is that in SICF as shown above is that parameter is defined as IDoc instead of idoc .. could it be the cause ??
when I test the SICF service , its pointing to the right url http://XXXXXXXXX:XXXX/sap/bc/srt/idoc?sap-client=400
The issue was strangely due to incorrect binding on /sap/bc/srt/idoc . I have deactivated and reactivated SRTIDOC and issue is gone now. Thus HCI to ECC works.
Now the other way around ECc to HCI I have the following error ICM_HTTP_CONNECTION_FAILED .
I have downloaded the certificates from the worker node of HCI and installed all the certificates in STRUST however I have the following issue.
IcmJ2EEScheduleFunc: Connection to osiris.bocm.com:5222 failed - please check host configuration ==> starngely I have no clue what is osiris.bocm.com
--------------------------------------------------------------------------------
| ICM Trace File (dev_icm) |
--------------------------------------------------------------------------------
---------------------------------------------------
trc file: "dev_icm", trc level: 1, release: "721"
---------------------------------------------------
sysno 22
sid PH2
systemid 390 (AMD/Intel x86_64 with Linux)
relno 7210
patchlevel 0
patchno 333
intno 20020600
make multithreaded, ASCII, 64 bit, optimized
profile /usr/sap/PH2/SYS/profile/PH2_DVEBMGS22_osiris
pid 20796
[Thr 182894226624] Sun Nov 15 18:17:49 2015
[Thr 182894226624] TRACE FILE TRUNCATED
[Thr 1086359904] Sun Nov 15 18:18:11 2015
[Thr 1086359904] *** WARNING => Connection request from (18/20956/0) to host: iflmapgbt108h0400avttaio-h0400.intaas.hana.ondeman
[Thr 1086359904] RM-T18, U20956, 030 ABADA, srvdcnlcxxa03, 18:18:06, M0, W11, SM59, 4/2 {000200a2} [icxxconn_mt.c 2108]
[Thr 1082661216] Sun Nov 15 18:18:12 2015
[Thr 1082661216] *** ERROR during SecudeSSL_SessionStart() from SSL_connect()==SSL_ERROR_SSL
[Thr 1082661216] session uses PSE file "/usr/sap/PH2/DVEBMGS22/sec/SAPSSLC.pse"
[Thr 1082661216] SecudeSSL_SessionStart: SSL_connect() failed --
[Thr 1082661216] secude_error 536872221 (0x2000051d) = "Failed to verify peer certificate. Peer not trusted."
[Thr 1082661216] >> ---------- Begin of Secude-SSL Errorstack ---------- >>
[Thr 1082661216] 0x2000051d | SAPCRYPTOLIB | SSL_connect
[Thr 1082661216] SSL API error
[Thr 1082661216] Failed to verify peer certificate. Peer not trusted.
[Thr 1082661216] 0xa0600203 | SSL | ssl_verify_peer_certificates
[Thr 1082661216] Peer not trusted
[Thr 1082661216] 0xa0600297 | SSL | ssl_cert_checker_verify_certificates
[Thr 1082661216] peer certificate (chain) is not trusted
[Thr 1082661216] Certificate:
[Thr 1082661216] Certificate:
[Thr 1082661216] Subject :CN=osiris.bocm.com, OU=I0720001338, OU=SAP Web AS, O=SAP Trust Community, C=DE
[Thr 1082661216] Issuer :CN=osiris.bocm.com, OU=I0720001338, OU=SAP Web AS, O=SAP Trust Community, C=DE
[Thr 1082661216] Serial number:0x0a20151019132901
[Thr 1082661216] Validity:
[Thr 1082661216] Not before :Mon Oct 19 14:29:01 2015
[Thr 1082661216] Not after :Fri Jan 1 01:00:01 2038
[Thr 1082661216] Key:
[Thr 1082661216] Key type :rsaEncryption (1.2.840.113549.1.1.1)
[Thr 1082661216] Key size :2048
[Thr 1082661216] PK_Fingerprint_MD5:E48F 66D7 7FF2 57C5 FEEB 8649 9B08 0B2B
[Thr 1082661216] Signature algorithm:sha1WithRsaEncryption (1.2.840.113549.1.1.5)
[Thr 1082661216] Fingerprint_MD5:AD:CE:CF:1D:06:35:33:71:96:46:AF:32:80:14:80:57
[Thr 1082661216] Fingerprint_SHA1:24B6 BB48 B9A8 60F9 E70C 6757 C069 B096 CDF1 6A84
[Thr 1082661216] Verification result:
[Thr 1082661216] Status :Not successful
[Thr 1082661216] Profile :1.3.6.1.4.1.694.2.2.2.2
[Thr 1082661216] DirectlyTrusted:Not successful
[Thr 1082661216]
[Thr 1082661216] << ---------- End of Secude-SSL Errorstack ----------
[Thr 1082661216] SSL_get_state() returned 0x00002131 "SSLv3 read server certificate B"
[Thr 1082661216] SSL NI-sock: unix domain socket="/tmp/.sapicm5222"
[Thr 1082661216] <<- ERROR: SapSSLSessionStart(sssl_hdl=0xf78f50)==SSSLERR_PEER_CERT_UNTRUSTED
[Thr 1082661216] *** ERROR => IcmConnInitClientSSL: SapSSLSessionStart failed (-102): SSSLERR_PEER_CERT_UNTRUSTED {000200a5} [ic
[Thr 1082661216] *** ERROR => IcmJ2EEScheduleFunc: Connection to osiris.bocm.com:5222 failed - please check host configuration (
I have made some progress re-installing. However, I still get the following error:
--------------------------------------------------------------------------------
| ICM Trace File (dev_icm) |
--------------------------------------------------------------------------------
---------------------------------------------------
trc file: "dev_icm", trc level: 3, release: "721"
---------------------------------------------------
sysno 22
sid PH2
systemid 390 (AMD/Intel x86_64 with Linux)
relno 7210
patchlevel 0
patchno 333
intno 20020600
make multithreaded, ASCII, 64 bit, optimized
profile /usr/sap/PH2/SYS/profile/PH2_DVEBMGS22_osiris
pid 21206
[Thr 182894226624] Sun Nov 15 18:50:54 2015
[Thr 182894226624] TRACE FILE TRUNCATED
[Thr 182894226624] <<- SapSSLSetTraceFile()==SAP_O_K
[Thr 182894226624] NiBufIAlloc: malloc ICM_EXT, to 80 bytes
[Thr 182894226624]
[Thr 182894226624] NiBufSend starting
[Thr 182894226624] NiIWrite: hdl 41 sent data (wrt=80,pac=1,MESG_IO)
[Thr 182894226624] MAIN TRACE END
[Thr 182894226624] SiSelPSelect: start select (timeout=-1)
[Thr 1082132832] Sun Nov 15 18:50:58 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#133 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmConnPoolNiWatchCheck: Check Ni Watch List with 0 entries
[Thr 1104202080] IcmCheckForBlockedThreads: check for blocked SSL-threads
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#134 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#135 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#136: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#136 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 1082132832] Sun Nov 15 18:51:08 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#137 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#138 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#139 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#140: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#140 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 182894226624] Sun Nov 15 18:51:11 2015
[Thr 182894226624] SiSelPNext: sock 30 selected (pos=13; revt=r--)
[Thr 182894226624] NiBufISelProcess: hdl 84 process r-
[Thr 182894226624] NiBufIAlloc: malloc NIBUF-IN, to 1116 bytes
[Thr 182894226624] NiIRead: hdl 84 received data (rcd=1116,pac=1,MESG_IO)
[Thr 182894226624] NiBufIIn: NIBUF len=1116
[Thr 182894226624] NiBufIIn: packet complete for hdl 84
[Thr 182894226624] NiBufISelUpdate: new MODE -- (r-) for hdl 84 in set0
[Thr 182894226624] SiSelPSet: set events of sock 30 to: ---
[Thr 182894226624] NiBufISelUpdate: new STAT r-- (---) for hdl 84 in set0
[Thr 182894226624] NiSelIListInsert: add hdl 84 [13] to buf-list (0) of set0
[Thr 182894226624] NiSelISelectInt: 1 handles selected (1 buffered)
[Thr 182894226624] MAIN TRACE BEGIN
[Thr 182894226624] IcmMsgProcess: Receive data from partner: WP(2), wp_no: 5
[Thr 182894226624]
[Thr 182894226624] NiBufReceive starting
[Thr 182894226624] NiBufISelUpdate: new MODE r- (--) for hdl 84 in set0
[Thr 182894226624] SiSelPSet: set events of sock 30 to: rp-
[Thr 182894226624] NiBufISelUpdate: new STAT --- (r--) for hdl 84 in set0
[Thr 182894226624] NiSelIListRemove: remove hdl 84 [13] from buf-list (1) of set0
[Thr 182894226624] IcmRecMsg: received 1116 bytes
[Thr 182894226624] ============================================
[Thr 182894226624] | COM_DATA:
[Thr 182894226624] | Offset: 64 | Version: 7210
[Thr 182894226624] | MsgNo: 192 | Opcode: ICM_COM_OP_CONNECT (4)
[Thr 182894226624] ============================================
[Thr 182894226624] IcmHandleAdmMsg: op: 4, auth: 1
[Thr 182894226624] MPI<3263>1#5 PeekSelectInbuf -1 0 7504 (1) -> MPI_EOS: End Of Stream
[Thr 182894226624] IcmHandleAdmMsg: need new slot
[Thr 182894226624] NiBufIAlloc: malloc NiBufadm, to 0 bytes
[Thr 182894226624] NiBufDup: ref 1 for buf 0xf7b2b0
[Thr 182894226624] IcmCreateRequest: Append request 30
[Thr 182894226624] IcmQueueAppend: queuelen: 1
[Thr 182894226624] NiBufIAlloc: malloc ICM_EXT, to 80 bytes
[Thr 182894226624]
[Thr 182894226624] NiBufSend starting
[Thr 182894226624] NiIWrite: hdl 84 sent data (wrt=80,pac=1,MESG_IO)
[Thr 182894226624] NiBufFree: ref 1 for buf 0xf7b2b0
[Thr 182894226624] MAIN TRACE END
[Thr 182894226624] SiSelPSelect: start select (timeout=-1)
[Thr 1084246368] IcmWorkerThread: worker 3 got the semaphore
[Thr 1084246368] REQUEST:
Type: CONNECT_TO_SERV Index = 30
[Thr 1084246368] IcmConnConnect: allocate new conn slot
[Thr 1084246368] IcmConnCheckStoredClientConn: check for client conn timeout
[Thr 1084246368] IcmConnCheckStoredClientConn: next client timeout check in 10 sec
[Thr 1084246368] REQ TRACE BEGIN: 1/19/1
[Thr 1084246368] MPI<3263>1#6 PeekSelectInbuf -1 0 7504 (1) -> MPI_EOS: End Of Stream
[Thr 1084246368] IcmConnAssignContext: searching for context:
[Thr 1084246368] tid: 21, uid: 22500, mode: 0
[Thr 1084246368] IcmConnConnect: context 1 assigned to tid: 21, uid: 22500, mode: 0
[Thr 1084246368] keep_alive_timeout: 10, proc_timeout: 0, wp_timeout: 500
[Thr 1084246368] NiIGetServNo: servicename '5222' = port 5222
[Thr 1084246368] IcmGetServicePtr: osiris.bocm.com:5222 - new serv_ref_count: 1
[Thr 1084246368] IcmIConnConnect: direct connect to iflmapgbt108h0400avttaio-h0400.intaas.hana.ondemand.com:443
[Thr 1084246368] NiHLGetNodeAddr: found hostname 'iflmapgbt108h0400avttaio-h0400.intaas.hana.ondemand.com' in cache
[Thr 1084246368] NiIGetNodeAddr: hostname 'iflmapgbt108h0400avttaio-h0400.intaas.hana.ondemand.com' = addr 155.56.210.45
[Thr 1084246368] NiIGetServNo: servicename '443' = port 443
[Thr 1084246368] NiICreateHandle: hdl 113 state NI_INITIAL_CON
[Thr 1084246368] NiILocalCheck: SiBind failed (sirc=7;99-Cannot assign requested address 155.56.210.45)
[Thr 1084246368] NiIInitSocket: set default settings for new hdl 113/sock 33 (I4; ST)
[Thr 1084246368] NiIBlockMode: set blockmode for hdl 113 FALSE
[Thr 1084246368] NiIConnectSocket: hdl 113 is connecting to 155.56.210.45:443 (timeout=5000)
[Thr 1084246368] Sun Nov 15 18:51:16 2015
[Thr 1084246368] SiPeekPendConn: SiPoll timed out for sock 33 (5000ms)
[Thr 1084246368] NiICheckPendConnection: connection of hdl 113 to 155.56.210.45:443 still in progress (5000)
[Thr 1084246368] NiIConnect: hdl 113 took local address 193.115.158.192:19898
[Thr 1084246368] NiIConnect: state of hdl 113 NI_CONN_WAIT
[Thr 1084246368] NiHLGetHostName: found address 155.56.210.45 in cache
[Thr 1084246368] NiIGetHostName: addr 155.56.210.45 = hostname 'iflmapgbt108h0400avttaio-h0400.intaas.hana.ondemand.com'
[Thr 1084246368] *** ERROR => NiBufIConnect: non-buffered connect pending after 5000ms (hdl 113;iflmapgbt108h0400avttaio-h0400.i
[Thr 1084246368] NiICloseHandle: called for hdl 113 while waiting for connection
[Thr 1084246368] NiICloseHandle: shutdown and close hdl 113/sock 33
[Thr 1084246368] *** WARNING => Connection request from (21/22500/0) to host: iflmapgbt108h0400avttaio-h0400.intaas.hana.ondeman
[Thr 1084246368] AP-T21, U22500, 030 ABADA, srvdcnlcxxa03, 18:51:11, M0, W5, , 1/0 {00010013} [icxxconn_mt.c 2108]
[Thr 1084246368] IcmConnConnect(id=1/19): free MPI request blocks
[Thr 1084246368] MPI<3263>1#7 GetInbuf -1 1c6038 7504 (1) -> MPI_EOS: End Of Stream
[Thr 1084246368] MPI<3263>1#8 FreeInbuf#1 0 1c6038 0 -> MPI_OK
[Thr 1084246368] MPI<3262>2#4 GetOutbuf -1 1c6038 65536 (0) -> 0x2aa5933058 20971520 MPI_OK
[Thr 1084246368] NiIGetServNo: servicename '8022' = port 8022
[Thr 1084246368] Address Offset Error response:
[Thr 1084246368] ------------------------------------------------------------------------
[Thr 1084246368] 0x2aa59330a0 000000 48545450 2f312e30 20343034 20436f6e |HTTP/1.0 404 Con|
[Thr 1084246368] 0x2aa59330b0 000016 6e656374 696f6e20 4661696c 65640d0a |nection Failed..|
[Thr 1084246368] 0x2aa59330c0 000032 44617465 3a205375 6e2c2031 35204e6f |Date: Sun, 15 No|
[Thr 1084246368] 0x2aa59330d0 000048 76203230 31352031 383a3531 3a313620 |v 2015 18:51:16 |
[Thr 1084246368] 0x2aa59330e0 000064 474d540d 0a536572 7665723a 20534150 |GMT..Server: SAP|
[Thr 1084246368] 0x2aa59330f0 000080 204e6574 57656176 65722041 70706c69 | NetWeaver Appli|
[Thr 1084246368] 0x2aa5933100 000096 63617469 6f6e2053 65727665 7220372e |cation Server 7.|
[Thr 1084246368] 0x2aa5933110 000112 3231202f 2049434d 20372e32 310d0a43 |21 / ICM 7.21..C|
[Thr 1084246368] 0x2aa5933120 000128 6f6e6e65 6374696f 6e3a2063 6c6f7365 |onnection: close|
[Thr 1084246368] 0x2aa5933130 000144 0d0a5341 502d4943 4d434c4e 54455252 |..SAP-ICMCLNTERR|
[Thr 1084246368] 0x2aa5933140 000160 4f523a20 3430300d 0a436f6e 74656e74 |OR: 400..Content|
[Thr 1084246368] 0x2aa5933150 000176 2d4c656e 6774683a 20323035 38202020 |-Length: 2058 |
[Thr 1084246368] 0x2aa5933160 000192 0d0a436f 6e74656e 742d5479 70653a20 |..Content-Type: |
[Thr 1084246368] 0x2aa5933170 000208 74657874 2f68746d 6c0d0a0d 0a3c6874 |text/html....<ht|
[Thr 1084246368] 0x2aa5933180 000224 6d6c3e3c 68656164 3e3c7469 746c653e |ml><head><title>|
[Thr 1084246368] 0x2aa5933190 000240 4170706c 69636174 696f6e20 53657276 |Application Serv|
[Thr 1084246368] 0x2aa59331a0 000256 65722045 72726f72 3c2f7469 746c653e |er Error</title>|
[Thr 1084246368] 0x2aa59331b0 000272 0d0a3c73 74796c65 20747970 653d2274 |..<style type="t|
[Thr 1084246368] 0x2aa59331c0 000288 6578742f 63737322 3e0d0a62 6f647920 |ext/css">..body |
[Thr 1084246368] 0x2aa59331d0 000304 7b20666f 6e742d66 616d696c 793a2061 |{ font-family: a|
[Thr 1084246368] 0x2aa59331e0 000320 7269616c 2c207361 6e732d73 65726966 |rial, sans-serif|
[Thr 1084246368] 0x2aa59331f0 000336 3b7d0d0a 3c2f7374 796c653e 0d0a3c2f |;}..</style>..</|
[Thr 1084246368] 0x2aa5933200 000352 68656164 3e0d0a3c 424f4459 20746578 |head>..<BODY tex|
[Thr 1084246368] 0x2aa5933210 000368 743d2223 31373239 37322220 6c696e6b |t="#172972" link|
[Thr 1084246368] 0x2aa5933220 000384 3d222338 30383038 30222076 6c696e6b |="#808080" vlink|
[Thr 1084246368] 0x2aa5933230 000400 3d222338 30383038 30220d0a 616c696e |="#808080"..alin|
[Thr 1084246368] 0x2aa5933240 000416 6b3d2223 38653233 36622220 6267636f |k="#8e236b" bgco|
[Thr 1084246368] 0x2aa5933250 000432 6c6f723d 77686974 6520206c 6566746d |lor=white leftm|
[Thr 1084246368] 0x2aa5933260 000448 61726769 6e3d2230 2220746f 706d6172 |argin="0" topmar|
[Thr 1084246368] 0x2aa5933270 000464 67696e3d 2230220d 0a6d6172 67696e68 |gin="0"..marginh|
[Thr 1084246368] 0x2aa5933280 000480 65696768 743d2230 22206d61 7267696e |eight="0" margin|
[Thr 1084246368] 0x2aa5933290 000496 77696474 683d2230 223e0d0a 3c746162 |width="0">..<tab|
[Thr 1084246368] 0x2aa59332a0 000512 6c652068 65696768 743d2236 31222077 |le height="61" w|
[Thr 1084246368] 0x2aa59332b0 000528 69647468 3d223130 30252220 626f7264 |idth="100%" bord|
[Thr 1084246368] 0x2aa59332c0 000544 65723d22 30222063 656c6c73 70616369 |er="0" cellspaci|
[Thr 1084246368] 0x2aa59332d0 000560 6e673d22 30220d0a 63656c6c 70616464 |ng="0"..cellpadd|
[Thr 1084246368] 0x2aa59332e0 000576 696e673d 2230223e 3c74723e 3c746420 |ing="0"><tr><td |
[Thr 1084246368] 0x2aa59332f0 000592 6261636b 67726f75 6e643d22 68747470 |background="http|
[Thr 1084246368] 0x2aa5933300 000608 3a2f2f6f 73697269 732e626f 636d2e63 |://osiris.bocm.c|
[Thr 1084246368] 0x2aa5933310 000624 6f6d3a38 3032322f 7361702f 7075626c |om:8022/sap/publ|
[Thr 1084246368] 0x2aa5933320 000640 69632f69 636d616e 2f696d67 2f626c75 |ic/icman/img/blu|
[Thr 1084246368] 0x2aa5933330 000656 65626172 5f74696c 652e6769 66220d0a |ebar_tile.gif"..|
[Thr 1084246368] 0x2aa5933340 000672 68656967 68743d22 3330223e 3c746162 |height="30"><tab|
[Thr 1084246368] 0x2aa5933350 000688 6c653e20 3c74723e 203c7464 20776964 |le> <tr> <td wid|
[Thr 1084246368] 0x2aa5933360 000704 74683d35 3e3c2f74 643e203c 74642077 |th=5></td> <td w|
[Thr 1084246368] 0x2aa5933370 000720 69647468 3d323025 206e6f77 7261703e |idth=20% nowrap>|
[Thr 1084246368] 0x2aa5933380 000736 3c666f6e 74206661 63653d61 7269616c |<font face=arial|
[Thr 1084246368] 0x2aa5933390 000752 2073697a 653d222d 31222063 6f6c6f72 | size="-1" color|
[Thr 1084246368] 0x2aa59333a0 000768 3d776869 74653e53 4150204e 65745765 |=white>SAP NetWe|
[Thr 1084246368] 0x2aa59333b0 000784 61766572 20417070 6c696361 74696f6e |aver Application|
[Thr 1084246368] 0x2aa59333c0 000800 20536572 7665720d 0a3c2f66 6f6e743e | Server..</font>|
[Thr 1084246368] 0x2aa59333d0 000816 3c2f7464 3e3c7464 20776964 74683d37 |</td><td width=7|
[Thr 1084246368] 0x2aa59333e0 000832 35252061 6c69676e 3d227269 67687422 |5% align="right"|
[Thr 1084246368] 0x2aa59333f0 000848 206e6f77 7261703e 3c666f6e 74206661 | nowrap><font fa|
[Thr 1084246368] 0x2aa5933400 000864 63653d61 7269616c 0d0a7369 7a653d22 |ce=arial..size="|
[Thr 1084246368] 0x2aa5933410 000880 2d312220 636f6c6f 723d2277 68697465 |-1" color="white|
[Thr 1084246368] 0x2aa5933420 000896 223e3c61 20687265 663d2268 7474703a |"><a href="http:|
[Thr 1084246368] 0x2aa5933430 000912 2f2f6865 6c702e73 61702e63 6f6d2f22 |//help.sap.com/"|
[Thr 1084246368] 0x2aa5933440 000928 3e48656c 700d0a3c 2f666f6e 743e3c2f |>Help..</font></|
[Thr 1084246368] 0x2aa5933450 000944 74643e3c 74642077 69647468 3d352520 |td><td width=5% |
[Thr 1084246368] 0x2aa5933460 000960 6e6f7772 61703e3c 2f666f6e 743e3c2f |nowrap></font></|
[Thr 1084246368] 0x2aa5933470 000976 74643e20 3c2f7472 3e3c2f74 61626c65 |td> </tr></table|
[Thr 1084246368] 0x2aa5933480 000992 3e0d0a3c 2f74643e 3c746420 726f7773 |>..</td><td rows|
[Thr 1084246368] 0x2aa5933490 001008 70616e3d 32207769 6474683d 31323220 |pan=2 width=122 |
[Thr 1084246368] 0x2aa59334a0 001024 68656967 68743d36 31207661 6c69676e |height=61 valign|
[Thr 1084246368] 0x2aa59334b0 001040 3d746f70 3e3c696d 67207372 633d0d0a |=top><img src=..|
[Thr 1084246368] 0x2aa59334c0 001056 22687474 703a2f2f 6f736972 69732e62 |"http://osiris.b|
[Thr 1084246368] 0x2aa59334d0 001072 6f636d2e 636f6d3a 38303232 2f736170 |ocm.com:8022/sap|
[Thr 1084246368] 0x2aa59334e0 001088 2f707562 6c69632f 69636d61 6e2f696d |/public/icman/im|
[Thr 1084246368] 0x2aa59334f0 001104 672f7468 656d652e 6a706722 20776964 |g/theme.jpg" wid|
[Thr 1084246368] 0x2aa5933500 001120 74683d31 32322068 65696768 743d3631 |th=122 height=61|
[Thr 1084246368] 0x2aa5933510 001136 20626f72 6465723d 3020616c 743d2253 | border=0 alt="S|
[Thr 1084246368] 0x2aa5933520 001152 4150223e 3c2f7464 3e0d0a3c 2f74723e |AP"></td>..</tr>|
[Thr 1084246368] 0x2aa5933530 001168 3c74723e 3c746420 6261636b 67726f75 |<tr><td backgrou|
[Thr 1084246368] 0x2aa5933540 001184 6e643d22 68747470 3a2f2f6f 73697269 |nd="http://osiri|
[Thr 1084246368] 0x2aa5933550 001200 732e626f 636d2e63 6f6d3a38 3032322f |s.bocm.com:8022/|
[Thr 1084246368] 0x2aa5933560 001216 7361702f 7075626c 69632f69 636d616e |sap/public/icman|
[Thr 1084246368] 0x2aa5933570 001232 2f696d67 2f677261 79626172 5f74696c |/img/graybar_til|
[Thr 1084246368] 0x2aa5933580 001248 652e6a70 67222068 65696768 743d2233 |e.jpg" height="3|
[Thr 1084246368] 0x2aa5933590 001264 31223e0d 0a266e62 73703b3c 2f74643e |1">.. </td>|
[Thr 1084246368] 0x2aa59335a0 001280 3c2f7472 3e0d0a3c 2f746162 6c653e0d |</tr>..</table>.|
[Thr 1084246368] 0x2aa59335b0 001296 0a3c6272 3e3c6272 3e0d0a3c 7461626c |.<br><br>..<tabl|
[Thr 1084246368] 0x2aa59335c0 001312 65207769 6474683d 3830303e 0d0a3c74 |e width=800>..<t|
[Thr 1084246368] 0x2aa59335d0 001328 723e3c74 64207769 6474683d 3530206e |r><td width=50 n|
[Thr 1084246368] 0x2aa59335e0 001344 6f777261 703e0d0a 3c2f7464 3e3c7464 |owrap>..</td><td|
[Thr 1084246368] 0x2aa59335f0 001360 3e0d0a3c 48323e3c 623e3430 34205265 |>..<H2><b>404 Re|
[Thr 1084246368] 0x2aa5933600 001376 736f7572 6365206e 6f742066 6f756e64 |source not found|
[Thr 1084246368] 0x2aa5933610 001392 3c2f623e 3c2f4832 3e3c6272 3e506172 |</b></H2><br>Par|
[Thr 1084246368] 0x2aa5933620 001408 746e6572 206e6f74 20726561 63686564 |tner not reached|
[Thr 1084246368] 0x2aa5933630 001424 3c62723e 3c62723e 3c68723e 0d0a3c74 |<br><br><hr>..<t|
[Thr 1084246368] 0x2aa5933640 001440 61626c65 20626f72 6465723d 2230223e |able border="0">|
[Thr 1084246368] 0x2aa5933650 001456 0d0a3c74 723e3c74 643e4572 726f723a |..<tr><td>Error:|
[Thr 1084246368] 0x2aa5933660 001472 3c2f7464 3e3c7464 3e2d3230 3c2f7464 |</td><td>-20</td|
[Thr 1084246368] 0x2aa5933670 001488 3e3c2f74 723e0d0a 3c74723e 3c74643e |></tr>..<tr><td>|
[Thr 1084246368] 0x2aa5933680 001504 56657273 696f6e3a 3c2f7464 3e3c7464 |Version:</td><td|
[Thr 1084246368] 0x2aa5933690 001520 3e373231 303c2f74 643e3c2f 74723e0d |>7210</td></tr>.|
[Thr 1084246368] 0x2aa59336a0 001536 0a3c7472 3e3c7464 3e436f6d 706f6e65 |.<tr><td>Compone|
[Thr 1084246368] 0x2aa59336b0 001552 6e743a3c 2f74643e 3c74643e 49434d3c |nt:</td><td>ICM<|
[Thr 1084246368] 0x2aa59336c0 001568 2f74643e 3c2f7472 3e0d0a3c 74723e3c |/td></tr>..<tr><|
[Thr 1084246368] 0x2aa59336d0 001584 74643e44 6174652f 54696d65 3a3c2f74 |td>Date/Time:</t|
[Thr 1084246368] 0x2aa59336e0 001600 643e3c74 643e5375 6e204e6f 76203135 |d><td>Sun Nov 15|
[Thr 1084246368] 0x2aa59336f0 001616 2031383a 35313a31 36203230 31350a3c | 18:51:16 2015.<|
[Thr 1084246368] 0x2aa5933700 001632 2f74643e 3c2f7472 3e0d0a3c 74723e3c |/td></tr>..<tr><|
[Thr 1084246368] 0x2aa5933710 001648 74643e4d 6f64756c 653a3c2f 74643e3c |td>Module:</td><|
[Thr 1084246368] 0x2aa5933720 001664 74643e69 63787863 6f6e6e5f 6d742e63 |td>icxxconn_mt.c|
[Thr 1084246368] 0x2aa5933730 001680 3c2f7464 3e3c2f74 723e0d0a 3c74723e |</td></tr>..<tr>|
[Thr 1084246368] 0x2aa5933740 001696 3c74643e 4c696e65 3a3c2f74 643e3c74 |<td>Line:</td><t|
[Thr 1084246368] 0x2aa5933750 001712 643e3231 30383c2f 74643e3c 2f74723e |d>2108</td></tr>|
[Thr 1084246368] 0x2aa5933760 001728 0d0a3c74 723e3c74 643e5365 72766572 |..<tr><td>Server|
[Thr 1084246368] 0x2aa5933770 001744 3a3c2f74 643e3c74 643e6f73 69726973 |:</td><td>osiris|
[Thr 1084246368] 0x2aa5933780 001760 5f504832 5f32323c 2f74643e 3c2f7472 |_PH2_22</td></tr|
[Thr 1084246368] 0x2aa5933790 001776 3e0d0a3c 74723e3c 74643e45 72726f72 |>..<tr><td>Error|
[Thr 1084246368] 0x2aa59337a0 001792 20546167 3a3c2f74 643e3c74 643e7b30 | Tag:</td><td>{0|
[Thr 1084246368] 0x2aa59337b0 001808 30303130 3031337d 3c2f7464 3e3c2f74 |0010013}</td></t|
[Thr 1084246368] 0x2aa59337c0 001824 723e0d0a 3c74723e 3c74643e 44657461 |r>..<tr><td>Deta|
[Thr 1084246368] 0x2aa59337d0 001840 696c3a3c 2f74643e 3c74643e 436f6e6e |il:</td><td>Conn|
[Thr 1084246368] 0x2aa59337e0 001856 65637469 6f6e2072 65717565 73742066 |ection request f|
[Thr 1084246368] 0x2aa59337f0 001872 726f6d20 2832312f 32323530 302f3029 |rom (21/22500/0)|
[Thr 1084246368] 0x2aa5933800 001888 20746f20 686f7374 3a206966 6c6d6170 | to host: iflmap|
[Thr 1084246368] 0x2aa5933810 001904 67627431 30386830 34303061 76747461 |gbt108h0400avtta|
[Thr 1084246368] 0x2aa5933820 001920 696f2d68 30343030 2e696e74 6161732e |io-h0400.intaas.|
[Thr 1084246368] 0x2aa5933830 001936 68616e61 2e6f6e64 656d616e 642e636f |hana.ondemand.co|
[Thr 1084246368] 0x2aa5933840 001952 6d2c2073 65727669 63653a20 34343320 |m, service: 443 |
[Thr 1084246368] 0x2aa5933850 001968 6661696c 65642028 4e494543 4f4e4e5f |failed (NIECONN_|
[Thr 1084246368] 0x2aa5933860 001984 52454655 53454429 0a41502d 5432312c |REFUSED).AP-T21,|
[Thr 1084246368] 0x2aa5933870 002000 20553232 3530302c 20303330 20414241 | U22500, 030 ABA|
[Thr 1084246368] 0x2aa5933880 002016 44412c20 73727664 636e6c63 78786130 |DA, srvdcnlcxxa0|
[Thr 1084246368] 0x2aa5933890 002032 332c2031 383a3531 3a31312c 204d302c |3, 18:51:11, M0,|
[Thr 1084246368] 0x2aa59338a0 002048 2057352c 20202020 202c2031 2f303c2f | W5, , 1/0</|
[Thr 1084246368] 0x2aa59338b0 002064 74643e3c 2f74723e 0d0a3c2f 7461626c |td></tr>..</tabl|
[Thr 1084246368] 0x2aa59338c0 002080 653e0d0a 3c703e3c 2f703e0d 0a3c2f74 |e>..<p></p>..</t|
[Thr 1084246368] 0x2aa59338d0 002096 643e3c2f 74723e3c 2f746162 6c653e0d |d></tr></table>.|
[Thr 1084246368] 0x2aa59338e0 002112 0a3c7461 626c653e 3c74723e 3c746420 |.<table><tr><td |
[Thr 1084246368] 0x2aa59338f0 002128 77696474 683d3530 206e6f77 7261703e |width=50 nowrap>|
[Thr 1084246368] 0x2aa5933900 002144 3c2f7464 3e0d0a3c 7464206e 6f777261 |</td>..<td nowra|
[Thr 1084246368] 0x2aa5933910 002160 703e3c46 4f4e5420 53495a45 3d2d313e |p><FONT SIZE=-1>|
[Thr 1084246368] 0x2aa5933920 002176 3c612068 7265663d 22687474 703a2f2f |<a href="http://|
[Thr 1084246368] 0x2aa5933930 002192 7777772e 7361702e 636f6d2f 223e2663 |www.sap.com/">&c|
[Thr 1084246368] 0x2aa5933940 002208 6f70793b 20323030 312d3230 30392c20 |opy; 2001-2009, |
[Thr 1084246368] 0x2aa5933950 002224 53415020 41473c2f 613e3c2f 464f4e54 |SAP AG</a></FONT|
[Thr 1084246368] 0x2aa5933960 002240 3e0d0a3c 2f74643e 3c2f7472 3e3c2f74 |>..</td></tr></t|
[Thr 1084246368] 0x2aa5933970 002256 61626c65 3e0d0a3c 2f626f64 793e3c2f |able>..</body></|
[Thr 1084246368] 0x2aa5933980 002272 68746d6c 3e0d0a |html>.. |
[Thr 1084246368] ------------------------------------------------------------------------
[Thr 1084246368] MPI<3262>2#5 FlushOutbuf -1 1 1 1c6038 2351 6 -> 0x2aa5933038 MPI_OK
[Thr 1084246368] IcmConnFreeContext: context 1 released
[Thr 1084246368] IcmServDecrRefCount: osiris.bocm.com:5222 - new serv_ref_count: 0
[Thr 1084246368] IcmWorkerThread: Thread 3: Waiting for event
[Thr 1082132832] Sun Nov 15 18:51:18 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#141 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmWatchDogThread: call schedules, last t: 1447613448, next t: 1447613478, cur t: 1447613478
[Thr 1104202080] IcmCreateRequest: Append request 31
[Thr 1104202080] IcmQueueAppend: queuelen: 1
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#142 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#143 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#144: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#144 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 1083717984] IcmWorkerThread: worker 2 got the semaphore
[Thr 1083717984] REQUEST:
Type: SCHEDULER Index = 31
[Thr 1083717984] IcmGetSchedule: found slot 0
[Thr 1083717984] IcmAlReportData: Reporting data to CCMS Alerting Infrastructure
[Thr 1083717984] NiIGetServNo: servicename '8022' = port 8022
[Thr 1083717984] IcmConnCheckStoredClientConn: next client timeout check in 3 sec
[Thr 1083717984] NiIGetServNo: servicename '8022' = port 8022
[Thr 1083717984] IcmGetServicePtr: osiris.bocm.com:8022 - new serv_ref_count: 1
[Thr 1083717984] PlugInHandleAdmMessage: request received:
[Thr 1083717984] PlugInHandleAdmMessage: opcode: ICM_COM_OP_CACHE_STAT (136), len: 272, dest_type: 2, subhdlkey: 262145
[Thr 1083717984] HttpISubHandlerItCreate: add reference to table 0xefc9c0, now 2 references, 1 tables used
[Thr 1083717984] HttpSubHandlerCall: Call Handler: HttpCacheHandler (0xf0d2a0/0xefc9c0), task=TASK_ADM_MSG(4), header_len=0
[Thr 1083717984] HttpCacheHandler: 4 0 0xf0d2a0 (nil)
[Thr 1083717984] SCACHE: adm request received:
[Thr 1083717984] SCACHE: opcode: 136, len: 272, dest_type: 2, dest:
[Thr 1083717984] MTX_LOCK 3184 0xf0f0d0
[Thr 1083717984] MTX_UNLOCK 3197 0xf0f0d0
[Thr 1083717984] IctCmGetCacheInfo#12 -> 0
[Thr 1083717984] IcmNetBufWrapBuf: allocated netbuf: 0xe70530, blocks used: 1
[Thr 1083717984] IcmNetBufWrapBuf: allocated netbuf: 0xe70530
[Thr 1083717984] HttpSubHandlerItDelete: remove reference to table 0xefc9c0, now 1 references, 1 tables used
[Thr 1083717984] IcmNetBufFree: free netbuf: 0xe70530 out of 1 used
[Thr 1083717984] IcmConnFreeContext: context 1 released
[Thr 1083717984] IcmServDecrRefCount: osiris.bocm.com:8022 - new serv_ref_count: 0
[Thr 1083717984] IcmGetSchedule: next schedule in 30 secs
[Thr 1083717984] IcmWorkerThread: Thread 2: Waiting for event
[Thr 182894226624] Sun Nov 15 18:51:21 2015
[Thr 182894226624] SiSelPNext: sock 31 selected (pos=11; revt=r--)
[Thr 182894226624] NiBufISelProcess: hdl 97 process r-
[Thr 182894226624] NiBufIAlloc: malloc NIBUF-IN, to 72 bytes
[Thr 182894226624] NiIRead: hdl 97 received data (rcd=72,pac=1,MESG_IO)
[Thr 182894226624] NiBufIIn: NIBUF len=72
[Thr 182894226624] NiBufIIn: packet complete for hdl 97
[Thr 182894226624] NiBufISelUpdate: new MODE -- (r-) for hdl 97 in set0
[Thr 182894226624] SiSelPSet: set events of sock 31 to: ---
[Thr 182894226624] NiBufISelUpdate: new STAT r-- (---) for hdl 97 in set0
[Thr 182894226624] NiSelIListInsert: add hdl 97 [11] to buf-list (0) of set0
[Thr 182894226624] NiSelISelectInt: 1 handles selected (1 buffered)
[Thr 182894226624] MAIN TRACE BEGIN
[Thr 182894226624] IcmMsgProcess: Receive data from partner: WP(2), wp_no: 4
[Thr 182894226624]
[Thr 182894226624] NiBufReceive starting
[Thr 182894226624] NiBufISelUpdate: new MODE r- (--) for hdl 97 in set0
[Thr 182894226624] SiSelPSet: set events of sock 31 to: rp-
[Thr 182894226624] NiBufISelUpdate: new STAT --- (r--) for hdl 97 in set0
[Thr 182894226624] NiSelIListRemove: remove hdl 97 [11] from buf-list (1) of set0
[Thr 182894226624] IcmRecMsg: received 72 bytes
[Thr 182894226624] ============================================
[Thr 182894226624] | COM_DATA:
[Thr 182894226624] | Offset: 0 | Version: 7210
[Thr 182894226624] | MsgNo: 76 | Opcode: ICM_COM_OP_ICM_MONITOR (66)
[Thr 182894226624] ============================================
[Thr 182894226624] IcmHandleAdmMsg: op: 66, auth: 1
[Thr 182894226624] NiBufIAlloc: malloc NiBufadm, to 0 bytes
[Thr 182894226624] NiBufDup: ref 1 for buf 0xf7b2b0
[Thr 182894226624] IcmCreateRequest: Append request 32
[Thr 182894226624] IcmQueueAppend: queuelen: 1
[Thr 182894226624] NiBufIAlloc: malloc ICM_EXT, to 80 bytes
[Thr 182894226624]
[Thr 182894226624] NiBufSend starting
[Thr 182894226624] NiIWrite: hdl 97 sent data (wrt=80,pac=1,MESG_IO)
[Thr 182894226624] NiBufFree: ref 1 for buf 0xf7b2b0
[Thr 182894226624] MAIN TRACE END
[Thr 182894226624] SiSelPSelect: start select (timeout=-1)
[Thr 1083189600] IcmWorkerThread: worker 1 got the semaphore
[Thr 1083189600] REQUEST:
Type: ADMMSG Index = 32
[Thr 1083189600] MPI<3265>1#5 GetInbuf -1 1c6038 1152 (1) -> MPI_EOS: End Of Stream
[Thr 1083189600] IcmHandleMonitorMessage: called with opcode: ICM_COM_OP_MON_INFO (100)
[Thr 1083189600] MPI<3264>2#4 GetOutbuf -1 1b6000 65536 (0) -> 0x2aa5923020 20971520 MPI_OK
[Thr 1083189600] MPI<3265>1#6 FreeInbuf#2 0 1c6038 0 -> MPI_OK
[Thr 1083189600] MPI<3264>2#5 FlushOutbuf -1 1 1 1b6000 4317 6 -> 0x2aa5923000 MPI_OK
[Thr 1083189600] IcmWorkerThread: Thread 1: Waiting for event
[Thr 1082132832] Sun Nov 15 18:51:28 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#145 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#146 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#147 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#148: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#148 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 1082132832] Sun Nov 15 18:51:38 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#149 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#150 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#151 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#152: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#152 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 1082132832] Sun Nov 15 18:51:48 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#153 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmWatchDogThread: call schedules, last t: 1447613478, next t: 1447613508, cur t: 1447613508
[Thr 1104202080] IcmCreateRequest: Append request 33
[Thr 1104202080] IcmQueueAppend: queuelen: 1
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#154 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#155 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#156: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#156 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 1082661216] IcmWorkerThread: worker 0 got the semaphore
[Thr 1082661216] REQUEST:
Type: SCHEDULER Index = 33
[Thr 1082661216] IcmGetSchedule: found slot 0
[Thr 1082661216] IcmAlReportData: Reporting data to CCMS Alerting Infrastructure
[Thr 1082661216] NiIGetServNo: servicename '8022' = port 8022
[Thr 1082661216] IcmConnCheckStoredClientConn: check for client conn timeout
[Thr 1082661216] IcmConnCheckStoredClientConn: next client timeout check in 10 sec
[Thr 1082661216] NiIGetServNo: servicename '8022' = port 8022
[Thr 1082661216] IcmGetServicePtr: osiris.bocm.com:8022 - new serv_ref_count: 1
[Thr 1082661216] PlugInHandleAdmMessage: request received:
[Thr 1082661216] PlugInHandleAdmMessage: opcode: ICM_COM_OP_CACHE_STAT (136), len: 272, dest_type: 2, subhdlkey: 262145
[Thr 1082661216] HttpISubHandlerItCreate: add reference to table 0xefc9c0, now 2 references, 1 tables used
[Thr 1082661216] HttpSubHandlerCall: Call Handler: HttpCacheHandler (0xf0d2a0/0xefc9c0), task=TASK_ADM_MSG(4), header_len=0
[Thr 1082661216] HttpCacheHandler: 4 0 0xf0d2a0 (nil)
[Thr 1082661216] SCACHE: adm request received:
[Thr 1082661216] SCACHE: opcode: 136, len: 272, dest_type: 2, dest:
[Thr 1082661216] MTX_LOCK 3184 0xf0f0d0
[Thr 1082661216] MTX_UNLOCK 3197 0xf0f0d0
[Thr 1082661216] IctCmGetCacheInfo#13 -> 0
[Thr 1082661216] IcmNetBufWrapBuf: allocated netbuf: 0xe70530, blocks used: 1
[Thr 1082661216] IcmNetBufWrapBuf: allocated netbuf: 0xe70530
[Thr 1082661216] HttpSubHandlerItDelete: remove reference to table 0xefc9c0, now 1 references, 1 tables used
[Thr 1082661216] IcmNetBufFree: free netbuf: 0xe70530 out of 1 used
[Thr 1082661216] IcmConnFreeContext: context 1 released
[Thr 1082661216] IcmServDecrRefCount: osiris.bocm.com:8022 - new serv_ref_count: 0
[Thr 1082661216] IcmGetSchedule: next schedule in 30 secs
[Thr 1082661216] IcmWorkerThread: Thread 0: Waiting for event
[Thr 1082132832] Sun Nov 15 18:51:58 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#157 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#158 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#159 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#160: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#160 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 1082132832] Sun Nov 15 18:52:08 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#161 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#162 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#163 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#164: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#164 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 1082132832] Sun Nov 15 18:52:18 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#165 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmWatchDogThread: call schedules, last t: 1447613508, next t: 1447613538, cur t: 1447613538
[Thr 1104202080] IcmCreateRequest: Append request 34
[Thr 1104202080] IcmQueueAppend: queuelen: 1
[Thr 1104202080] IcmConnPoolNiWatchCheck: Check Ni Watch List with 0 entries
[Thr 1104202080] IcmCheckForBlockedThreads: check for blocked SSL-threads
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1085303136] IcmWorkerThread: worker 5 got the semaphore
[Thr 1085303136] REQUEST:
Type: SCHEDULER Index = 34
[Thr 1085303136] IcmGetSchedule: found slot 0
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#166 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1085303136] IcmAlReportData: Reporting data to CCMS Alerting Infrastructure
[Thr 1095809376] MPI<323b>0#167 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#168: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#168 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 1085303136] NiIGetServNo: servicename '8022' = port 8022
[Thr 1085303136] IcmConnCheckStoredClientConn: check for client conn timeout
[Thr 1085303136] IcmConnCheckStoredClientConn: next client timeout check in 10 sec
[Thr 1085303136] NiIGetServNo: servicename '8022' = port 8022
[Thr 1085303136] IcmGetServicePtr: osiris.bocm.com:8022 - new serv_ref_count: 1
[Thr 1085303136] PlugInHandleAdmMessage: request received:
[Thr 1085303136] PlugInHandleAdmMessage: opcode: ICM_COM_OP_CACHE_STAT (136), len: 272, dest_type: 2, subhdlkey: 262145
[Thr 1085303136] HttpISubHandlerItCreate: add reference to table 0xefc9c0, now 2 references, 1 tables used
[Thr 1085303136] HttpSubHandlerCall: Call Handler: HttpCacheHandler (0xf0d2a0/0xefc9c0), task=TASK_ADM_MSG(4), header_len=0
[Thr 1085303136] HttpCacheHandler: 4 0 0xf0d2a0 (nil)
[Thr 1085303136] SCACHE: adm request received:
[Thr 1085303136] SCACHE: opcode: 136, len: 272, dest_type: 2, dest:
[Thr 1085303136] MTX_LOCK 3184 0xf0f0d0
[Thr 1085303136] MTX_UNLOCK 3197 0xf0f0d0
[Thr 1085303136] IctCmGetCacheInfo#14 -> 0
[Thr 1085303136] IcmNetBufWrapBuf: allocated netbuf: 0xe70530, blocks used: 1
[Thr 1085303136] IcmNetBufWrapBuf: allocated netbuf: 0xe70530
[Thr 1085303136] HttpSubHandlerItDelete: remove reference to table 0xefc9c0, now 1 references, 1 tables used
[Thr 1085303136] IcmNetBufFree: free netbuf: 0xe70530 out of 1 used
[Thr 1085303136] IcmConnFreeContext: context 1 released
[Thr 1085303136] IcmServDecrRefCount: osiris.bocm.com:8022 - new serv_ref_count: 0
[Thr 1085303136] IcmGetSchedule: next schedule in 30 secs
[Thr 1085303136] IcmWorkerThread: Thread 5: Waiting for event
[Thr 1082132832] Sun Nov 15 18:52:28 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#169 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#170 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#171 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#172: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#172 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 1082132832] Sun Nov 15 18:52:38 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#173 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#174 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#175 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#176: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#176 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 1082132832] Sun Nov 15 18:52:48 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#177 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmWatchDogThread: call schedules, last t: 1447613538, next t: 1447613568, cur t: 1447613568
[Thr 1104202080] IcmCreateRequest: Append request 35
[Thr 1104202080] IcmQueueAppend: queuelen: 1
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#178 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#179 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#180: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#180 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 1084774752] IcmWorkerThread: worker 4 got the semaphore
[Thr 1084774752] REQUEST:
Type: SCHEDULER Index = 35
[Thr 1084774752] IcmGetSchedule: found slot 0
[Thr 1084774752] IcmAlReportData: Reporting data to CCMS Alerting Infrastructure
[Thr 1084774752] NiIGetServNo: servicename '8022' = port 8022
[Thr 1084774752] IcmConnCheckStoredClientConn: check for client conn timeout
[Thr 1084774752] IcmConnCheckStoredClientConn: next client timeout check in 10 sec
[Thr 1084774752] NiIGetServNo: servicename '8022' = port 8022
[Thr 1084774752] IcmGetServicePtr: osiris.bocm.com:8022 - new serv_ref_count: 1
[Thr 1084774752] PlugInHandleAdmMessage: request received:
[Thr 1084774752] PlugInHandleAdmMessage: opcode: ICM_COM_OP_CACHE_STAT (136), len: 272, dest_type: 2, subhdlkey: 262145
[Thr 1084774752] HttpISubHandlerItCreate: add reference to table 0xefc9c0, now 2 references, 1 tables used
[Thr 1084774752] HttpSubHandlerCall: Call Handler: HttpCacheHandler (0xf0d2a0/0xefc9c0), task=TASK_ADM_MSG(4), header_len=0
[Thr 1084774752] HttpCacheHandler: 4 0 0xf0d2a0 (nil)
[Thr 1084774752] SCACHE: adm request received:
[Thr 1084774752] SCACHE: opcode: 136, len: 272, dest_type: 2, dest:
[Thr 1084774752] MTX_LOCK 3184 0xf0f0d0
[Thr 1084774752] MTX_UNLOCK 3197 0xf0f0d0
[Thr 1084774752] IctCmGetCacheInfo#15 -> 0
[Thr 1084774752] IcmNetBufWrapBuf: allocated netbuf: 0xe70530, blocks used: 1
[Thr 1084774752] IcmNetBufWrapBuf: allocated netbuf: 0xe70530
[Thr 1084774752] HttpSubHandlerItDelete: remove reference to table 0xefc9c0, now 1 references, 1 tables used
[Thr 1084774752] IcmNetBufFree: free netbuf: 0xe70530 out of 1 used
[Thr 1084774752] IcmConnFreeContext: context 1 released
[Thr 1084774752] IcmServDecrRefCount: osiris.bocm.com:8022 - new serv_ref_count: 0
[Thr 1084774752] IcmGetSchedule: next schedule in 30 secs
[Thr 1084774752] IcmWorkerThread: Thread 4: Waiting for event
[Thr 1082132832] Sun Nov 15 18:52:58 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#181 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#182 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#183 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#184: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#184 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 1082132832] Sun Nov 15 18:53:08 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#185 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#186 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#187 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#188: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#188 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 1082132832] Sun Nov 15 18:53:18 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#189 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmWatchDogThread: call schedules, last t: 1447613568, next t: 1447613598, cur t: 1447613598
[Thr 1104202080] IcmCreateRequest: Append request 36
[Thr 1104202080] IcmQueueAppend: queuelen: 1
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1086359904] IcmWorkerThread: worker 7 got the semaphore
[Thr 1086359904] REQUEST:
Type: SCHEDULER Index = 36
[Thr 1086359904] IcmGetSchedule: found slot 0
[Thr 1086359904] IcmAlReportData: Reporting data to CCMS Alerting Infrastructure
[Thr 1095809376] MPI<323b>0#190 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#191 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#192: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#192 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 1086359904] NiIGetServNo: servicename '8022' = port 8022
[Thr 1086359904] IcmConnCheckStoredClientConn: check for client conn timeout
[Thr 1086359904] IcmConnCheckStoredClientConn: next client timeout check in 10 sec
[Thr 1086359904] NiIGetServNo: servicename '8022' = port 8022
[Thr 1086359904] IcmGetServicePtr: osiris.bocm.com:8022 - new serv_ref_count: 1
[Thr 1086359904] PlugInHandleAdmMessage: request received:
[Thr 1086359904] PlugInHandleAdmMessage: opcode: ICM_COM_OP_CACHE_STAT (136), len: 272, dest_type: 2, subhdlkey: 262145
[Thr 1086359904] HttpISubHandlerItCreate: add reference to table 0xefc9c0, now 2 references, 1 tables used
[Thr 1086359904] HttpSubHandlerCall: Call Handler: HttpCacheHandler (0xf0d2a0/0xefc9c0), task=TASK_ADM_MSG(4), header_len=0
[Thr 1086359904] HttpCacheHandler: 4 0 0xf0d2a0 (nil)
[Thr 1086359904] SCACHE: adm request received:
[Thr 1086359904] SCACHE: opcode: 136, len: 272, dest_type: 2, dest:
[Thr 1086359904] MTX_LOCK 3184 0xf0f0d0
[Thr 1086359904] MTX_UNLOCK 3197 0xf0f0d0
[Thr 1086359904] IctCmGetCacheInfo#16 -> 0
[Thr 1086359904] IcmNetBufWrapBuf: allocated netbuf: 0xe70530, blocks used: 1
[Thr 1086359904] IcmNetBufWrapBuf: allocated netbuf: 0xe70530
[Thr 1086359904] HttpSubHandlerItDelete: remove reference to table 0xefc9c0, now 1 references, 1 tables used
[Thr 1086359904] IcmNetBufFree: free netbuf: 0xe70530 out of 1 used
[Thr 1086359904] IcmConnFreeContext: context 1 released
[Thr 1086359904] IcmServDecrRefCount: osiris.bocm.com:8022 - new serv_ref_count: 0
[Thr 1086359904] IcmGetSchedule: next schedule in 30 secs
[Thr 1086359904] IcmWorkerThread: Thread 7: Waiting for event
[Thr 1082132832] Sun Nov 15 18:53:28 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#193 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#194 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#195 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#196: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#196 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 1082132832] Sun Nov 15 18:53:38 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#197 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmConnPoolNiWatchCheck: Check Ni Watch List with 0 entries
[Thr 1104202080] IcmCheckForBlockedThreads: check for blocked SSL-threads
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#198 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#199 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#200: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#200 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 1082132832] Sun Nov 15 18:53:48 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#201 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmWatchDogThread: call schedules, last t: 1447613598, next t: 1447613628, cur t: 1447613628
[Thr 1104202080] IcmCreateRequest: Append request 37
[Thr 1104202080] IcmQueueAppend: queuelen: 1
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#202 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#203 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#204: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#204 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 1085831520] IcmWorkerThread: worker 6 got the semaphore
[Thr 1085831520] REQUEST:
Type: SCHEDULER Index = 37
[Thr 1085831520] IcmGetSchedule: found slot 0
[Thr 1085831520] IcmAlReportData: Reporting data to CCMS Alerting Infrastructure
[Thr 1085831520] NiIGetServNo: servicename '8022' = port 8022
[Thr 1085831520] IcmConnCheckStoredClientConn: check for client conn timeout
[Thr 1085831520] IcmConnCheckStoredClientConn: next client timeout check in 10 sec
[Thr 1085831520] NiIGetServNo: servicename '8022' = port 8022
[Thr 1085831520] IcmGetServicePtr: osiris.bocm.com:8022 - new serv_ref_count: 1
[Thr 1085831520] PlugInHandleAdmMessage: request received:
[Thr 1085831520] PlugInHandleAdmMessage: opcode: ICM_COM_OP_CACHE_STAT (136), len: 272, dest_type: 2, subhdlkey: 262145
[Thr 1085831520] HttpISubHandlerItCreate: add reference to table 0xefc9c0, now 2 references, 1 tables used
[Thr 1085831520] HttpSubHandlerCall: Call Handler: HttpCacheHandler (0xf0d2a0/0xefc9c0), task=TASK_ADM_MSG(4), header_len=0
[Thr 1085831520] HttpCacheHandler: 4 0 0xf0d2a0 (nil)
[Thr 1085831520] SCACHE: adm request received:
[Thr 1085831520] SCACHE: opcode: 136, len: 272, dest_type: 2, dest:
[Thr 1085831520] MTX_LOCK 3184 0xf0f0d0
[Thr 1085831520] MTX_UNLOCK 3197 0xf0f0d0
[Thr 1085831520] IctCmGetCacheInfo#17 -> 0
[Thr 1085831520] IcmNetBufWrapBuf: allocated netbuf: 0xe70530, blocks used: 1
[Thr 1085831520] IcmNetBufWrapBuf: allocated netbuf: 0xe70530
[Thr 1085831520] HttpSubHandlerItDelete: remove reference to table 0xefc9c0, now 1 references, 1 tables used
[Thr 1085831520] IcmNetBufFree: free netbuf: 0xe70530 out of 1 used
[Thr 1085831520] IcmConnFreeContext: context 1 released
[Thr 1085831520] IcmServDecrRefCount: osiris.bocm.com:8022 - new serv_ref_count: 0
[Thr 1085831520] IcmGetSchedule: next schedule in 30 secs
[Thr 1085831520] IcmWorkerThread: Thread 6: Waiting for event
[Thr 1082132832] Sun Nov 15 18:53:58 2015
[Thr 1082132832] SiSelPSelect: of 1 sockets 0 selected
[Thr 1082132832] IcmProxyWatchDog: check sockets (timeout=10000)
[Thr 1082132832] SiSelPSelect: start select (timeout=10000)
[Thr 1104202080] NiSelISelectInt: 0 handles selected (0 buffered)
[Thr 1104202080] WATCHDOG TRACE BEGIN
[Thr 1104202080] IcmWatchDogThread: Wakeup Workers waiting for MPI
[Thr 1104202080] IcmMpiWatchWakeUp: watchdog wakeup performed, wakeup sent cnt 0, new watch entry cnt 0
[Thr 1104202080] IcmWatchDogThread: Wakeup MPI Watchdog
[Thr 1104202080] MPI<323b>0#205 WriteOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7
[Thr 1104202080] IcmWatchDogThread: check ni handles (timeout=10000)
[Thr 1104202080] WATCHDOG TRACE END
[Thr 1104202080] SiSelPSelect: start select (timeout=10000)
[Thr 1095809376] MPI<323b>0#206 PeekInbuf 0 0 0 (0) -> MPI_EOUTOFBAND: out-of-band message
[Thr 1095809376] MpiSelSelect( e -1 ) -> MPI_OK
[Thr 1095809376] MPI WATCHDOG TRACE BEGIN
[Thr 1095809376] IcmMpiWatchDogThread: Wakeup OOB received
[Thr 1095809376] MPI<323b>0#207 ReadOOB A0BED041 02000000 CA404400 00000000 0A000000 00000000 70FFE7 -> MPI_OK
[Thr 1095809376] IcmMpiWatchDogThread: call MpiSelSelect
[Thr 1095809376] MPI WATCHDOG TRACE END
[Thr 1095809376] MPI<323b>0#208: GetInbuf: check avail. buffers 0 0
[Thr 1095809376] MPI<323b>0#208 PeekInbuf 0 0 0 (0) -> MPI_EAGAIN: resource busy
[Thr 1095809376] MpiSelect: 0 waiting for events
[Thr 182894226624] Sun Nov 15 18:54:00 2015
[Thr 182894226624] SiSelPNext: sock 28 selected (pos=10; revt=r--)
[Thr 182894226624] NiBufISelProcess: hdl 73 process r-
[Thr 182894226624] NiBufIAlloc: malloc NIBUF-IN, to 72 bytes
[Thr 182894226624] NiIRead: hdl 73 received data (rcd=72,pac=1,MESG_IO)
[Thr 182894226624] NiBufIIn: NIBUF len=72
[Thr 182894226624] NiBufIIn: packet complete for hdl 73
[Thr 182894226624] NiBufISelUpdate: new MODE -- (r-) for hdl 73 in set0
[Thr 182894226624] SiSelPSet: set events of sock 28 to: ---
[Thr 182894226624] NiBufISelUpdate: new STAT r-- (---) for hdl 73 in set0
[Thr 182894226624] NiSelIListInsert: add hdl 73 [10] to buf-list (0) of set0
[Thr 182894226624] NiSelISelectInt: 1 handles selected (1 buffered)
[Thr 182894226624] MAIN TRACE BEGIN
[Thr 182894226624] IcmMsgProcess: Receive data from partner: WP(2), wp_no: 11
[Thr 182894226624]
[Thr 182894226624] NiBufReceive starting
[Thr 182894226624] NiBufISelUpdate: new MODE r- (--) for hdl 73 in set0
[Thr 182894226624] SiSelPSet: set events of sock 28 to: rp-
[Thr 182894226624] NiBufISelUpdate: new STAT --- (r--) for hdl 73 in set0
[Thr 182894226624] NiSelIListRemove: remove hdl 73 [10] from buf-list (1) of set0
[Thr 182894226624] IcmRecMsg: received 72 bytes
[Thr 182894226624] ============================================
[Thr 182894226624] | COM_DATA:
[Thr 182894226624] | Offset: 0 | Version: 7210
[Thr 182894226624] | MsgNo: 176 | Opcode: ICM_COM_OP_ICM_MONITOR (66)
[Thr 182894226624] ============================================
[Thr 182894226624] IcmHandleAdmMsg: op: 66, auth: 1
[Thr 182894226624] NiBufIAlloc: malloc NiBufadm, to 0 bytes
[Thr 182894226624] NiBufDup: ref 1 for buf 0xf7b2b0
[Thr 182894226624] IcmCreateRequest: Append request 38
[Thr 182894226624] IcmQueueAppend: queuelen: 1
[Thr 182894226624] NiBufIAlloc: malloc ICM_EXT, to 80 bytes
[Thr 182894226624]
[Thr 182894226624] NiBufSend starting
[Thr 182894226624] NiIWrite: hdl 73 sent data (wrt=80,pac=1,MESG_IO)
[Thr 182894226624] NiBufFree: ref 1 for buf 0xf7b2b0
[Thr 182894226624] MAIN TRACE END
[Thr 182894226624] SiSelPSelect: start select (timeout=-1)
[Thr 1087416672] IcmWorkerThread: worker 9 got the semaphore
[Thr 1087416672] REQUEST:
Type: ADMMSG Index = 38
[Thr 1087416672] MPI<3267>1#5 GetInbuf -1 1b6000 1152 (1) -> MPI_EOS: End Of Stream
[Thr 1087416672] IcmHandleMonitorMessage: called with opcode: ICM_COM_OP_MON_INFO (100)
[Thr 1087416672] MPI<3266>2#4 GetOutbuf -1 1c6038 65536 (0) -> 0x2aa5933058 20971520 MPI_OK
[Thr 1087416672] MPI<3267>1#6 FreeInbuf#2 0 1b6000 0 -> MPI_OK
[Thr 1087416672] MPI<3266>2#5 FlushOutbuf -1 1 1 1c6038 4317 6 -> 0x2aa5933038 MPI_OK
[Thr 1087416672] IcmWorkerThread: Thread 9: Waiting for event
User | Count |
---|---|
8 | |
1 | |
1 | |
1 | |
1 | |
1 | |
1 |
You must be a registered user to add a comment. If you've already registered, sign in. Otherwise, register and sign in.