Some Eclipse Foundation services are deprecated, or will be soon. Please ensure you've read this important communication.

Bug 337823

Summary:

"Check the logs" is unhelpful - which logs?

Product:

[RT] Virgo

Reporter:

Alex Blewitt <alex.blewitt>

Component:

runtime

Assignee:

Project Inbox <virgo-inbox>

Status:

CLOSED FIXED

QA Contact:

Severity:

normal

Priority:

CC:

glyn.normington

Version:

3.0.0.M01

Target Milestone:

3.0.0.M02

Hardware:

OS:

Windows All

Whiteboard:

Attachments:

Description	Flags
WAB which throws an exception during its servlet init method	none
WAB with an unresolvable package import	none
WAB with invalid web.xml	none
PAR containing a WAB with bad web.xml	none

Description Alex Blewitt

2011-02-22 07:47:26 EST

A frustration in trying to find out why a PAR didn't install is an exercise in frustration trying to find what the error is. Although the servicability directory has a plethora of logs, the 'check the logs for more details' message appears to be distributed across most of them which is of course mostly useless.

It also doesn't help that the exception seems to be recorded in most logs, but without any kind of useful information. And with most of them being called 'log.log', it's really not very helpful in tracking down errors.

Since there are two categories of bugs - ones where bundles don't resolve vs ones where an exception occurs programmatically, it would be useful to point the user to the appropriate place for searching for logs. For example, if a bundle constraint could not be satisfied, point them to <deployer.log>, and if a program threw a NPE, point them to <com.example.par/log.log>.

Comment 1 Glyn Normington

2011-02-22 08:57:56 EST

"Check the logs" is part of the message for TomcatServletContainer in gemini web. Gemini Web, of course, knows nothing of Virgo's "plethora" of logs, so I suppose the fix will have to be to catch the exception in Virgo and re-throw a more meaningful exception.

Comment 2 Alex Blewitt

2011-02-22 12:14:45 EST

That would certainly be useful, particularly if it could help differentiate between 'could not resolve' and 'could not start'. In my experience, these end up in different logs. (A ServletFilter's init() method throwing will prevent a web bundle from starting, even if it can install properly.)

Comment 3 Glyn Normington

2011-02-28 06:29:49 EST

Created attachment 189927 [details]
WAB which throws an exception during its servlet init method

Comment 4 Glyn Normington

2011-02-28 06:30:34 EST

Created attachment 189928 [details]
WAB with an unresolvable package import

Comment 5 Glyn Normington

2011-02-28 07:52:17 EST

Throwing an exception from the servlet init method does not produce the "check the logs" event log message as it causes a failure during request processing rather than web app start processing.

Comment 6 Glyn Normington

2011-02-28 07:56:04 EST

Created attachment 189937 [details]
WAB with invalid web.xml

Comment 7 Glyn Normington

2011-02-28 08:00:34 EST

The attached WAB with invalid web.xml produces the following exception log messages:

[2011-02-28 12:54:39.003] fs-watcher                   <HD0001I> Hot deployer processing 'CREATED' event for file 'SampleWAB-1.0.0.jar'. 
[2011-02-28 12:54:39.086] fs-watcher                   <DE0000I> Installing bundle 'SampleWAB' version '1.0.0'. 
[2011-02-28 12:54:39.195] fs-watcher                   <DE0001I> Installed bundle 'SampleWAB' version '1.0.0'. 
[2011-02-28 12:54:39.209] fs-watcher                   <DE0004I> Starting bundle 'SampleWAB' version '1.0.0'. 
[2011-02-28 12:54:39.212] start-signalling-4           <WE0000I> Starting web bundle 'SampleWAB' version '1.0.0' with context path '/samplewab'. 
[2011-02-28 12:54:39.308] start-signalling-4           <WE0005E> Failed to start web bundle 'SampleWAB' version '1.0.0': consult the serviceability log for further details. 
[2011-02-28 12:54:39.312] start-signalling-4           <DE0006E> Start failed for bundle 'SampleWAB' version '1.0.0'. org.eclipse.virgo.kernel.deployer.core.DeploymentException: Web application failed to start
	at org.eclipse.virgo.web.core.internal.WebBundleLifecycleListener.onStarted(WebBundleLifecycleListener.java:131)
	at org.eclipse.virgo.kernel.install.artifact.internal.StandardArtifactStateMonitor.onStarted(StandardArtifactStateMonitor.java:247)
	at org.eclipse.virgo.kernel.install.artifact.internal.AbstractInstallArtifact.asyncStartSucceeded(AbstractInstallArtifact.java:293)
	at org.eclipse.virgo.kernel.install.artifact.internal.AbstractInstallArtifact.access$0(AbstractInstallArtifact.java:290)
	at org.eclipse.virgo.kernel.install.artifact.internal.AbstractInstallArtifact$StateMonitorSignal.signalSuccessfulCompletion(AbstractInstallArtifact.java:228)
	at org.eclipse.virgo.kernel.core.internal.BundleStartTracker$1.run(BundleStartTracker.java:143)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:680)
