[PATCH 1 of 2] Core: connect() error log message made more verbose
Maxim Dounin
mdounin at mdounin.ru
Wed Feb 22 19:55:29 UTC 2023
Hello!
On Wed, Feb 22, 2023 at 03:37:51PM +0400, Sergey Kandaurov wrote:
> > On 9 Feb 2023, at 12:11, Maxim Dounin <mdounin at mdounin.ru> wrote:
> >
> >> # HG changeset patch
> >> # User Safar Safarly <hafl at me.com>
> >> # Date 1675779866 -10800
> >> # Tue Feb 07 17:24:26 2023 +0300
> >> # Node ID 55553146bd984be7e9e3bbfa851c282feda82d93
> >> # Parent cffaf3f2eec8fd33605c2a37814f5ffc30371989
> >> Core: connect() error log message made more verbose
> >>
> >> There was a major problem in logs: we could not identify to which servers
> >> connect() has failed. Previously log produced:
> >>
> >> ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, ngx_socket_errno,
> >> "connect() failed");
> >>
> >> And now we'll have an address or unix socket in log:
> >>
> >> ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, ngx_socket_errno,
> >> "connect() to %V failed", &peer->server.name);
> >>
> >> Message format has chosen to be exact as it is used in ngx_event_connect.c:242
> >> with similar error logging:
> >>
> >> ngx_log_error(level, c->log, err, "connect() to %V failed",
> >> pc->name);
> >>
> >> So everywhere connect() could fail we'd get a uniform and verbose error message
> >> in log.
> >
> > Thanks for the patch.
> >
> > Indeed, it might be non-trivial to find out what goes wrong when
> > no context is provided in error messages, and logging to syslog
> > fails to provide any.
> >
> > Please see comments below.
> >
> > [..]
> >>
> >> goto failed;
> >> }
> >> diff -r cffaf3f2eec8 -r 55553146bd98 src/core/ngx_syslog.c
> >> --- a/src/core/ngx_syslog.c Thu Feb 02 23:38:48 2023 +0300
> >> +++ b/src/core/ngx_syslog.c Tue Feb 07 17:24:26 2023 +0300
> >> @@ -337,7 +337,7 @@
> >>
> >> if (connect(fd, peer->server.sockaddr, peer->server.socklen) == -1) {
> >> ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, ngx_socket_errno,
> >> - "connect() failed");
> >> + "connect() to %V failed", &peer->server.name);
> >> goto failed;
> >> }
> >
> > For syslog logging, I tend to think that this isn't really enough.
> > For example, consider send() errors which also might happen when
> > logging to syslog. Right now these are logged as:
> >
> > 2023/02/09 07:29:11 [alert] 23230#100162: send() failed (49: Can't assign requested address)
> > 2023/02/09 07:29:11 [alert] 23230#100162: send() failed (49: Can't assign requested address)
> >
> > Clearly no better than connect() errors:
> >
> > 2023/02/09 07:29:11 [alert] 23230#100162: connect() failed (2: No such file or directory)
> >
> > A better fix would be to provide a log handler, similarly to
> > ngx_resolver_log_error() mentioned above. With a simple log
> > handler the above messages will instead look like:
> >
> > 2023/02/09 07:48:11 [alert] 23699#100145: send() failed (49: Can't assign requested address) while logging to syslog, server: 127.0.0.2:514
> > 2023/02/09 07:48:11 [alert] 23699#100145: send() failed (49: Can't assign requested address) while logging to syslog, server: 127.0.0.2:514
> > 2023/02/09 07:48:11 [alert] 23699#100145: connect() failed (2: No such file or directory) while logging to syslog, server: unix:/log.socket
> >
> > Patch:
> >
> > # HG changeset patch
> > # User Maxim Dounin <mdounin at mdounin.ru>
> > # Date 1675929813 -10800
> > # Thu Feb 09 11:03:33 2023 +0300
> > # Node ID 6b662855bf77c678a3954939aefe3fd4b4af4c70
> > # Parent cffaf3f2eec8fd33605c2a37814f5ffc30371989
> > Syslog: introduced error log handler.
> >
> > This ensures that errors which happen during logging to syslog are logged
> > with proper context, such as "while logging to syslog" and the server name.
> >
> > Prodded by Safar Safarly.
> >
> > diff --git a/src/core/ngx_syslog.c b/src/core/ngx_syslog.c
> > --- a/src/core/ngx_syslog.c
> > +++ b/src/core/ngx_syslog.c
> > @@ -18,6 +18,7 @@
> > static char *ngx_syslog_parse_args(ngx_conf_t *cf, ngx_syslog_peer_t *peer);
> > static ngx_int_t ngx_syslog_init_peer(ngx_syslog_peer_t *peer);
> > static void ngx_syslog_cleanup(void *data);
> > +static u_char *ngx_syslog_log_error(ngx_log_t *log, u_char *buf, size_t len);
> >
> >
> > static char *facilities[] = {
> > @@ -66,6 +67,8 @@ ngx_syslog_process_conf(ngx_conf_t *cf,
> > ngx_str_set(&peer->tag, "nginx");
> > }
> >
> > + peer->logp = &cf->cycle->new_log;
> > +
>
> You may want to reflect this change in the description.
> That's, this now follows other error logging by using log from
> the configuration that is going to be applied (cycle->new_log):
>
> src/core/ngx_log.c: dummy = &cf->cycle->new_log;
> src/mail/ngx_mail_core_module.c: conf->error_log = &cf->cycle->new_log;
> src/stream/ngx_stream_core_module.c: conf->error_log = &cf->cycle->new_log;
> src/http/ngx_http_core_module.c: conf->error_log = &cf->cycle->new_log;
> src/core/ngx_resolver.c: r->log = &cf->cycle->new_log;
> src/core/ngx_cycle.c: cycle->log = &cycle->new_log;
>
> Previously, before configuration was read, it used init_cycle configuration,
> that's builtin error_log on the NGX_LOG_NOTICE level, which means that its
> own ngx_send debug appeared only after the configuration was read, and other
> syslog error logging was limited to the builtin error log.
The main goal of introduction of peer->logp is to avoid
re-initializing peer->log on each ngx_syslog_send() call.
Previous code used to initialize peer->conn.log on each call,
though now there are more things to initialize, and doing this on
each call makes the issue obvious.
But yes, the resulting code is consistent with other uses and
matches how logging is expected to be used: when something is used
in a context of a configuration, it uses logging from the
configuration.
A side note: it looks like ngx_syslog_add_header() uses
ngx_cycle->hostname. During initial startup this will use
init_cycle->hostname, which is empty.
Looking at all this again I tend to think it might be a good idea
to ditch ngx_cycle usage in a separate patch (both for
ngx_cycle->log and ngx_cycle->hostname), and implement proper
logging context on top of it. Patches below.
> > peer->conn.fd = (ngx_socket_t) -1;
> >
> > peer->conn.read = &ngx_syslog_dummy_event;
> > @@ -286,15 +289,19 @@ ngx_syslog_send(ngx_syslog_peer_t *peer,
> > {
> > ssize_t n;
> >
> > + if (peer->log.handler == NULL) {
> > + peer->log = *peer->logp;
> > + peer->log.handler = ngx_syslog_log_error;
> > + peer->log.data = peer;
> > + peer->log.action = "logging to syslog";
> > + }
> > +
> > if (peer->conn.fd == (ngx_socket_t) -1) {
> > if (ngx_syslog_init_peer(peer) != NGX_OK) {
> > return NGX_ERROR;
> > }
> > }
> >
> > - /* log syslog socket events with valid log */
> > - peer->conn.log = ngx_cycle->log;
> > -
> > if (ngx_send) {
> > n = ngx_send(&peer->conn, buf, len);
> >
>
> One conversion to &peer->log is missing in the ngx_send error handling:
>
> diff --git a/src/core/ngx_syslog.c b/src/core/ngx_syslog.c
> --- a/src/core/ngx_syslog.c
> +++ b/src/core/ngx_syslog.c
> @@ -313,7 +313,7 @@ ngx_syslog_send(ngx_syslog_peer_t *peer,
> if (n == NGX_ERROR) {
>
> if (ngx_close_socket(peer->conn.fd) == -1) {
> - ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, ngx_socket_errno,
> + ngx_log_error(NGX_LOG_ALERT, &peer->log, ngx_socket_errno,
> ngx_close_socket_n " failed");
> }
>
>
> Other than that it looks good.
Applied, thanks.
Updated patches below.
# HG changeset patch
# User Maxim Dounin <mdounin at mdounin.ru>
# Date 1677095349 -10800
# Wed Feb 22 22:49:09 2023 +0300
# Node ID a964a013031dabbdd05fb0637de496640070c416
# Parent cffaf3f2eec8fd33605c2a37814f5ffc30371989
Syslog: removed usage of ngx_cycle->log and ngx_cycle->hostname.
During initial startup the ngx_cycle->hostname is not available, and
previously this resulted in incorrect logging. Instead, hostname from the
configuration being parsed is now preserved in the syslog peer structure
and then used during logging.
Similarly, ngx_cycle->log might not match the configuration where the
syslog peer is defined if the configuration is not yet fully applied,
and previously this resulted in unexpected logging of syslog errors
and debug information. Instead, cf->cycle->new_log is now referenced
in the syslog peer structure and used for logging, similarly to how it
is done in other modules.
diff --git a/src/core/ngx_syslog.c b/src/core/ngx_syslog.c
--- a/src/core/ngx_syslog.c
+++ b/src/core/ngx_syslog.c
@@ -66,6 +66,9 @@ ngx_syslog_process_conf(ngx_conf_t *cf,
ngx_str_set(&peer->tag, "nginx");
}
+ peer->hostname = &cf->cycle->hostname;
+ peer->log = &cf->cycle->new_log;
+
peer->conn.fd = (ngx_socket_t) -1;
peer->conn.read = &ngx_syslog_dummy_event;
@@ -243,7 +246,7 @@ ngx_syslog_add_header(ngx_syslog_peer_t
}
return ngx_sprintf(buf, "<%ui>%V %V %V: ", pri, &ngx_cached_syslog_time,
- &ngx_cycle->hostname, &peer->tag);
+ peer->hostname, &peer->tag);
}
@@ -292,9 +295,6 @@ ngx_syslog_send(ngx_syslog_peer_t *peer,
}
}
- /* log syslog socket events with valid log */
- peer->conn.log = ngx_cycle->log;
-
if (ngx_send) {
n = ngx_send(&peer->conn, buf, len);
@@ -306,7 +306,7 @@ ngx_syslog_send(ngx_syslog_peer_t *peer,
if (n == NGX_ERROR) {
if (ngx_close_socket(peer->conn.fd) == -1) {
- ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, ngx_socket_errno,
+ ngx_log_error(NGX_LOG_ALERT, peer->log, ngx_socket_errno,
ngx_close_socket_n " failed");
}
@@ -324,24 +324,25 @@ ngx_syslog_init_peer(ngx_syslog_peer_t *
fd = ngx_socket(peer->server.sockaddr->sa_family, SOCK_DGRAM, 0);
if (fd == (ngx_socket_t) -1) {
- ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, ngx_socket_errno,
+ ngx_log_error(NGX_LOG_ALERT, peer->log, ngx_socket_errno,
ngx_socket_n " failed");
return NGX_ERROR;
}
if (ngx_nonblocking(fd) == -1) {
- ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, ngx_socket_errno,
+ ngx_log_error(NGX_LOG_ALERT, peer->log, ngx_socket_errno,
ngx_nonblocking_n " failed");
goto failed;
}
if (connect(fd, peer->server.sockaddr, peer->server.socklen) == -1) {
- ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, ngx_socket_errno,
+ ngx_log_error(NGX_LOG_ALERT, peer->log, ngx_socket_errno,
"connect() failed");
goto failed;
}
peer->conn.fd = fd;
+ peer->conn.log = peer->log;
/* UDP sockets are always ready to write */
peer->conn.write->ready = 1;
@@ -351,7 +352,7 @@ ngx_syslog_init_peer(ngx_syslog_peer_t *
failed:
if (ngx_close_socket(fd) == -1) {
- ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, ngx_socket_errno,
+ ngx_log_error(NGX_LOG_ALERT, peer->log, ngx_socket_errno,
ngx_close_socket_n " failed");
}
@@ -372,7 +373,7 @@ ngx_syslog_cleanup(void *data)
}
if (ngx_close_socket(peer->conn.fd) == -1) {
- ngx_log_error(NGX_LOG_ALERT, ngx_cycle->log, ngx_socket_errno,
+ ngx_log_error(NGX_LOG_ALERT, peer->log, ngx_socket_errno,
ngx_close_socket_n " failed");
}
}
diff --git a/src/core/ngx_syslog.h b/src/core/ngx_syslog.h
--- a/src/core/ngx_syslog.h
+++ b/src/core/ngx_syslog.h
@@ -9,14 +9,19 @@
typedef struct {
- ngx_uint_t facility;
- ngx_uint_t severity;
- ngx_str_t tag;
+ ngx_uint_t facility;
+ ngx_uint_t severity;
+ ngx_str_t tag;
+
+ ngx_str_t *hostname;
- ngx_addr_t server;
- ngx_connection_t conn;
- unsigned busy:1;
- unsigned nohostname:1;
+ ngx_addr_t server;
+ ngx_connection_t conn;
+
+ ngx_log_t *log;
+
+ unsigned busy:1;
+ unsigned nohostname:1;
} ngx_syslog_peer_t;
# HG changeset patch
# User Maxim Dounin <mdounin at mdounin.ru>
# Date 1677095351 -10800
# Wed Feb 22 22:49:11 2023 +0300
# Node ID 8f7c464c54e0b18bdb4d505866755cd600fac9fb
# Parent a964a013031dabbdd05fb0637de496640070c416
Syslog: introduced error log handler.
This ensures that errors which happen during logging to syslog are logged
with proper context, such as "while logging to syslog" and the server name.
Prodded by Safar Safarly.
diff --git a/src/core/ngx_syslog.c b/src/core/ngx_syslog.c
--- a/src/core/ngx_syslog.c
+++ b/src/core/ngx_syslog.c
@@ -18,6 +18,7 @@
static char *ngx_syslog_parse_args(ngx_conf_t *cf, ngx_syslog_peer_t *peer);
static ngx_int_t ngx_syslog_init_peer(ngx_syslog_peer_t *peer);
static void ngx_syslog_cleanup(void *data);
+static u_char *ngx_syslog_log_error(ngx_log_t *log, u_char *buf, size_t len);
static char *facilities[] = {
@@ -67,7 +68,7 @@ ngx_syslog_process_conf(ngx_conf_t *cf,
}
peer->hostname = &cf->cycle->hostname;
- peer->log = &cf->cycle->new_log;
+ peer->logp = &cf->cycle->new_log;
peer->conn.fd = (ngx_socket_t) -1;
@@ -289,6 +290,13 @@ ngx_syslog_send(ngx_syslog_peer_t *peer,
{
ssize_t n;
+ if (peer->log.handler == NULL) {
+ peer->log = *peer->logp;
+ peer->log.handler = ngx_syslog_log_error;
+ peer->log.data = peer;
+ peer->log.action = "logging to syslog";
+ }
+
if (peer->conn.fd == (ngx_socket_t) -1) {
if (ngx_syslog_init_peer(peer) != NGX_OK) {
return NGX_ERROR;
@@ -306,7 +314,7 @@ ngx_syslog_send(ngx_syslog_peer_t *peer,
if (n == NGX_ERROR) {
if (ngx_close_socket(peer->conn.fd) == -1) {
- ngx_log_error(NGX_LOG_ALERT, peer->log, ngx_socket_errno,
+ ngx_log_error(NGX_LOG_ALERT, &peer->log, ngx_socket_errno,
ngx_close_socket_n " failed");
}
@@ -324,25 +332,25 @@ ngx_syslog_init_peer(ngx_syslog_peer_t *
fd = ngx_socket(peer->server.sockaddr->sa_family, SOCK_DGRAM, 0);
if (fd == (ngx_socket_t) -1) {
- ngx_log_error(NGX_LOG_ALERT, peer->log, ngx_socket_errno,
+ ngx_log_error(NGX_LOG_ALERT, &peer->log, ngx_socket_errno,
ngx_socket_n " failed");
return NGX_ERROR;
}
if (ngx_nonblocking(fd) == -1) {
- ngx_log_error(NGX_LOG_ALERT, peer->log, ngx_socket_errno,
+ ngx_log_error(NGX_LOG_ALERT, &peer->log, ngx_socket_errno,
ngx_nonblocking_n " failed");
goto failed;
}
if (connect(fd, peer->server.sockaddr, peer->server.socklen) == -1) {
- ngx_log_error(NGX_LOG_ALERT, peer->log, ngx_socket_errno,
+ ngx_log_error(NGX_LOG_ALERT, &peer->log, ngx_socket_errno,
"connect() failed");
goto failed;
}
peer->conn.fd = fd;
- peer->conn.log = peer->log;
+ peer->conn.log = &peer->log;
/* UDP sockets are always ready to write */
peer->conn.write->ready = 1;
@@ -352,7 +360,7 @@ ngx_syslog_init_peer(ngx_syslog_peer_t *
failed:
if (ngx_close_socket(fd) == -1) {
- ngx_log_error(NGX_LOG_ALERT, peer->log, ngx_socket_errno,
+ ngx_log_error(NGX_LOG_ALERT, &peer->log, ngx_socket_errno,
ngx_close_socket_n " failed");
}
@@ -373,7 +381,30 @@ ngx_syslog_cleanup(void *data)
}
if (ngx_close_socket(peer->conn.fd) == -1) {
- ngx_log_error(NGX_LOG_ALERT, peer->log, ngx_socket_errno,
+ ngx_log_error(NGX_LOG_ALERT, &peer->log, ngx_socket_errno,
ngx_close_socket_n " failed");
}
}
+
+
+static u_char *
+ngx_syslog_log_error(ngx_log_t *log, u_char *buf, size_t len)
+{
+ u_char *p;
+ ngx_syslog_peer_t *peer;
+
+ p = buf;
+
+ if (log->action) {
+ p = ngx_snprintf(buf, len, " while %s", log->action);
+ len -= p - buf;
+ }
+
+ peer = log->data;
+
+ if (peer) {
+ p = ngx_snprintf(p, len, ", server: %V", &peer->server.name);
+ }
+
+ return p;
+}
diff --git a/src/core/ngx_syslog.h b/src/core/ngx_syslog.h
--- a/src/core/ngx_syslog.h
+++ b/src/core/ngx_syslog.h
@@ -18,7 +18,8 @@ typedef struct {
ngx_addr_t server;
ngx_connection_t conn;
- ngx_log_t *log;
+ ngx_log_t log;
+ ngx_log_t *logp;
unsigned busy:1;
unsigned nohostname:1;
--
Maxim Dounin
http://mdounin.ru/
More information about the nginx-devel
mailing list