Troubleshooting Notes and Sametime

Often IBM support will request trace data to further investigate a problem. What is this data, how is it enabled, and how can it be used to pro-actively solve problems before contacting IBM? The Expeditor Wiki contains detailed information related to enabling and collecting trace. For information regarding trace (log) files available and their usage, see the article IBM Lotus Expeditor Logs-What are they good for. This post is intended to be a practical top-down overview for administrators investigating problems with deployed Notes and Sametime applications.

Tracing is debug information written to the platform’s log file. For performance reasons, tracing is not enabled by default; it is normally enabled after a problem has been encountered.  Trace messages are added during the development of an application in anticipation of problems encountered in the field. Such messages may include configuration settings, runtime values, or output of problems encountered during the operation of an application. Most Notes and Sametime applications use JSR47 logging. Because such tracing uses JSR47, you can follow a consistent approach to debugging most problems. A simple snippet on JSR47 tracing is below.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
private final String clazz = ViewPart.class.getName(); // this Class' name
private Logger logger = Logger.getLogger(clazz); // the logger for this Class
 
private void foo() {
logger.entering(clazz, "foo");
 
try {
SECRET.charAt(1); // java.lang.StringIndexOutOfBoundsException
 
logger.log(Level.FINE, "The secret is " + SECRET);
} catch (java.lang.StringIndexOutOfBoundsException e) {
logger.log(Level.SEVERE,
"foo()'s SECRET did not have a character at index 1", e);
}
 
logger.exiting(clazz, "foo");
}

Tracing has varying levels that control the amount of data written to the trace files. In order of information, they are: CONFIG, FINE, FINER and FINEST. In the above example, the message “The secret is” will be written to the trace file if we enable trace at the FINE level. For practical reasons, it’s generally accepted to simply start with the FINEST level to ensure no relevant messages are accidentally omitted.

IBM support may ask you to enable trace for a particular plugin. For example, the request may be stated as, “Please enable trace for com.ibm.rcp.accounts at the FINEST level”. Or support may refer to the specification “com.ibm.rcp.accounts FINEST”.

The preferred manner is using dynamic tracing. Support often prefers dynamic tracing because it can be enabled just prior to reproducing a problem. By enabling trace only when needed, the amount of unnecessary information is omitted. Enabling trace in this manner can be done with the below command.

setlogrlev com.ibm.rcp.accounts FINEST

To enable trace for multiple packages, simply issue the setlogrlev command with the package and level on multiple lines (use enter at the end of each command).

Tracing may be also enabled statically – meaning the trace level will persist after the client restarts. Because dynamic tracing ends when the client is restarted, static tracing is helpful when the client is expected to be restarted (such as provisioning or installation problems) or when the problem may not occur for some time. Update the rcpinstall.properties file with the following.

com.ibm.rcp.accounts.level=FINEST

For multiple packages, add the trace specifications on separate lines. A restart must occur after the rcpinstall.properties has been updated.

Application users and administrators can be pro-active in problem solving using the following steps.

  1. Identify a problem has occurred. This can be done either when an application dialog appears with an error message or the application simply fails to respond appropriately.
  2. Consult the trace file. Use the Viewing the trace file article to review the log file. Identify any suspicious entries and enable trace in the relevant area. Suspicious entries may include any message severity with WARNING or SEVERE. A stack trace (seen in the message below) is a good indication of abnormal behavior.
  3. Enable tracing. Below is a snippet of a WARNING message. The code encountering a “problem” is within the com.ibm.collaboration.realtime.community.internal package. Enabling trace for com.ibm.collaboration.realtime.community.internal at the FINEST level is a good start, but it is too narrow in scope. This would obtain information only for the com.ibm.collaboration.realtime.community.internal package and the problem may exist “higher” in the stack. As a general rule of thumb, expand the scope by removing one or two packages. For example, instead of com.ibm.collaboration.realtime.community.internal, use com.ibm.collaboration.realtime or com.ibm.collaboration.realtime.community. But be careful, not to go too high such as com.ibm.collaboration or com.ibm.rcp or you may receive too much logging, which is difficult to review.

Finding a Plugin’s ‘Owner’

How much importance do you give to a plugin’s name?

Most developers new to rich client platform development generally name their projects not realizing the importance of the project name. You might start a new software feature with the project name MyRemoteWebServiceClient. The “problem” is that Eclipse’s plugin development environment inherits the bundle’s symbolic name from the project name. So both the project name and plugin name are MyRemoteWebServiceClient. Why is this a problem?

If you look at Lotus Notes, Sametime, or Expeditor plugin names, they appear verbose. A plugin named com.ibm.rcp.support.ws.remote.client.jaxws seems more unwieldily than just MyRemoteWebServiceClient. Naming convention becomes more useful after deployment.