Caused by: org.eclipse.gemini.web.core.WebApplicationStartFailedException: org.eclipse.gemini.web.core.spi.ServletContainerException: Web application at '/samplewab' failed to start. Check the logs for more details.
	at org.eclipse.gemini.web.internal.StandardWebApplication.start(StandardWebApplication.java:108)
	at org.eclipse.virgo.web.core.internal.WebBundleLifecycleListener.onStarted(WebBundleLifecycleListener.java:122)
	... 8 common frames omitted
Caused by: org.eclipse.gemini.web.core.spi.ServletContainerException: Web application at '/samplewab' failed to start. Check the logs for more details.
	at org.eclipse.gemini.web.tomcat.internal.TomcatServletContainer.startWebApplication(TomcatServletContainer.java:123)
	at org.eclipse.gemini.web.internal.StandardWebApplication.start(StandardWebApplication.java:91)
	... 9 common frames omitted

[2011-02-28 12:54:39.316] start-signalling-4           <DE0010I> Stopping bundle 'SampleWAB' version '1.0.0'. 
[2011-02-28 12:54:39.318] start-signalling-4           <DE0011I> Stopped bundle 'SampleWAB' version '1.0.0'.

Comment 8 Glyn Normington

2011-02-28 08:18:37 EST

The fix is to improve the WE005E message, thus:

<WE0005E> Failed to start web bundle 'SampleWAB' version '1.0.0': consult serviceability/logs/log.log for further details.

Comment 9 Glyn Normington

2011-02-28 08:21:30 EST

The WAB with an unresolvable package import (attached) produces the event log messages below. These messages are sufficient to diagnose the problem and do not refer to "Check the logs".


[2011-02-28 13:18:59.297] fs-watcher                   <HD0001I> Hot deployer processing 'CREATED' event for file 'SampleWAB-1.0.0.jar'. 
[2011-02-28 13:18:59.361] fs-watcher                   <DE0000I> Installing bundle 'SampleWAB' version '1.0.0'. 
[2011-02-28 13:19:10.587] fs-watcher                   <ME0003I> Dump 'serviceability/dump/2011-02-28-13-18-455' generated 
[2011-02-28 13:19:10.591] fs-watcher                   <DE0002E> Installation of bundle 'SampleWAB' version '1.0.0' failed. org.eclipse.virgo.kernel.osgi.framework.UnableToSatisfyBundleDependenciesException: Unable to satisfy dependencies of bundle 'SampleWAB' at version '1.0.0': Cannot resolve: SampleWAB
    Resolver report:
        An Import-Package could not be resolved. Caused by missing constraint in bundle <SampleWAB_1.0.0>
             constraint: <Import-Package: no.such.package; version="0.0.0">

	at org.eclipse.virgo.kernel.install.pipeline.stage.resolve.internal.QuasiResolveStage.process(QuasiResolveStage.java:45)
	at org.eclipse.virgo.kernel.install.pipeline.internal.StandardPipeline.doProcessTree(StandardPipeline.java:62)
	at org.eclipse.virgo.kernel.install.pipeline.internal.CompensatingPipeline.doProcessTree(CompensatingPipeline.java:72)
	at org.eclipse.virgo.kernel.install.pipeline.stage.AbstractPipelineStage.process(AbstractPipelineStage.java:41)
	at org.eclipse.virgo.kernel.install.pipeline.internal.StandardPipeline.doProcessTree(StandardPipeline.java:62)
	at org.eclipse.virgo.kernel.install.pipeline.stage.AbstractPipelineStage.process(AbstractPipelineStage.java:41)
	at org.eclipse.virgo.kernel.deployer.core.internal.PipelinedApplicationDeployer.driveInstallPipeline(PipelinedApplicationDeployer.java:277)
	at org.eclipse.virgo.kernel.deployer.core.internal.PipelinedApplicationDeployer.doInstall(PipelinedApplicationDeployer.java:157)
	at org.eclipse.virgo.kernel.deployer.core.internal.PipelinedApplicationDeployer.install(PipelinedApplicationDeployer.java:129)
	at org.eclipse.virgo.kernel.deployer.core.internal.PipelinedApplicationDeployer.deploy(PipelinedApplicationDeployer.java:196)
	at org.eclipse.virgo.kernel.deployer.hot.HotDeploymentFileSystemListener.deploy(HotDeploymentFileSystemListener.java:174)
	at org.eclipse.virgo.kernel.deployer.hot.HotDeploymentFileSystemListener.onChange(HotDeploymentFileSystemListener.java:78)
	at org.eclipse.virgo.util.io.FileSystemChecker.notifyListeners(FileSystemChecker.java:245)
	at org.eclipse.virgo.util.io.FileSystemChecker.check(FileSystemChecker.java:166)
	at org.eclipse.virgo.kernel.deployer.hot.WatchTask.run(WatchTask.java:58)
	at java.lang.Thread.run(Thread.java:680)

