[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