Generally, plugin naming convention mimics the Java package naming within the source code. For any plugin, I’d expect the top level package in the plugin to be named the same. For example, com.ibm.rcp.support.ws.remote.client.jaxws should have a top level package called com.ibm.rcp.support.ws.remote.client.jaxws. Why is this useful? Let’s assume that a product fails with the exception:

Caused by: javax.xml.ws.soap.SOAPFaultException: org.xml.sax.SAXParseException: The root element is required in a well-formed document. Message being parsed:
at com.sun.xml.internal.ws.fault.SOAP11Fault.getProtocolException(SOAP11Fault.java:183)
at com.sun.xml.internal.ws.fault.SOAPFaultBuilder.createException(SOAPFaultBuilder.java:106)
at com.sun.xml.internal.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:252)
at com.sun.xml.internal.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:222)
at com.sun.xml.internal.ws.client.sei.SEIStub.invoke(SEIStub.java:115)
at $Proxy28.getSystemTime(Unknown Source)
at com.ibm.rcp.support.ws.remote.RemoteSystemProxy.getSystemTime(RemoteSystemProxy.java:81)
at com.ibm.rcp.support.ws.remote.client.jaxws.Activator.start(Activator.java:46

Once you move beyond the Sun packages, you’re in the plugin developer’s code . The com.ibm.rcp.support.ws.remote.RemoteSystemProxy class threw the exception, but what feature contains this plugin?  How can I find the plugin owner to fix the defect? You can start by inspecting the client platform using some OSGI commands from a previous post. To find the bundle, you might use the class’ package hierarchy and issue the command:

ss com.ibm.rcp.support.ws

This might output the following.

Framework is launched.
id State Bundle
24329 RESOLVED com.ibm.rcp.support.ws.remote.client.jaxws_1.0.0
24330 ACTIVE com.ibm.rcp.support.ws.remote.client.shelf_6.2.1.qualifier

Now you know there are actually two bundles sharing the com.ibm.rcp.support.ws identifier. They’re probably related, but more importantly the bundle with ID 24329 matches the offending class’ package seen in the stack trace. There’s the offending plugin – or at least a highly suspicious one.

Using the OSGI Console in IBM Notes and Sametime

The OSGI console can assist with development investigation and troubleshooting runtime errors.  It’s worth becoming familiar with a few basic commands.

When using the Expeditor or Sametime client, append -console to the client shortcut. If you are using Notes, append -RPARAMS -console. For example, here is the Notes shortcut C:\notes\notes.exe -RPARAMS -console.  After starting the client, the OSGI console will display in a separate window.  Eclipse developers may already be familiar with the OSGI console.  It’s often used during development, and the same commands listed below are applicable to Eclipse.

Notes, Sametime, or Expeditor OSGI Console
Notes, Sametime, or Expeditor OSGI Console
Eclipse OSGI Console
Eclipse OSGI Console

Commands can be input to the platform by typing the command next to the osgi> prompt. If you do not see the prompt simply press enter. For a complete list of commands available, type ? and then press enter.

If the client experiences a platform hang or crash, the following commands provide useful data to locate the cause.

  • dump heap generates a JVM heap dump which is useful when analyzing heap memory usage or memory leaks.
  • dump threads generates a javacore which can be used to analyze the stack trace of various threads; it’s recommended to run dump threads several times and compare threads over time.

See IBM Thread and Monitor Dump Analyzer for Java for analyzing output from the dump commands. The location of dump output can be redirected by editing the rcpinstall.properties file.

env.set.IBM_JAVACOREDIR=${rcp.data}/logs
env.set.IBM_COREDIR=${rcp.data}/logs
env.set.IBM_HEAPDUMPDIR=${rcp.data}/logs

When trying to isolate why a particular feature may be failing, it’s useful to start by understanding the bundle’s state.  Is it installed, is it started, or has it failed to start? The OSGI console accepts either the bundle’s symbolic name or the bundle ID.

  • ss or short status list matching bundles and their state.
  • start starts a bundle.
  • stop stops the bundle.
  • diag determines if the bundle has unresolved dependencies which could lead to runtime problems or an inability to use the bundle.
  • bundle displays a verbose set of information related to exported packages, dependencies, etc.

To enable trace output or limit the amount use the following command.

  • setlogrlev dynamically adjusts log output provide the logger ID (normally the bundle’s symbolic name) and a level (FINEST, FINER, FINE, INFO, WARNING, CONFIG).

Here are a few examples of the above commands.

setlogrlev com.ibm.rcp.ui.launcher FINEST
ss com.ibm.rcp.sync
ss sync
start com.ibm.rcp.syncui.schedule
start 606
diag com.ibm.rcp.syncui.schedule
bundle com.ibm.rcp.syncui.schedule