Topic
  • 8 replies
  • Latest Post - ‏2013-12-11T15:53:45Z by DGawron
EJW
EJW
18 Posts

Pinned topic Repetitious logging by Web Service Call Builder set to log "inputs and outputs only"

‏2013-12-02T16:06:22Z |

We are using WPF6.1.5 and make lots of Web Service Calls using the Web Service Call Builder (in service provider models). We find it useful to log all requests sent and responses received (and these appear in the serviceCalls.txt log file) however we find that this logging always duplicates the requests and responses 3 times (each with the same or very similiar data).

We would like to be able to control this so that only one log is made for each request and response as the log files fill up (and turn over) very rapidly and this makes it difficult to locate errors especially if they are not reported for many hours afterwards. Is this possible with any builder options? - the other Logging options "all", "none" or "envelops only" are not acceptable - see below for the current log4j.properties we have in use...

log4j.logger.bowstreet.system.webservice.serviceCall=${LOG_Functionality},ServiceCalls

log4j.logger.bowstreet.system.webservice.incomingSOAPRequest=ERROR,IncomingSOAPRequests

log4j.logger.bowstreet.builders.webapp.serviceConsumer=${LOG_Infra},ServiceConsumer

 

# -------------- The ServiceCalls appender sends its output to serviceCalls.txt --------------

log4j.appender.ServiceCalls=org.apache.log4j.RollingFileAppender

log4j.appender.ServiceCalls.File=${LOG_ROOT}/ContactCentre/serviceCalls.txt

log4j.appender.ServiceCalls.MaxFileSize=${LOG_MaxFileSize}

log4j.appender.ServiceCalls.MaxBackupIndex=${LOG_ServiceCalls_MaxBackupIndex}

#Don't truncate the logging file if it already exists.

log4j.appender.ServiceCalls.Append=true

log4j.appender.ServiceCalls.layout=org.apache.log4j.PatternLayout