[2011-02-28 13:19:10.594] fs-watcher                   <DE0003E> Install failed for bundle 'SampleWAB' version '1.0.0'. 
[2011-02-28 13:19:10.596] fs-watcher                   <DE0500E> Unable to install application from URI 'file:/Users/glynnormington/bugs/337823/virgo-web-server-3.0.0.BUILD-20110228121344/pickup/SampleWAB-1.0.0.jar'. Cannot satisfy constraints for bundle 'SampleWAB' version '1.0.0'. Cannot resolve: SampleWAB
    Resolver report:
        An Import-Package could not be resolved. Caused by missing constraint in bundle <SampleWAB_1.0.0>
             constraint: <Import-Package: no.such.package; version="0.0.0">
. org.eclipse.virgo.kernel.osgi.framework.UnableToSatisfyBundleDependenciesException: Unable to satisfy dependencies of bundle 'SampleWAB' at version '1.0.0': Cannot resolve: SampleWAB
    Resolver report:
        An Import-Package could not be resolved. Caused by missing constraint in bundle <SampleWAB_1.0.0>
             constraint: <Import-Package: no.such.package; version="0.0.0">

	at org.eclipse.virgo.kernel.install.pipeline.stage.resolve.internal.QuasiResolveStage.process(QuasiResolveStage.java:45)
	at org.eclipse.virgo.kernel.install.pipeline.internal.StandardPipeline.doProcessTree(StandardPipeline.java:62)
	at org.eclipse.virgo.kernel.install.pipeline.internal.CompensatingPipeline.doProcessTree(CompensatingPipeline.java:72)
	at org.eclipse.virgo.kernel.install.pipeline.stage.AbstractPipelineStage.process(AbstractPipelineStage.java:41)
	at org.eclipse.virgo.kernel.install.pipeline.internal.StandardPipeline.doProcessTree(StandardPipeline.java:62)
	at org.eclipse.virgo.kernel.install.pipeline.stage.AbstractPipelineStage.process(AbstractPipelineStage.java:41)
	at org.eclipse.virgo.kernel.deployer.core.internal.PipelinedApplicationDeployer.driveInstallPipeline(PipelinedApplicationDeployer.java:277)
	at org.eclipse.virgo.kernel.deployer.core.internal.PipelinedApplicationDeployer.doInstall(PipelinedApplicationDeployer.java:157)
	at org.eclipse.virgo.kernel.deployer.core.internal.PipelinedApplicationDeployer.install(PipelinedApplicationDeployer.java:129)
	at org.eclipse.virgo.kernel.deployer.core.internal.PipelinedApplicationDeployer.deploy(PipelinedApplicationDeployer.java:196)
	at org.eclipse.virgo.kernel.deployer.hot.HotDeploymentFileSystemListener.deploy(HotDeploymentFileSystemListener.java:174)
	at org.eclipse.virgo.kernel.deployer.hot.HotDeploymentFileSystemListener.onChange(HotDeploymentFileSystemListener.java:78)
	at org.eclipse.virgo.util.io.FileSystemChecker.notifyListeners(FileSystemChecker.java:245)
	at org.eclipse.virgo.util.io.FileSystemChecker.check(FileSystemChecker.java:166)
	at org.eclipse.virgo.kernel.deployer.hot.WatchTask.run(WatchTask.java:58)
	at java.lang.Thread.run(Thread.java:680)

