Layer7 API Management

  • 1.  I/O error while   processing message: Stream timeout

    Posted Feb 08, 2017 09:33 PM

    I have weird error for one client. Gateway reports that message is processed successfully, however after 60 seconds, in the log gateway reports Stream timeout, and that is the message that is passed to the client.

    Web service has 2 methods with similar payload. Method A(16:41 20) is processed without issue, method B with issue bellow:

    Capture

    2017-02-08T15:41:26.601-0600 INFO    683 com.l7tech.server.message: Processing request for service: NotificationServicePS [/NOVA/NotificationServicePS]
    2017-02-08T15:41:26.601-0600 INFO    683 com.l7tech.server.policy.assertion.ServerSslAssertion: 4114: Found client certificate for CN=ssgcarootqamts,OU=Middleware,O=Rogers,C=CA
    2017-02-08T15:41:26.601-0600 WARNING 683 com.l7tech.server.policy.assertion.ServerMessageBufferingAssertion: 7225: Request message has already been buffered
    2017-02-08T15:41:26.601-0600 WARNING 683 com.l7tech.server.message: Message processed successfully

     


    2017-02-08T15:42:26.815-0600 WARNING 1433 com.l7tech.server.SoapMessageProcessingServlet: I/O error while processing message: Stream timeout

     

    I also debugged the policy, and when running in debug mode message is processed successfully.

    Client is running WebLogic 10.3.6.

     

    All test executed from SOAP UI using the same message are processed without issues.

     

    Error is 100% reproducible. Case is opened. Any help and direction where to look for the problem resolution is welcome.

     

    Thanks,


    Zoran



  • 2.  Re: I/O error while   processing message: Stream timeout

    Posted Feb 08, 2017 10:09 PM

    View from Client side:

     

    1. Method A processed successfully:

    15:52:48,295 INFO  com.rogers.nova.km.KMcontentService  - Creating channel graph....
    [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] 2017-02-06 15:52:48,295 INFO  com.rogers.nova.km.IQClient  - creating new IQServiceClient.
    [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] 2017-02-06 15:52:50,070 INFO  com.rogers.nova.km.KMcontentService  - Channel graph created
    [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] 2017-02-06 15:52:50,073 INFO  com.rogers.nova.util.IMConnectionPool  - Returning connection
    [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] 2017-02-06 15:52:50,093 INFO  com.rogers.nova.util.IMConnectionPool  - Returning connection
    [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] 2017-02-06 15:52:50,117 INFO  com.rogers.nova.util.IMConnectionPool  - Returning connection
    [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] 2017-02-06 15:52:50,261 INFO  com.rogers.nova.webService.ens.ENSService  - calling webService with SOAP Request
    [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] 2017-02-06 15:52:50,261 INFO  com.rogers.nova.webService.ens.ENSService  - <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><SOAP-ENV:Body><previewNotification xmlns="http://www.rogers.com/Notification/NotificationService/v1.0"><PreviewNotificationRequest xmlns="http://www.rogers.com/Notification/NotificationService"><RequestHeader><Franchise xmlns="http://www.rogers.com/schema/apps/ssp">ROGERS</Franchise><ApplicationID xmlns="http://www.rogers.com/schema/apps/ssp">NOVA</ApplicationID><UserID xmlns="http://www.rogers.com/schema/apps/ssp">jeff.smith</UserID><SessionID xmlns="http://www.rogers.com/schema/apps/ssp">293bad5d-2680-464e-ae0f-e316cb3180af</SessionID><TransactionID xmlns="http://www.rogers.com/schema/apps/ssp">293bad5d-2680-464e-ae0f-e316cb3180af</TransactionID><RequestLanguage xmlns="http://www.rogers.com/schema/apps/ssp">EN</RequestLanguage><Timestamp xmlns="http://www.rogers.com/schema/apps/ssp">2017-02-06T15:52:50.252-05:00</Timestamp><IPAddress xmlns="http://www.rogers.com/schema/apps/ssp">10.13.49.41</IPAddress><EnvInstance xmlns="http://www.rogers.com/schema/apps/ssp">QA</EnvInstance></RequestHeader><Notification><RequestID>000000</RequestID><TemplateID>KM_ARTICLE</TemplateID><TemplateData>&lt;?xml version="1.0" encoding="UTF-8" standalone="no"?&gt;

     

     

    2. Method B failed:

    [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] 2017-02-06 15:52:58,263 INFO  com.rogers.nova.km.KMcontentService  - Creating channel graph....
    [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] 2017-02-06 15:52:58,263 INFO  com.rogers.nova.km.IQClient  - creating new IQServiceClient.
    [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] 2017-02-06 15:53:00,294 INFO  com.rogers.nova.km.KMcontentService  - Channel graph created
    [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] 2017-02-06 15:53:00,296 INFO  com.rogers.nova.util.IMConnectionPool  - Returning connection
    [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] 2017-02-06 15:53:00,312 INFO  com.rogers.nova.util.IMConnectionPool  - Returning connection
    [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] 2017-02-06 15:53:00,333 INFO  com.rogers.nova.util.IMConnectionPool  - Returning connection
    [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] 2017-02-06 15:53:00,480 INFO  com.rogers.nova.webService.ens.ENSService  - calling webService with SOAP Request
    [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] 2017-02-06 15:53:00,480 INFO  com.rogers.nova.webService.ens.ENSService  - <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><SOAP-ENV:Body><sendNotification xmlns="http://www.rogers.com/Notification/NotificationService/v1.0"><SendNotificationRequest xmlns="http://www.rogers.com/Notification/NotificationService"><RequestHeader><Franchise xmlns="http://www.rogers.com/schema/apps/ssp">ROGERS</Franchise><ApplicationID xmlns="http://www.rogers.com/schema/apps/ssp">NOVA</ApplicationID><UserID xmlns="http://www.rogers.com/schema/apps/ssp">jeff.smith</UserID><SessionID xmlns="http://www.rogers.com/schema/apps/ssp">8f37aafb-f96f-41e0-bf33-2dbe43457573</SessionID><TransactionID xmlns="http://www.rogers.com/schema/apps/ssp">8f37aafb-f96f-41e0-bf33-2dbe43457573</TransactionID><RequestLanguage xmlns="http://www.rogers.com/schema/apps/ssp">EN</RequestLanguage><Timestamp xmlns="http://www.rogers.com/schema/apps/ssp">2017-02-06T15:53:00.469-05:00</Timestamp><IPAddress xmlns="http://www.rogers.com/schema/apps/ssp">10.13.49.41</IPAddress><EnvInstance xmlns="http://www.rogers.com/schema/apps/ssp">QA</EnvInstance></RequestHeader><Notification><RequestID>000000</RequestID><TemplateID>KM_ARTICLE</TemplateID><TemplateData>&lt;?xml version="1.0" encoding="UTF-8" standalone="no"?&gt;

     

    [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] 2017-02-06 15:54:00,920 ERROR com.rogers.nova.webService.ens.ENSService  - WebService response has fault
    [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] 2017-02-06 15:54:00,920 ERROR com.rogers.nova.webService.ens.ENSService  - <?xml version="1.0" encoding="UTF-8"?>
    <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/">
        <soapenv:Body>
            <soapenv:Fault>
                <faultcode>soapenv:Server</faultcode>
                <faultstring>Error in assertion processing</faultstring>
                <faultactor>https://ssgsft04p.rogers.com:8443/NOVA/NotificationServicePS</faultactor>
                <detail>
                    <l7:policyResult status="Stream timeout" xmlns:l7="http://www.layer7tech.com/ws/policy/fault"/>
                </detail>
            </soapenv:Fault>
        </soapenv:Body>
    </soapenv:Envelope>



  • 3.  Re: I/O error while   processing message: Stream timeout

    Posted Feb 09, 2017 08:42 AM

    60 secs reminded me the http connection time-out or transport layer issue, somehow your service client in weblogic is expected to send some http-header about connection behaviour. So please track the HTTP Header through SOAP-UI & Your Client must have some parameter different. Also control the max message-size setting in GW Global Variables. 



  • 4.  Re: I/O error while   processing message: Stream timeout

    Posted Feb 09, 2017 02:16 PM

    I added assertions to Limit Message Size, and Protection Against XML Document Structure Threats.

    HTTP Headers from SOAP UI are following:

    http.allheadervalues = {Object[]} size = 7
    [0] = {String} "accept-encoding:gzip,deflate"
    [1] = {String} "connection:Keep-Alive"
    [2] = {String} "content-length:6853"
    [3] = {String} "content-type:text/xml;charset=UTF-8"
    [4] = {String} "host:ssgsft04.rogers.com:8443"
    [5] = {String} "soapaction:"""
    [6] = {String} "user-agent:Apache-HttpClient/4.1.1 (java 1.5)"

     

    HTTP Headers from SOAP UI are following:

    http.allheadervalues = {Object[]} size = 7
    [0] = {String} "accept:text/xml, text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2"
    [1] = {String} "connection:Keep-Alive"
    [2] = {String} "content-length:6010"
    [3] = {String} "content-type:text/xml; charset=utf-8"
    [4] = {String} "host:ssgsft04p.rogers.com:8443"
    [5] = {String} "soapaction:"""
    [6] = {String} "user-agent:Java1.6.0_91"

     

    I'll follow up with client about header[0] difference. 

     

    Thanks,

     

    Zoran



  • 5.  Re: I/O error while   processing message: Stream timeout
    Best Answer

    Posted Feb 14, 2017 01:54 PM

    This issue is reproducible in only one API Gateway environment which is hosting multiple clients. Only one client has this issue, and most likely is due to setting on the client side. From API Gateway perspective issue is closed.