[jboss-dev] Delayed Shutdown

[Brian Stansberry]

Thanks, Ron.  Yeah, I don't think there is any remoting issue here; 
seems like it was just bad luck that its finalize() method logged 
something in the middle of whatever the real problem was.

And, doh, for sure it's not the JBAS-5590 change, as the EJB3 connector 
isn't even touched by the UnifiedInvoker.

Ron Sigal wrote:
> Hi Brian,
> 
> Sorry for the delay.  I had an eye test this afternoon, and the world is 
> even murkier than usual today.  :-)
> 
> 1. Like you, I don't see how JBAS-5590 could cause this problem.
> 
> 2. If there were anything in Remoting that would concern me, it would  
> be some changes I made in response to JBREM-821 "JBoss Remoting fails 
> under load" - in particular, the part where Tim Fox said
> 
>> 2) The connector close process is not clean. I would suggest the code 
>> should be changed so the server threads are shut down at the beginning 
>> of the connector close process.
>> I.e.
>> a) Wait for current invocations on that server invoker to complete - 
>> and don't allow any more.
>> b) Once all are complete shut it down. 
> 
> So my first thought was to worry that some worker threads were hanging 
> up.  But the lines
> 
>>
>> 2008-06-11 05:31:02,486 DEBUG 
>> [org.jboss.remoting.transport.socket.SocketServerInvoker] (JBoss 
>> Shutdown Hook) SocketServerInvoker[10.18.6.175:3873] stopped threads 
>> in clientpool
>> 2008-06-11 05:31:02,486 DEBUG 
>> [org.jboss.remoting.transport.socket.SocketServerInvoker] 
>> (ServerSocketRefresh) ServerSocketRefresh shutting down
>> 2008-06-11 05:31:02,487 DEBUG 
>> [org.jboss.remoting.transport.socket.SocketServerInvoker] (JBoss 
>> Shutdown Hook) SocketServerInvoker[10.18.6.175:3873] stopped threads 
>> in threadpool 
> 
> convince me that all is well in that regard.
> 
> 3. The EJB3 server shouldn't even have any ServerInvokerCallbackHandlers 
> to shut down.
> 
> 4. So, I don't *think* there are any Remoting problems here.  This is 
> the kind of event that really makes me believe in gremlins.
> 
> 5. I suppose the only reason for the existence of 
> SocketServerInvoker.finalize() is just to be super sure someone doesn't 
> forget to call stop().  But if it's causing a problem for some as yet 
> unknown reason, I guess we could just remove it.
> 
> -Ron
> 
> Brian Stansberry wrote:
>> Ron,
>>
>> I'd better defer this one to you for an opinion. :)
>>
>> I don't really see how the JBAS-5590 change would cause this, but that 
>> was a minor issue affecting just one unit test of an edge-case, so for 
>> now I'll revert that and re-open the JIRA. Once we know it's safe to 
>> proceed I can restore the fix.
>>
>> Here's what I've found:
>>
>> The SocketServerInvoker that might be taking a long time to finalize 
>> is the one for the EJB3 connector:
>>
>> 2008-06-11 05:31:12,707 DEBUG 
>> [org.jboss.deployers.plugins.deployers.DeployersImpl] (JBoss Shutdown 
>> Hook) Fully Undeployed 
>> vfsfile:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/server/all/conf/jboss-service.xml 
>>
>> 2008-06-11 05:31:54,744 DEBUG [org.jboss.remoting.ServerInvoker] 
>> (Finalizer) SocketServerInvoker[10.18.6.175:3873] stopped
>>
>> Looking earlier in the log, I see that SocketServerInvoker was already 
>> stopped as part of the undeploy of the connector:
>>
>> 2008-06-11 05:31:02,486 DEBUG [org.jboss.system.ServiceController] 
>> (JBoss Shutdown Hook) stopping service: 
>> jboss.remoting:type=Connector,name=DefaultEjb3Connector,handler=ejb3
>> 2008-06-11 05:31:02,486 DEBUG 
>> [org.jboss.remoting.transport.socket.SocketServerInvoker] (JBoss 
>> Shutdown Hook) SocketServerInvoker[10.18.6.175:3873] stopped threads 
>> in clientpool
>> 2008-06-11 05:31:02,486 DEBUG 
>> [org.jboss.remoting.transport.socket.SocketServerInvoker] 
>> (ServerSocketRefresh) ServerSocketRefresh shutting down
>> 2008-06-11 05:31:02,487 DEBUG 
>> [org.jboss.remoting.transport.socket.SocketServerInvoker] (JBoss 
>> Shutdown Hook) SocketServerInvoker[10.18.6.175:3873] stopped threads 
>> in threadpool
>> 2008-06-11 05:31:02,487 DEBUG 
>> [org.jboss.remoting.transport.socket.SocketServerInvoker] (JBoss 
>> Shutdown Hook) SocketServerInvoker[10.18.6.175:3873] exiting
>> 2008-06-11 05:31:02,487 DEBUG [org.jboss.remoting.ServerInvoker] 
>> (JBoss Shutdown Hook) SocketServerInvoker[10.18.6.175:3873] stopped
>> 2008-06-11 05:31:02,487 DEBUG [org.jboss.system.ServiceController] 
>> (JBoss Shutdown Hook) destroying service: 
>> jboss.remoting:type=Connector,name=DefaultEjb3Connector,handler=ejb3
>> 2008-06-11 05:31:02,487 DEBUG [org.jboss.system.ServiceController] 
>> (JBoss Shutdown Hook) removing service: 
>> jboss.remoting:type=Connector,name=DefaultEjb3Connector,handler=ejb3
>> 2008-06-11 05:31:02,487 DEBUG [org.jboss.system.ServiceCreator] (JBoss 
>> Shutdown Hook) Removing mbean from server: 
>> jboss.remoting:type=Connector,name=DefaultEjb3Connector,handler=ejb3
>> 2008-06-11 05:31:02,490 DEBUG 
>> [org.jboss.deployers.structure.spi.helpers.AbstractDeploymentContext] 
>> (JBoss Shutdown Hook) Removed component 
>> jboss.remoting:handler=ejb3,name=DefaultEjb3Connector,type=Connector 
>> from 
>> vfsfile:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/server/all/deploy/ejb3-connectors-service.xml 
>>
>>
>> The finalize() method on SocketServerInvoker calls stop() again; hence 
>> the second logging.  Looking at the stop() code I don't see anything 
>> that should take a long time; the first call to stop() should have 
>> already called destroy() on any ServerInvokerCallbackHandler, and once 
>> that's done, doing it again should be very fast, just a couple of null 
>> checks.
>>
>> It's quite possible this is completely unrelated to remoting; i.e. 
>> something else is going on with the Finalizer thread and it's just our 
>> bad luck that remoting happened to log something and focus attention 
>> on us. :-)
>>
>> - Brian
>>
>> Brian Stansberry wrote:
>>> I'll have a look. I for sure I didn't see that effect when I tested 
>>> that change.
>>>
>>> Dimitris Andreadis wrote:
>>>> Hm, probably related to this:
>>>> http://jira.jboss.com/jira/browse/JBAS-5590?page=comments
>>>>
>>>> Dimitris Andreadis wrote:
>>>>> The AS testsuite fails because of a delayed shutdown of the all 
>>>>> config:
>>>>> http://hudson.qa.jboss.com/hudson/view/JBoss%20AS/job/JBoss-AS-5.0.x-TestSuite-sun15/649/artifact/trunk/build/output/jboss-5.0.0.CR1/server/all/log/ 
>>>>>
>>>>>
>>>>> The last entry in the log is this weird ServerInvoker finalizer 
>>>>> thread the seems to be holding the server for more than 42 seconds 
>>>>> after the previous log message:
>>>>>
>>>>> Any idea where is this coming from?
>>>>>
>>>>> 2008-06-11 05:31:12,707 DEBUG 
>>>>> [org.jboss.deployers.plugins.deployers.DeployersImpl] (JBoss 
>>>>> Shutdown Hook) Fully Undeployed 
>>>>> vfsfile:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/server/all/conf/jboss-service.xml 
>>>>>
>>>>> 2008-06-11 05:31:54,744 DEBUG [org.jboss.remoting.ServerInvoker] 
>>>>> (Finalizer) SocketServerInvoker[10.18.6.175:3873] stopped
>>>>>
>>>>> _______________________________________________
>>>>> jboss-development mailing list
>>>>> jboss-development at lists.jboss.org
>>>>> https://lists.jboss.org/mailman/listinfo/jboss-development
>>>
>>
> 

-- 
Brian Stansberry
Lead, AS Clustering
JBoss, a division of Red Hat
brian.stansberry at redhat.com