From patchwork Fri Feb 10 14:27:11 2023 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Arne Schwabe X-Patchwork-Id: 3077 Return-Path: Delivered-To: patchwork@openvpn.net Received: by 2002:a05:7300:c95:b0:82:e4b3:40a0 with SMTP id p21csp1313034dyk; Fri, 10 Feb 2023 06:28:21 -0800 (PST) X-Google-Smtp-Source: AK7set/tXXw16LNHJIXrNTSePbUoLBdcY7EGVu3l/NlpUjEqBS0JuHhv+y9NxpfxvSv1Xackmwnd X-Received: by 2002:a17:902:da8b:b0:199:bd4:9fbb with SMTP id j11-20020a170902da8b00b001990bd49fbbmr17874097plx.43.1676039301072; Fri, 10 Feb 2023 06:28:21 -0800 (PST) ARC-Seal: i=1; a=rsa-sha256; t=1676039301; cv=none; d=google.com; s=arc-20160816; b=e9Ap1ZLU6E1+YBemzX498Em7jvAVHr29hfimkS3MPLE+2hMm4LapgzGDmU4Zi3Igyy o5DiBzyHYqP3HpJAvYQdhwY71bnt8xgrEU18epHwGdqTpt5SnSxbiedRHxV3fnFKZDyx vAcZqmMfpr2pZPMG9gWqrN9r6niG9YW1H2g/4WAK0rWIkDUdBy32wTQnOR4j7szEjg0O +Dgzbkl6JC6wZoYGCHYuwipPnW25omKKu/tRQMe+q3WiR5E5ou4Ii8pRxC8ssQXvbx/v k3J2P3uDO6Fn+C0co0ymFggKOaao8aXWcOkuJEKreMRPptRIHpRSZRdNLxsRYKTKVB4u vyzg== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=errors-to:content-transfer-encoding:list-subscribe:list-help :list-post:list-archive:list-unsubscribe:list-id:precedence:subject :mime-version:references:in-reply-to:message-id:date:to:from :dkim-signature:dkim-signature; bh=lGYOGQlsvNFCIoK5e0Ah77qVkY64eCvH0d3PDyQIIVU=; b=L9vIPwNyeSmqzTfBSJwwTAm8K/CnytWVy1czk8kS5at/yndraBEuf9xEPeFrfM2hhY xtpiU+BDq8KDIR8eMEcDrEKfVdLwvhWbgINYc6Ic2qfMHzmD+EcYVEuCS6Qw+tApar34 PBQJsNyiWYkQBMzJX1Rnnm4cP24pFvEknRxzrEMsRI+uX7tQIEKhRYLGOE7ZpdN/w/N2 afHMPA7ATdR/HPrf99YkWq8orV94uiyKNtl86VPa7QMK+RSH0uNl2UVrXffLqz3D3a2Q JRjowCpCdAsKa5cC5DCLDoXmwqnUjhnYAuyLr181s+V1Cd2rJBw2casJESc3nHwIU4Un BW3A== ARC-Authentication-Results: i=1; mx.google.com; dkim=neutral (body hash did not verify) header.i=@sourceforge.net header.s=x header.b="ICq/k+Ma"; dkim=neutral (body hash did not verify) header.i=@sf.net header.s=x header.b="T+Zul//r"; spf=pass (google.com: domain of openvpn-devel-bounces@lists.sourceforge.net designates 216.105.38.7 as permitted sender) smtp.mailfrom=openvpn-devel-bounces@lists.sourceforge.net Received: from lists.sourceforge.net (lists.sourceforge.net. [216.105.38.7]) by mx.google.com with ESMTPS id u15-20020a17090341cf00b00193f8c6a020si5179535ple.111.2023.02.10.06.28.20 (version=TLS1_2 cipher=ECDHE-ECDSA-AES128-GCM-SHA256 bits=128/128); Fri, 10 Feb 2023 06:28:21 -0800 (PST) Received-SPF: pass (google.com: domain of openvpn-devel-bounces@lists.sourceforge.net designates 216.105.38.7 as permitted sender) client-ip=216.105.38.7; Authentication-Results: mx.google.com; dkim=neutral (body hash did not verify) header.i=@sourceforge.net header.s=x header.b="ICq/k+Ma"; dkim=neutral (body hash did not verify) header.i=@sf.net header.s=x header.b="T+Zul//r"; spf=pass (google.com: domain of openvpn-devel-bounces@lists.sourceforge.net designates 216.105.38.7 as permitted sender) smtp.mailfrom=openvpn-devel-bounces@lists.sourceforge.net Received: from [127.0.0.1] (helo=sfs-ml-1.v29.lw.sourceforge.com) by sfs-ml-1.v29.lw.sourceforge.com with esmtp (Exim 4.95) (envelope-from ) id 1pQUND-0006zs-Ie; Fri, 10 Feb 2023 14:27:34 +0000 Received: from [172.30.20.202] (helo=mx.sourceforge.net) by sfs-ml-1.v29.lw.sourceforge.com with esmtps (TLS1.2) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.95) (envelope-from ) id 1pQUN7-0006yS-1C for openvpn-devel@lists.sourceforge.net; Fri, 10 Feb 2023 14:27:28 +0000 DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=sourceforge.net; s=x; h=Content-Transfer-Encoding:MIME-Version:References: In-Reply-To:Message-Id:Date:Subject:To:From:Sender:Reply-To:Cc:Content-Type: Content-ID:Content-Description:Resent-Date:Resent-From:Resent-Sender: Resent-To:Resent-Cc:Resent-Message-ID:List-Id:List-Help:List-Unsubscribe: List-Subscribe:List-Post:List-Owner:List-Archive; bh=HK+7fRBTFtRMPIm4SW5nJ4yh1ByF1eJ8IHI0rQaDHno=; b=ICq/k+Mabg1JpYEHBPCPtm5N4T YRBqxCebRrLdR6Da7xjJDLMRhpjhSS8zt6/WN2ERh87BKu5BDtoBIa/ZZTs07pxW04rieV8Krfzmx MVxkIYxzlc2+TlEl62wJIMuEp7w6aN+Q1cGx2j7Zrozd2VMHHqlg1gxTtdQwidvKS9E4=; DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=sf.net; s=x ; h=Content-Transfer-Encoding:MIME-Version:References:In-Reply-To:Message-Id: Date:Subject:To:From:Sender:Reply-To:Cc:Content-Type:Content-ID: Content-Description:Resent-Date:Resent-From:Resent-Sender:Resent-To:Resent-Cc :Resent-Message-ID:List-Id:List-Help:List-Unsubscribe:List-Subscribe: List-Post:List-Owner:List-Archive; bh=HK+7fRBTFtRMPIm4SW5nJ4yh1ByF1eJ8IHI0rQaDHno=; b=T+Zul//rKs1gmCHIXbOXEIdgLT zDlBvQUyd/+PGUHGw3wg4uFCaoGT7SGMbilGkkITwyz6ukQQKXjO+Ud/Snbp3swrg2IJ1VKSGpwYm wFyKf1SZNrB5/ubPYz4JHntlkuFXtn3/BNk0ucxT05c+eH36yQVBxwv++AsG3sV7FlvU=; Received: from mail.blinkt.de ([192.26.174.232]) by sfi-mx-2.v28.lw.sourceforge.com with esmtps (TLS1.2:ECDHE-RSA-AES256-GCM-SHA384:256) (Exim 4.95) id 1pQUN1-0007Ei-8g for openvpn-devel@lists.sourceforge.net; Fri, 10 Feb 2023 14:27:28 +0000 Received: from kamera.blinkt.de ([2001:638:502:390:20c:29ff:fec8:535c]) by mail.blinkt.de with smtp (Exim 4.95 (FreeBSD)) (envelope-from ) id 1pQUMq-00051i-8s for openvpn-devel@lists.sourceforge.net; Fri, 10 Feb 2023 15:27:12 +0100 Received: (nullmailer pid 572368 invoked by uid 10006); Fri, 10 Feb 2023 14:27:12 -0000 From: Arne Schwabe To: openvpn-devel@lists.sourceforge.net Date: Fri, 10 Feb 2023 15:27:11 +0100 Message-Id: <20230210142712.572303-8-arne@rfc2549.org> X-Mailer: git-send-email 2.25.1 In-Reply-To: <20230210142712.572303-1-arne@rfc2549.org> References: <20230210142712.572303-1-arne@rfc2549.org> MIME-Version: 1.0 X-Spam-Score: 0.3 (/) X-Spam-Report: Spam detection software, running on the system "util-spamd-1.v13.lw.sourceforge.com", has NOT identified this incoming email as spam. The original message has been attached to this so you can view it or label similar future email. If you have any questions, see the administrator of that system for details. Content preview: The messages about cipher initialisation are currently very noisy, especially if tls-auth/tls-crypt is in use. Typically messages like this is display for AES-256-CBC with SHA256: Outgoing Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key Outgoing Data Channel: Using 256 bit message hash 'SHA256' for HMAC authentication Incoming Data Channel: Cipher 'AES-256-CBC' [...] Content analysis details: (0.3 points, 6.0 required) pts rule name description ---- ---------------------- -------------------------------------------------- 0.2 HEADER_FROM_DIFFERENT_DOMAINS From and EnvelopeFrom 2nd level mail domains are different 0.0 SPF_HELO_NONE SPF: HELO does not publish an SPF Record 0.0 SPF_NONE SPF: sender does not publish an SPF Record X-Headers-End: 1pQUN1-0007Ei-8g Subject: [Openvpn-devel] [PATCH 4/4] Reduce initialisation spam from verb <= 3 and print summary instead X-BeenThere: openvpn-devel@lists.sourceforge.net X-Mailman-Version: 2.1.21 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: openvpn-devel-bounces@lists.sourceforge.net X-getmail-retrieved-from-mailbox: Inbox X-GMAIL-THRID: =?utf-8?q?1757454586076387716?= X-GMAIL-MSGID: =?utf-8?q?1757454586076387716?= The messages about cipher initialisation are currently very noisy, especially if tls-auth/tls-crypt is in use. Typically messages like this is display for AES-256-CBC with SHA256: Outgoing Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key Outgoing Data Channel: Using 256 bit message hash 'SHA256' for HMAC authentication Incoming Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key Incoming Data Channel: Using 256 bit message hash 'SHA256' for HMAC authentication in addition to the tls-crypt/tls-auth messages that has the amount of messages. These message are not that helpful. The only meaningful information is better suited in compat messages. This commit moves the spammy messages to verb 4 and consistently prints out the cipher/auth used in the data channel instead on verb 2: Data Channel: cipher 'AES-256-CBC' auth 'SHA256' This patches also summarises other aspects of the imported options for VPN connection and prints them (even if not coming from pulled options): Data Channel: cipher 'AES-256-GCM' Timers: ping 8, ping-restart 40 Protocol options: explicit-exit-notify 1, protocol-flags tls-ekm And move the OPTIONS IMPORT: xx modified that are included in the new messages to D_PUSH_DEBUG (verb 7) since they do not add any useful information anymore. Signed-off-by: Arne Schwabe --- src/openvpn/crypto.c | 4 +- src/openvpn/errlevel.h | 1 + src/openvpn/init.c | 143 +++++++++++++++++++++++++++++++++++++++-- src/openvpn/occ.h | 16 +++++ src/openvpn/sig.c | 15 ----- src/openvpn/ssl.c | 5 -- src/openvpn/ssl_ncp.c | 2 +- 7 files changed, 159 insertions(+), 27 deletions(-) diff --git a/src/openvpn/crypto.c b/src/openvpn/crypto.c index 073f47e47..5e1c495b0 100644 --- a/src/openvpn/crypto.c +++ b/src/openvpn/crypto.c @@ -835,7 +835,7 @@ init_key_ctx(struct key_ctx *ctx, const struct key *key, cipher_ctx_init(ctx->cipher, key->cipher, kt->cipher, enc); const char *ciphername = cipher_kt_name(kt->cipher); - msg(D_HANDSHAKE, "%s: Cipher '%s' initialized with %d bit key", + msg(D_CIPHER_INIT, "%s: Cipher '%s' initialized with %d bit key", prefix, ciphername, cipher_kt_key_size(kt->cipher) * 8); dmsg(D_SHOW_KEYS, "%s: CIPHER KEY: %s", prefix, @@ -850,7 +850,7 @@ init_key_ctx(struct key_ctx *ctx, const struct key *key, ctx->hmac = hmac_ctx_new(); hmac_ctx_init(ctx->hmac, key->hmac, kt->digest); - msg(D_HANDSHAKE, + msg(D_CIPHER_INIT, "%s: Using %d bit message hash '%s' for HMAC authentication", prefix, md_kt_size(kt->digest) * 8, md_kt_name(kt->digest)); diff --git a/src/openvpn/errlevel.h b/src/openvpn/errlevel.h index c69ea91d6..4699d1ac2 100644 --- a/src/openvpn/errlevel.h +++ b/src/openvpn/errlevel.h @@ -105,6 +105,7 @@ #define D_MTU_INFO LOGLEV(4, 61, 0) /* show terse MTU info */ #define D_PID_DEBUG_LOW LOGLEV(4, 63, 0) /* show low-freq packet-id debugging info */ #define D_PID_DEBUG_MEDIUM LOGLEV(4, 64, 0) /* show medium-freq packet-id debugging info */ +#define D_CIPHER_INIT LOGLEV(4, 65, 0) /* show messages about cipher init */ #define D_LOG_RW LOGLEV(5, 0, 0) /* Print 'R' or 'W' to stdout for read/write */ diff --git a/src/openvpn/init.c b/src/openvpn/init.c index b500d3543..66daa7760 100644 --- a/src/openvpn/init.c +++ b/src/openvpn/init.c @@ -2209,6 +2209,139 @@ p2p_set_dco_keepalive(struct context *c) } return true; } + +/** + * Helper function for tls_print_deferred_options_results + * Adds the ", " delimitor if there already some data in the + * buffer. + */ +static void +add_delim_if_non_empty(struct buffer *buf, const char *header) +{ + if (buf_len(buf) > strlen(header)) + { + buf_printf(buf, ", "); + } +} + + +/** + * Prints the results of options imported for the data channel + * @param o + */ +static void +tls_print_deferred_options_results(struct context *c) +{ + struct options *o = &c->options; + + struct buffer out; + uint8_t line[1024] = { 0 }; + buf_set_write(&out, line, sizeof(line)); + + + if (cipher_kt_mode_aead(o->ciphername)) + { + buf_printf(&out, "Data Channel: cipher '%s'", + cipher_kt_name(o->ciphername)); + } + else + { + buf_printf(&out, "Data Channel: cipher '%s', auth '%s'", + cipher_kt_name(o->ciphername), md_kt_name(o->authname)); + } + + if (o->use_peer_id) + { + buf_printf(&out, ", peer-id: %d", o->peer_id); + } + + if (c->c2.comp_context) + { + buf_printf(&out, ", compression: '%s'", c->c2.comp_context->alg.name); + } + + msg(D_HANDSHAKE, "%s", BSTR(&out)); + + buf_clear(&out); + + const char *header = "Timers: "; + + buf_printf(&out, "%s", header); + + if (o->ping_send_timeout) + { + buf_printf(&out, "ping %d", o->ping_send_timeout); + } + + if (o->ping_rec_timeout_action != PING_UNDEF) + { + /* yes unidirectional ping is possible .... */ + add_delim_if_non_empty(&out, header); + + if (o->ping_rec_timeout_action == PING_EXIT) + { + buf_printf(&out, "ping-exit %d", o->ping_rec_timeout); + } + else + { + buf_printf(&out, "ping-restart %d", o->ping_rec_timeout); + } + } + + if (o->inactivity_timeout) + { + add_delim_if_non_empty(&out, header); + + buf_printf(&out, "inactive %d", o->inactivity_timeout); + if (o->inactivity_minimum_bytes) + { + buf_printf(&out, " %" PRIu64, o->inactivity_minimum_bytes); + } + } + + if (o->session_timeout) + { + add_delim_if_non_empty(&out, header); + buf_printf(&out, "session-timeout %d", o->session_timeout); + } + + if (buf_len(&out) > strlen(header)) + { + msg(D_HANDSHAKE, "%s", BSTR(&out)); + } + + buf_clear(&out); + header = "Protocol options: "; + buf_printf(&out, "%s", header); + + if (c->options.ce.explicit_exit_notification) + { + buf_printf(&out, "explicit-exit-notify %d", + c->options.ce.explicit_exit_notification); + } + if (c->options.imported_protocol_flags) + { + add_delim_if_non_empty(&out, header); + + buf_printf(&out, "protocol-flags"); + + if (o->imported_protocol_flags & CO_USE_CC_EXIT_NOTIFY) + { + buf_printf(&out, " cc-exit"); + } + if (o->imported_protocol_flags & CO_USE_TLS_KEY_MATERIAL_EXPORT) + { + buf_printf(&out, " tls-ekm"); + } + } + + if (buf_len(&out) > strlen(header)) + { + msg(D_HANDSHAKE, "%s", BSTR(&out)); + } +} + + /** * This function is expected to be invoked after open_tun() was performed. * @@ -2370,6 +2503,8 @@ do_up(struct context *c, bool pulled_options, unsigned int option_types_found) initialization_sequence_completed(c, error_flags); /* client/p2p restart with --persist-tun */ } + tls_print_deferred_options_results(c); + c->c2.do_up_ran = true; if (c->c2.tls_multi) { @@ -2470,7 +2605,7 @@ do_deferred_options(struct context *c, const unsigned int found) if (found & OPT_P_TIMER) { do_init_timers(c, true); - msg(D_PUSH, "OPTIONS IMPORT: timers and/or timeouts modified"); + msg(D_PUSH_DEBUG, "OPTIONS IMPORT: timers and/or timeouts modified"); } if (found & OPT_P_EXPLICIT_NOTIFY) @@ -2482,14 +2617,14 @@ do_deferred_options(struct context *c, const unsigned int found) } else { - msg(D_PUSH, "OPTIONS IMPORT: explicit notify parm(s) modified"); + msg(D_PUSH_DEBUG, "OPTIONS IMPORT: explicit notify parm(s) modified"); } } #ifdef USE_COMP if (found & OPT_P_COMP) { - msg(D_PUSH, "OPTIONS IMPORT: compression parms modified"); + msg(D_PUSH_DEBUG, "OPTIONS IMPORT: compression parms modified"); comp_uninit(c->c2.comp_context); c->c2.comp_context = comp_init(&c->options.comp); } @@ -2540,7 +2675,7 @@ do_deferred_options(struct context *c, const unsigned int found) if (found & OPT_P_PEER_ID) { - msg(D_PUSH, "OPTIONS IMPORT: peer-id set"); + msg(D_PUSH_DEBUG, "OPTIONS IMPORT: peer-id set"); c->c2.tls_multi->use_peer_id = true; c->c2.tls_multi->peer_id = c->options.peer_id; } diff --git a/src/openvpn/occ.h b/src/openvpn/occ.h index 4320bd119..e382482f6 100644 --- a/src/openvpn/occ.h +++ b/src/openvpn/occ.h @@ -153,4 +153,20 @@ check_send_occ_msg(struct context *c) } } +/** + * Small helper function to determine if we should send the exit notification + * via control channel. + * @return control channel exit message should be used */ +static inline bool +cc_exit_notify_enabled(struct context *c) +{ + /* Check if we have TLS active at all */ + if (!c->c2.tls_multi) + { + return false; + } + + const struct key_state *ks = get_primary_key(c->c2.tls_multi); + return (ks->crypto_options.flags & CO_USE_CC_EXIT_NOTIFY); +} #endif /* ifndef OCC_H */ diff --git a/src/openvpn/sig.c b/src/openvpn/sig.c index 0d5346010..5b89bb42b 100644 --- a/src/openvpn/sig.c +++ b/src/openvpn/sig.c @@ -342,21 +342,6 @@ print_status(const struct context *c, struct status_output *so) } -/* Small helper function to determine if we should send the exit notification - * via control channel */ -static inline bool -cc_exit_notify_enabled(struct context *c) -{ - /* Check if we have TLS active at all */ - if (!c->c2.tls_multi) - { - return false; - } - - const struct key_state *ks = get_primary_key(c->c2.tls_multi); - return (ks->crypto_options.flags & CO_USE_CC_EXIT_NOTIFY); -} - /* * Handle the triggering and time-wait of explicit * exit notification. diff --git a/src/openvpn/ssl.c b/src/openvpn/ssl.c index 016bdc57f..47f3702b2 100644 --- a/src/openvpn/ssl.c +++ b/src/openvpn/ssl.c @@ -1730,11 +1730,6 @@ tls_session_update_crypto_params_do_work(struct tls_multi *multi, return true; } - if (strcmp(options->ciphername, session->opt->config_ciphername)) - { - msg(D_HANDSHAKE, "Data Channel: using negotiated cipher '%s'", - options->ciphername); - } init_key_type(&session->opt->key_type, options->ciphername, options->authname, true, true); diff --git a/src/openvpn/ssl_ncp.c b/src/openvpn/ssl_ncp.c index fe6f6fa7c..97619be5e 100644 --- a/src/openvpn/ssl_ncp.c +++ b/src/openvpn/ssl_ncp.c @@ -318,7 +318,7 @@ check_pull_client_ncp(struct context *c, const int found) { if (found & OPT_P_NCP) { - msg(D_PUSH, "OPTIONS IMPORT: data channel crypto options modified"); + msg(D_PUSH_DEBUG, "OPTIONS IMPORT: data channel crypto options modified"); return true; }