networkd: use structured logging for links and bridges

4 files changed, 143 insertions, 75 deletions

diff --git a/TODO b/TODO
index eec1eb91c6..8d2f1a0962 100644
--- a/TODO
+++ b/TODO
@@ -32,6 +32,8 @@ External:
 
 Features:
 
+* machinectl bash completion is missing
+
 * Introduce PrivateDevices=yes/no which works like PrivateTmp= but for /dev setting up a tmpfs for it that only includes /dev/null, /dev/zero, /dev/random, /dev/urandom, but nothing else.
 
 * libsystemd-journal returns the object created as first param in sd_journal_new(), sd_bus_new() and suchlike as last...
diff --git a/src/network/networkd-bridge.c b/src/network/networkd-bridge.c
index 1b05bf1caa..d644bd5f55 100644
--- a/src/network/networkd-bridge.c
+++ b/src/network/networkd-bridge.c
@@ -86,21 +86,25 @@ static int bridge_join_ready(Bridge *bridge, Link* link, sd_rtnl_message_handler
 
         r = sd_rtnl_message_link_new(RTM_SETLINK, link->ifindex, &req);
         if (r < 0) {
-                log_error("Could not allocate RTM_SETLINK message: %s",
-                          strerror(-r));
+                log_error_bridge(bridge,
+                                 "Could not allocate RTM_SETLINK message: %s",
+                                 strerror(-r));
                 return r;
         }
 
         r = sd_rtnl_message_append_u32(req, IFLA_MASTER, bridge->link->ifindex);
         if (r < 0) {
-                log_error("Could not append IFLA_MASTER attribute: %s",
-                          strerror(-r));
+                log_error_bridge(bridge,
+                                 "Could not append IFLA_MASTER attribute: %s",
+                                 strerror(-r));
                 return r;
         }
 
         r = sd_rtnl_call_async(bridge->manager->rtnl, req, callback, link, 0, NULL);
         if (r < 0) {
-                log_error("Could not send rtnetlink message: %s", strerror(-r));
+                log_error_bridge(bridge,
+                                 "Could not send rtnetlink message: %s",
+                                 strerror(-r));
                 return r;
         }
 
@@ -112,7 +116,7 @@ static int bridge_enter_ready(Bridge *bridge) {
 
         bridge->state = BRIDGE_STATE_READY;
 
-        log_info("%s: bridge ready", bridge->name);
+        log_bridge_info(bridge, "bridge ready");
 
         LIST_FOREACH(callbacks, callback, bridge->callbacks) {
                 /* join the links that were attempted to be joined befor the
@@ -131,7 +135,7 @@ static int bridge_create_handler(sd_rtnl *rtnl, sd_rtnl_message *m, void *userda
 
         r = sd_rtnl_message_get_errno(m);
         if (r < 0) {
-                log_warning("%s: bridge failed: %s", bridge->name, strerror(-r));
+                log_warning_bridge(bridge, "bridge failed: %s", strerror(-r));
                 bridge_enter_failed(bridge);
 
                 return 1;
@@ -157,46 +161,52 @@ static int bridge_create(Bridge *bridge) {
 
         r = sd_rtnl_message_link_new(RTM_NEWLINK, 0, &req);
         if (r < 0) {
-                log_error("Could not allocate RTM_NEWLINK message: %s",
-                          strerror(-r));
+                log_error_bridge(bridge,
+                                 "Could not allocate RTM_NEWLINK message: %s",
+                                 strerror(-r));
                 return r;
         }
 
         r = sd_rtnl_message_append_string(req, IFLA_IFNAME, bridge->name);
         if (r < 0) {
-                log_error("Could not append IFLA_IFNAME attribute: %s",
-                          strerror(-r));
+                log_error_bridge(bridge,
+                                 "Could not append IFLA_IFNAME attribute: %s",
+                                 strerror(-r));
                 return r;
         }
 
         r = sd_rtnl_message_open_container(req, IFLA_LINKINFO);
         if (r < 0) {
-                log_error("Colud not open IFLA_LINKINFO container: %s",
-                          strerror(-r));
+                log_error_bridge(bridge,
+                                 "Could not open IFLA_LINKINFO container: %s",
+                                 strerror(-r));
                 return r;
         }
 
         r = sd_rtnl_message_append_string(req, IFLA_INFO_KIND, "bridge");
         if (r < 0) {
-                log_error("Could not append IFLA_INFO_KIND attribute: %s",
-                          strerror(-r));
+                log_error_bridge(bridge,
+                                 "Could not append IFLA_INFO_KIND attribute: %s",
+                                 strerror(-r));
                 return r;
         }
 
         r = sd_rtnl_message_close_container(req);
         if (r < 0) {
-                log_error("Could not close IFLA_LINKINFO container %s",
-                          strerror(-r));
+                log_error_bridge(bridge,
+                                 "Could not close IFLA_LINKINFO container %s",
+                                 strerror(-r));
                 return r;
         }
 
         r = sd_rtnl_call_async(bridge->manager->rtnl, req, &bridge_create_handler, bridge, 0, NULL);
         if (r < 0) {
-                log_error("Could not send rtnetlink message: %s", strerror(-r));
+                log_error_bridge(bridge,
+                                 "Could not send rtnetlink message: %s", strerror(-r));
                 return r;
         }
 
-        log_debug("%s: creating bridge", bridge->name);
+        log_bridge_debug(bridge, "creating bridge");
 
         bridge->state = BRIDGE_STATE_CREATING;
 
diff --git a/src/network/networkd-link.c b/src/network/networkd-link.c
index bc8ca21c82..2ed5e6b63f 100644
--- a/src/network/networkd-link.c
+++ b/src/network/networkd-link.c
@@ -134,7 +134,7 @@ static int link_enter_configured(Link *link) {
         assert(link);
         assert(link->state == LINK_STATE_SETTING_ROUTES);
 
-        log_info("%s: link configured", link->ifname);
+        log_link_info(link, "link configured");
 
         link->state = LINK_STATE_CONFIGURED;
 
@@ -144,7 +144,7 @@ static int link_enter_configured(Link *link) {
 static void link_enter_failed(Link *link) {
         assert(link);
 
-        log_warning("%s: failed", link->ifname);
+        log_link_warning(link, "failed");
 
         link->state = LINK_STATE_FAILED;
 }
@@ -165,13 +165,12 @@ static int route_handler(sd_rtnl *rtnl, sd_rtnl_message *m, void *userdata) {
 
         r = sd_rtnl_message_get_errno(m);
         if (r < 0 && r != -EEXIST)
-                log_warning("%s: could not set route: %s",
-                            link->ifname, strerror(-r));
+                log_warning_link(link, "could not set route: %s", strerror(-r));
 
         /* we might have received an old reply after moving back to SETTING_ADDRESSES,
          * ignore it */
         if (link->route_messages == 0 && link->state == LINK_STATE_SETTING_ROUTES) {
-                log_debug("%s: routes set", link->ifname);
+                log_link_debug(link, "routes set");
                 link_enter_configured(link);
         }
 
@@ -191,12 +190,13 @@ static int link_enter_set_routes(Link *link) {
         if (!link->network->static_routes && !link->dhcp_route)
                 return link_enter_configured(link);
 
-        log_debug("%s: setting routes", link->ifname);
+        log_link_debug(link, "setting routes");
 
         LIST_FOREACH(static_routes, route, link->network->static_routes) {
                 r = route_configure(route, link, &route_handler);
                 if (r < 0) {
-                        log_warning("%s: could not set routes", link->ifname);
+                        log_warning_link(link,
+                                         "could not set routes: %s", strerror(-r));
                         link_enter_failed(link);
                         return r;
                 }
@@ -207,7 +207,8 @@ static int link_enter_set_routes(Link *link) {
         if (link->dhcp_route) {
                 r = route_configure(link->dhcp_route, link, &route_handler);
                 if (r < 0) {
-                        log_warning("%s: could not set routes", link->ifname);
+                        log_warning_link(link,
+                                         "could not set routes: %s", strerror(-r));
                         link_enter_failed(link);
                         return r;
                 }
@@ -235,11 +236,14 @@ static int address_handler(sd_rtnl *rtnl, sd_rtnl_message *m, void *userdata) {
 
         r = sd_rtnl_message_get_errno(m);
         if (r < 0 && r != -EEXIST)
-                log_warning("%s: could not set address: %s",
-                            link->ifname, strerror(-r));
+                log_struct_link(LOG_ERR, link,
+                                "MESSAGE=%s: could not set address: %s",
+                                link->ifname, strerror(-r),
+                                "ERRNO=%d", -r,
+                                NULL);
 
         if (link->addr_messages == 0) {
-                log_debug("%s: addresses set", link->ifname);
+                log_link_debug(link, "addresses set");
                 link_enter_set_routes(link);
         }
 
@@ -259,12 +263,13 @@ static int link_enter_set_addresses(Link *link) {
         if (!link->network->static_addresses && !link->dhcp_address)
                 return link_enter_set_routes(link);
 
-        log_debug("%s: setting addresses", link->ifname);
+        log_link_debug(link, "setting addresses");
 
         LIST_FOREACH(static_addresses, address, link->network->static_addresses) {
                 r = address_configure(address, link, &address_handler);
                 if (r < 0) {
-                        log_warning("%s: could not set addresses", link->ifname);
+                        log_warning_link(link,
+                                         "could not set addresses: %s", strerror(-r));
                         link_enter_failed(link);
                         return r;
                 }
@@ -275,7 +280,8 @@ static int link_enter_set_addresses(Link *link) {
         if (link->dhcp_address) {
                 r = address_configure(link->dhcp_address, link, &address_handler);
                 if (r < 0) {
-                        log_warning("%s: could not set addresses", link->ifname);
+                        log_warning_link(link,
+                                         "could not set addresses: %s", strerror(-r));
                         link_enter_failed(link);
                         return r;
                 }
@@ -299,8 +305,7 @@ static int address_drop_handler(sd_rtnl *rtnl, sd_rtnl_message *m, void *userdat
 
         r = sd_rtnl_message_get_errno(m);
         if (r < 0 && r != -EEXIST)
-                log_warning("%s: could not drop address: %s",
-                            link->ifname, strerror(-r));
+                log_warning_link(link, "could not drop address: %s", strerror(-r));
 
         return 1;
 }
@@ -319,13 +324,13 @@ static void dhcp_handler(sd_dhcp_client *client, int event, void *userdata) {
                 return;
 
         if (event < 0) {
-                log_warning("%s: DHCP error: %s", link->ifname, strerror(-event));
+                log_warning_link(link, "DHCP error: %s", strerror(-event));
                 link_enter_failed(link);
                 return;
         }
 
         if (event == DHCP_EVENT_NO_LEASE)
-                log_debug("%s: IP address in use.", link->ifname);
+                log_link_debug(link, "IP address in use.");
 
         if (event == DHCP_EVENT_IP_CHANGE || event == DHCP_EVENT_EXPIRED ||
             event == DHCP_EVENT_STOP) {
@@ -344,28 +349,28 @@ static void dhcp_handler(sd_dhcp_client *client, int event, void *userdata) {
 
         r = sd_dhcp_client_get_address(client, &address);
         if (r < 0) {
-                log_warning("%s: DHCP error: no address", link->ifname);
+                log_link_warning(link, "DHCP error: no address");
                 link_enter_failed(link);
                 return;
         }
 
         r = sd_dhcp_client_get_netmask(client, &netmask);
         if (r < 0) {
-                log_warning("%s: DHCP error: no netmask", link->ifname);
+                log_link_warning(link, "DHCP error: no netmask");
                 link_enter_failed(link);
                 return;
         }
 
         prefixlen = sd_dhcp_client_prefixlen(&netmask);
         if (prefixlen < 0) {
-                log_warning("%s: DHCP error: no prefixlen", link->ifname);
+                log_link_warning(link, "DHCP error: no prefixlen");
                 link_enter_failed(link);
                 return;
         }
 
         r = sd_dhcp_client_get_router(client, &gateway);
         if (r < 0) {
-                log_warning("%s: DHCP error: no router", link->ifname);
+                log_link_warning(link, "DHCP error: no router");
                 link_enter_failed(link);
                 return;
         }
@@ -374,11 +379,11 @@ static void dhcp_handler(sd_dhcp_client *client, int event, void *userdata) {
                 _cleanup_address_free_ Address *addr = NULL;
                 _cleanup_route_free_ Route *rt = NULL;
 
-                log_info("%s: received config over DHCPv4", link->ifname);
+                log_link_info(link, "received config over DHCPv4");
 
                 r = address_new_dynamic(&addr);
                 if (r < 0) {
-                        log_error("Could not allocate address");
+                        log_link_error(link, "Could not allocate address");
                         link_enter_failed(link);
                         return;
                 }
@@ -390,7 +395,7 @@ static void dhcp_handler(sd_dhcp_client *client, int event, void *userdata) {
 
                 r = route_new_dynamic(&rt);
                 if (r < 0) {
-                        log_error("Could not allocate route");
+                        log_link_error(link, "Could not allocate route");
                         link_enter_failed(link);
                         return;
                 }
@@ -453,20 +458,17 @@ static int link_update_flags(Link *link, unsigned flags) {
                 return 0;
 
         if (link->flags == flags) {
-                log_debug("%s: link status unchanged: %#x", link->ifname, flags);
+                log_debug_link(link, "link status unchanged: %#x", flags);
                 return 0;
         }
 
-        if ((link->flags & IFF_UP) != (flags & IFF_UP)) {
-                if (flags & IFF_UP)
-                        log_info("%s: power on", link->ifname);
-                else
-                        log_info("%s: power off", link->ifname);
-        }
+        if ((link->flags & IFF_UP) != (flags & IFF_UP))
+                log_info_link(link,
+                              "power %s", flags & IFF_UP ? "on": "off");
 
         if ((link->flags & IFF_LOWER_UP) != (flags & IFF_LOWER_UP)) {
                 if (flags & IFF_LOWER_UP) {
-                        log_info("%s: carrier on", link->ifname);
+                        log_link_info(link, "carrier on");
 
                         if (link->network->dhcp) {
                                 r = link_acquire_conf(link);
@@ -476,7 +478,7 @@ static int link_update_flags(Link *link, unsigned flags) {
                                 }
                         }
                 } else {
-                        log_info("%s: carrier off", link->ifname);
+                        log_link_info(link, "carrier off");
 
                         if (link->network->dhcp) {
                                 r = sd_dhcp_client_stop(link->dhcp);
@@ -488,7 +490,8 @@ static int link_update_flags(Link *link, unsigned flags) {
                 }
         }
 
-        log_debug("%s: link status updated: %#x -> %#x", link->ifname, link->flags, flags);
+        log_debug_link(link,
+                       "link status updated: %#x -> %#x", link->flags, flags);
 
         link->flags = flags;
 
@@ -506,8 +509,8 @@ static int link_up_handler(sd_rtnl *rtnl, sd_rtnl_message *m, void *userdata) {
 
         r = sd_rtnl_message_get_errno(m);
         if (r < 0) {
-                log_warning("%s: could not bring up interface: %s",
-                            link->ifname, strerror(-r));
+                log_warning_link(link,
+                                 "could not bring up interface: %s", strerror(-r));
                 link_enter_failed(link);
         }
 
@@ -524,23 +527,24 @@ static int link_up(Link *link) {
         assert(link->manager);
         assert(link->manager->rtnl);
 
-        log_debug("%s: bringing up link", link->ifname);
+        log_link_debug(link, "bringing link up");
 
         r = sd_rtnl_message_link_new(RTM_SETLINK, link->ifindex, &req);
         if (r < 0) {
-                log_error("Could not allocate RTM_SETLINK message");
+                log_link_error(link, "Could not allocate RTM_SETLINK message");
                 return r;
         }
 
         r = sd_rtnl_message_link_set_flags(req, IFF_UP);
         if (r < 0) {
-                log_error("Could not set link flags");
+                log_error_link(link, "Could not set link flags: %s", strerror(-r));
                 return r;
         }
 
         r = sd_rtnl_call_async(link->manager->rtnl, req, link_up_handler, link, 0, NULL);
         if (r < 0) {
-                log_error("Could not send rtnetlink message: %s", strerror(-r));
+                log_error_link(link,
+                               "Could not send rtnetlink message: %s", strerror(-r));
                 return r;
         }
 
@@ -579,14 +583,20 @@ static int bridge_handler(sd_rtnl *rtnl, sd_rtnl_message *m, void *userdata) {
 
         r = sd_rtnl_message_get_errno(m);
         if (r < 0) {
-                log_warning("%s: could not join bridge '%s': %s",
-                            link->ifname, link->network->bridge->name, strerror(-r));
+                log_struct_link(LOG_ERR, link,
+                                "MESSAGE=%s: could not join bridge '%s': %s",
+                                link->ifname, link->network->bridge->name, strerror(-r),
+                                BRIDGE(link->network->bridge),
+                                NULL);
                 link_enter_failed(link);
                 return 1;
-        } else
-                log_debug("%s: joined bridge '%s'",
-                            link->ifname, link->network->bridge->name);
+        }
 
+        log_struct_link(LOG_DEBUG, link,
+                        "MESSAGE=%s: joined bridge '%s'",
+                        link->network->bridge->name,
+                        BRIDGE(link->network->bridge),
+                        NULL);
         link_bridge_joined(link);
 
         return 1;
@@ -604,12 +614,20 @@ static int link_enter_join_bridge(Link *link) {
         if (!link->network->bridge)
                 return link_bridge_joined(link);
 
-        log_debug("%s: joining bridge", link->ifname);
+        log_struct_link(LOG_DEBUG, link,
+                        "MESSAGE=%s: joining bridge '%s'",
+                        link->network->bridge->name,
+                        BRIDGE(link->network->bridge),
+                        NULL);
+        log_link_debug(link, "joining bridge");
 
         r = bridge_join(link->network->bridge, link, &bridge_handler);
         if (r < 0) {
-                log_warning("%s: could not join bridge '%s'", link->ifname,
-                            link->network->bridge->name);
+                log_struct_link(LOG_WARNING, link,
+                                "MESSAGE=%s: could not join bridge '%s': %s",
+                                link->network->bridge->name, strerror(-r),
+                                BRIDGE(link->network->bridge),
+                                NULL);
                 link_enter_failed(link);
                 return r;
         }
@@ -628,12 +646,11 @@ static int link_get_handler(sd_rtnl *rtnl, sd_rtnl_message *m, void *userdata) {
 
         r = sd_rtnl_message_get_errno(m);
         if (r < 0) {
-                log_warning("%s: could not get state: %s",
-                            link->ifname, strerror(-r));
+                log_warning_link(link, "could not get state: %s", strerror(-r));
                 link_enter_failed(link);
         }
 
-        log_debug("%s: got link state", link->ifname);
+        log_link_debug(link, "got link state");
 
         link_update(link, m);
 
@@ -648,17 +665,18 @@ static int link_get(Link *link) {
         assert(link->manager);
         assert(link->manager->rtnl);
 
-        log_debug("%s: requesting link status", link->ifname);
+        log_link_debug(link, "requesting link status");
 
         r = sd_rtnl_message_link_new(RTM_GETLINK, link->ifindex, &req);
         if (r < 0) {
-                log_error("Could not allocate RTM_GETLINK message");
+                log_link_error(link, "Could not allocate RTM_GETLINK message");
                 return r;
         }
 
         r = sd_rtnl_call_async(link->manager->rtnl, req, link_get_handler, link, 0, NULL);
         if (r < 0) {
-                log_error("Could not send rtnetlink message: %s", strerror(-r));
+                log_error_link(link,
+                               "Could not send rtnetlink message: %s", strerror(-r));
                 return r;
         }
 
@@ -693,7 +711,7 @@ int link_update(Link *link, sd_rtnl_message *m) {
 
         r = sd_rtnl_message_link_get_flags(m, &flags);
         if (r < 0) {
-                log_warning("%s: could not get link flags", link->ifname);
+                log_link_warning(link, "could not get link flags");
                 return r;
         }
 
diff --git a/src/network/networkd.h b/src/network/networkd.h
index bfa01a94f0..9be9330c99 100644
--- a/src/network/networkd.h
+++ b/src/network/networkd.h
@@ -278,3 +278,41 @@ int link_update(Link *link, sd_rtnl_message *message);
 
 DEFINE_TRIVIAL_CLEANUP_FUNC(Link*, link_free);
 #define _cleanup_link_free_ _cleanup_(link_freep)
+
+/* Macros which append INTERFACE= to the message */
+
+#define log_full_link(level, link, fmt, ...) log_meta_object(level, __FILE__, __LINE__, __func__, "INTERFACE=", link->ifname, "%s: " fmt, link->ifname, __VA_ARGS__)
+#define log_debug_link(link, ...)       log_full_link(LOG_DEBUG, link, __VA_ARGS__)
+#define log_info_link(link, ...)        log_full_link(LOG_INFO, link, __VA_ARGS__)
+#define log_notice_link(link, ...)      log_full_link(LOG_NOTICE, link, __VA_ARGS__)
+#define log_warning_link(link, ...)     log_full_link(LOG_WARNING, link, __VA_ARGS__)
+#define log_error_link(link, ...)       log_full_link(LOG_ERR, link, __VA_ARGS__)
+
+#define log_link_full(level, link, message) log_meta_object(level, __FILE__, __LINE__, __func__, "INTERFACE=", link->ifname, "%s: " message, link->ifname)
+#define log_link_debug(link, ...)       log_link_full(LOG_DEBUG, link, __VA_ARGS__)
+#define log_link_info(link, ...)        log_link_full(LOG_INFO, link, __VA_ARGS__)
+#define log_link_notice(link, ...)      log_link_full(LOG_NOTICE, link, __VA_ARGS__)
+#define log_link_warning(link, ...)     log_link_full(LOG_WARNING, link, __VA_ARGS__)
+#define log_link_error(link, ...)       log_link_full(LOG_ERR, link, __VA_ARGS__)
+
+#define log_struct_link(level, link, ...) log_struct(level, "INTERFACE=%s", link->ifname, __VA_ARGS__)
+
+/* More macros which append INTERFACE= to the message */
+
+#define log_full_bridge(level, bridge, fmt, ...) log_meta_object(level, __FILE__, __LINE__, __func__, "INTERFACE=", bridge->name, "%s: " fmt, bridge->name, __VA_ARGS__)
+#define log_debug_bridge(bridge, ...)       log_full_bridge(LOG_DEBUG, bridge, __VA_ARGS__)
+#define log_info_bridge(bridge, ...)        log_full_bridge(LOG_INFO, bridge, __VA_ARGS__)
+#define log_notice_bridge(bridge, ...)      log_full_bridge(LOG_NOTICE, bridge, __VA_ARGS__)
+#define log_warning_bridge(bridge, ...)     log_full_bridge(LOG_WARNING, bridge, __VA_ARGS__)
+#define log_error_bridge(bridge, ...)       log_full_bridge(LOG_ERR, bridge, __VA_ARGS__)
+
+#define log_bridge_full(level, bridge, message) log_meta_object(level, __FILE__, __LINE__, __func__, "INTERFACE=", bridge->name, "%s: " message, bridge->name)
+#define log_bridge_debug(bridge, ...)       log_bridge_full(LOG_DEBUG, bridge, __VA_ARGS__)
+#define log_bridge_info(bridge, ...)        log_bridge_full(LOG_INFO, bridge, __VA_ARGS__)
+#define log_bridge_notice(bridge, ...)      log_bridge_full(LOG_NOTICE, bridge, __VA_ARGS__)
+#define log_bridge_warning(bridge, ...)     log_bridge_full(LOG_WARNING, bridge, __VA_ARGS__)
+#define log_bridge_error(bridge, ...)       log_bridge_full(LOG_ERR, bridge, __VA_ARGS__)
+
+#define log_struct_bridge(level, bridge, ...) log_struct(level, "INTERFACE=%s", bridge->name, __VA_ARGS__)
+
+#define BRIDGE(bridge) "INTERFACE=%s", bridge->name