[PATCH 1 of 2] Core: connect() error log message made more verbose
Sergey Kandaurov
pluknet at nginx.com
Wed Feb 22 11:37:51 UTC 2023
> On 9 Feb 2023, at 12:11, Maxim Dounin <mdounin at mdounin.ru> wrote:
>
> Hello!
>
> On Wed, Feb 08, 2023 at 06:54:06PM +0300, Safar Safarly via nginx-devel 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.
> 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.
> @@ -324,24 +331,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 +359,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 +380,30 @@ 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");
> }
> }
> +
> +
> +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
> @@ -9,14 +9,18 @@
>
>
> 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_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;
> + ngx_log_t *logp;
> +
> + unsigned busy:1;
> + unsigned nohostname:1;
> } ngx_syslog_peer_t;
>
>
--
Sergey Kandaurov
More information about the nginx-devel
mailing list