From 55679e291c6f01e07ae4a76f65cd364b46c85984 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= Date: Thu, 10 Dec 2020 12:32:12 +0100 Subject: [PATCH] nss-resolve: initialize logging, log json errors MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- src/nss-resolve/nss-resolve.c | 43 +++++++++++++++++++++++++---------- 1 file changed, 31 insertions(+), 12 deletions(-) diff --git a/src/nss-resolve/nss-resolve.c b/src/nss-resolve/nss-resolve.c index 3fee4f5813..be9d28d993 100644 --- a/src/nss-resolve/nss-resolve.c +++ b/src/nss-resolve/nss-resolve.c @@ -3,6 +3,7 @@ #include #include #include +#include #include #include #include @@ -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;