[vbox-dev] Unable to use restarted VBoxWebSrv

[Klaus Espenlaub]

Hi Allen,

On 19.12.2013 16:00, Allen Granum wrote:
> I am writing a virtual machine management front end in Java (Windows
> 8.1) using the java bindings included in the 4.3.4 SDK. Part of this
> front end monitors that the VBox processes are up and running by
> performing a getVersion on them every once in a while. If this call
> throws we look at the exception and will restart these processes
> (VBoxWebSrv & VBoxSVC) in an attempt to regain a sane connection again.

Very odd that you need this... so far I haven't heard that vboxwebsrv 
itself becomes confused to the point that it needs restarting. Of course 
it might make sense for your (remote) application to monitor whether the 
webservice is alive.

In any case, vboxwebsrv can deal with VBoxSVC crashes (or unexpected 
exits in general), which it handles by waiting a bit and then restarting 
VBoxSVC.

> When I tear things down, I call VirtualBoxManager.disconnect() and
> VirtualBoxManager.cleanup(). I then set my reference to the
> VirtualBoxManager to null and set my reference to the IVirtualBox to
> null (see below)
>
> VirtualBoxManager mgr;
> IVirtualBox  vboxServer;
> ISession vmPlayerSession;
>
> vmPlayerSession.releaseRemote();
>
> vboxServer.releaseRemote();
>
> mgr.disconnect();
> mgr.cleanup();
>
> vboxServer = null;
> mgr = null;
> vmPlayerSession = null;

