From patchwork Fri Jan 20 09:41:00 2023 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Selva Nair X-Patchwork-Id: 3009 Return-Path: Delivered-To: patchwork@openvpn.net Received: by 2002:a05:7300:c95:b0:82:e4b3:40a0 with SMTP id p21csp1198432dyk; Fri, 20 Jan 2023 01:41:57 -0800 (PST) X-Google-Smtp-Source: AMrXdXs4BrP3/NhkOZeEajMmekj01mxAdTNympzldT6b4Q9yMMl1+8ZiWeOrrAf5r1/Vodmd9oUy X-Received: by 2002:a05:6a20:4f9a:b0:b8:6cc8:673c with SMTP id gh26-20020a056a204f9a00b000b86cc8673cmr19748219pzb.10.1674207717410; Fri, 20 Jan 2023 01:41:57 -0800 (PST) ARC-Seal: i=1; a=rsa-sha256; t=1674207717; cv=none; d=google.com; s=arc-20160816; b=II2Bq6qlzDyEEjzjcuGSercc9rxRxCx4P4+I3yucU8jyQu4LR2K30ynltoPcilEO8e 6nsHmCZBalOmC5yor5UYwuhuAPs1LEuLMEPpe6vjstpiiwfTvqOP7yzZCf5zjm54p/Rd f6gAdZ80jtPzZD7XdTsKyumiJ2MyfQYSAOVwHX7l0T6lAgRL7GG9RWcZ3lwDakTU/MrA TVfr8U49s4WlmAn1lHVM/YykNGFob71USl345YmUmTQJ1W6ed84bsO8fRHPANXElvRUf DCAxAKp4ENh2kNOdkgPanpBykfIqx78qE03JisJ9FiestciFEjCh5Kt9HI/m/yZDK6rt 3gNw== 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=7AstHFffmK0JVB7H43f9/2O8Ns8ayXx53fBDM9/jzxo=; b=dlcSbwdpWCfCbFgKwZueEPuS3y4Qet0KDr8B9BbTA55orsPpJNPh7RGz74n7/vOQVn /MYz/MqoBWBaaMw4ELml5dpUYq6ltEYzrXVYj6S6P/ANtkDy0EqTGoCKg7BnQxwqLG36 sS3vSHBvhWf+csLrEre+8WmIAH44cqxjGLaGlgV38gPI6QY2BZTZlUp5ovZwFRYiBnV6 xmUYO8/EQnt8t+8IGB0oEyaaGjz2fS8RcL6e9Fk6Ghr/aB6RzPoXtvyeWqTAo4UlsV/x A81uC5vTtaWc2IOPLBI411YuQexsBVcLPkma7yGxoFy8yYIe2sqXw9FzmIBvco2uwmzo L6sQ== ARC-Authentication-Results: i=1; mx.google.com; dkim=neutral (body hash did not verify) header.i=@sourceforge.net header.s=x header.b=a4FzNyzU; dkim=neutral (body hash did not verify) header.i=@sf.net header.s=x header.b=mVfB9zHn; dkim=neutral (body hash did not verify) header.i=@gmail.com header.s=20210112 header.b=GWEc8TO+; 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 j62-20020a62c541000000b0058e1e6dc44fsi170336pfg.349.2023.01.20.01.41.56 (version=TLS1_2 cipher=ECDHE-ECDSA-AES128-GCM-SHA256 bits=128/128); Fri, 20 Jan 2023 01:41:57 -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=a4FzNyzU; dkim=neutral (body hash did not verify) header.i=@sf.net header.s=x header.b=mVfB9zHn; dkim=neutral (body hash did not verify) header.i=@gmail.com header.s=20210112 header.b=GWEc8TO+; 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 1pInts-0007rM-SO; Fri, 20 Jan 2023 09:41:31 +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 1pInts-0007rG-Cc for openvpn-devel@lists.sourceforge.net; Fri, 20 Jan 2023 09:41:30 +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=J0bn3Zeb2ZzNGTDNM3xx0z3y0DK7CzzrEB9mHN0MYww=; b=a4FzNyzUujauvnjwi+1cwuAu4U KWC+OwnSV2j8p1PwRrnzvlrUNwrNlyzCL9D0VIJvE8qpC7IKOQSlyc6UWYovWhzDkkeNM4db87hXw 6XIfejS6/qxVJ4i8H2FINXelG8IHlaxTyWxmkVGZuroYP4WO4CZh9O5CBZdtZ9WZUd2A=; 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=J0bn3Zeb2ZzNGTDNM3xx0z3y0DK7CzzrEB9mHN0MYww=; b=mVfB9zHnDQGRJTAFG+IY+gPMn7 eQ7ue+OhWkIAh54pEE8rEPX3iT8NhUoWpxgscOydyikgSrShvNI/iR4b79EyfKKkiTv2IbpGWRD0I 6Xb99GGThhtnoDyKMqwkca10jkSA8+F7dU/zItl+Q8C/5sw99x3Ck1jOgiweUmSM8dyY=; Received: from mail-il1-f178.google.com ([209.85.166.178]) by sfi-mx-2.v28.lw.sourceforge.com with esmtps (TLS1.2:ECDHE-RSA-AES128-GCM-SHA256:128) (Exim 4.95) id 1pIntq-0006ab-48 for openvpn-devel@lists.sourceforge.net; Fri, 20 Jan 2023 09:41:30 +0000 Received: by mail-il1-f178.google.com with SMTP id m15so2474722ilq.2 for ; Fri, 20 Jan 2023 01:41:30 -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=J0bn3Zeb2ZzNGTDNM3xx0z3y0DK7CzzrEB9mHN0MYww=; b=GWEc8TO+TLXXBJ7mmn4f4ZRrmL0vk6JlDtbuvIAaIsfKcc/jvy1x38NgpcTFL0Rw4C /UIjeBPo1gtn1pzmXRplvu3B+8Z6+smKp1xZbfnVvkNv8Ps3gsNWTFPR+gk6woDz8Yax lX25uX5Fn0+0bGcUMa0aVg4FRoG+fVDFeOcfKgkTF9zFC4v1XK8yoSVbUuhqWfNLVviu 7M32X/FyQOjsR92RxssFsjAK9wDE0q5rDzfLJ+tP77hxrdr1zcQRak+8rZ/wkoedjRxX V1eaS+S1rt3un3wjTAlk6Pbz2+KKJMHYQSR2l2Hup6/q0luMk1xg5majdNto1Se1xCRj P9WA== 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=J0bn3Zeb2ZzNGTDNM3xx0z3y0DK7CzzrEB9mHN0MYww=; b=ChQtSYeyIi4xsA1BaRKLykqjqXkFnJ/sN+0tI/1JQsWpHN20li5A/I9KqHTwjtgnBo pioV37wzieDdTkRHW1hOJA+Giwaf//819TJlAgRqiMxCh1Ng7uMK6WksUybQ/NjLu6AZ 1Fhvr+sKfuaick4VPFbXd4Qa6p6R16BkExKplRY+X0j9kbE+vRkefm4dOehq/aOBAe3c 8SHooOyulrarrQcs0fr4BkudtrgHcqrNnZOqM+zVA6OEDp/eIY8pG87xO8i98sxCVqOw PBqERsAITqMj7IkWhaFZzUsPV2xWDrCzRWdNBvnHJMfxgkzBqBvCpil67PUSXoo8Qzc5 1+NA== X-Gm-Message-State: AFqh2kpWg7gnsq9dASjxf3MmO92ZU1cBvt2Ui/x1jp2o1/5YUVHoxCtu Ye5ibJ6NOcuFy/YdVTEyjjnB9CWqs4E= X-Received: by 2002:a92:d841:0:b0:30e:ed5c:8c87 with SMTP id h1-20020a92d841000000b0030eed5c8c87mr1842580ilq.3.1674207684259; Fri, 20 Jan 2023 01:41:24 -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 a4-20020a92ce44000000b0030ef2eedef5sm5040804ilr.69.2023.01.20.01.41.23 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Fri, 20 Jan 2023 01:41:24 -0800 (PST) From: selva.nair@gmail.com To: openvpn-devel@lists.sourceforge.net Date: Fri, 20 Jan 2023 04:41:00 -0500 Message-Id: <20230120094100.2063883-1-selva.nair@gmail.com> X-Mailer: git-send-email 2.34.1 In-Reply-To: <20230113235754.1942385-2-selva.nair@gmail.com> References: <20230113235754.1942385-2-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-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: 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 RCVD_IN_DNSWL_NONE RBL: Sender listed at https://www.dnswl.org/, no trust [209.85.166.178 listed in list.dnswl.org] 0.0 SPF_HELO_NONE SPF: HELO does not publish an SPF Record 0.0 FREEMAIL_FROM Sender email is commonly abused enduser mail provider [selva.nair[at]gmail.com] -0.0 RCVD_IN_MSPIKE_H2 RBL: Average reputation (+2) [209.85.166.178 listed in wl.mailspike.net] -0.1 DKIM_VALID_AU Message has a valid DKIM or DK signature from author's domain -0.1 DKIM_VALID_EF Message has a valid DKIM or DK signature from envelope-from domain -0.1 DKIM_VALID Message has at least one valid DKIM or DK signature 0.1 DKIM_SIGNED Message has a DKIM or DK signature, not necessarily valid X-Headers-End: 1pIntq-0006ab-48 Subject: [Openvpn-devel] [PATCH v2 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?1755534031813829792?= 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. v2: rebase to master Signed-off-by: Selva Nair Acked-by: Lev Stipakov --- src/openvpn/route.c | 66 +++++++++++++++++++++++++++++++-------------- 1 file changed, 46 insertions(+), 20 deletions(-) diff --git a/src/openvpn/route.c b/src/openvpn/route.c index 61a40ff1..8f54eb50 100644 --- a/src/openvpn/route.c +++ b/src/openvpn/route.c @@ -1641,17 +1641,15 @@ 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) { @@ -1660,12 +1658,12 @@ add_route(struct route_ipv4 *r, "ERROR: Windows route add command failed"); status = ret ? RTA_SUCCESS : RTA_ERROR; 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"); @@ -1674,12 +1672,18 @@ add_route(struct route_ipv4 *r, "ERROR: Windows route add command failed [adaptive]"); status = ret ? RTA_SUCCESS : RTA_ERROR; 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) @@ -1881,7 +1885,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) ) @@ -1893,6 +1896,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; @@ -1925,8 +1929,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 @@ -2871,14 +2881,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); + } } } } @@ -2914,7 +2926,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)); } } @@ -2938,10 +2950,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; } @@ -3042,9 +3057,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 { @@ -3096,9 +3119,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; }