PH26035: CLIENT REQUESTS FOR LIGHTWEIGHT WEB SERVICE TRACE FOR SOAP MESSAGES IN LIBERTY

APAR status

• Closed as new function.

Error description

• We hit two issues trying to Trace the SOAP Inbound and
  Outbound
  message in WebSphere Liberty 20.x:
  
  1. We initially used the
  web service trace string
  "org.apache.cxf.*=all:com.ibm.ws.jaxws.*=all" which is
  documented in
  https://www.ibm.com/support/pages/set-trace-and-ge
  t-full-dump-websphere-liberty, we found it generates too
  much
  trace,
  and even caused the function break in BAW, some of the
  threads just hangs, such as:
  [2020-05-29T05:47:56.457+0000]
  00000136
  com.ibm.tx.jta.embeddable.impl.EmbeddableTimeoutManager I
  WTRN0124I: When the timeout occurred the thread with which
  the
  transaction is, or was most recently, associated was
  Thread[BPM-EM-Thread-39653,5,Default Executor Thread Group].
  The stack trace of this thread when the timeout occurred
  was:
  
  java.io.FileOutputStream.writeBytes(Native Method)
  
  java.io.FileOutputStream.write(FileOutputStream.java:342)
  com.i
  bm.ws.logging.internal.impl.CountingOutputStream.write(Count
  ingO
  utputStream.java:47)
  
  java.io.PrintStream.write(PrintStream.java:504)
  sun.nio.cs.Stre
  amEncoder.writeBytes(StreamEncoder.java:233)
  [2020-05-29T04:36:4
  2.421+0000] 000000b4 id=00000000
  com.ibm.tx.jta.embeddable.impl.EmbeddableTimeoutManager I
  WTRN0124I: When the timeout occurred the thread with which
  the
  transaction is, or was most recently, associated was
  Thread[Default Executor-thread-28496,5,Default Executor
  Thread
  Group]. The stack trace of this thread when the timeout
  occurred was:
  com.ibm.ws.logging.internal.impl.BaseTraceService.
  writeStreamOutput(BaseTraceService.java:1807)
  com.ibm.ws.logging
  .internal.impl.ConsoleLogHandler.synchronousWrite(ConsoleLog
  Hand
  ler.java:166)
  com.ibm.ws.collector.manager.buffer.BufferManagerI
  mpl.add(BufferManagerImpl.java:108)
  com.ibm.ws.logging.source.Tr
  aceSource.publish(TraceSource.java:92)
  com.ibm.ws.logging.intern
  al.impl.BaseTraceService.publishTraceLogRecord(BaseTraceServ
  ice.
  java:1178)
  com.ibm.ws.logging.internal.impl.BaseTraceService.pub
  lishLogRecord(BaseTraceService.java:1128)
  com.ibm.ws.logging.int
  ernal.impl.BaseTraceService$2.publish(BaseTraceService.java:
  283)
  
  java.util.logging.Logger.log(Logger.java:749)
  [2020-05-29T04:37
  :24.203+0000] 00000187 id=00000000
  com.ibm.tx.jta.embeddable.impl.EmbeddableTimeoutManager I
  WTRN0124I: When the timeout occurred the thread with which
  the
  transaction is, or was most recently, associated was
  Thread[Default Executor-thread-28504,5,Default Executor
  Thread
  Group]. The stack trace of this thread when the timeout
  occurred was:
  com.ibm.ws.logging.collector.CollectorJsonHelpers.
  addToJSON(CollectorJsonHelpers.java:111)
  com.ibm.ws.logging.coll
  ector.CollectorJsonHelpers.addUnchangingFieldsJSON_Trace(Col
  lect
  orJsonHelpers.java:266)
  com.ibm.ws.logging.collector.CollectorJs
  onHelpers.startTraceJsonFields(CollectorJsonHelpers.java:609
  )
  co
  m.ibm.ws.logging.collector.CollectorJsonUtils_JSON.jsonifyTr
  aceA
  ndMessage(CollectorJsonUtils_JSON.java:282)
  com.ibm.ws.logging.c
  ollector.CollectorJsonUtils_JSON.jsonifyEvent(CollectorJsonU
  tils
  _JSON.java:71)
  com.ibm.ws.logging.collector.CollectorJsonUtils.j
  sonifyEvent(CollectorJsonUtils.java:59)
  com.ibm.ws.logging.inter
  nal.impl.JsonLogHandler.formatEvent(JsonLogHandler.java:162)
  com
  .ibm.ws.logging.internal.impl.ConsoleLogHandler.synchronousW
  rite
  (ConsoleLogHandler.java:106)
  com.ibm.ws.collector.manager.buffer
  .BufferManagerImpl.add(BufferManagerImpl.java:108)
  com.ibm.ws.lo
  gging.source.TraceSource.publish(TraceSource.java:92)
  com.ibm.ws
  .logging.internal.impl.BaseTraceService.publishTraceLogRecor
  d(Ba
  seTraceService.java:1178)
  com.ibm.ws.logging.internal.impl.BaseT
  raceService.publishLogRecord(BaseTraceService.java:1128)
  com.ibm
  .ws.logging.internal.impl.BaseTraceService$2.publish(BaseTra
  ceSe
  rvice.java:283)
  java.util.logging.Logger.log(Logger.java:749)
  
  2
  . We like to use a Light-Weight Trace string in Liberty to
  print out SOAP message for both Inbound and Outbound Web
  Service calls. We can get this done in tWAS by trace string
  "com
  .ibm.ws.webservices.trace.*=all:com.ibm.ws.websvcs.trace.*=a
  ll"
  .
  Liberty seems to use
  org.apache.cxf.interceptor.LoggingInInterceptor and
  org.apache.cxf.interceptor.LoggingOutInterceptor=all to
  print
  out the trace, since we can enable following trace string to
  get SOAP message:
  org.apache.cxf.interceptor.LoggingInIntercepto
  r=all:org.apache.cxf.interceptor.LoggingOutInterceptor=all:c
  om.i
  bm.ws.jaxws.wsat.WSATFeatureBusListener=all
  WSATFeatureBusListen
  er adds the Logging Interceptor into Bus during Server
  Startup,
  looks like if we add above trace string, have to restart
  server.
  Here is our questions:
  
  - What trace string we should
  use in liberty if we just want the soap message without
  server
  restart?
  
  - What trace string we should use to print out the
  soap message w/o WS-AT?
  
  Client can not use TCPMON either when
  connected to client or customer systems.
  

