On 10/8/21 1:36 PM, Daniel P. Berrangé wrote:

On Fri, Oct 08, 2021 at 01:12:49PM +0200, Michal Privoznik wrote:

...

When a server decides to close a client, the virNetServerClientCloseLocked() is called. In here various cleanup steps are taken, but the most important part (from this commit's POV at least) is the way that the socket is closed. Firstly, removal of the socket associated with the client from the event loop is signalized and then the socket is unrefed. The socket is not closed just yet though, because the event loop holds a reference to it. This reference will be freed as soon as the event loop wakes up and starts issuing callbacks (in this case virNetSocketEventFree()).

So far, this is how things usually work. But if the daemon reaches the number of opened files limit, things start to work differently.

If the RLIMIT_NOFILE limit is reached and there's a client that wants to connect then the event loop wakes up, sees POLLIN on the socket and calls virNetServerServiceAccept() which in turn calls virNetSocketAccept(). But because of the limit, accept() fails with EMFILE leaving the POLLIN event unhandled. The dispatch then continues to next FDs with events on them. BUT, it will NOT call the socket removal callback (virNetSocketEventFree()) because it has low priority (G_PRIORITY_DEFAULT_IDLE). Per glib's documentation:

if virNetSocketAccept fails, there's no client socket to remove/close. AFAIK, we are not removing the server socket either.

So I'm not following which socket is supposedly being removed in this scenario ?

Right. I didn't phrase it properly. Let's call the /var/run/libvirt/libvirt-sock SockA and accepted socket (i.e. per client) SockB. Let the NOFILE limit be just the right value so that both SockA and SockB can exist, but no more. Now, let's have another client trying to connect(). The event loop wakes up, because there's an event on SockA. But the connection can't be accept()-ed. Alright, so let the already connected client disconnect (that is, SockB). This will result in: g_idle_add(virEventGLibHandleRemoveIdle, SockB); /* I've made a shortcut here, in reality there's a data variable that points to SockB, but you get the idea */ Now, because we still haven't handled the connection attempt at SockA the idle source won't ever be called because it has lower priority. Therefore, the event loop is stuck in endless loop trying to accept() connection on SockA.

...

* Each event source is assigned a priority. The default priority, * %G_PRIORITY_DEFAULT, is 0. Values less than 0 denote higher priorities. * Values greater than 0 denote lower priorities. Events from high priority * sources are always processed before events from lower priority sources.

and per g_idle_add() documentation:

* Adds a function to be called whenever there are no higher priority * events pending to the default main loop. The function is given the * default idle priority, %G_PRIORITY_DEFAULT_IDLE.

Now, because we did not accept() the client we are constantly seeing POLLIN on the main socket and thus the removal of the client socket won't ever happen.

The fix is to set at least the same priority as other sources, but since we want to just close an FD, let's give it the highest priority and call it before handling other events.

This issue can be easily reproduced, for instance:

# ulimit -S -n 40 (tweak this number if needed) # ./src/libvirtd

from another terminal:

# for ((i=0; i<100; i++)); do virsh list & done; virsh list

The last `virsh list` must not get stuck.

The bug below describes libvirt core dumps rather than hangs. Do you know why it dumped ?

Because of glib. We called some glib function which internally wanted to open a pipe which failed. Thus glib aborted. I don't remember the exact function, but I can look it up if you want. Michal

On 10/8/21 2:23 PM, Daniel P. Berrangé wrote:

On Fri, Oct 08, 2021 at 01:56:24PM +0200, Michal Prívozník wrote:

...

On 10/8/21 1:36 PM, Daniel P. Berrangé wrote:

...

On Fri, Oct 08, 2021 at 01:12:49PM +0200, Michal Privoznik wrote:

...

When a server decides to close a client, the virNetServerClientCloseLocked() is called. In here various cleanup steps are taken, but the most important part (from this commit's POV at least) is the way that the socket is closed. Firstly, removal of the socket associated with the client from the event loop is signalized and then the socket is unrefed. The socket is not closed just yet though, because the event loop holds a reference to it. This reference will be freed as soon as the event loop wakes up and starts issuing callbacks (in this case virNetSocketEventFree()).

So far, this is how things usually work. But if the daemon reaches the number of opened files limit, things start to work differently.

If the RLIMIT_NOFILE limit is reached and there's a client that wants to connect then the event loop wakes up, sees POLLIN on the socket and calls virNetServerServiceAccept() which in turn calls virNetSocketAccept(). But because of the limit, accept() fails with EMFILE leaving the POLLIN event unhandled. The dispatch then continues to next FDs with events on them. BUT, it will NOT call the socket removal callback (virNetSocketEventFree()) because it has low priority (G_PRIORITY_DEFAULT_IDLE). Per glib's documentation:

if virNetSocketAccept fails, there's no client socket to remove/close. AFAIK, we are not removing the server socket either.

So I'm not following which socket is supposedly being removed in this scenario ?

Right. I didn't phrase it properly. Let's call the /var/run/libvirt/libvirt-sock SockA and accepted socket (i.e. per client) SockB. Let the NOFILE limit be just the right value so that both SockA and SockB can exist, but no more. Now, let's have another client trying to connect(). The event loop wakes up, because there's an event on SockA. But the connection can't be accept()-ed. Alright, so let the already connected client disconnect (that is, SockB). This will result in:

g_idle_add(virEventGLibHandleRemoveIdle, SockB); /* I've made a shortcut here, in reality there's a data variable that points to SockB, but you get the idea */

Now, because we still haven't handled the connection attempt at SockA the idle source won't ever be called because it has lower priority. Therefore, the event loop is stuck in endless loop trying to accept() connection on SockA.

Ah i see, "idle" callbacks aren't called because the event loop isn't idle.

So with this change, we'll let the idle callback run, which will close the FD which will let libvird accept the client which gets us out of the 100% CPU burn loop..... unless there were two pending clients....

So, ACK to this patch as a quick fix, but it feels like we ultimately have a more serious problem.

I wonder if we should temporarily stop watching events on the incoming server if we get EMFILE first time on accept, and set a timer to re-enable events 60 seconds later. Rinse, repeat.

Yes, good idea. But I worry that 60 seconds may be too long. Or needlessly short - depending on usage. Nevertheless, let us start with 60 seconds and we can fine tune later. So are you okay with me pushing this patch and sending this ^^ as a follow up?

...

...

...

* Each event source is assigned a priority. The default priority, * %G_PRIORITY_DEFAULT, is 0. Values less than 0 denote higher priorities. * Values greater than 0 denote lower priorities. Events from high priority * sources are always processed before events from lower priority sources.

and per g_idle_add() documentation:

* Adds a function to be called whenever there are no higher priority * events pending to the default main loop. The function is given the * default idle priority, %G_PRIORITY_DEFAULT_IDLE.

Now, because we did not accept() the client we are constantly seeing POLLIN on the main socket and thus the removal of the client socket won't ever happen.

The fix is to set at least the same priority as other sources, but since we want to just close an FD, let's give it the highest priority and call it before handling other events.

This issue can be easily reproduced, for instance:

# ulimit -S -n 40 (tweak this number if needed) # ./src/libvirtd

from another terminal:

# for ((i=0; i<100; i++)); do virsh list & done; virsh list

The last `virsh list` must not get stuck.

The bug below describes libvirt core dumps rather than hangs. Do you know why it dumped ?

Because of glib. We called some glib function which internally wanted to open a pipe which failed. Thus glib aborted. I don't remember the exact function, but I can look it up if you want.

Oh, so this patch is not actually fixing the core dump scenario then. Even after we fix the bug that prevents clients disconnecting, it will still dump if this API is called at a point where we are in a EMFILE state ?

Yes. But I am afraid there's no way around it. Found the stack trace: Stack trace of thread 52231: #0 0x000003ffa90be9e4 raise (libc.so.6) #1 0x000003ffa96590ee g_log_default_handler (libglib-2.0.so.0) #2 0x000003ffa965935e g_logv (libglib-2.0.so.0) #3 0x000003ffa965955a g_log (libglib-2.0.so.0) #4 0x000003ffa969dd70 g_wakeup_new (libglib-2.0.so.0) #5 0x000003ffa964eb38 g_main_context_new (libglib-2.0.so.0) #6 0x000003ffa9946886 vir_event_thread_init (libvirt.so.0) #7 0x000003ffa95b5ff8 g_type_create_instance (libgobject-2.0.so.0) #8 0x000003ffa95978cc g_object_new_internal (libgobject-2.0.so.0) #9 0x000003ffa95990de g_object_new_with_properties (libgobject-2.0.so.0) #10 0x000003ffa9599ab6 g_object_new (libgobject-2.0.so.0) #11 0x000003ffa9946b78 virEventThreadNew (libvirt.so.0) #12 0x000003ff6c2c8bd8 qemuProcessQMPNew (libvirt_driver_qemu.so) #13 0x000003ff6c1f57b8 virQEMUCapsInitQMPSingle (libvirt_driver_qemu.so) #14 0x000003ff6c1f59ec virQEMUCapsNewForBinaryInternal (libvirt_driver_qemu.so) #15 0x000003ff6c1f5c92 virQEMUCapsNewData (libvirt_driver_qemu.so) #16 0x000003ffa99510f4 virFileCacheValidate (libvirt.so.0) #17 0x000003ffa995133c virFileCacheLookup (libvirt.so.0) #18 0x000003ff6c1f5e4a virQEMUCapsCacheLookup (libvirt_driver_qemu.so) #19 0x000003ff6c1f621e virQEMUCapsCacheLookupCopy (libvirt_driver_qemu.so) #20 0x000003ff6c2c4a44 qemuProcessInit (libvirt_driver_qemu.so) #21 0x000003ff6c2c67f2 qemuProcessStart (libvirt_driver_qemu.so) #22 0x000003ff6c26358c qemuDomainObjStart.constprop.55 (libvirt_driver_qemu.so) #23 0x000003ff6c2639c8 qemuDomainCreateWithFlags (libvirt_driver_qemu.so) #24 0x000003ffa9b77902 virDomainCreate (libvirt.so.0) #25 0x000002aa34ad2d52 remoteDispatchDomainCreateHelper (libvirtd) #26 0x000003ffa9a6094a virNetServerProgramDispatch (libvirt.so.0) #27 0x000003ffa9a665b6 virNetServerHandleJob (libvirt.so.0) #28 0x000003ffa99a0d32 virThreadPoolWorker (libvirt.so.0) #29 0x000003ffa99a02d6 virThreadHelper (libvirt.so.0) #30 0x000003ffa85880c6 start_thread (libpthread.so.0) #31 0x000003ffa917bd36 thread_start (libc.so.6) So my bad, it failed opening eventfd (in frame #4 g_wakeup_new()) but anyway, I don't think we can mitigate this. But I think there was another stacktrace attached to BZ where it failed in glib in pipe(). Doesn't really matter though. It's glib - we accepted abort policy when adopting it. Michal