From patchwork Fri Jan 13 23:57:54 2023 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Selva Nair X-Patchwork-Id: 3001 Return-Path: Delivered-To: patchwork@openvpn.net Received: by 2002:a05:7300:c95:b0:82:e4b3:40a0 with SMTP id p21csp10454dyk; Fri, 13 Jan 2023 15:58:39 -0800 (PST) X-Google-Smtp-Source: AMrXdXvfnBkcQMYv/uGD3ywGP1SXxBLGPKnjhdWDchiTN9RpbgaEs264Am618e1iw8QHLh9JiUEk X-Received: by 2002:a05:6a20:2d1f:b0:ac:9d6b:c1f0 with SMTP id g31-20020a056a202d1f00b000ac9d6bc1f0mr104565270pzl.40.1673654318851; Fri, 13 Jan 2023 15:58:38 -0800 (PST) ARC-Seal: i=1; a=rsa-sha256; t=1673654318; cv=none; d=google.com; s=arc-20160816; b=L5TZcdA9FgGVp6JkpYhOchtmtCxJ23J1ysvBTQ5TjyWAUbNoR9JRyK4Cc957Uzj4v2 tmB8aP+raTasbNxohGmZ6Ws8Na4HePkEeC0LYeJDRlNF4q6zihShG4HyMkGaF2ke1atS xntC3S6u/7paB6b8PMBBdhWrNdHZHqtxUiN1n9YoAB89C5mIifx5h7pH9x3Fh36VCWid DylMQfT/8+laH3saXF/7mJ7jqK1UpOAAWyNlbImR1aO7QMIRP6t9eTS6g0MXgCIZfokr 1i/KplsV0UMzcfIoG1/wJQiVWUG2OSadZKgSW8atmjmSxMFXo+B0YI4c7ue83pDqGM+i fjMw== 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:dkim-signature; bh=ZILmuxdCl1YNvKtG+c798BpCR2a3rM3rRCjrjvHHxT8=; b=FDKbnfqlsv5A2I9WyjN7Koz/vdKt/BFt1KTWMV1cLMXjfHY+CpfZ1Ogb6UrD+/aBJL qvqqozWFcf+KjAYE8T6bHwjcEOHYrPOwcZLoANiqmNOeZQcMlJs2ajDxl7i2FYsbUk4m X0NqPpFjhDqafzQFy75riBTMyajirbuWAoxzOEmhT6NZYqY+fXJcPfzDrW+jlH0lvvXM Oh1C5cqZbxoxAZNnewNLbjwt8vKWExPVvnTR8sZAORUWv4rEiCc1hqu5TUp/0tciI5f2 Srl+DOjj2sZ2adsCrdedmNm/TVcqILEqFE4X33qx+dX0vQonyNOQ9oPW5TZ4CfKX7umz Y1kg== ARC-Authentication-Results: i=1; mx.google.com; dkim=neutral (body hash did not verify) header.i=@sourceforge.net header.s=x header.b=GwKxN0Eb; dkim=neutral (body hash did not verify) header.i=@sf.net header.s=x header.b=TxNLIb+P; dkim=neutral (body hash did not verify) header.i=@gmail.com header.s=20210112 header.b="dOOF7JM/"; 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; dmarc=fail (p=NONE sp=QUARANTINE dis=NONE) header.from=gmail.com Received: from lists.sourceforge.net (lists.sourceforge.net. [216.105.38.7]) by mx.google.com with ESMTPS id v3-20020a056a00148300b00575428b9ea7si22583497pfu.204.2023.01.13.15.58.38 (version=TLS1_2 cipher=ECDHE-ECDSA-AES128-GCM-SHA256 bits=128/128); Fri, 13 Jan 2023 15:58:38 -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=GwKxN0Eb; dkim=neutral (body hash did not verify) header.i=@sf.net header.s=x header.b=TxNLIb+P; dkim=neutral (body hash did not verify) header.i=@gmail.com header.s=20210112 header.b="dOOF7JM/"; 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; dmarc=fail (p=NONE sp=QUARANTINE dis=NONE) header.from=gmail.com Received: from [127.0.0.1] (helo=sfs-ml-4.v29.lw.sourceforge.com) by sfs-ml-4.v29.lw.sourceforge.com with esmtp (Exim 4.95) (envelope-from ) id 1pGTw4-000355-4B; Fri, 13 Jan 2023 23:58:10 +0000 Received: from [172.30.20.202] (helo=mx.sourceforge.net) by sfs-ml-4.v29.lw.sourceforge.com with esmtps (TLS1.2) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.95) (envelope-from ) id 1pGTw2-00034y-UV for openvpn-devel@lists.sourceforge.net; Fri, 13 Jan 2023 23:58:09 +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:Cc:To:From:Sender:Reply-To: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=xRicL78XXZ+4hAwYK+JKM0ibPwREkMcLG6+149LyBy4=; b=GwKxN0EbL2qC774WyfwSWGFJj3 QEFl9eiKgPDrY55ClN39VqZWuHxday8Iz5K1Z2ZJCTj7K2FRKmnaCHcrxzSX4CrEXiFgMC3of0aG5 tCSEHYsJJUOmR/GUNpy3k01zpVlUqI3in49M7BPVhLC6BZDcc9Pqa+AnuFJLrjqjy4Zg=; 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:Cc:To:From:Sender:Reply-To: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=xRicL78XXZ+4hAwYK+JKM0ibPwREkMcLG6+149LyBy4=; b=TxNLIb+PlsGxnR1YzDzibPufDI OPUpNS13tQA/9T1jgmTRlsmZIfOAmJLt2Pypr2rI6KPRHU0GFPjbYJ8RqSL6zxIpYtfm8VIHqPGaO 6wnjK/R+huDKHMufJm/Ya1Ij8Borf1lhy26PytYg9t6l81PQYvftvekhc7Gl9d5KteLI=; Received: from mail-io1-f52.google.com ([209.85.166.52]) by sfi-mx-2.v28.lw.sourceforge.com with esmtps (TLS1.2:ECDHE-RSA-AES128-GCM-SHA256:128) (Exim 4.95) id 1pGTw0-0000UC-Kw for openvpn-devel@lists.sourceforge.net; Fri, 13 Jan 2023 23:58:09 +0000 Received: by mail-io1-f52.google.com with SMTP id d22so2374039iof.5 for ; Fri, 13 Jan 2023 15:58:08 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; h=content-transfer-encoding:mime-version:references:in-reply-to :message-id:date:subject:cc:to:from:from:to:cc:subject:date :message-id:reply-to; bh=xRicL78XXZ+4hAwYK+JKM0ibPwREkMcLG6+149LyBy4=; b=dOOF7JM/uQge9+e+RhvXKH0j8Z6pfpyyHrcR9Wz8AvLtl+snhwickADYtpdVvk43M8 6mgkIe+RFG9M9TX3327juDjHXKgrPfO9Onb/TRyJD5p4m2Ni6K6Om1hll/EPzlx1i5ms scEHuCDcUcG+MrwIKSI7DK0y9Etqqi4jRwlPHSZW4+lcww/gYTLZv4b+vKYY80SALDtU zYVZrg6jvVwOS8hKGoJkBdfQVOXuDlbOMmGrqBseF6sS8sfXvlZYQqbC98Jl7b8VT4UG atrzCxrUapH6brxtFyrYXhy5dXHD6KOkTw9Vmy1QyWD7zdE0AfAmTfemKnDGJKn/CQL/ AKnw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=content-transfer-encoding:mime-version:references:in-reply-to :message-id:date:subject:cc:to:from:x-gm-message-state:from:to:cc :subject:date:message-id:reply-to; bh=xRicL78XXZ+4hAwYK+JKM0ibPwREkMcLG6+149LyBy4=; b=tBMpfxpJs0Rz1672D9Vl/71tOzALU6v7B2VFDNZwHnACXQAZ4OzT7EDvLvGaT+Rxwv OjnyCh570cM+ntk2MKB2lcPD2PpROX2xHYGzWF7SvLG4yG1LrS9T1OjJv+hx+CkzN6jg e/59DbSu4+ozzgaH9nsT5q9Bmc5YNPGBiniJYwf+0ZU9GWMAz7PaaQ4wRqhxHufCA+Pp wgDOS30BQZ7C7QFr3SYDDlvLQqnK4CczivyZQ/dnCh8eOCz6vSxTTRyRgb0n0AkEDl6s l1840pWQgiRZuuJd/YcmlRdNTVmRn8r7brtdJsntRPshO+kzpVzJ2tzYRY8uAjNSOb8N bFew== X-Gm-Message-State: AFqh2krQnonfUkeO6I2UpXJkMwl4xKvwx1lYcJd5AAW+VdYH8IQugLdi TvclIOLM63DQK3pBtNyLYyYoY6ywUPE= X-Received: by 2002:a5d:990e:0:b0:6df:128f:ca12 with SMTP id x14-20020a5d990e000000b006df128fca12mr10329771iol.1.1673654279541; Fri, 13 Jan 2023 15:57:59 -0800 (PST) Received: from uranus.sansel.ca (bras-vprn-tnhlon4053w-lp130-01-70-51-222-66.dsl.bell.ca. [70.51.222.66]) by smtp.gmail.com with ESMTPSA id x12-20020a026f0c000000b0039e60720706sm6493680jab.25.2023.01.13.15.57.58 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Fri, 13 Jan 2023 15:57:59 -0800 (PST) From: selva.nair@gmail.com To: openvpn-devel@lists.sourceforge.net Date: Fri, 13 Jan 2023 18:57:54 -0500 Message-Id: <20230113235754.1942385-2-selva.nair@gmail.com> X-Mailer: git-send-email 2.34.1 In-Reply-To: <20230113235754.1942385-1-selva.nair@gmail.com> References: <20230113235754.1942385-1-selva.nair@gmail.com> MIME-Version: 1.0 X-Spam-Score: -0.2 (/) X-Spam-Report: Spam detection software, running on the system "util-spamd-2.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: From: Selva Nair Use a unified logging format for various route-methods - Route add/delete errors are always logged with M_WARN, so log only additional information (succeed/exists) with D_ROUTE. Content analysis details: (-0.2 points, 6.0 required) pts rule name description ---- ---------------------- -------------------------------------------------- -0.0 SPF_PASS SPF: sender matches SPF record 0.0 FREEMAIL_FROM Sender email is commonly abused enduser mail provider [selva.nair[at]gmail.com] 0.0 SPF_HELO_NONE SPF: HELO does not publish an SPF Record -0.0 RCVD_IN_MSPIKE_H2 RBL: Average reputation (+2) [209.85.166.52 listed in wl.mailspike.net] -0.0 RCVD_IN_DNSWL_NONE RBL: Sender listed at https://www.dnswl.org/, no trust [209.85.166.52 listed in list.dnswl.org] 0.1 DKIM_SIGNED Message has a DKIM or DK signature, not necessarily valid -0.1 DKIM_VALID_AU Message has a valid DKIM or DK signature from author's domain -0.1 DKIM_VALID Message has at least one valid DKIM or DK signature -0.1 DKIM_VALID_EF Message has a valid DKIM or DK signature from envelope-from domain X-Headers-End: 1pGTw0-0000UC-Kw Subject: [Openvpn-devel] [PATCH 2/2] Cleanup route error and debug logging on Windows 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?1754953750852330719?= X-GMAIL-MSGID: =?utf-8?q?1754953750852330719?= From: Selva Nair Use a unified logging format for various route-methods - Route add/delete errors are always logged with M_WARN, so log only additional information (succeed/exists) with D_ROUTE. - Non-windows platforms log route errors with a prefix "ERROR:" and debug info with "ROUTE:". Do the same on Windows. Do not log errors or success multiple times. - In add_route_ipv6, log the interface id instead of device name as the latter always point to the tun/tap adapter name on Windows. Log lines prefixed with a PACKAGE_NAME "ROUTE" are unchanged. They appear to use the same format on all platforms. Signed-off-by: Selva Nair --- src/openvpn/route.c | 63 +++++++++++++++++++++++++++++++++------------ 1 file changed, 46 insertions(+), 17 deletions(-) diff --git a/src/openvpn/route.c b/src/openvpn/route.c index fe5cda2a..8117c648 100644 --- a/src/openvpn/route.c +++ b/src/openvpn/route.c @@ -1640,38 +1640,45 @@ add_route(struct route_ipv4 *r, argv_msg(D_ROUTE, &argv); + const char *method = "service"; if ((flags & ROUTE_METHOD_MASK) == ROUTE_METHOD_SERVICE) { status = add_route_service(r, tt); - msg(D_ROUTE, "Route addition via service %s", (status == RTA_SUCCESS) ? "succeeded" : "failed"); } else if ((flags & ROUTE_METHOD_MASK) == ROUTE_METHOD_IPAPI) { status = add_route_ipapi(r, tt, ai); - msg(D_ROUTE, "Route addition via IPAPI %s", (status == RTA_SUCCESS) ? "succeeded" : "failed"); + method = "ipapi"; } else if ((flags & ROUTE_METHOD_MASK) == ROUTE_METHOD_EXE) { netcmd_semaphore_lock(); status = openvpn_execve_check(&argv, es, 0, "ERROR: Windows route add command failed"); netcmd_semaphore_release(); + method = "route.exe"; } else if ((flags & ROUTE_METHOD_MASK) == ROUTE_METHOD_ADAPTIVE) { status = add_route_ipapi(r, tt, ai); - msg(D_ROUTE, "Route addition via IPAPI %s [adaptive]", (status == RTA_SUCCESS) ? "succeeded" : "failed"); + method = "ipapi [adaptive]"; if (status == RTA_ERROR) { msg(D_ROUTE, "Route addition fallback to route.exe"); netcmd_semaphore_lock(); status = openvpn_execve_check(&argv, es, 0, "ERROR: Windows route add command failed [adaptive]"); netcmd_semaphore_release(); + method = "route.exe"; } } else { ASSERT(0); } + if (status != RTA_ERROR) /* error is logged upstream */ + { + msg(D_ROUTE, "Route addition via %s %s", method, (status == RTA_SUCCESS) ? + "succeeded" : "failed because route exists"); + } } #elif defined (TARGET_SOLARIS) @@ -1867,7 +1874,6 @@ add_route_ipv6(struct route_ipv6 *r6, const struct tuntap *tt, openvpn_net_ctx_t *ctx) { int status = 0; - const char *device = tt->actual_name; bool gateway_needed = false; if (!(r6->flags & RT_DEFINED) ) @@ -1879,6 +1885,7 @@ add_route_ipv6(struct route_ipv6 *r6, const struct tuntap *tt, struct gc_arena gc = gc_new(); #ifndef _WIN32 + const char *device = tt->actual_name; if (r6->iface != NULL) /* vpn server special route */ { device = r6->iface; @@ -1911,8 +1918,14 @@ add_route_ipv6(struct route_ipv6 *r6, const struct tuntap *tt, } #endif +#ifndef _WIN32 msg( M_INFO, "add_route_ipv6(%s/%d -> %s metric %d) dev %s", network, r6->netbits, gateway, r6->metric, device ); +#else + msg( M_INFO, "add_route_ipv6(%s/%d -> %s metric %d) IF %lu", + network, r6->netbits, gateway, r6->metric, + r6->adapter_index ? r6->adapter_index : tt->adapter_index); +#endif /* * Filter out routes which are essentially no-ops @@ -2851,14 +2864,16 @@ add_route_ipapi(const struct route_ipv4 *r, const struct tuntap *tt, DWORD adapt doublebreak: if (status != NO_ERROR) { - msg(M_WARN, "ROUTE: route addition failed using CreateIpForwardEntry: %s [status=%u if_index=%u]", - strerror_win32(status, &gc), - (unsigned int)status, - (unsigned int)if_index); if (status == ERROR_OBJECT_ALREADY_EXISTS) { ret = RTA_EEXIST; } + else + { + msg(M_WARN, "ERROR: route addition failed using CreateIpForwardEntry: " + "%s [status=%u if_index=%u]", strerror_win32(status, &gc), + (unsigned int)status, (unsigned int)if_index); + } } } } @@ -2894,7 +2909,7 @@ del_route_ipapi(const struct route_ipv4 *r, const struct tuntap *tt) } else { - msg(M_WARN, "ROUTE: route deletion failed using DeleteIpForwardEntry: %s", + msg(M_WARN, "ERROR: route deletion failed using DeleteIpForwardEntry: %s", strerror_win32(status, &gc)); } } @@ -2918,10 +2933,13 @@ do_route_service(const bool add, const route_message_t *rt, const size_t size, H if (ack.error_number != NO_ERROR) { - msg(M_WARN, "ROUTE: route %s failed using service: %s [status=%u if_index=%d]", - (add ? "addition" : "deletion"), strerror_win32(ack.error_number, &gc), - ack.error_number, rt->iface.index); ret = (ack.error_number == ERROR_OBJECT_ALREADY_EXISTS) ? RTA_EEXIST : RTA_ERROR; + if (ret == RTA_ERROR) + { + msg(M_WARN, "ERROR: route %s failed using service: %s [status=%u if_index=%d]", + (add ? "addition" : "deletion"), strerror_win32(ack.error_number, &gc), + ack.error_number, rt->iface.index); + } goto out; } @@ -3022,9 +3040,17 @@ route_ipv6_ipapi(const bool add, const struct route_ipv6 *r, const struct tuntap out: if (err != NO_ERROR) { - msg(M_WARN, "ROUTE: route %s failed using ipapi: %s [status=%lu if_index=%lu]", - (add ? "addition" : "deletion"), strerror_win32(err, &gc), err, fwd_row->InterfaceIndex); ret = (err == ERROR_OBJECT_ALREADY_EXISTS) ? RTA_EEXIST : RTA_ERROR; + if (ret == RTA_ERROR) + { + msg(M_WARN, "ERROR: route %s failed using ipapi: %s [status=%lu if_index=%lu]", + (add ? "addition" : "deletion"), strerror_win32(err, &gc), err, + fwd_row->InterfaceIndex); + } + else if (add) + { + msg(D_ROUTE, "IPv6 route addition using ipapi failed because route exists"); + } } else { @@ -3076,9 +3102,12 @@ do_route_ipv6_service(const bool add, const struct route_ipv6 *r, const struct t } status = do_route_service(add, &msg, sizeof(msg), tt->options.msg_channel); - msg(D_ROUTE, "IPv6 route %s via service %s", - add ? "addition" : "deletion", - (status == RTA_SUCCESS) ? "succeeded" : "failed"); + if (status != RTA_ERROR) + { + msg(D_ROUTE, "IPv6 route %s via service %s", + add ? "addition" : "deletion", + (status == RTA_SUCCESS) ? "succeeded" : "failed because route exists"); + } return status; }