Note that in general (independent of this cleanup context, actually here 
they're redundant as they most likely won't reach the webservice any 
more, you found it's dead) "releaseRemote" calls are only safe if you 
know for sure that no one will be using the wrapper objects after this 
point in time (even in other threads, no matter what the scheduler 
does), otherwise calls to those objects will trigger exceptions.

So the remaining cleanup looks perfect to me, and should really make 
sure that no webservice connection remains.

> I then re-launch the VBoxWebSrv (which launched the VBoxSVC) and then
> perform  the startup/connect sequence:
>
> VirtualBoxManager mgr = VirtualBoxManager.createInstance(null);
> mgr.connect(VBOX_WEB_SERVER_URI, VBOX_WEB_SERVER_USER, VBOX_WEB_SERVER_PWD);
> vboxServer = mgr.getVBox();
>
>
> The problem I'm seeing....
> When I use this newly launched and connected VBoxWeb interface using the
> java bingings, the webserver seems to hang when I call findMachine. This
> in turn hangs my java app because it is sitting on the vboxWebServer
> socket waiting for a reply with an indefinite timeout (can this timeout
> be set in VBox config somewhere?).
>
> This only ever happens on a restart of the VBox processes from within my
> java app. It is as if the java bindings are not entirely cleaned up when
> I take things down.
>
> Am I missing something on the cleanup?

Nope, not as far as I can see.

> My app stack trace. You can see it stuck on the socketRead
> -------------------------------------------------------------
>
> Thread [WorkUnit508] (Suspended)
> owns: BufferedInputStream (id=56)
> owns: HttpURLConnection (id=57)
> owns: Fiber (id=58)
> SocketInputStream.socketRead0(FileDescriptor, byte[], int, int, int)
> line: not available [native method]
> SocketInputStream.read(byte[], int, int, int) line: 152
> SocketInputStream.read(byte[], int, int) line: 122
> BufferedInputStream.fill() line: 235
> BufferedInputStream.read1(byte[], int, int) line: 275
> BufferedInputStream.read(byte[], int, int) line: 334
> HttpClient.parseHTTPHeader(MessageHeader, ProgressSource,
> HttpURLConnection) line: 687
> HttpClient.parseHTTP(MessageHeader, ProgressSource, HttpURLConnection)
> line: 633
> HttpURLConnection.getInputStream() line: 1323
> HttpURLConnection(HttpURLConnection).getResponseCode() line: 468
> HttpClientTransport.readResponseCodeAndMessage() line: 192
> HttpTransportPipe.createResponsePacket(Packet, HttpClientTransport)
> line: 212
> HttpTransportPipe.process(Packet) line: 203
> HttpTransportPipe.processRequest(Packet) line: 122
> DeferredTransportPipe.processRequest(Packet) line: 95
> Fiber.__doRun(Tube) line: 626
> Fiber._doRun(Tube) line: 585
> Fiber.doRun(Tube) line: 570
> Fiber.runSync(Tube, Packet) line: 467
> SEIStub(Stub).process(Packet, RequestContext, ResponseContextReceiver)
> line: 308
> SEIStub.doProcess(Packet, RequestContext, ResponseContextReceiver) line:
> 146
> SyncMethodHandler.invoke(Object, Object[], RequestContext,
> ResponseContextReceiver) line: 98
> SyncMethodHandler.invoke(Object, Object[]) line: 78
> SEIStub.invoke(Object, Method, Object[]) line: 129
> $Proxy33.iVirtualBoxFindMachine(String, String) line: not available
> IVirtualBox.findMachine(String) line: 850
> VirtualBoxPlayer.findMachine(String) line: 516
> VirtualBoxPlayer.startVirtualMachine(VmAppliance) line: 483
> VirtualBoxJob.call() line: 113
> VirtualBoxJob(Job).call() line: 1
> FutureTask<V>.run() line: 262
> ThreadPoolExecutor.runWorker(ThreadPoolExecutor$Worker) line: 1145
> ThreadPoolExecutor$Worker.run() line: 615
> Thread.run() line: 724
>
>
>
>
>
> The verbose logs from the VBoxWebSrv. It seems to be part way through
> its internal call to findMachine.
> ---------------------------------------------------------------------------------------------------------
>
> 00:00:00.015011 main Package type: WINDOWS_64BITS_GENERIC
> 00:00:00.432661 main Pumping COM event queue
> 00:00:00.432661 Watchdog Watchdog thread started
> 00:00:00.432661 Watchdog Watchdog: sleeping 5 seconds
> 00:00:00.509351 SQPmp Socket connection successful: host = default
> (localhost), port = 18083, master socket = 704
> 00:00:04.984021 SQPmp Request 1 on socket 840 queued for processing (1
> items on Q)
> 00:00:04.984021 SQW01 New SOAP thread started
> 00:00:04.984021 SQW01 Processing connection from IP=127.0.0.1 socket=840
> (0 out of 1 threads idle)
> 00:00:04.984021 SQW01 -- entering __vbox__IWebsessionManager_USCORElogon
> 00:00:04.988023 SQW01 external authentication library is 'null'
> 00:00:04.989024 SQW01 * ManagedObjectRef::ManagedObjectRef: MOR created
> for ISession*=0x0000000137ce68 (IUnknown*=0x0000000137cdd8; COM refcount
> now 3/4), new ID is 1; now 1 objects total
> 00:00:04.989024 SQW01 * WebServiceSession::authenticate: created session
> object with comptr 0x0000000137ce68, MOR = e3b14703552e6d85-0000000000000001
> 00:00:04.989024 SQW01 * ManagedObjectRef::ManagedObjectRef: MOR created
> for IVirtualBox*=0x000000012855e8 (IUnknown*=0x00000001292748; COM
> refcount now 5/6), new ID is 2; now 2 objects total
> 00:00:04.989024 SQW01 VirtualBox object ref is
> e3b14703552e6d85-0000000000000002
> 00:00:04.989024 SQW01 -- leaving __vbox__IWebsessionManager_USCORElogon,
> rc: 0x0
> 00:00:04.991026 SQW01 -- entering __vbox__IVirtualBox_USCOREgetVersion
> 00:00:04.991026 SQW01 ManagedObjectRef::findRefFromId(): looking up
> objref e3b14703552e6d85-0000000000000002
> 00:00:04.991026 SQW01 findComPtrFromId(): returning original
> IVirtualBox*=0x12855E8 (IUnknown*=0x1292748)
> 00:00:04.991026 SQW01 calling COM method COMGETTER(Version)
> 00:00:04.991026 SQW01 done calling COM method
> 00:00:04.991026 SQW01 convert COM output "version" back to caller format
> 00:00:04.991026 SQW01 done converting COM output "version" back to
> caller format
> 00:00:04.991026 SQW01 -- leaving __vbox__IVirtualBox_USCOREgetVersion,
> rc: 0x0 (0)
> 00:00:04.992027 SQPmp Request 2 on socket 900 queued for processing (1
> items on Q)
> 00:00:04.992027 SQW02 New SOAP thread started
> 00:00:04.992027 SQW02 Processing connection from IP=127.0.0.1 socket=900
> (0 out of 2 threads idle)
> 00:00:04.992027 SQW02 -- entering __vbox__IVirtualBox_USCOREgetVersion
> 00:00:04.992027 SQW02 ManagedObjectRef::findRefFromId(): looking up
> objref e3b14703552e6d85-0000000000000002
> 00:00:04.992027 SQW02 findComPtrFromId(): returning original
> IVirtualBox*=0x12855E8 (IUnknown*=0x1292748)
> 00:00:04.992027 SQW02 calling COM method COMGETTER(Version)
> 00:00:04.993027 SQW02 done calling COM method
> 00:00:04.993027 SQW02 convert COM output "version" back to caller format
> 00:00:04.993027 SQW02 done converting COM output "version" back to
> caller format
> 00:00:04.993027 SQW02 -- leaving __vbox__IVirtualBox_USCOREgetVersion,
> rc: 0x0 (0)
> 00:00:05.089091 SQW02 -- entering __vbox__IVirtualBox_USCOREfindMachine
> 00:00:05.089091 SQW02 ManagedObjectRef::findRefFromId(): looking up
> objref e3b14703552e6d85-0000000000000002
> 00:00:05.089091 SQW02 findComPtrFromId(): returning original
> IVirtualBox*=0x12855E8 (IUnknown*=0x1292748)
>
> Thats it.

This actually hints that the webservice hangs somewhere after 
translating the object id to a COM/XPCOM stub pointer (if the log is 
accurate, before actually calling the API method because immediately 
before that there would be another log statement which should show up).

As this is super unlikely (converting the string parameter and creating 
a smart pointer instance can't hang, unless the entire memory has been 
corrupted), this hints that there's unwanted log buffering active, which 
means we don't know exactly where the problem happens.

Quite a mystery what does the buffering... our logger defaults to 
non-buffered, which means it flushes the log buffer after every log 
command. I wonder if the C library on Windows does some additional 
buffering...

You seem to be starting the webservice relatively directly anyway, so 
you could try if the log differs if it goes to the screen (if you 
previously used logging to file) or vice versa.

Hope that this helps finding the cause...

Klaus

> Allen Granum
> agranum at leonovus.com
>
>
> 1309 Carling Avenue
> Ottawa, Ontario, Canada K1Z 7L3
> (613) 722-3232
> x263
>