Comment 1 Glyn Normington 2012-01-04 06:18:40 EST

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]$

Comment 2 Lazar Kirchev 2012-01-05 02:36:20 EST

In VTS 3.0.2 these logs do not appear in either the logs, or the console. 
Are they expected to appear at all?

Comment 3 Glyn Normington 2012-01-05 02:48:06 EST

(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.)

Comment 4 Borislav Kapukaranov 2012-01-05 02:56:38 EST

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.

Comment 5 Lazar Kirchev 2012-01-05 03:03:26 EST

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?

Comment 6 Glyn Normington 2012-01-05 03:33:20 EST

(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?

Comment 7 Glyn Normington 2012-01-05 03:33:50 EST

(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.

Comment 8 Borislav Kapukaranov 2012-01-06 12:13:17 EST

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.

Comment 9 Glyn Normington 2012-01-09 05:25:24 EST

(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.

Comment 10 Borislav Kapukaranov 2012-01-09 05:44:03 EST

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.

Comment 11 Lazar Kirchev 2012-02-19 10:40:52 EST

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.

Comment 12 Lazar Kirchev 2012-02-19 10:42:15 EST

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.

Comment 13 Lazar Kirchev 2012-02-19 10:51:53 EST

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.

Comment 14 Chris Frost 2012-03-23 13:21:13 EDT

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.

Comment 15 Chris Frost 2012-03-26 09:27:33 EDT

Fixed with commit de5e7734861d6c0003678d87e50aecc4bd98237f