[PATCH 2 of 5] Syslog: introduced ngx_syslog_send() error logging moderation

[Vladimir Homutov]

On Fri, Mar 01, 2024 at 06:18:18AM +0300, Maxim Dounin wrote:
> # HG changeset patch
> # User Maxim Dounin <mdounin at mdounin.ru>
> # Date 1709260932 -10800
> #      Fri Mar 01 05:42:12 2024 +0300
> # Node ID 1c9264603adc240b226e1a149c01491d62302ded
> # Parent  c7c8354f99face52f3b51442360317f3e2768492
> Syslog: introduced ngx_syslog_send() error logging moderation.
>
> Errors when logging to syslog are now logged at most once per second.
> This ensures that persistent errors won't flood other logs, and spontaneous
> errors, such as ENOBUFS as observed on BSD systems when syslogd cannot cope
> with load, or EAGAIN as seen in similar situation on Linux, won't further
> overload logging subsystem, leading to more errors.
>
> Further, errors now can only trigger reconnects at most once per second.
> This ensures that persistent errors, which cannot be fixed with reconnects,
> don't trigger too much unneeded work.
>
> Additionally, in case of connection errors, such as when syslogd is not
> running, connection attempts are only made once per second.

The change is good, but I can't get the remaining logic:
We don't do reconnects too often (good), but we are still trying
to send into socket that responded with error last time.

Previously, we closed such socket (the goal was to recover from
persistent error).

With the patch we are trying to recoverr once per second, but still
trying to use the (presumably) bad socket.
Maybe we should instead just stop sending anything for the second?

If it seems too much (we can produce a lot of logs during a second and
if an error was random, things would run just fine), then I guess that
we can introduce a counter: close the socket in case of N successive
errors, and put it into moderation mode, and retry again in 1 second.

Other patches look good for me.


>
> diff --git a/src/core/ngx_connection.c b/src/core/ngx_connection.c
> --- a/src/core/ngx_connection.c
> +++ b/src/core/ngx_connection.c
> @@ -1604,6 +1604,10 @@ ngx_connection_error(ngx_connection_t *c
>      {
>          switch (c->log_error) {
>
> +        case NGX_ERROR_DEBUG:
> +            level = NGX_LOG_DEBUG;
> +            break;
> +
>          case NGX_ERROR_IGNORE_EMSGSIZE:
>          case NGX_ERROR_IGNORE_EINVAL:
>          case NGX_ERROR_IGNORE_ECONNRESET:
> @@ -1615,6 +1619,9 @@ ngx_connection_error(ngx_connection_t *c
>              level = NGX_LOG_ERR;
>          }
>
> +    } else if (c->log_error == NGX_ERROR_DEBUG) {
> +        level = NGX_LOG_DEBUG;
> +
>      } else {
>          level = NGX_LOG_ALERT;
>      }
> diff --git a/src/core/ngx_connection.h b/src/core/ngx_connection.h
> --- a/src/core/ngx_connection.h
> +++ b/src/core/ngx_connection.h
> @@ -98,7 +98,8 @@ typedef enum {
>      NGX_ERROR_INFO,
>      NGX_ERROR_IGNORE_ECONNRESET,
>      NGX_ERROR_IGNORE_EINVAL,
> -    NGX_ERROR_IGNORE_EMSGSIZE
> +    NGX_ERROR_IGNORE_EMSGSIZE,
> +    NGX_ERROR_DEBUG
>  } ngx_connection_log_error_e;
>
>
> 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
> @@ -303,6 +303,10 @@ ngx_syslog_send(ngx_syslog_peer_t *peer,
>          }
>      }
>
> +    if (ngx_time() == peer->error_log_time) {
> +        peer->conn.log_error = NGX_ERROR_DEBUG;
> +    }
> +
>      if (ngx_send) {
>          n = ngx_send(&peer->conn, buf, len);
>
> @@ -311,20 +315,27 @@ ngx_syslog_send(ngx_syslog_peer_t *peer,
>          n = ngx_os_io.send(&peer->conn, buf, len);
>      }
>
> -    if (n == NGX_ERROR) {
> -
> +    if (n == NGX_ERROR
> +        && peer->conn.log_error != NGX_ERROR_DEBUG)
> +    {
>          if (ngx_close_socket(peer->conn.fd) == -1) {
>              ngx_log_error(NGX_LOG_ALERT, &peer->log, ngx_socket_errno,
>                            ngx_close_socket_n " failed");
>          }
>
>          peer->conn.fd = (ngx_socket_t) -1;
> +        peer->error_log_time = ngx_time();
>
> -    } else if ((size_t) n != len) {
> +    } else if ((size_t) n != len
> +               && peer->conn.log_error != NGX_ERROR_DEBUG)
> +    {
>          ngx_log_error(NGX_LOG_CRIT, &peer->log, 0,
>                        "send() incomplete");
> +        peer->error_log_time = ngx_time();
>      }
>
> +    peer->conn.log_error = NGX_ERROR_ERR;
> +
>      return n;
>  }
>
> @@ -334,10 +345,15 @@ ngx_syslog_init_peer(ngx_syslog_peer_t *
>  {
>      ngx_socket_t  fd;
>
> +    if (ngx_time() == peer->connect_error_time) {
> +        return NGX_ERROR;
> +    }
> +
>      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_socket_n " failed");
> +        peer->connect_error_time = ngx_time();
>          return NGX_ERROR;
>      }
>
> @@ -355,6 +371,7 @@ ngx_syslog_init_peer(ngx_syslog_peer_t *
>
>      peer->conn.fd = fd;
>      peer->conn.log = &peer->log;
> +    peer->conn.log_error = NGX_ERROR_ERR;
>
>      /* UDP sockets are always ready to write */
>      peer->conn.write->ready = 1;
> @@ -363,6 +380,8 @@ ngx_syslog_init_peer(ngx_syslog_peer_t *
>
>  failed:
>
> +    peer->connect_error_time = ngx_time();
> +
>      if (ngx_close_socket(fd) == -1) {
>          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
> @@ -21,6 +21,9 @@ typedef struct {
>      ngx_log_t          log;
>      ngx_log_t         *logp;
>
> +    time_t             error_log_time;
> +    time_t             connect_error_time;
> +
>      unsigned           busy:1;
>      unsigned           nohostname:1;
>  } ngx_syslog_peer_t;
>
> --
> nginx-devel mailing list
> nginx-devel at freenginx.org
> https://freenginx.org/mailman/listinfo/nginx-devel