Local fix

• N/A
  

Problem summary

• ****************************************************************
  * USERS AFFECTED:  IBM WebSphere Application Server Liberty    *
  *                  users of JAX-WS Web Services                *
  ****************************************************************
  * PROBLEM DESCRIPTION: Dynamic tracing of Outbound and Inbound *
  *                      SOAP messages does not work in Liberty  *
  ****************************************************************
  * RECOMMENDATION:                                              *
  ****************************************************************
  After server was started, if tracing was enabled for
  LoggingInInterceptor and LoggingOutInterceptor classes, the
  outbound and inbound SOAP messages were not logged in trace.log
  because these Logging interceptors were only initialized during
  server startup if trace was enabled before server startup.
  

Problem conclusion

• The problem was fixed by adding two new logging interceptor
  classes: LibertyLoggingInInterceptor and
  LibertyLoggingOutInterceptor which are initialized at server
  startup, even if trace is not enabled, so these interceptors
  will be active when trace is enabled after server is started.
  
  The fix for this APAR is currently targeted for inclusion in
  Liberty 20.0.0.7.  Please refer to the Recommended Updates page
  for delivery information:
  http://www.ibm.com/support/docview.wss?rs=180&uid=swg27004980
  

Temporary fix

• Restart server after enabling tracing for logging interceptors.
  

Comments

APAR Information

• APAR is sysrouted FROM one or more of the following:

• APAR is sysrouted TO one or more of the following:

Fix information

• Fixed component name

  LIBERTY PROFILE

• Fixed component ID

  5724J0814

Applicable component levels