Cleanup route error and debug logging on Windows

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 <selva.nair@gmail.com>
Acked-by: Lev Stipakov <lstipakov@gmail.com>
Message-Id: <20230120094100.2063883-1-selva.nair@gmail.com>
URL: https://www.mail-archive.com/openvpn-devel@lists.sourceforge.net/msg26058.html
Signed-off-by: Gert Doering <gert@greenie.muc.de>

diff --git a/src/openvpn/route.c b/src/openvpn/route.c
index f1257b0050b833cf637bf527274df8e35de9e5b9..82519c94ba89f484850acbdb283c6847abb61232 100644 (file)
--- a/src/openvpn/route.c
+++ b/src/openvpn/route.c
@@ -1647,17 +1647,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)
         {
@@ -1666,12 +1664,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");
@@ -1680,12 +1678,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)
@@ -1887,7 +1891,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) )
@@ -1899,6 +1902,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;
@@ -1931,8 +1935,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
@@ -2883,14 +2893,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);
+                }
             }
         }
     }
@@ -2926,7 +2938,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));
         }
     }
@@ -2950,10 +2962,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;
     }
 
@@ -3054,9 +3069,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
     {
@@ -3108,9 +3131,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;
 }