GNOME Bugzilla – Bug 792219
Critical warning when TLS connection is dropped
Last modified: 2018-03-06 02:48:24 UTC
Geary occasionally emits the following warning when the underlying connection to its mail server has dropped, and it finally notices it after attempting to send some command which times out: > [deb] 23:34:19 29.993534 imap-client-connection.vala:799: [0015/203.18.245.241:993/GEARY_IMAP_CLIENT_CONNECTION_STATE_DEIDLING] on_cmd_timeout > [deb] 23:34:19 0.000072 imap-client-session.vala:1866: [0015/mail.quuxo.net/default:993 GEARY_IMAP_CLIENT_SESSION_STATE_SELECTED] Receive failed: No response to command(s) after 30 seconds > [deb] 23:34:19 0.000035 imap-client-session.vala:1575: [0015/mail.quuxo.net/default:993 GEARY_IMAP_CLIENT_SESSION_STATE_SELECTED] Receive error, disconnecting: No response to command(s) after 30 seconds > [snip] > (geary:3012): GLib-Net-CRITICAL **: g_tls_output_stream_gnutls_write: assertion 'conn != NULL' failed Backtrace for this looks as follows: Thread 860 "pool" received signal SIGTRAP, Trace/breakpoint trap.
+ Trace 238314
Thread 140732659660544 (LWP 10760)
GBufferedOutputStream seems to be attempting to flush buffered data when the base stream has closed due to some network failure, resulting in a critical warning. However since a GTLS stream is involved, it looks like it might be the same issue as Bug 738277.
Bug #738277 is unrelated. CC Olivier since he changed this code to use GWeakRef in bug #735754, though the bug actually predates that. I'm not sure about this. I *think* the only problem here is that criticals are being printed. It's legit for the GTlsOutputStreamGnutls to outlive its associated GTlsConnectionGnutls; all you have to do to make that happen is to ref the GOutputStream (which GBufferedOutputStream's parent class, GFilterOutputStream, does) and then somewhere unref the GTlsConnection. Then you would expect to have a nonfunctional GOutputStream, but one that probably should not be emitting critical warnings like this. So I *think* we should just replace the g_return_val_if_fail() with normal returns, figure out a suitable GError to bubble up (G_IO_ERROR_CONNECTION_CLOSED seems good to me), and move on. My only hesitation is that I'm sure the g_return_val_if_fail()s are there to warn us that GTlsConnectionGnutls should in fact not be destroyed at this point. But that seems to simply be a programming error. The other problem is that it's probably a bug in Geary -- or whatever is creating the GBufferedOutputStream -- that the GBufferedOutputStream is destroyed by the GTlsConnection. Michael, do you have any idea where the GBufferedOutputStream is coming from?
One complication is that g_pollable_output_stream_create_source() and g_pollable_input_stream_create_source() are not fallible, so I guess we have to return a dummy GSource in this case. That's not great, but should be OK.
(In reply to Michael Catanzaro from comment #1) > The other problem is that it's probably a bug in Geary -- or whatever is > creating the GBufferedOutputStream -- that the GBufferedOutputStream is > destroyed by the GTlsConnection. "by" -> "before"
(In reply to Michael Catanzaro from comment #1) > The other problem is that it's probably a bug in Geary -- or whatever is > creating the GBufferedOutputStream -- that the GBufferedOutputStream is > destroyed by the GTlsConnection. Michael, do you have any idea where the > GBufferedOutputStream is coming from? Yeah, I was also wondering if that was the case. When I first created this bug Geary was not explicitly closing the GBufferedOutputStream, and relying on it cleaning itself up when deallocated. I pushed commit 479e9946 just a few weeks ago which explicitly closes GBufferedOutputStream before closing the GTlsConnection. I was expecting the critical to go away, but I think I've seen it at least once since then, but to be honest I can't remember if I was on master or another branch without the patch at the time. I'm usually running Geary under gdb with glib fatal-criticals enabled, so if it happens again I'll mention it here.
That commit is in Geary's repo, obvs: https://git.gnome.org/browse/geary/commit/?id=479e99465d2beed7d9d57401e00153de2ea55dca
Just got one then on master, i.e. including the fixes described above. Debug output leading up to it was basically the same as above, stack trace is a bit different: Thread 1 "geary" received signal SIGTRAP, Trace/breakpoint trap. _g_log_abort (breakpoint=breakpoint@entry=1) at ../../../../glib/gmessages.c:554 554 ../../../../glib/gmessages.c: No such file or directory. (gdb) bt
+ Trace 238397
(In reply to Michael Catanzaro from comment #1) > The other problem is that it's probably a bug in Geary -- or whatever is > creating the GBufferedOutputStream -- that the GBufferedOutputStream is > destroyed by the GTlsConnection. Michael, do you have any idea where the > GBufferedOutputStream is coming from? Sorry, I missed this question - I believe it's the one that is constructed after the GTlsClientConnection is constructed, and then passed to the IMAP serialiser, here: https://git.gnome.org/browse/geary/tree/src/engine/imap/transport/imap-client-connection.vala#n461 This is the only time Geary explicitly constructs an instance of GBufferedOutputStream. Also, I'm not sure if it's relevant, but one of the first things Geary does when it hits the command timeout is to disable graceful disconnect on the underlying GTcpConnection, then proceeds to close the buffered output stream and cause the objects that wrap the GTlsClientConnection's input/output streams to be destructed. Note also that we're explicitly not closing the underlying input/output streams obtained from the TLS connection, just the connection itself.
(In reply to Michael Gratton from comment #7) > Also, I'm not sure if it's relevant, but one of the first things Geary does > when it hits the command timeout is to disable graceful disconnect on the > underlying GTcpConnection That's probably wrong, because it will prevent GTlsConnection from gracefully closing the TLS connection. > then proceeds to close the buffered output stream > and cause the objects that wrap the GTlsClientConnection's input/output > streams to be destructed. Note also that we're explicitly not closing the > underlying input/output streams obtained from the TLS connection, just the > connection itself. That seems like the right order. It doesn't explain why the GBufferedOutputStream is attempting to flush its buffer on a secondary thread after the GTlsConnection has been destroyed. But these criticals need to go away: we should return a nice GError instead in this situation, not a critical.
Created attachment 369165 [details] [review] Input/output streams should expect to outlast their GTlsConnection While it's not great for the GTlsConnection's GInputStream and GOutputStream objects to outlive the GTlsConnection, it's hardly unexpected: reffing objects is hardly disallowed. We should return nice errors in this case instead of emitting criticals.
(In reply to Michael Catanzaro from comment #8) > That's probably wrong, because it will prevent GTlsConnection from > gracefully closing the TLS connection. And it will prevent the GBufferedOutputStream from flushing its buffer (via GTlsConnection) on close.
(In reply to Michael Catanzaro from comment #8) > (In reply to Michael Gratton from comment #7) > > Also, I'm not sure if it's relevant, but one of the first things Geary does > > when it hits the command timeout is to disable graceful disconnect on the > > underlying GTcpConnection > > That's probably wrong, because it will prevent GTlsConnection from > gracefully closing the TLS connection. Ignore that, and ignore my previous comment #10. I misread your comment as "one of the first things Geary does when it hits the command timeout is to perform a graceful disconnect on the underlying GTcpConnection." That's not what you wrote. ;)
Attachment 369165 [details] pushed as e5dac2b - Input/output streams should expect to outlast their GTlsConnection
Review of attachment 369165 [details] [review]: Post-hoc review: this looks fine to me.
This sounds good to me, fwiw. Cheers!