[2011-02-28 13:19:10.603] fs-watcher                   <HD0002E> Hot deploy failed for file 'SampleWAB-1.0.0.jar'. org.eclipse.virgo.kernel.deployer.core.DeploymentException: Dependency satisfaction failed
	at org.eclipse.virgo.kernel.deployer.core.internal.PipelinedApplicationDeployer.driveInstallPipeline(PipelinedApplicationDeployer.java:280)
	at org.eclipse.virgo.kernel.deployer.core.internal.PipelinedApplicationDeployer.doInstall(PipelinedApplicationDeployer.java:157)
	at org.eclipse.virgo.kernel.deployer.core.internal.PipelinedApplicationDeployer.install(PipelinedApplicationDeployer.java:129)
	at org.eclipse.virgo.kernel.deployer.core.internal.PipelinedApplicationDeployer.deploy(PipelinedApplicationDeployer.java:196)
	at org.eclipse.virgo.kernel.deployer.hot.HotDeploymentFileSystemListener.deploy(HotDeploymentFileSystemListener.java:174)
	at org.eclipse.virgo.kernel.deployer.hot.HotDeploymentFileSystemListener.onChange(HotDeploymentFileSystemListener.java:78)
	at org.eclipse.virgo.util.io.FileSystemChecker.notifyListeners(FileSystemChecker.java:245)
	at org.eclipse.virgo.util.io.FileSystemChecker.check(FileSystemChecker.java:166)
	at org.eclipse.virgo.kernel.deployer.hot.WatchTask.run(WatchTask.java:58)
	at java.lang.Thread.run(Thread.java:680)
Caused by: org.eclipse.virgo.kernel.osgi.framework.UnableToSatisfyBundleDependenciesException: Unable to satisfy dependencies of bundle 'SampleWAB' at version '1.0.0': Cannot resolve: SampleWAB
    Resolver report:
        An Import-Package could not be resolved. Caused by missing constraint in bundle <SampleWAB_1.0.0>
             constraint: <Import-Package: no.such.package; version="0.0.0">

	at org.eclipse.virgo.kernel.install.pipeline.stage.resolve.internal.QuasiResolveStage.process(QuasiResolveStage.java:45)
	at org.eclipse.virgo.kernel.install.pipeline.internal.StandardPipeline.doProcessTree(StandardPipeline.java:62)
	at org.eclipse.virgo.kernel.install.pipeline.internal.CompensatingPipeline.doProcessTree(CompensatingPipeline.java:72)
	at org.eclipse.virgo.kernel.install.pipeline.stage.AbstractPipelineStage.process(AbstractPipelineStage.java:41)
	at org.eclipse.virgo.kernel.install.pipeline.internal.StandardPipeline.doProcessTree(StandardPipeline.java:62)
	at org.eclipse.virgo.kernel.install.pipeline.stage.AbstractPipelineStage.process(AbstractPipelineStage.java:41)
	at org.eclipse.virgo.kernel.deployer.core.internal.PipelinedApplicationDeployer.driveInstallPipeline(PipelinedApplicationDeployer.java:277)
	... 9 common frames omitted

Comment 10 Alex Blewitt

2011-02-28 09:14:24 EST

The log file will be different if it is a WAB inside a PAR, in my experience. Also have found the NPE in a filter init leaves par in a half starting state (the web component is stopped).

Comment 11 Glyn Normington

2011-02-28 09:17:02 EST

(In reply to comment #10)
> The log file will be different if it is a WAB inside a PAR, in my experience.

I'll try it. The logs should always come out in serviceability/logs/log.log regardless of which other logs they come out in.

> Also have found the NPE in a filter init leaves par in a half starting state
> (the web component is stopped).

If you can capture that in a small example, please would you raise a bug?

Comment 12 Glyn Normington

2011-02-28 09:24:26 EST

(In reply to comment #11)
> (In reply to comment #10)
> 
> > Also have found the NPE in a filter init leaves par in a half starting state
> > (the web component is stopped).
> 
> If you can capture that in a small example, please would you raise a bug?

No need. My first attempt reproduced the problem, which I will raise and copy you.

Comment 13 Glyn Normington

2011-02-28 09:46:53 EST

Created attachment 189946 [details]
PAR containing a WAB with bad web.xml

Comment 14 Glyn Normington

2011-02-28 09:47:59 EST

(In reply to comment #11)
> (In reply to comment #10)
> > The log file will be different if it is a WAB inside a PAR, in my experience.
> 
> I'll try it. The logs should always come out in serviceability/logs/log.log
> regardless of which other logs they come out in.

The attached PAR behaves the way I expected. The detailed messages from Tomcat come out in serviceability/logs/log.log.

If you find an example where that doesn't happen, please raise another bug.