log4j.appender.ServiceCalls.layout.ConversionPattern=*-- TIME: [%d] --* %nCategory: %c%nPriority: %p%nThread: %t%nMsg: %m%n%n%n

 

 

  • mburati
    mburati
    2568 Posts

    Re: Repetitious logging by Web Service Call Builder set to log "inputs and outputs only"

    ‏2013-12-02T18:57:00Z  

    Dave's the expert on the WS Call logging, but afaik, that's meant mainly for developer design-time debugging not for runtime logging, as it's fairly heavy weight in what it logs to aid in dev-time debugging.  

    Do you need the actual SOAP envelopes or just the inputs/outputs?   If the latter then maybe doing your own logging of just what you need would be better than trying to rely on the debug-time logging for your runtime logging needs.

    I hope that info helps,
    ..Mike Burati 
    The postings on this site are my own and do not necessarily represent the positions, strategies, or opinions of IBM.
  • DGawron
    DGawron
    580 Posts

    Re: Repetitious logging by Web Service Call Builder set to log "inputs and outputs only"

    ‏2013-12-02T19:07:59Z  

    The logging input in the Web Service Call and Web Service MultiOp builders is intended only for dev and debugging given the amount of runtime overhead it can incur writing data.  While some customers do use it in production, I caution against that unless the number of requests is low and the envelopes sizes are small.  The are no other builder inputs that can be used to customize this logging.

    Depending upon what data you want to log there may be a better alternative.  For example, you can get access to the request and response envelopes from the builder's LJO and write those out in some action in the provider.  And any robust provider should have error handlers to trap any SOAP faults.  You can log the faults as part of the error handling flow.

    If you were on WEF 8 or better I would recommend implementing a custom JAX-WS handler to perform web service logging.  Support for JAX-WS handlers was added in WEF 8 and I believe I posted a sample that does a bit of custom logging.

    It's unclear why you are seeing 3 copies.  Are you seeing 3 copies in the same file or 3 copies spreads across several files?  Usually when this happens it's caused by the Log4J configuration (including the configuration of parent appenders).

  • EJW
    EJW
    18 Posts

    Re: Repetitious logging by Web Service Call Builder set to log "inputs and outputs only"

    ‏2013-12-02T21:19:40Z  
    • DGawron
    • ‏2013-12-02T19:07:59Z

    The logging input in the Web Service Call and Web Service MultiOp builders is intended only for dev and debugging given the amount of runtime overhead it can incur writing data.  While some customers do use it in production, I caution against that unless the number of requests is low and the envelopes sizes are small.  The are no other builder inputs that can be used to customize this logging.

    Depending upon what data you want to log there may be a better alternative.  For example, you can get access to the request and response envelopes from the builder's LJO and write those out in some action in the provider.  And any robust provider should have error handlers to trap any SOAP faults.  You can log the faults as part of the error handling flow.

    If you were on WEF 8 or better I would recommend implementing a custom JAX-WS handler to perform web service logging.  Support for JAX-WS handlers was added in WEF 8 and I believe I posted a sample that does a bit of custom logging.

    It's unclear why you are seeing 3 copies.  Are you seeing 3 copies in the same file or 3 copies spreads across several files?  Usually when this happens it's caused by the Log4J configuration (including the configuration of parent appenders).

    Many thanks for yours and MB's speedy reply. This is the first I have heard that the built in WSC builder logging is really designed for developers  debugging rather than production support !

    I have pasted below some cut-down excerpts from a service call log file for a single call to a service - the "duplicate" logging is all in the same file and we don't believe there are issues with the log4j appenders. NB where you see a "..." we would typically see 10-50 lines of xml payload so as you can see these are unwieldy.

    I think we might, from time to time, need to log out the the SOAP envelopes but generally we would not need to - so I am considering changing the logging approach to use the "none" option in the Web Service Builder itself but instead rely on some custom logging. As we enjoy the ability to dynamically change our logging levels through WAS admin console if we could log the SOAP envelopes as say DEBUGs but the Requests and Responses as say INFOs I believe we could "dial-up" the logging when needed to expose these otherwise we would then appreciate seeing just the  1 request and 1 response in these logs. I think I can see how to do this inside the action lists that we typically use to call services using a service consumer builder via the DataServices invoke method (and to direct the logging for the model or services heper LJO into the existing serviceCall log file) however I am not clear how to do something similar from within the service provider models - which is where I think from what you are saying we will have to do the logging if we ever need to expose the SOAP envelopes. We have many such consumer and provider models currently in the project so obviously I am hoping a centralised or copy and paste solution will be available to implement the change!

     

    START OF LOGGING FOR 1 SERVICE CALL IN SAME SERVICECALLS.TXT FILE -

    Please note: All log entries have a Category of bowstreet.system.webservice.serviceCall and are all logged as INFO so all come in ServiceCalls log files....Ideally we would be able to control the categorization and we would then choose to downgrade most to DEBUGs so they wouldn't appear unless we chose to "dial up" the logging levels for a time....
     

     

    *-- TIME: [2013-12-02 15:23:52,980] --*
    Category: bowstreet.system.webservice.serviceCall
    Priority: INFO
    Thread:   WebContainer : 11
    Msg:      com.bowstreet.util.soap.SOAPRequest:
    == com.bowstreet.util.soap.SOAPRequest state dump ==
    target url=http://localhost:nnnn/xxx/yyy
    soapAction=urn:invoke2
    timeout(ms)=5000
    methodName=invoke
    methodNamespaceURI=http://www.xxx.com/xxxx/xxxxx/xxxxx
    schemaNamespaceURI=null
    SOAP Style=DOCUMENT
    SOAP EncodingStyle=literal
    replyName=response
    replyType=res
    complexReplyType=res
    complexReplyNamespace=http://www.xxx.com/xxxx/xxxxx/xxxxx
    args:
    argname:parameters
    argclass:class com.bowstreet.services.base.TaggedData
    ...
    ...
    SOAP headers:
    HTTP headers:
    HTTP Cookies:
    == end SOAPRequest state dump ==

     

    *-- TIME: [2013-12-02 15:23:52,980] --*
    Category: bowstreet.system.webservice.serviceCall
    Priority: INFO
    Thread:   WebContainer : 11
    Msg:      com.bowstreet.util.soap.SOAPRequest:Set expected reply name and type to: response {http://www.xxxx/xxxxx}res


    *-- TIME: [2013-12-02 15:23:52,980] --*
    Category: bowstreet.system.webservice.serviceCall
    Priority: INFO
    Thread:   WebContainer : 11
    Msg:      com.bowstreet.util.soap.SOAPRequest:Registered reply type mapping to IXml.class for: {http://www.xxxxx/xxxx}res


    *-- TIME: [2013-12-02 15:23:52,981] --*
    Category: bowstreet.system.webservice.serviceCall
    Priority: INFO
    Thread:   WebContainer : 11
    Msg:      com.bowstreet.util.soap.SOAPRequest:invoking SOAP request on target URL:http://localhost:nnnn/xxxx/xxxx


    *-- TIME: [2013-12-02 15:23:53,021] --*
    Category: bowstreet.system.webservice.serviceCall
    Priority: INFO
    Thread:   WebContainer : 11
    Msg:      com.bowstreet.util.soap.SOAPRequest:Request Envelope:<soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"><soapenv:Body>
    ...
    ....
    </soapenv:Body></soapenv:Envelope>


    *-- TIME: [2013-12-02 15:23:53,022] --*
    Category: bowstreet.system.webservice.serviceCall
    Priority: INFO
    Thread:   WebContainer : 11
    Msg:      com.bowstreet.util.soap.SOAPRequest:Response Envelope:<soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:dec="http://www.xxxx/xxxx">
    <soapenv:Body><res xmlns="http://www.xxxx/xxxx">
    ...
    ...
      </res></soapenv:Body></soapenv:Envelope>


    *-- TIME: [2013-12-02 15:23:53,023] --*
    Category: bowstreet.system.webservice.serviceCall
    Priority: INFO
    Thread:   WebContainer : 11
    Msg:      com.bowstreet.util.soap.SOAPRequest:Response (Vector):[<res xmlns="http://www.xxxx/xxxx">
    ...
    ...
      </res>]


    *-- TIME: [2013-12-02 15:23:53,024] --*
    Category: bowstreet.system.webservice.serviceCall
    Priority: INFO
    Thread:   WebContainer : 11
    Msg:      ServiceCall: SOAP.Response=<res xmlns="http://www.xxxx/xxxxx">
    ...
    ...
      </res>

    END OF LOGGING FOR 1 SERVICE CALL IN SAME SERVICECALLS.TXT FILE

     

  • DGawron
    DGawron
    580 Posts

    Re: Repetitious logging by Web Service Call Builder set to log "inputs and outputs only"

    ‏2013-12-02T22:43:31Z  
    • EJW
    • ‏2013-12-02T21:19:40Z

    Many thanks for yours and MB's speedy reply. This is the first I have heard that the built in WSC builder logging is really designed for developers  debugging rather than production support !

    I have pasted below some cut-down excerpts from a service call log file for a single call to a service - the "duplicate" logging is all in the same file and we don't believe there are issues with the log4j appenders. NB where you see a "..." we would typically see 10-50 lines of xml payload so as you can see these are unwieldy.

    I think we might, from time to time, need to log out the the SOAP envelopes but generally we would not need to - so I am considering changing the logging approach to use the "none" option in the Web Service Builder itself but instead rely on some custom logging. As we enjoy the ability to dynamically change our logging levels through WAS admin console if we could log the SOAP envelopes as say DEBUGs but the Requests and Responses as say INFOs I believe we could "dial-up" the logging when needed to expose these otherwise we would then appreciate seeing just the  1 request and 1 response in these logs. I think I can see how to do this inside the action lists that we typically use to call services using a service consumer builder via the DataServices invoke method (and to direct the logging for the model or services heper LJO into the existing serviceCall log file) however I am not clear how to do something similar from within the service provider models - which is where I think from what you are saying we will have to do the logging if we ever need to expose the SOAP envelopes. We have many such consumer and provider models currently in the project so obviously I am hoping a centralised or copy and paste solution will be available to implement the change!

     

    START OF LOGGING FOR 1 SERVICE CALL IN SAME SERVICECALLS.TXT FILE -

    Please note: All log entries have a Category of bowstreet.system.webservice.serviceCall and are all logged as INFO so all come in ServiceCalls log files....Ideally we would be able to control the categorization and we would then choose to downgrade most to DEBUGs so they wouldn't appear unless we chose to "dial up" the logging levels for a time....
     

     

    *-- TIME: [2013-12-02 15:23:52,980] --*
    Category: bowstreet.system.webservice.serviceCall
    Priority: INFO
    Thread:   WebContainer : 11
    Msg:      com.bowstreet.util.soap.SOAPRequest:
    == com.bowstreet.util.soap.SOAPRequest state dump ==
    target url=http://localhost:nnnn/xxx/yyy
    soapAction=urn:invoke2
    timeout(ms)=5000
    methodName=invoke
    methodNamespaceURI=http://www.xxx.com/xxxx/xxxxx/xxxxx
    schemaNamespaceURI=null
    SOAP Style=DOCUMENT
    SOAP EncodingStyle=literal
    replyName=response
    replyType=res
    complexReplyType=res
    complexReplyNamespace=http://www.xxx.com/xxxx/xxxxx/xxxxx
    args:
    argname:parameters
    argclass:class com.bowstreet.services.base.TaggedData
    ...
    ...
    SOAP headers:
    HTTP headers:
    HTTP Cookies:
    == end SOAPRequest state dump ==

     

    *-- TIME: [2013-12-02 15:23:52,980] --*
    Category: bowstreet.system.webservice.serviceCall
    Priority: INFO
    Thread:   WebContainer : 11
    Msg:      com.bowstreet.util.soap.SOAPRequest:Set expected reply name and type to: response {http://www.xxxx/xxxxx}res


    *-- TIME: [2013-12-02 15:23:52,980] --*
    Category: bowstreet.system.webservice.serviceCall
    Priority: INFO
    Thread:   WebContainer : 11
    Msg:      com.bowstreet.util.soap.SOAPRequest:Registered reply type mapping to IXml.class for: {http://www.xxxxx/xxxx}res


    *-- TIME: [2013-12-02 15:23:52,981] --*
    Category: bowstreet.system.webservice.serviceCall
    Priority: INFO
    Thread:   WebContainer : 11
    Msg:      com.bowstreet.util.soap.SOAPRequest:invoking SOAP request on target URL:http://localhost:nnnn/xxxx/xxxx


    *-- TIME: [2013-12-02 15:23:53,021] --*
    Category: bowstreet.system.webservice.serviceCall
    Priority: INFO
    Thread:   WebContainer : 11
    Msg:      com.bowstreet.util.soap.SOAPRequest:Request Envelope:<soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"><soapenv:Body>
    ...
    ....
    </soapenv:Body></soapenv:Envelope>


    *-- TIME: [2013-12-02 15:23:53,022] --*
    Category: bowstreet.system.webservice.serviceCall
    Priority: INFO
    Thread:   WebContainer : 11
    Msg:      com.bowstreet.util.soap.SOAPRequest:Response Envelope:<soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:dec="http://www.xxxx/xxxx">
    <soapenv:Body><res xmlns="http://www.xxxx/xxxx">
    ...
    ...
      </res></soapenv:Body></soapenv:Envelope>


    *-- TIME: [2013-12-02 15:23:53,023] --*
    Category: bowstreet.system.webservice.serviceCall
    Priority: INFO
    Thread:   WebContainer : 11
    Msg:      com.bowstreet.util.soap.SOAPRequest:Response (Vector):[<res xmlns="http://www.xxxx/xxxx">
    ...
    ...
      </res>]


    *-- TIME: [2013-12-02 15:23:53,024] --*
    Category: bowstreet.system.webservice.serviceCall
    Priority: INFO
    Thread:   WebContainer : 11
    Msg:      ServiceCall: SOAP.Response=<res xmlns="http://www.xxxx/xxxxx">
    ...
    ...
      </res>

    END OF LOGGING FOR 1 SERVICE CALL IN SAME SERVICECALLS.TXT FILE

     

    As a general rule logging inputs offered by a builder should be considered "for dev and debug use" only unless explicitly stated otherwise.  It's been a while since I looked at our best practices guidelines, but I do recall one of the items saying you should disable logging in various builders (Action Lists, SQL, Web Service, etc.) before putting models into production.  We are considering an update to the logging input in the Web Services builders to make the input's intended dev/debug use more obvious.

    The logging message sequence you provided looks normal to me and it appears to be the "all" option.  What I think you are seeing as duplicates are actually the XML data being logged several times in slightly different forms/contexts as it moves through WEF's web services plumbing on its way out to the network as a SOAP envelope and then back in as a response for consumption as plain old XML.

    Assuming that you've already tried the "envelopes only" option and found it insufficient, I don't know of an other easy way for you to update all of your providers.  It is possible to create a custom Log4J appender/filter that could be used to selectively drop logged messages that meet certain criteria, but this is often an unsatisfactory solution because it doesn't do anything to avoid the runtime impact of generating the logging messages.  Could this work for you?

    When you eventually move to WEF 8 or later you'll have the ability to implement custom logging for web service calls.

  • EJW
    EJW
    18 Posts

    Re: Repetitious logging by Web Service Call Builder set to log "inputs and outputs only"

    ‏2013-12-03T10:50:47Z  
    • DGawron
    • ‏2013-12-02T22:43:31Z

    As a general rule logging inputs offered by a builder should be considered "for dev and debug use" only unless explicitly stated otherwise.  It's been a while since I looked at our best practices guidelines, but I do recall one of the items saying you should disable logging in various builders (Action Lists, SQL, Web Service, etc.) before putting models into production.  We are considering an update to the logging input in the Web Services builders to make the input's intended dev/debug use more obvious.

    The logging message sequence you provided looks normal to me and it appears to be the "all" option.  What I think you are seeing as duplicates are actually the XML data being logged several times in slightly different forms/contexts as it moves through WEF's web services plumbing on its way out to the network as a SOAP envelope and then back in as a response for consumption as plain old XML.

    Assuming that you've already tried the "envelopes only" option and found it insufficient, I don't know of an other easy way for you to update all of your providers.  It is possible to create a custom Log4J appender/filter that could be used to selectively drop logged messages that meet certain criteria, but this is often an unsatisfactory solution because it doesn't do anything to avoid the runtime impact of generating the logging messages.  Could this work for you?

    When you eventually move to WEF 8 or later you'll have the ability to implement custom logging for web service calls.

    Thanks for the further update. I can confirm however that we are definately selecting the "inputs and outputs" logging option in the Web Service Call Builders - as we have found that when we do so the quantity of logging is slightly less than "all". I don't think we have any immediate plans to upgrade to WEF 8 so I am thinking we will have to:

    1. Change all the builders to use the "none " logging option,

    or

    2. Downgrade all bowstreet.system.webservice.serviceCall category logs to DEBUG so they could still be dynamically switched back on in production by dialling up the log level

    plus

    3. Add custom logging methods in an common service helper LJO which could be called from the action lists we use to invoke the DataService say logServiceRequest() and logServiceResponse() into which we would pass the DataService inputs and results respectively. The method would then log these as INFOs and we would direct all logging from this LJO at the Service Calls Log File. An advantage of this would be we could also write to the logs the service correlation GUID which we generate (and show onscreen in the event of an error) as this would then facilitate locating the error and also generally the marrying up of each request and response pair (as there are often many interwoven requests and responses for different calls in-flight in the logs).

    Does this seem a sensible approach?

     

  • DGawron
    DGawron
    580 Posts

    Re: Repetitious logging by Web Service Call Builder set to log "inputs and outputs only"

    ‏2013-12-05T13:58:49Z  
    • EJW
    • ‏2013-12-03T10:50:47Z

    Thanks for the further update. I can confirm however that we are definately selecting the "inputs and outputs" logging option in the Web Service Call Builders - as we have found that when we do so the quantity of logging is slightly less than "all". I don't think we have any immediate plans to upgrade to WEF 8 so I am thinking we will have to:

    1. Change all the builders to use the "none " logging option,

    or

    2. Downgrade all bowstreet.system.webservice.serviceCall category logs to DEBUG so they could still be dynamically switched back on in production by dialling up the log level

    plus

    3. Add custom logging methods in an common service helper LJO which could be called from the action lists we use to invoke the DataService say logServiceRequest() and logServiceResponse() into which we would pass the DataService inputs and results respectively. The method would then log these as INFOs and we would direct all logging from this LJO at the Service Calls Log File. An advantage of this would be we could also write to the logs the service correlation GUID which we generate (and show onscreen in the event of an error) as this would then facilitate locating the error and also generally the marrying up of each request and response pair (as there are often many interwoven requests and responses for different calls in-flight in the logs).

    Does this seem a sensible approach?

     

    That sounds reasonable.  In the provider model there will be an LJO for each web service operation and those LJOs have methods for getting the request and response envelopes.  You're logging actions can use these methods to easily record what is being sent and received.  If you are using WEF's JAX-WS infrastructure, then you'll need to set the override property bowstreet.soap.aggressivelyOptimizeMemory to false so that the envelopes are preserved for your logging.

  • EJW
    EJW
    18 Posts

    Re: Repetitious logging by Web Service Call Builder set to log "inputs and outputs only"

    ‏2013-12-11T12:14:19Z  
    • DGawron
    • ‏2013-12-05T13:58:49Z

    That sounds reasonable.  In the provider model there will be an LJO for each web service operation and those LJOs have methods for getting the request and response envelopes.  You're logging actions can use these methods to easily record what is being sent and received.  If you are using WEF's JAX-WS infrastructure, then you'll need to set the override property bowstreet.soap.aggressivelyOptimizeMemory to false so that the envelopes are preserved for your logging.

    Hi, re "In the provider model there will be an LJO for each web service operation and those LJOs have methods for getting the request and response envelopes" could you confirm the names of these classes and methods please - I havent seen these exposed in the pickers for use from within say an action list so am a bit unclear how I can make use of these in the custom logging approach I have in mind. Thanks!

  • DGawron
    DGawron
    580 Posts

    Re: Repetitious logging by Web Service Call Builder set to log "inputs and outputs only"

    ‏2013-12-11T15:53:45Z  
    • EJW
    • ‏2013-12-11T12:14:19Z

    Hi, re "In the provider model there will be an LJO for each web service operation and those LJOs have methods for getting the request and response envelopes" could you confirm the names of these classes and methods please - I havent seen these exposed in the pickers for use from within say an action list so am a bit unclear how I can make use of these in the custom logging approach I have in mind. Thanks!

    The class of the LJOs will be com.bowstreet.builders.webapp.methods.ServiceCallMethods.  The methods you want are getRequestEnvelope() and getResponseEnvelope().  Each returns a string representation of the envelope.  You may need to press the "Show More" button in a picker to see the LJOs.

    One last thought.  When you set bowstreet.soap.aggressivelyOptimizeMemory to false that tells the web service LJOs to keep optional data (the envelope strings for example) because the model will need them.  Make sure you use a stateless provider so that all this optional data doesn't sit around across requests taking up heap.