Bugzilla – Full Text Bug Listing
| Summary: | [nano] shutdown of VTS or VJS outputs logs to the console | ||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | [RT] Virgo | Reporter: | Glyn Normington <glyn.normington> | ||||||||
| Component: | runtime | Assignee: | Chris Frost <eclipse> | ||||||||
| Status: | CLOSED FIXED | QA Contact: | |||||||||
| Severity: | normal | ||||||||||
| Priority: | P3 | CC: | b.kapukaranov, eclipse, l.kirchev | ||||||||
| Version: | 3.1.0.M01 | ||||||||||
| Target Milestone: | 3.5.0.M04 | ||||||||||
| Hardware: | PC | ||||||||||
| OS: | Mac OS X - Carbon (unsup.) | ||||||||||
| Whiteboard: | |||||||||||
| Attachments: |
|
||||||||||
|
Description
Glyn Normington
This also happens in VJS, although there are fewer logs: Jan 4, 2012 11:17:32 AM org.springframework.osgi.context.support.AbstractOsgiBundleApplicationContext unpublishContextAsOsgiService INFO: Unpublishing application context OSGi service for bundle Admin Console Web Bundle (org.eclipse.virgo.apps.admin.web) Jan 4, 2012 11:17:32 AM org.springframework.context.support.AbstractApplicationContext doClose INFO: Closing ServerOsgiBundleXmlWebApplicationContext(bundle=org.eclipse.virgo.apps.admin.web, config=/WEB-INF/applicationContext.xml): startup date [Wed Jan 04 11:16:53 GMT 2012]; root of context hierarchy Jan 4, 2012 11:17:32 AM org.springframework.beans.factory.support.DefaultSingletonBeanRegistry destroySingletons INFO: Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@a06514b: defining beans [artifactService,dumpInspectorService,stateHolder,configAdmin]; root of factory hierarchy [gnormington-desktop:virgo-jetty-server-3.1.0.M01]$ In VTS 3.0.2 these logs do not appear in either the logs, or the console. Are they expected to appear at all? (In reply to comment #2) > In VTS 3.0.2 these logs do not appear in either the logs, or the console. > Are they expected to appear at all? Thanks for that observation. The log messages themselves look reasonable, so I presume that in 3.0.2 they were being discarded rather than appearing on the console. I wonder if medic is shutting down a little before the bundles that are outputting those logs and that somehow logging has been redirected to the console? Perhaps there is a window *during* the stopping of medic when logs are redirected to the console after which they are discarded. Perhaps this is also related to the greater freedom with which bundles are started and therefore potentially also stopped? (Note that 3.1.0.M01 does not include the recent change to split logback out of medic core, so that's not the cause.) We need to check how the shutdown sequence stops bundles (in what order if any). In 3.1.0.M01 the medic bundles are started right after simpleconfigurator, which means they are always first to start. That's because they have start level 3, all others are on 4. I did this because the medic bundles were otherwise alphabetically late in the startup sequence and the logging misbehaved. If the shutdown happens again with respect for the startlevels it stands to reason medics are the first to stop or the last. The messages "Stopping Tomcat" and "Stopped Tomcat" appear both in the console and the log files. But in the console between these two messages there are INFO logs, which do not appear in the log files. So probably the medic does not stop before the bundles, which output the logs? (In reply to comment #4) > We need to check how the shutdown sequence stops bundles (in what order if > any). > In 3.1.0.M01 the medic bundles are started right after simpleconfigurator, > which means they are always first to start. That's because they have start > level 3, all others are on 4. > I did this because the medic bundles were otherwise alphabetically late in the > startup sequence and the logging misbehaved. > > If the shutdown happens again with respect for the startlevels it stands to > reason medics are the first to stop or the last. So perhaps the root cause for us seeing extra log messages (regardless of where they appear) is that medic is lingering on longer than it used to? (In reply to comment #5) > The messages "Stopping Tomcat" and "Stopped Tomcat" appear both in the console > and the log files. But in the console between these two messages there are INFO > logs, which do not appear in the log files. So probably the medic does not stop > before the bundles, which output the logs? Agreed. After comparing the log files of 3.1.0.M01 and 3.0.2 I found there's a little difference. On 3.1.0.M01 the web-container stops at a bit later point, when medic is already stopped and have redirected the output to System.out in this method (http://virgo-opengrok.springsource.org/xref/virgo/org.eclipse.virgo.medic/org.eclipse.virgo.medic.core/src/main/java/org/eclipse/virgo/medic/impl/LogController.java#155). I believe this causes the web-container to dump these traces in the console. On 3.0.2 It seems Tomcat stops fairly early(before medic), thus no traces in the console. This doesn't explain however why these traces do not appear in the log.log file on this release. Even more strange is that similar traces appear at the startup of the web container: TC0010I Creating HTTP/1.1 connector with scheme http on port 8080. Starting ProtocolHandler ["http-bio-8080"] TC0010I Creating HTTP/1.1 connector with scheme https on port 8443. Starting ProtocolHandler ["http-bio-8443"] TC0010I Creating AJP/1.3 connector with scheme http on port 8009. Starting ProtocolHandler ["ajp-bio-8009"] TC0001I Started Tomcat. So it stands to reason the traces appearing during shutdown should appear in the logs too. Probably this was a bug in the old release and was hidden somehow. As for 3.1.0.M01 it appears we don't have much control over the shutdown sequence so I don't think we can stop medic at a later point. I can think of several workarounds to make medic's stop slow down, but it's more a workaround that a solution. (In reply to comment #8) > As for 3.1.0.M01 it appears we don't have much control over the shutdown > sequence so I don't think we can stop medic at a later point. Do you think this is a consequence of us having less control of the startup sequence in 3.1.0.M01? You see, we've never seen this before and I would hope that Equinox reverses the start sequence when stopping bundles. Actually we don't try to apply any control over the shutdown sequence in both 3.1.0.M01 and prior that. I was just thinking aloud on the results I found comparing the two log files. We don't have any control over the order in which bundles are stopped and I believe we never did. Having said that I doubt we can do any more pre-processing. I think we'll need to do some debugging here, but it sounds like a timing issue for now. Lastly another fact: the medic bundles are installed with much lower ID's prior 3.1.0.M01. 6 and 10 compared to 32 and 33 in 3.1.0.M01. That's because of the alphabetic order in which bundles are installed in 3.1.0.M01. Created attachment 211242 [details]
VTS bundles sorted by sland id when stopping
This is a list of the VTS bundles in ascending order by start level and id.
Created attachment 211243 [details]
List of VTS bundles additionally sorted by dependency
This is the previous list, sorted in ascending order by start level and id, but additionally sorted by dependency.
I made some initial debugging on this issue. There is something strange regarding the order in which the framework stops the bundles. According to the osgi spec the framework should start by stopping the bundles with the highest start level and proceed to start level 0 by decreasing the start level by one and stopping all bundles with the current start level. The start level manager first sorts all installed bundles in ascending order by start level and id. The list, as I saw it in the debugger, is in the first attached file. What seems strange to me is that the medic bundles are placed after other bundles with higher start level, which I think should not be the case. Further, the Start level manager sorts the once sorted array by dependencies. And then starts to stop the bundles in the resulting list from the end of the list to start. This list is in the second attachment. Thus it happens that the medic bundles are stopped before the tomcat bundles. I still don't get completely the logic of these sortings. Some more debugging should be made. Created attachment 213115 [details]
Fixed order of bundles shutdown
This bug is caused by the default start level being 1 for bundles installed via BundleContext.installBundle. See, FrameworkStartLevel.setInitialBundleStartLevel(int) for JavaDoc. This can be fixed by adding this line to the UserRegionFactory Activator.
((FrameworkStartLevel)componentContext.getBundleContext().getBundle(0).adapt(FrameworkStartLevel.class)).setInitialBundleStartLevel(6);
Once done, this attachment shows the new ordering of bundles for shutdown.
Fixed with commit de5e7734861d6c0003678d87e50aecc4bd98237f |