[Openvpn-devel,v3] Improve data key id not found error message

Message ID 20220914172527.2661529-1-arne@rfc2549.org
State Accepted
Headers show
Series [Openvpn-devel,v3] Improve data key id not found error message | expand

Commit Message

Arne Schwabe Sept. 14, 2022, 7:25 a.m. UTC
With delayed data key generation now with deferred auth, NCP and similar
mechanism the "TLS Error: local/remote TLS keys are out of sync" is shown
much too frequent and confuses a lot of people.

This also removes the dead code of printing multi not ready keys and
replace it with an assert.

Factor out printing of error messages into an extra function to make
the code easier to understand and also to only call into that function
in the case that a key is not found and avoid the overhead.

Patch v2: fix comparing key_id to state value, improve message
Patch v3: also take key_id into account

Signed-off-by: Arne Schwabe <arne@rfc2549.org>
---
 src/openvpn/ssl.c | 75 +++++++++++++++++++++++++++++++++++------------
 1 file changed, 57 insertions(+), 18 deletions(-)

Comments

Frank Lichtenheld Sept. 15, 2022, 4:19 a.m. UTC | #1
On Wed, Sep 14, 2022 at 07:25:27PM +0200, Arne Schwabe wrote:
> With delayed data key generation now with deferred auth, NCP and similar
> mechanism the "TLS Error: local/remote TLS keys are out of sync" is shown
> much too frequent and confuses a lot of people.
> 
> This also removes the dead code of printing multi not ready keys and
> replace it with an assert.
> 
> Factor out printing of error messages into an extra function to make
> the code easier to understand and also to only call into that function
> in the case that a key is not found and avoid the overhead.
> 
> Patch v2: fix comparing key_id to state value, improve message
> Patch v3: also take key_id into account

Code looks good to me now. Is there any way of testing this?

Regards,
Arne Schwabe Oct. 19, 2022, 11:21 a.m. UTC | #2
>> Patch v2: fix comparing key_id to state value, improve message
>> Patch v3: also take key_id into account
> 
> Code looks good to me now. Is there any way of testing this?

You need to get both peer in some kind of inconsistent state. Like short 
reneg-sec on one side and dealyed auth on the other side or deauthing 
(e.g. via management) and seeing packet in the last five seconds before 
the session gets killed. Also somethning like reneg-sec 60 on one side 
might trigger these warnings.

If I trigger them again with something reliable to trigger them, I will 
follow up.

Arne
Gert Doering Nov. 8, 2022, 5:28 a.m. UTC | #3
Acked-by: Gert Doering <gert@greenie.muc.de>

Most of it is actually straightforward (if no workable key is
found, go to the "print fail" function, find the right key slot
*again*, print "not initialized" or "not authorized" according
to ks->state / ks->authenticated - and if nothing matches, print
the existing "generic out of sync" message.

We still don't know how to trigger this on-demand, but even so it
won't do harm, and cleans up handle_data_channel_packet() a bit.

What I do not like so much is the extra gc + 3 gc_free() calls
(while the caller has its own gc + gc_free() right after calling
print_key_id_not_found_reason()...) - but then, gc is "something
local", so be it...  and for some reason the existing gc_free()
gets moved around - that looks a bit spurious (but harmless).

I fed this to the client/server test bed, to see if I could
trigger something (or it would *break* something) - didn't break
anything, but didn't trigger key messages either...

Your patch has been applied to the master branch.

commit 616a143552143a8c0a3b727362cc3931541ca785
Author: Arne Schwabe
Date:   Wed Sep 14 19:25:27 2022 +0200

     Improve data key id not found error message

     Signed-off-by: Arne Schwabe <arne@rfc2549.org>
     Acked-by: Gert Doering <gert@greenie.muc.de>
     Message-Id: <20220914172527.2661529-1-arne@rfc2549.org>
     URL: https://www.mail-archive.com/openvpn-devel@lists.sourceforge.net/msg25212.html
     Signed-off-by: Gert Doering <gert@greenie.muc.de>


--
kind regards,

Gert Doering

Patch

diff --git a/src/openvpn/ssl.c b/src/openvpn/ssl.c
index 672cd9c84..c0d8add97 100644
--- a/src/openvpn/ssl.c
+++ b/src/openvpn/ssl.c
@@ -3210,11 +3210,62 @@  nohard:
     return (tas == TLS_AUTHENTICATION_FAILED) ? TLSMP_KILL : active;
 }
 
