Level: Intermediate Robert Weisz (weisz@ca.ibm.com), Staff Software Engineer, IBM Toronto Lab
Shane Cartledge (shanec@ca.ibm.com), Staff Service Analyst, IBM Toronto Lab
Greg Knittl (gregk@ca.ibm.com), Staff Service Analyst, IBM Toronto Lab
08 Jan 2003 Deciphering the different Application Developer log files and stack traces can help you diagnose and fix complex bugs, including system hangs and crashes that produce no error messages. This article shows you how.
Introduction
IBM® WebSphere® Studio Application Developer 5.0 (hereafter called Application Developer) provides logging facilities for plug-in developers to log and trace important events, primarily expected or unexpected errors. Log files are a crucial part of the Application Developer problem determination process. This article describes the log files, tells you where to find them, and uses examples to show you how to use them.
When to use log files
The only reason use log files is if you encounter unexpected program behaviour. In some cases, an error message tells you explicitly to look at the error log:
Unfortunately, the error is not always so explicit. Sometimes your application crashes your system or hangs, and sometimes it simply gives unexpected results without any outward signs. In these cases, the log files may contain information that can speed up the problem determination process.
Log file characteristics
There are two main log files:
.log
and
LoggingUtil.log
.
The
.log
file is provided and maintained by WebSphere Studio Workbench (which is based on the open source
Eclipse
infrastructure). The Workbench uses the
.log
file to capture Eclipse notifications, errors, and any uncaught exceptions from Application Developer plug-ins.
The
LoggingUtil.log
file is provided by the Application-Developer-specific tools (a set of plug-ins added on top of WebSphere Studio Workbench). The Application Developer plug-ins use
LoggingUtil.log
to log various events, errors, and caught exceptions through a logging API.
Both the
.log
and
LoggingUtil.log
files are located in the
<workspace>\.metadata
directory. They are ASCII files, easily read with any text editor.
In Application Developer the
.log
file is cumulative in its behaviour -- each new session of Application Developer appends its messages to the end of the
.log
file without deleting any previous messages. This enables you to see a history of past messages over multiple Application Developer sessions, each one starting with the
!SESSION
string.
On the other hand, a new
LoggingUtil.log
file is created each time Application Developer is started. The previous
LoggingUtil.log
file is renamed and saved by appending a unique string such as a timestamp to its filename. At any given time, the
<workspace>\.metadata
directory contains one
.log
file, one
LoggingUtil.log
and possibly some additional
LoggingUtil.log.*
files from previous Application Developer sessions.
Events in the log files are recorded by appending to the end of the file, so the files are in chronological order, with the oldest event at the beginning of the file and the most recent event at the end.
Examples of log file content, interpretation, and use
Example using the .log file
This example concerns a situation encountered in Application Developer 4.0.3. I finished editing my EJB project, rebuilt it without errors, and tried to export it into a JAR file to send it to a colleague to test. However, I got a
JAR Export Error
with a message box that reads
Creation of JAR Failed -- Invalid Thread Access
. Knowing about the log files, I look in the
.log
file and see the following trace:
........
4 org.eclipse.jdt.ui 566 Creation of JAR failed
org.eclipse.swt.SWTException: Invalid thread access
at org.eclipse.swt.SWT.error(SWT.java:1708)
at org.eclipse.swt.SWT.error(SWT.java:1642)
at org.eclipse.swt.widgets.Widget.error(Widget.java:368)
at org.eclipse.swt.widgets.Widget.checkWidget(Widget.java(CompiledCode))
at org.eclipse.swt.widgets.Widget.getData(Widget.java(CompiledCode))
at org.eclipse.ui.part.MultiPageEditorPart.getEditor(MultiPageEditorPart.java:265)
at org.eclipse.ui.part.MultiPageEditorPart.isDirty(MultiPageEditorPart.java:365)
at org.eclipse.jdt.internal.ui.JavaPlugin.getDirtyEditors(JavaPlugin.java:154)
at org.eclipse.jdt.internal.ui.jarpackager.JarFileExportOperation.preconditionsOK
(JarFileExportOperation.java:484)
at org.eclipse.jdt.internal.ui.jarpackager.JarFileExportOperation.singleRun
(JarFileExportOperation.java:640)
at org.eclipse.jdt.internal.ui.jarpackager.JarFileExportOperation.run
(JarFileExportOperation.java:558)
at org.eclipse.jface.operation.ModalContext$ModalContextThread.run
(ModalContext.java:98)
......... |
In contrast to the overall
.log
file, the stack traces within it go in
reverse
chronological order, with the most recent event at the top of the stack trace and the oldest event at the bottom. Thus, in the above trace, the routine
org.eclipse.swt.widgets.Widget.checkWidget()
, which is compiled code and has no information about source line numbers, calls
org.eclipse.swt.widgets.Widget.error()
, which is a Java™ method located in
Widget.java
at line 368, and so on.
Interestingly, the above log seems to indicate that the exception occurred in an editor (
org.eclipse.ui.part.MultiPageEditorPart
), even though I wasn't editing anymore and was trying to export to a JAR file. Based on this information, and since I don't need an editor to do the export, I can close all the editors, retry the export, and see if the exception goes away because no editors are open. This is indeed what happens!
This means two things: I have found a workaround that lets me continue my work, and I have probably found a bug in an Application Developer editor. Since the workaround is inconvenient, I report the problem to IBM Support. The log file and the workaround I found should help them quickly diagnose the exact source of the problem and get a fix in place.
Example using the LoggingUtil.log file
A second example was encountered using Application Developer 5.0 Early Availability. After importing a few tables from a database and activating an EJB bottom-up mapping, I found that no EJBs where created and no error messages were shown on the screen. The
LoggingUtil.log
file showed the following trace:
<String logging.util.agent_idref="AGENT_CREATE.com.ibm.etools.j2ee.1036797332.22"
logging.util.MsgLoggerLevel="SEVERE"Value="*** ERROR *** Fri Nov08 17:16:27 CST 2002
caller: at com.ibm.etools.ejbrdbmapping.command.CreateBottomUpMappingCommand.
execute(CreateBottomUpMappingCommand.java:192)java.lang.NullPointerException
at com.ibm.etools.ejbrdbmapping.domain.EJBRDBMappingPluginAdapterDomain.
addAttributeCommand(EJBRDBMappingPluginAdapterDomain.java:214)
at com.ibm.etools.ejbrdbmapping.command.InitializeCMPAttributeCommand.copyObject
(InitializeCMPAttributeCommand.java:144)
at com.ibm.etools.ejbrdbmapping.command.InitializeEjbCopyOverrideCommand.execute
(InitializeEjbCopyOverrideCommand.java:308)
at com.ibm.etools.emf.edit.command.AbstractOverrideableCommand.execute
(AbstractOverrideableCommand.java:122)
at com.ibm.etools.common.command.CompoundCommand.execute
(CompoundCommand.java:228)
at com.ibm.etools.common.command.StrictCompoundCommand.execute
(StrictCompoundCommand.java:279)
at com.ibm.etools.emf.edit.command.CopyCommand.execute
(CopyCommand.java:196)
at com.ibm.etools.emf.edit.command.DragAndDropCommand.execute
(DragAndDropCommand.java:779)
at com.ibm.etools.ejbrdbmapping.command.BottomUpDatabaseCommand.mapTable
(BottomUpDatabaseCommand.java:231)
at com.ibm.etools.ejbrdbmapping.command.BottomUpDatabaseCommand.mapTables
(BottomUpDatabaseCommand.java:192)
at com.ibm.etools.ejbrdbmapping.command.BottomUpDatabaseCommand.execute
(BottomUpDatabaseCommand.java:409)
at com.ibm.etools.j2ee.workbench.ParentCommand.execute
(ParentCommand.java:69)
at com.ibm.etools.ejbrdbmapping.command.EjbRdbMappingPersistentCommandStack.
superSuperExecute(EjbRdbMappingPersistentCommandStack.java:705)
at com.ibm.etools.ejbrdbmapping.command.WrappingEjbRdbMappingPersistentCommandStack.
execute(WrappingEjbRdbMappingPersistentCommandStack.java:58)
at com.ibm.etools.ejbrdbmapping.command.CreateBottomUpMappingCommand.mapTables
(CreateBottomUpMappingCommand.java:532)
at com.ibm.etools.ejbrdbmapping.command.CreateBottomUpMappingCommand.execute
(CreateBottomUpMappingCommand.java:188)
at com.ibm.etools.common.command.BasicCommandStack.execute
(BasicCommandStack.java:84)
at com.ibm.etools.ejb.operations.EjbProgressOperation.execute
(EjbProgressOperation.java:61)
at com.ibm.etools.j2ee.operations.HeadlessJ2EEOperation$1.run
(HeadlessJ2EEOperation.java:73)
at org.eclipse.core.internal.resources.Workspace.run
(Workspace.java:1378)
at com.ibm.etools.j2ee.operations.HeadlessJ2EEOperation.run
(HeadlessJ2EEOperation.java:87)
at com.ibm.etools.j2ee.common.ui.RunnableWithProgressWrapper.run
(RunnableWithProgressWrapper.java:57)
at org.eclipse.jface.operation.ModalContext.runInCurrentThread
(ModalContext.java:299)
at org.eclipse.jface.operation.ModalContext.run(ModalContext.java:249)
at org.eclipse.jface.wizard.WizardDialog.run(WizardDialog.java:720)
at com.ibm.etools.ejbrdbmapping.presentation.MappingWizard.performFinish
(MappingWizard.java:525)
at org.eclipse.jface.wizard.WizardDialog.finishPressed(WizardDialog.java:577)
at org.eclipse.jface.wizard.WizardDialog.buttonPressed(WizardDialog.java:312)
at org.eclipse.jface.dialogs.Dialog$1.widgetSelected(Dialog.java:398)
at org.eclipse.swt.widgets.TypedListener.handleEvent(TypedListener.java:87)
at org.eclipse.swt.widgets.EventTable.sendEvent(EventTable.java(CompiledCode))
at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:827)
at org.eclipse.swt.widgets.Display.runDeferredEvents(Display.java:1529
at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:1291)
at org.eclipse.jface.window.Window.runEventLoop(Window.java:562)
at org.eclipse.jface.window.Window.open(Window.java:542)
at com.ibm.etools.ejbrdbmapping.action.CreateMappingAction.
createAndOpenWizardDialog(CreateMappingAction.java:78)
at com.ibm.etools.ejbrdbmapping.action.CreateMappingAction.run
(CreateMappingAction.java:130)
at org.eclipse.ui.internal.PluginAction.runWithEvent
(PluginAction.java:210)
at org.eclipse.jface.action.ActionContributionItem.handleWidgetSelection
(ActionContributionItem.java:407)
at org.eclipse.jface.action.ActionContributionItem.handleWidgetEvent
(ActionContributionItem.java:361)
at org.eclipse.jface.action.ActionContributionItem.access$0
(ActionContributionItem.java:352)
at org.eclipse.jface.action.ActionContributionItem$ActionListener.handleEvent
(ActionContributionItem.java:47)
at org.eclipse.swt.widgets.EventTable.sendEvent
(EventTable.java(CompiledCode))
at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:827)
at org.eclipse.swt.widgets.Display.runDeferredEvents(Display.java:1529)
at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:1291)
at org.eclipse.ui.internal.Workbench.runEventLoop(Workbench.java:1256)
at org.eclipse.ui.internal.Workbench.run(Workbench.java:1239)
at org.eclipse.core.internal.boot.InternalBootLoader.run
(InternalBootLoader.java:775)
at org.eclipse.core.boot.BootLoader.run(BootLoader.java:462)
at java.lang.reflect.Method.invoke(NativeMethod)
at org.eclipse.core.launcher.Main.basicRun(Main.java:247)
at org.eclipse.core.launcher.Main.run(Main.java:703)
at org.eclipse.core.launcher.Main.main(Main.java:539) |
Something seems to have gone wrong in the
com.ibm.etools.ejbrdbmapping.command.CreateBottomUpMappingCommand.execute()
method (
java.lang.NullPointerException
at the top of the trace). The method name sounds quite related to what I was doing at the time. In this case, there is no obvious workaround. Based on the
java.lang.NullPointerException
, it seems that Application Developer wasn't able to handle an unexpected error. I do a Web search for similar problems and notify IBM Support, so that this trace can help them diagnose the problem and get a fix in place.
Best practices
In order to isolate all problem information in the
.log
file, the best approach is to shut down Application Developer, delete the cumulative
.log
file, restart Application Developer, reproduce the problem, and then once again shut down Application Developer. This way the entries in the
.log
file apply only to the current session, making the problem easier to isolate. Also, shutting down Application Developer ensures that the entire log buffer will be flushed to the
.log
file.
When looking for problems in
.log
files, it's often helpful to search on the string
exception
. Of course, not all exceptions are signs of irrecoverable errors. As mentioned above in the section
When to use log files
, you need to pay attention to
.log
files only in case of unexpected program behaviour.
You also need to be familiar with the concept of nested exceptions. which occur when an exception triggers another exception and possibly a chain of exceptions. In nested exceptions, you need to focus on the first (earliest) exception in the chain, since it is the root cause of the error. The other exceptions are caused by poor handling of the first unexpected error.
Conclusion
Knowing how to interpret the contents of the Application Developer
.log
files can help you find temporary workarounds for unexpected program behaviour, and can also enable you to supply critical information to IBM Support to help them diagnose the problem and get a fix in place.
Acknowledgement
The authors wish to thank Angel Vera, Staff Software
Developer, IBM Toronto Lab, for reviewing this article.
IBM and WebSphere are trademarks or registered
trademarks of IBM Corporation in the United States,
other countries, or both. Java and all Java-based
trademarks and logos are trademarks or registered
trademarks of Sun Microsystems, Inc. in the United
States, other countries, or both. Other company,
product, and service names may be trademarks or service
marks of others. IBM copyright and trademark
information
About the authors  | | | Robert Weisz
works with the WebSphere Studio Application Developer Technical Support team at the IBM Toronto Lab. He worked as a developer on the CDT plug-ins for Eclipse. |
| | | Shane Cartledge
works with the WebSphere Studio Application Developer Technical Support team at the IBM Toronto Lab. |
| | | Greg Knittl works with the WebSphere Studio Application Developer Technical Support team at the IBM Toronto Lab. |
Rate this page
| 
