Hello!

On Wed, Feb 08, 2023 at 06:54:06PM +0300, Safar Safarly via nginx-devel wrote:

> # HG changeset patch
> # User Safar Safarly <hafl@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.

>
> diff -r cffaf3f2eec8 -r 55553146bd98 src/core/ngx_resolver.c
> --- a/src/core/ngx_resolver.c Thu Feb 02 23:38:48 2023 +0300
> +++ b/src/core/ngx_resolver.c Tue Feb 07 17:24:26 2023 +0300
> @@ -4512,7 +4512,7 @@
>
> if (rc == -1) {
> ngx_log_error(NGX_LOG_CRIT, &rec->log, ngx_socket_errno,
> - "connect() failed");
> + "connect() to %V failed", &rec->server);

Resolver already provides details about the particular server it
connects to, for example:

2023/02/08 19:39:53 [crit] 23077#100129: connect() failed (2: No such file or directory) while resolving, resolver: unix:/resolver.socket

See ngx_resolver_log_error() for more information.

>
> 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@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;
+
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);

@@ -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;



--
Maxim Dounin
http://mdounin.ru/
_______________________________________________
nginx-devel mailing list
nginx-devel@nginx.org
https://mailman.nginx.org/mailman/listinfo/nginx-devel