cancel
Showing results for 
Search instead for 
Did you mean: 

HCI/ECC connection issue with reverse proxy

florianbus
Contributor
0 Kudos

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_

] }

Accepted Solutions (1)

Accepted Solutions (1)

fabianl
Product and Topic Expert
Product and Topic Expert
0 Kudos

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

florianbus
Contributor
0 Kudos

Hi Fabian,

the reverse proxy certificate was signed by Thawte DV SSL CA. Which is signed by thawte Primary Root CA.

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?

Best Regards

Florian

fabianl
Product and Topic Expert
Product and Topic Expert
0 Kudos

Hi Florian,

in our case, this has solved our issue because the signed certificate from our ERP/Proxy was not imported.

Additional u can see that HCI cannot find the cert for the target.

"SunCertPathBuilderException:unable to find valid certification path to requested target"

br,

Fabian

Pragya_Pande
Contributor
0 Kudos

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

fabianl
Product and Topic Expert
Product and Topic Expert
0 Kudos

Hi Pragya,

i know, in our case we haven an COMODOHigh cert.

After the import of these cert into the system.jks by SAP all work´s fine.


br,

fabian

Pragya_Pande
Contributor
0 Kudos

Hello Florian,

Did you get the guide section?

Which direction communication is raising an issue HCI->ECC or ECC->HCI?

security guide -

https://websmp102.sap-ag.de/~form/sapnet?_SCENARIO=01100035870000000202&_SHORTKEY=012002523100001064...

Best Regards,

Pragya


Pragya_Pande
Contributor
0 Kudos

Hello Florian,

Please check this link :

SAP HANA Cloud Integration

This has the latest list as well.

Best Regards,

Pragya

florianbus
Contributor
0 Kudos

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

Pragya_Pande
Contributor
0 Kudos

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

fabianl
Product and Topic Expert
Product and Topic Expert
0 Kudos

Hi Florian,

pls have look at the picture from the C4C Training, u can see that "SAP imports the reverse proxy root certificate".

br,

fabian

Pragya_Pande
Contributor
0 Kudos

+adding to my reply-

the list in security guide is for C4C trusted issuers. The HANA documentation is for HCI trusted issuers.

So for your scenario - HANA one is what you need to check.

Best Regards,

Pragya

0 Kudos

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

AbinashNanda
Product and Topic Expert
Product and Topic Expert
0 Kudos

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

florianbus
Contributor
0 Kudos

Hi Abinash,

we requested the import of the following chain to the RP but without success. The key store was updated but still the same err.r

Best Regards

Florian

AbinashNanda
Product and Topic Expert
Product and Topic Expert
0 Kudos

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

florianbus
Contributor
0 Kudos

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

AbinashNanda
Product and Topic Expert
Product and Topic Expert
0 Kudos

Hello Florian,

Ok I check with the processor of the message. Do you have your email id mentioned in any of the ticket incase I need to reach out to you directly.

Best regards, Abinash

florianbus
Contributor
0 Kudos

Hi Abinash,

yes, they were just added by our customer.

Best Regards

Florian

florianbus
Contributor
0 Kudos

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>

AbinashNanda
Product and Topic Expert
Product and Topic Expert
0 Kudos

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


florianbus
Contributor
0 Kudos

Hello Abinash,

attached you will find the SMICM trace (3).

Best Regards

Florian

AbinashNanda
Product and Topic Expert
Product and Topic Expert
0 Kudos

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

AbinashNanda
Product and Topic Expert
Product and Topic Expert
0 Kudos

Hello Florian,

Additionally could you please check if you have set the following parameters in ICM

ICM set up to accept
client certificate over HTTP header

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

Configure SAP Web AS ABAP to accept client
certificates

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

florianbus
Contributor
0 Kudos

Hi Abinash,

on our customers ECC the parameter "icm/accept_forwarded_cert_via_http" is not existing at all. Can you provide some details on how toe get it set up or what is missing in order to get it?

Best Regards

Florian

AbinashNanda
Product and Topic Expert
Product and Topic Expert
0 Kudos

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

florianbus
Contributor
0 Kudos

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

former_member192561
Participant
0 Kudos

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_

] }

AbinashNanda
Product and Topic Expert
Product and Topic Expert
0 Kudos

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

fabianl
Product and Topic Expert
Product and Topic Expert
0 Kudos

Hi,

the server’s root certificate must be in the HCI Keystore (create a CSS Ticket, Component: HCI-LOD).

Additional the port 443 to HCI must be open for the communiication to the HCI.

br,

fabian

florianbus
Contributor
0 Kudos

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

former_member192561
Participant
0 Kudos

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)

florianbus
Contributor
0 Kudos

Dear Amber,

are you connecting HCI to ECC or are you a reverse proxy? The server HCI connects to for integration requires to be officially signed.

Best Regards

Florian

former_member192561
Participant
0 Kudos

Florain,

No reverse proxy. Just a "direct connection" from HCI to ECC. I think I have some thing in the trace as copied above. Could you see any thing in the trace , if a connection is made ??

florianbus
Contributor
0 Kudos

Hi Amber,

do you get any details if you do a trace with SRTUTIL with selection of the technical user used for integration into ECC. Do you get any trace there?

Best Regards

Florian

former_member192561
Participant
0 Kudos

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.

former_member192561
Participant
0 Kudos

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

florianbus
Contributor
0 Kudos

This is not a problem. The url using "idoc" is fine.

former_member192561
Participant
0 Kudos

I put an external break-point on class CREATE_FROM_HTTP_SERVER and discovered that there is no binding for /sap/bc/srt/idoc in table srt_reg_bind .  I have now deleted the binding using SRTIDOC and recreated it. I need to wait till the transport to test system happens to further test.

former_member192561
Participant
0 Kudos

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 (

former_member192561
Participant
0 Kudos

Our ECC server is osiris.bocm.com. Strangely in the above trace I see that it issues error on  its own CN

CN=osiris.bocm.com, OU=I0720001338, OU=SAP Web AS, O=SAP Trust Community, C=DE

This is for communication towards HCI from ECC

former_member192561
Participant
0 Kudos

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

Answers (0)