Merge pull request #17928 from keszybz/nss-logging

Enable logging in nss modules
Add Pull Request Labeler
2025-09-26 07:14:45 +02:00 · 2020-12-14 09:48:23 +09:00 · 2020-12-14 09:43:38 +09:00 · 2020-12-10 20:52:03 +01:00 · 2020-12-10 20:51:59 +01:00 · 2020-12-10 20:50:01 +01:00
7 changed files with 129 additions and 27 deletions
--- a/.github/labeler.yml
+++ b/.github/labeler.yml
@ -0,0 +1,29 @@
+hwdb:
+  - hwdb.d/**/*
+units:
+  - units/**/*
+documentation:
+  - NEWS
+  - man/*
+  - docs/*
+network:
+  - src/libsystemd-network/**/*
+  - src/network/**/*
+udev:
+  - src/udev/**/*
+  - src/libudev/*
+selinux:
+  - '**/*selinux*'
+apparmor:
+  - '**/*apparmor*'
+meson:
+  - '**/meson.build'
+  - meson_option.txt
+busctl:
+  - src/busctl/*
+systemctl:
+  - src/systemctl/*
+journal:
+  - src/journal/*
+journal-remote:
+  - src/journal-remote/*
--- a/.github/workflows/labeler.yml
+++ b/.github/workflows/labeler.yml
@ -0,0 +1,12 @@
+name: "Pull Request Labeler"
+on:
+- pull_request_target
+
+jobs:
+  triage:
+    runs-on: ubuntu-latest
+    steps:
+    - uses: actions/labeler@main
+      with:
+        repo-token: "${{ secrets.GITHUB_TOKEN }}"
+        configuration-path: .github/labeler.yml
--- a/src/basic/static-destruct.h
+++ b/src/basic/static-destruct.h
@ -30,15 +30,16 @@ typedef struct StaticDestructor {
        _alignptr_                                                      \
        /* Make sure this is not dropped from the image because not explicitly referenced */ \
        _used_                                                          \
-        /* Make sure that AddressSanitizer doesn't pad this variable: we want everything in this section packed next to each other so that we can enumerate it. */ \
+        /* Make sure that AddressSanitizer doesn't pad this variable: we want everything in this section
+         * packed next to each other so that we can enumerate it. */     \
        _variable_no_sanitize_address_                                  \
        static const StaticDestructor UNIQ_T(static_destructor_entry, uq) = { \
                .data = &(variable),                                    \
                .destroy = UNIQ_T(static_destructor_wrapper, uq),       \
        }

-/* Beginning and end of our section listing the destructors. We define these as weak as we want this to work even if
- * there's not a single destructor is defined in which case the section will be missing. */
+/* Beginning and end of our section listing the destructors. We define these as weak as we want this to work
+ * even if no destructors are defined and the section is missing. */
 extern const struct StaticDestructor _weak_ __start_SYSTEMD_STATIC_DESTRUCT[];
 extern const struct StaticDestructor _weak_ __stop_SYSTEMD_STATIC_DESTRUCT[];

--- a/src/nss-mymachines/nss-mymachines.c
+++ b/src/nss-mymachines/nss-mymachines.c
@ -2,6 +2,7 @@

 #include <netdb.h>
 #include <nss.h>
+#include <pthread.h>

 #include "sd-bus.h"
 #include "sd-login.h"
@ -14,12 +15,27 @@
 #include "format-util.h"
 #include "hostname-util.h"
 #include "in-addr-util.h"
+#include "log.h"
 #include "macro.h"
 #include "memory-util.h"
 #include "nss-util.h"
 #include "signal-util.h"
 #include "string-util.h"

+static void setup_logging(void) {
+        /* We need a dummy function because log_parse_environment is a macro. */
+        log_parse_environment();
+}
+
+static void setup_logging_once(void) {
+        static pthread_once_t once = PTHREAD_ONCE_INIT;
+        assert_se(pthread_once(&once, setup_logging) == 0);
+}
+
+#define NSS_ENTRYPOINT_BEGIN                    \
+        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);       \
+        setup_logging_once()
+
 NSS_GETHOSTBYNAME_PROTOTYPES(mymachines);
 NSS_GETPW_PROTOTYPES(mymachines);
 NSS_GETGR_PROTOTYPES(mymachines);