-/*
- * Pre and post-process the encryption & decryption buffers in order
- * to implement a multiplexed TLS channel over the TCP/UDP port.
+/**
+ * We have not found a matching key to decrypt data channel packet,
+ * try to generate a sensible error message and print it
  */
+static void
+print_key_id_not_found_reason(struct tls_multi *multi,
+                              const struct link_socket_actual *from, int key_id)
+{
+    struct gc_arena gc = gc_new();
+    const char *source = print_link_socket_actual(from, &gc);
+
 
+    for (int i = 0; i < KEY_SCAN_SIZE; ++i)
+    {
+        struct key_state *ks = get_key_scan(multi, i);
+        if (ks->key_id != key_id)
+        {
+            continue;
+        }
+
+        /* Our key state has been progressed far enough to be part of a valid
+         * session but has not generated keys. */
+        if (ks->state >= S_INITIAL && ks->state < S_GENERATED_KEYS)
+        {
+            msg(D_MULTI_DROPPED,
+                "Key %s [%d] not initialized (yet), dropping packet.",
+                source, key_id);
+            gc_free(&gc);
+            return;
+        }
+        if (ks->state >= S_ACTIVE && ks->authenticated != KS_AUTH_TRUE)
+        {
+            msg(D_MULTI_DROPPED,
+                "Key %s [%d] not authorized%s, dropping packet.",
+                source, key_id,
+                (ks->authenticated == KS_AUTH_DEFERRED) ? " (deferred)" : "");
+            gc_free(&gc);
+            return;
+        }
+    }
+
+    msg(D_TLS_ERRORS,
+        "TLS Error: local/remote TLS keys are out of sync: %s "
+        "(received key id: %d, known key ids: %s)",
+        source, key_id,
+        print_key_id(multi, &gc));
+    gc_free(&gc);
+}
+
+/**
+ * Check the keyid of the an incoming data channel packet and
+ * return the matching crypto parameters in \c opt if found.
+ * Also move the \c buf to the start of the encrypted data, skipping
+ * the opcode and peer id header and setting also set \c ad_start for
+ * AEAD ciphers to the start of the authenticated data.
+ */
 static inline void
 handle_data_channel_packet(struct tls_multi *multi,
                            const struct link_socket_actual *from,
@@ -3229,7 +3280,6 @@  handle_data_channel_packet(struct tls_multi *multi,
     int op = c >> P_OPCODE_SHIFT;
     int key_id = c & P_KEY_ID_MASK;
 
-    /* data channel packet */
     for (int i = 0; i < KEY_SCAN_SIZE; ++i)
     {
         struct key_state *ks = get_key_scan(multi, i);
@@ -3251,14 +3301,7 @@  handle_data_channel_packet(struct tls_multi *multi,
             && ks->authenticated == KS_AUTH_TRUE
             && (floated || link_socket_actual_match(from, &ks->remote_addr)))
         {
-            if (!ks->crypto_options.key_ctx_bi.initialized)
-            {
-                msg(D_MULTI_DROPPED,
-                    "Key %s [%d] not initialized (yet), dropping packet.",
-                    print_link_socket_actual(from, &gc), key_id);
-                goto done;
-            }
-
+            ASSERT(ks->crypto_options.key_ctx_bi.initialized);
             /* return appropriate data channel decrypt key in opt */
             *opt = &ks->crypto_options;
             if (op == P_DATA_V2)
@@ -3292,17 +3335,13 @@  handle_data_channel_packet(struct tls_multi *multi,
         }
     }
 
-    msg(D_TLS_ERRORS,
-        "TLS Error: local/remote TLS keys are out of sync: %s "
-        "(received key id: %d, known key ids: %s)",
-        print_link_socket_actual(from, &gc), key_id,
-        print_key_id(multi, &gc));
+    print_key_id_not_found_reason(multi, from, key_id);
 
 done:
+    gc_free(&gc);
     tls_clear_error();
     buf->len = 0;
     *opt = NULL;
-    gc_free(&gc);
 }
 
 /*