bug#25060: gnutls: asynchronous spurious "fatal error"

bug#25060: gnutls: asynchronous spurious "fatal error"

[Andy Wingo]

Using Emacs 25.1.1 and GnuTLS 3.5.4, consider this interaction:

    (url-retrieve "https://www.gnu.org/"
                  #'(lambda (status)
                      (message "success")))

If I evaluate this a few times in a row directly in my scratch buffer, I
get messages like this:

    Contacting host: www.gnu.org:443
    #<buffer  *http www.gnu.org:443*-960341>
    success
    Contacting host: www.gnu.org:443
    #<buffer  *http www.gnu.org:443*-228158>
    success
    Contacting host: www.gnu.org:443
    #<buffer  *http www.gnu.org:443*-76553>
    success
    Contacting host: www.gnu.org:443
    #<buffer  *http www.gnu.org:443*-944613>
    success
    Contacting host: www.gnu.org:443
    #<buffer  *http www.gnu.org:443*-171378>
    success

And then, after a couple seconds:

    gnutls.c: [0] (Emacs) fatal error: The TLS connection was non-properly terminated.

Indeed if I wait a couple seconds after a single fetch, I always get the
above message after some timeout of inactivity.  Here is a log with
gnutls-log-level set to 2:

    Contacting host: www.gnu.org:443
    gnutls.c: [1] (Emacs) allocating credentials
    gnutls.c: [2] (Emacs) allocating x509 credentials
    gnutls.c: [2] (Emacs) using default verification flags
    gnutls.c: [1] (Emacs) setting the trustfile:  /etc/ssl/certs/ca-certificates.crt
    gnutls.c: [1] (Emacs) setting the trustfile:  /etc/pki/tls/certs/ca-bundle.crt
    gnutls.c: [1] (Emacs) gnutls callbacks
    gnutls.c: [1] (Emacs) gnutls_init
    gnutls.c: [1] (Emacs) got non-default priority string: NORMAL
    gnutls.c: [1] (Emacs) setting the priority string
    gnutls.c: [audit] Note that the security level of the Diffie-Hellman key exchange has been lowered to 256 bits and this may allow decryption of the session data
    gnutls.c: [1] (Emacs) non-fatal error: Resource temporarily unavailable, try again. [3088 times]
    gnutls.c: [2] received curve SECP256R1
    gnutls.c: [1] (Emacs) non-fatal error: Resource temporarily unavailable, try again. [2816 times]
    #<buffer  *http www.gnu.org:443*-346477>
    gnutls.c: [1] (Emacs) non-fatal error: Resource temporarily unavailable, try again. [5 times]
    success

Then after a couple seconds:

    gnutls.c: [0] (Emacs) fatal error: The TLS connection was non-properly terminated.
    gnutls.c: [2] (Emacs) Deallocating x509 credentials

No idea what that non-fatal error appearing thousands of times is, I
suspect Emacs is polling on a non-blocking file descriptor or
something.  Anyway this error appears to not affect anything as it's
asynchronous and it is not handleable by anything, and just makes people
think they have problems :)  Can you make it go away?

Regards,

Andy

bug#25060: gnutls: asynchronous spurious "fatal error"

[Ted Zlatanov]

On Tue, 29 Nov 2016 11:10:17 +0100 Andy Wingo <wingo@igalia.com> wrote: 

AW>     gnutls.c: [1] (Emacs) non-fatal error: Resource temporarily unavailable, try again. [3088 times]
AW>     gnutls.c: [2] received curve SECP256R1
AW>     gnutls.c: [1] (Emacs) non-fatal error: Resource temporarily unavailable, try again. [2816 times]
AW>     #<buffer  *http www.gnu.org:443*-346477>
AW>     gnutls.c: [1] (Emacs) non-fatal error: Resource temporarily unavailable, try again. [5 times]
AW>     success
...
AW> No idea what that non-fatal error appearing thousands of times is, I
AW> suspect Emacs is polling on a non-blocking file descriptor or
AW> something.  Anyway this error appears to not affect anything as it's
AW> asynchronous and it is not handleable by anything, and just makes people
AW> think they have problems :)  Can you make it go away?

I think that's reasonable for that one specific message. But could it be
in fact indicating a real problem at the C level? I don't want to
silence it then.

Ted

bug#25060: gnutls: asynchronous spurious "fatal error"

[Lars Ingebrigtsen]

Andy Wingo <wingo@igalia.com> writes:

>     (url-retrieve "https://www.gnu.org/"
>                   #'(lambda (status)
>                       (message "success")))

[...]

> And then, after a couple seconds:
>
>     gnutls.c: [0] (Emacs) fatal error: The TLS connection was non-properly terminated.

Yes, it just means that the peer ended the connection.  I think gnutls.c
shouldn't say anything in that case -- any sentinels get the proper
callback and stuff, and as information it's pretty worthless for the
user.

I'm installing the following patch, but if there's any disagreement
here, we can discuss further...

diff --git a/src/gnutls.c b/src/gnutls.c
index 735d2e3..6fa0e10 100644
--- a/src/gnutls.c
+++ b/src/gnutls.c
@@ -582,8 +582,15 @@ emacs_gnutls_handle_error (gnutls_session_t session, int err)
 
   if (gnutls_error_is_fatal (err))
     {
+      int level = 1;
+      /* Mostly ignore "The TLS connection was non-properly
+	 terminated" message which just means that the peer closed the
+	 connection.  */
+      if (err == GNUTLS_E_PREMATURE_TERMINATION)
+	level = 3;
+
+      GNUTLS_LOG2 (level, max_log_level, "fatal error:", str);
       ret = 0;
-      GNUTLS_LOG2 (1, max_log_level, "fatal error:", str);
     }
   else
     {


-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#25059: bug#25060: gnutls: asynchronous spurious "fatal error"

[Ted Zlatanov]

On Wed, 25 Jan 2017 00:17:58 +0100 Lars Ingebrigtsen <larsi@gnus.org> wrote: 

LI> Yes, it just means that the peer ended the connection.  I think gnutls.c
LI> shouldn't say anything in that case -- any sentinels get the proper
LI> callback and stuff, and as information it's pretty worthless for the
LI> user.

LI> I'm installing the following patch, but if there's any disagreement
LI> here, we can discuss further...

LI> diff --git a/src/gnutls.c b/src/gnutls.c
LI> index 735d2e3..6fa0e10 100644
LI> --- a/src/gnutls.c
LI> +++ b/src/gnutls.c
LI> @@ -582,8 +582,15 @@ emacs_gnutls_handle_error (gnutls_session_t session, int err)
 
LI>    if (gnutls_error_is_fatal (err))
LI>      {
LI> +      int level = 1;
LI> +      /* Mostly ignore "The TLS connection was non-properly
LI> +	 terminated" message which just means that the peer closed the
LI> +	 connection.  */
LI> +      if (err == GNUTLS_E_PREMATURE_TERMINATION)
LI> +	level = 3;
LI> +
LI> +      GNUTLS_LOG2 (level, max_log_level, "fatal error:", str);
LI>        ret = 0;
LI> -      GNUTLS_LOG2 (1, max_log_level, "fatal error:", str);
LI>      }
LI>    else
LI>      {

IIRC that #define wasn't available until recently so we couldn't use it
until now :) Thanks! It resolves the issue for me. We may want to add a
per-connection counter of these, though, in case code or users want to
examine it.

Ted