@ -94,7 +110,7 @@ enum nss_status _nss_mymachines_gethostbyname4_r(
        int n_ifindices, r;

        PROTECT_ERRNO;
-        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);
+        NSS_ENTRYPOINT_BEGIN;

        assert(name);
        assert(pat);
@ -244,7 +260,7 @@ enum nss_status _nss_mymachines_gethostbyname3_r(
        int r;

        PROTECT_ERRNO;
-        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);
+        NSS_ENTRYPOINT_BEGIN;

        assert(name);
        assert(result);
--- a/src/nss-resolve/nss-resolve.c
+++ b/src/nss-resolve/nss-resolve.c
@ -3,6 +3,7 @@
 #include <errno.h>
 #include <netdb.h>
 #include <nss.h>
+#include <pthread.h>
 #include <stdlib.h>
 #include <sys/types.h>
 #include <unistd.h>
@ -17,6 +18,24 @@
 #include "strv.h"
 #include "varlink.h"

+static JsonDispatchFlags json_dispatch_flags = 0;
+
+static void setup_logging(void) {
+        log_parse_environment();
+
+        if (DEBUG_LOGGING)
+                json_dispatch_flags = JSON_LOG;
+}
+
+static void setup_logging_once(void) {
+        static pthread_once_t once = PTHREAD_ONCE_INIT;
+        assert_se(pthread_once(&once, setup_logging) == 0);
+}
+
+#define NSS_ENTRYPOINT_BEGIN                    \
+        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);       \
+        setup_logging_once()
+
 NSS_GETHOSTBYNAME_PROTOTYPES(resolve);
 NSS_GETHOSTBYADDR_PROTOTYPES(resolve);

@ -183,7 +202,7 @@ enum nss_status _nss_resolve_gethostbyname4_r(
        int r;

        PROTECT_ERRNO;
-        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);
+        NSS_ENTRYPOINT_BEGIN;

        assert(name);
        assert(pat);
@ -214,7 +233,7 @@ enum nss_status _nss_resolve_gethostbyname4_r(
                goto fail;
        }

-        r = json_dispatch(rparams, resolve_hostname_reply_dispatch_table, NULL, 0, &p);
+        r = json_dispatch(rparams, resolve_hostname_reply_dispatch_table, NULL, json_dispatch_flags, &p);
        if (r < 0)
                goto fail;
        if (json_variant_is_blank_object(p.addresses))
@ -223,7 +242,7 @@ enum nss_status _nss_resolve_gethostbyname4_r(
        JSON_VARIANT_ARRAY_FOREACH(entry, p.addresses) {
                AddressParameters q = {};

-                r = json_dispatch(entry, address_parameters_dispatch_table, NULL, 0, &q);
+                r = json_dispatch(entry, address_parameters_dispatch_table, NULL, json_dispatch_flags, &q);
                if (r < 0)
                        goto fail;

@ -260,7 +279,7 @@ enum nss_status _nss_resolve_gethostbyname4_r(
        JSON_VARIANT_ARRAY_FOREACH(entry, p.addresses) {
                AddressParameters q = {};

-                r = json_dispatch(entry, address_parameters_dispatch_table, NULL, 0, &q);
+                r = json_dispatch(entry, address_parameters_dispatch_table, NULL, json_dispatch_flags, &q);
                if (r < 0)
                        goto fail;

@ -327,7 +346,7 @@ enum nss_status _nss_resolve_gethostbyname3_r(
        int r;

        PROTECT_ERRNO;
-        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);
+        NSS_ENTRYPOINT_BEGIN;

        assert(name);
        assert(result);
@ -361,7 +380,7 @@ enum nss_status _nss_resolve_gethostbyname3_r(
                goto fail;
        }

-        r = json_dispatch(rparams, resolve_hostname_reply_dispatch_table, NULL, 0, &p);
+        r = json_dispatch(rparams, resolve_hostname_reply_dispatch_table, NULL, json_dispatch_flags, &p);
        if (r < 0)
                goto fail;
        if (json_variant_is_blank_object(p.addresses))
@ -370,7 +389,7 @@ enum nss_status _nss_resolve_gethostbyname3_r(
        JSON_VARIANT_ARRAY_FOREACH(entry, p.addresses) {
                AddressParameters q = {};

-                r = json_dispatch(entry, address_parameters_dispatch_table, NULL, 0, &q);
+                r = json_dispatch(entry, address_parameters_dispatch_table, NULL, json_dispatch_flags, &q);
                if (r < 0)
                        goto fail;

@ -415,7 +434,7 @@ enum nss_status _nss_resolve_gethostbyname3_r(
        JSON_VARIANT_ARRAY_FOREACH(entry, p.addresses) {
                AddressParameters q = {};

-                r = json_dispatch(entry, address_parameters_dispatch_table, NULL, 0, &q);
+                r = json_dispatch(entry, address_parameters_dispatch_table, NULL, json_dispatch_flags, &q);
                if (r < 0)
                        goto fail;

@ -527,7 +546,7 @@ enum nss_status _nss_resolve_gethostbyaddr2_r(
        int r;

        PROTECT_ERRNO;
-        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);
+        NSS_ENTRYPOINT_BEGIN;

        assert(addr);
        assert(result);
@ -565,7 +584,7 @@ enum nss_status _nss_resolve_gethostbyaddr2_r(
                goto fail;
        }

-        r = json_dispatch(rparams, resolve_address_reply_dispatch_table, NULL, 0, &p);
+        r = json_dispatch(rparams, resolve_address_reply_dispatch_table, NULL, json_dispatch_flags, &p);
        if (r < 0)
                goto fail;
        if (json_variant_is_blank_object(p.names))
@ -574,7 +593,7 @@ enum nss_status _nss_resolve_gethostbyaddr2_r(
        JSON_VARIANT_ARRAY_FOREACH(entry, p.names) {
                _cleanup_(name_parameters_destroy) NameParameters q = {};

-                r = json_dispatch(entry, name_parameters_dispatch_table, NULL, 0, &q);
+                r = json_dispatch(entry, name_parameters_dispatch_table, NULL, json_dispatch_flags, &q);
                if (r < 0)
                        goto fail;

@ -615,7 +634,7 @@ enum nss_status _nss_resolve_gethostbyaddr2_r(
                size_t l;
                char *z;

-                r = json_dispatch(entry, name_parameters_dispatch_table, NULL, 0, &q);
+                r = json_dispatch(entry, name_parameters_dispatch_table, NULL, json_dispatch_flags, &q);
                if (r < 0)
                        goto fail;

--- a/src/nss-systemd/nss-systemd.c
+++ b/src/nss-systemd/nss-systemd.c
@ -6,6 +6,7 @@
 #include "env-util.h"
 #include "errno-util.h"
 #include "fd-util.h"
+#include "log.h"
 #include "macro.h"
 #include "nss-systemd.h"
 #include "nss-util.h"
@ -72,6 +73,20 @@ static GetentData getgrent_data = {
        .mutex = PTHREAD_MUTEX_INITIALIZER
 };

+static void setup_logging(void) {
+        /* We need a dummy function because log_parse_environment is a macro. */
+        log_parse_environment();
+}
+
+static void setup_logging_once(void) {
+        static pthread_once_t once = PTHREAD_ONCE_INIT;
+        assert_se(pthread_once(&once, setup_logging) == 0);
+}
+
+#define NSS_ENTRYPOINT_BEGIN                    \
+        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);       \
+        setup_logging_once()
+
 NSS_GETPW_PROTOTYPES(systemd);
 NSS_GETGR_PROTOTYPES(systemd);
 NSS_PWENT_PROTOTYPES(systemd);
@ -88,7 +103,7 @@ enum nss_status _nss_systemd_getpwnam_r(
        int e;

        PROTECT_ERRNO;
-        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);
+        NSS_ENTRYPOINT_BEGIN;

        assert(name);
        assert(pwd);
@ -139,7 +154,7 @@ enum nss_status _nss_systemd_getpwuid_r(
        int e;

        PROTECT_ERRNO;
-        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);
+        NSS_ENTRYPOINT_BEGIN;

        assert(pwd);
        assert(errnop);
@ -188,7 +203,7 @@ enum nss_status _nss_systemd_getgrnam_r(
        int e;

        PROTECT_ERRNO;
-        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);
+        NSS_ENTRYPOINT_BEGIN;

        assert(name);
        assert(gr);
@ -236,7 +251,7 @@ enum nss_status _nss_systemd_getgrgid_r(
        int e;

        PROTECT_ERRNO;
-        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);
+        NSS_ENTRYPOINT_BEGIN;

        assert(gr);
        assert(errnop);
@ -275,7 +290,7 @@ enum nss_status _nss_systemd_getgrgid_r(

 static enum nss_status nss_systemd_endent(GetentData *p) {
        PROTECT_ERRNO;
-        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);
+        NSS_ENTRYPOINT_BEGIN;

        assert(p);

@ -298,7 +313,7 @@ enum nss_status _nss_systemd_endgrent(void) {

 enum nss_status _nss_systemd_setpwent(int stayopen) {
        PROTECT_ERRNO;
-        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);
+        NSS_ENTRYPOINT_BEGIN;

        if (_nss_systemd_is_blocked())
                return NSS_STATUS_NOTFOUND;
@ -322,7 +337,7 @@ enum nss_status _nss_systemd_setpwent(int stayopen) {

 enum nss_status _nss_systemd_setgrent(int stayopen) {
        PROTECT_ERRNO;
-        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);
+        NSS_ENTRYPOINT_BEGIN;

        if (_nss_systemd_is_blocked())
                return NSS_STATUS_NOTFOUND;
@ -349,7 +364,7 @@ enum nss_status _nss_systemd_getpwent_r(
        int r;

        PROTECT_ERRNO;
-        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);
+        NSS_ENTRYPOINT_BEGIN;

        assert(result);
        assert(errnop);
@ -396,7 +411,7 @@ enum nss_status _nss_systemd_getgrent_r(
        int r;

        PROTECT_ERRNO;
-        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);
+        NSS_ENTRYPOINT_BEGIN;

        assert(result);
        assert(errnop);
@ -525,7 +540,7 @@ enum nss_status _nss_systemd_initgroups_dyn(
        int r;

        PROTECT_ERRNO;
-        BLOCK_SIGNALS(NSS_SIGNALS_BLOCK);
+        NSS_ENTRYPOINT_BEGIN;

        assert(user_name);
        assert(start);
--- a/src/shared/json.c
+++ b/src/shared/json.c
@ -3854,6 +3854,16 @@ int json_log_internal(
                                "CONFIG_COLUMN=%u", source_column,
                                LOG_MESSAGE("%s:%u:%u: %s", source, source_line, source_column, buffer),
                                NULL);
+        else if (source_line > 0 && source_column > 0)
+                return log_struct_internal(
+                                LOG_REALM_PLUS_LEVEL(LOG_REALM_SYSTEMD, level),
+                                error,
+                                file, line, func,
+                                "MESSAGE_ID=" SD_MESSAGE_INVALID_CONFIGURATION_STR,
+                                "CONFIG_LINE=%u", source_line,
+                                "CONFIG_COLUMN=%u", source_column,
+                                LOG_MESSAGE("(string):%u:%u: %s", source_line, source_column, buffer),
+                                NULL);
        else
                return log_struct_internal(
                                LOG_REALM_PLUS_LEVEL(LOG_REALM_SYSTEMD, level),
Author	SHA1	Message	Date
Yu Watanabe	ba9385d91f	Merge pull request #17928 from keszybz/nss-logging Enable logging in nss modules	2020-12-14 09:48:23 +09:00
Jameer Pathan	292420ce4b	Add Pull Request Labeler	2020-12-14 09:43:38 +09:00
Zbigniew Jędrzejewski-Szmek	e5d5edc3ff	nss-mymachines: initialize logging No logging is done directly by nss-mymachines.c code, but we call into sd-bus, which will log.	2020-12-10 20:52:03 +01:00
Zbigniew Jędrzejewski-Szmek	3339381f22	nss-systemd: initialize logging	2020-12-10 20:51:59 +01:00
Zbigniew Jędrzejewski-Szmek	55679e291c	nss-resolve: initialize logging, log json errors When the .so module is loaded, it gets a separate copy of stuff in src/basic, including the log level variables. So any logging settings are unaffected by the loading program calling log_parse_environment() or such. Let's also parse the environment here so that we can have nice logging. Initialization is done from each exported function, and pthread_once_t is used to avoid duplicate initialization. I didn't merge PROTECT_ERRNO into NSS_ENTRYPOINT_BEGIN because UNPROTECT_ERRNO is called in a bunch of places and it would feel strange to have PROTECT_ERRNO hidden, but not UNPROTECT_ERRNO. The most interesting stuff in this module is the varlink messages, and any potential errors in json. So let's enable json logging when debug messages are enabled. With those changes, figuring out the issue in https://github.com/systemd/systemd/pull/17823 is trivial: $ LD_LIBRARY_PATH=build/ SYSTEMD_LOG_COLOR=1 SYSTEMD_LOG_LOCATION=1 SYSTEMD_LOG_LEVEL=debug getent hosts mirrors.fedoraproject.org src/shared/varlink.c:237: n/a: varlink: setting state idle-client src/shared/varlink.c:1240: n/a: Sending message: {"method":"io.systemd.Resolve.ResolveHostname","parameters":{"name":"mirrors.fedoraproject.org","family":10}} src/shared/varlink.c:240: n/a: varlink: changing state idle-client → calling src/shared/varlink.c:588: n/a: New incoming message: {"parameters":{"addresses":[{"ifindex":0,"family":10,"address":[42,5,208,20,0,16,120,3,247,116,77,124,226,119,164,87]},{"ifindex":0,"family":10,"address":[42,5,208,28,12,106,204,3,38,58,132,9,185,97,126,2]},{"ifindex":0,"family":10,"address":[38,32,0,82,0,3,0,1,222,173,190,239,202,254,254,215]},{"ifindex":0,"family":10,"address":[38,5,188,128,48,16,6,0,222,173,190,239,202,254,254,217]},{"ifindex":0,"family":10,"address":[38,4,21,128,254,0,0,0,222,173,190,239,202,254,254,209]},{"ifindex":0,"family":10,"address":[38,32,0,82,0,3,0,1,222,173,190,239,202,254,254,214]},{"ifindex":0,"family":10,"address":[38,16,0,40,48,144,48,1,222,173,190,239,202,254,254,211]},{"ifindex":0,"family":10,"address":[32,1,65,120,0,2,18,105,0,0,0,0,0,0,254,210]}],"name":"wildcard.fedoraproject.org","flags":1}} src/shared/varlink.c:240: n/a: varlink: changing state calling → called src/shared/varlink.c:240: n/a: varlink: changing state called → idle-client src/nss-resolve/nss-resolve.c:84: (string):1:40: JSON field 'ifindex' is out of bounds for an interface index.	2020-12-10 20:50:01 +01:00
Zbigniew Jędrzejewski-Szmek	1f568ba13f	basic/static-destruct: fix grammar in comment	2020-12-10 13:00:14 +01:00
Zbigniew Jędrzejewski-Szmek	d401a5e411	json: log location also when there is no file E.g. in nss-resolve it is still useful to print the location of the error: src/test/test-nss.c:231: dlsym(0x0x1dc6fb0, _nss_resolve_gethostbyname2_r) → 0x0x7fdbfc53f626 (string):1:40: JSON field ifindex is out of bounds for an interface index. I opted to use a partially duplicated if condition to avoid nesting. It's nice to have the log calls vertically aligned. The compiler will optimize this nicely.	2020-12-10 13:00:02 +01:00