Re: [PATCH 11/11] syslog: Use a printf buffer directly to construct the entire packet

[Adhemerval Zanella Netto <adhemerval.zanella@linaro.org>]

On 09/02/24 12:26, Florian Weimer wrote:
> This defers buffer management largely to the asprintf implementation.
> It is quite close to the original implementation around
> open_memstream, except that an on-stack buffer is used for shorter
> messages, and that strftime no longer writes directly into the
> buffer.
> 
> The new version no longer uses the (slow) %n format specifier.
> It also fixes an issue in the localtime_r failure path, where
> the message is prefixed with ": " due to an incorrect placement
> of the %n specifier.
> ---
>  misc/syslog.c | 184 ++++++++++++++++----------------------------------
>  1 file changed, 58 insertions(+), 126 deletions(-)
> 
> diff --git a/misc/syslog.c b/misc/syslog.c
> index 68ee3aef5f..50cb252f47 100644
> --- a/misc/syslog.c
> +++ b/misc/syslog.c
> @@ -38,13 +38,11 @@ static char sccsid[] = "@(#)syslog.c	8.4 (Berkeley) 3/18/94";
>  #include <paths.h>
>  #include <stdarg.h>
>  #include <stdlib.h>
> -#include <stdio.h>
> -#include <stdio_ext.h>
>  #include <sys/socket.h>
> -#include <sys/uio.h>
>  #include <sys/un.h>
>  #include <syslog.h>
>  #include <limits.h>
> +#include <printf_buffer.h>
>  
>  static int LogType = SOCK_DGRAM;	/* type of socket connection */
>  static int LogFile = -1;		/* fd for log */
> @@ -60,27 +58,23 @@ __libc_lock_define_initialized (static, syslog_lock)
>  static void openlog_internal (const char *, int, int);
>  static void closelog_internal (void);
>  
> -struct cleanup_arg
> +/* Unlock and deallocate the buffer.  */
> +static void
> +cancel_handler_buf (void *ptr)
>  {
> -  void *buf;
> -  struct sigaction *oldaction;
> -};
> +  __libc_lock_unlock (syslog_lock);
> +
> +  struct __printf_buffer_asprintf *buf = ptr;
> +  __printf_buffer_asprintf_free (buf);
> +}
>  
> +/* Only unlock.  */
>  static void
>  cancel_handler (void *ptr)
>  {
> -  /* Restore the old signal handler.  */
> -  struct cleanup_arg *clarg = (struct cleanup_arg *) ptr;
> -
> -  if (clarg != NULL)
> -    /* Free the memstream buffer,  */
> -    free (clarg->buf);
> -
> -  /* Free the lock.  */
>    __libc_lock_unlock (syslog_lock);
>  }
>  
> -
>  /*
>   * syslog, vsyslog --
>   *	print message on log file; output is intended for syslogd(8).
> @@ -122,16 +116,21 @@ __vsyslog_chk (int pri, int flag, const char *fmt, va_list ap)
>    __vsyslog_internal (pri, fmt, ap, (flag > 0) ? PRINTF_FORTIFY : 0);
>  }
>  
> +/* Send the buffer contents over the syslog socket.  */
> +static ssize_t
> +__syslog_send (struct __printf_buffer *buf)
> +{
> +  /* Send the trailing NUL byte for LogType == SOCK_STREAM  only.  */
> +  return __send (LogFile, buf->write_base,
> +		 buf->write_ptr - buf->write_base - (LogType != SOCK_STREAM),
> +		 MSG_NOSIGNAL)

Maybe encapsulate this on a function (__printf_buffer_write_len or
something)? I think we should avoid mess the internal printf buffer
state where possible.

> +}
> +
>  void
>  __vsyslog_internal (int pri, const char *fmt, va_list ap,
>  		    unsigned int mode_flags)
>  {
> -  /* Try to use a static buffer as an optimization.  */
> -  char bufs[1024];
> -  char *buf = bufs;
> -  size_t bufsize;
> -
> -  int msgoff;
> +  ptrdiff_t msgoff;
>    int saved_errno = errno;
>  
>  #define	INTERNALLOG LOG_ERR|LOG_CONS|LOG_PERROR|LOG_PID
> @@ -144,8 +143,9 @@ __vsyslog_internal (int pri, const char *fmt, va_list ap,
>  
>    /* Prepare for multiple users.  We have to take care: most syscalls we are
>       using are cancellation points.  */
> -  struct cleanup_arg clarg = { NULL, NULL };
> -  __libc_cleanup_push (cancel_handler, &clarg);
> +  struct __printf_buffer_asprintf buf;
> +  __printf_buffer_asprintf_init (&buf);
> +  __libc_cleanup_push (cancel_handler_buf, &buf);
>    __libc_lock_lock (syslog_lock);
>  
>    /* Check priority against setlogmask values. */
> @@ -173,122 +173,56 @@ __vsyslog_internal (int pri, const char *fmt, va_list ap,
>      __strftime_l (timestamp, sizeof timestamp, "%h %e %T ", now_tmp,
>  		  _nl_C_locobj_ptr);
>  
> -#define SYSLOG_HEADER(__pri, __timestamp, __msgoff, pid) \
> -  "<%d>%s%n%s%s%.0d%s: ",                                \
> -  __pri, __timestamp, __msgoff,                          \
> -  LogTag == NULL ? __progname : LogTag,                  \
> -  "[" + (pid == 0), pid, "]" + (pid == 0)
> +  __printf_buffer (&buf.base, "<%d>", pri);
>  
> -#define SYSLOG_HEADER_WITHOUT_TS(__pri, __msgoff)        \
> -  "<%d>: %n", __pri, __msgoff
> -
> -  int l, vl;
>    if (has_ts)
> -    l = __snprintf (bufs, sizeof bufs,
> -		    SYSLOG_HEADER (pri, timestamp, &msgoff, pid));
> -  else
> -    l = __snprintf (bufs, sizeof bufs,
> -		    SYSLOG_HEADER_WITHOUT_TS (pri, &msgoff));
> -  if (l < 0)
> -    goto out;
> -
> -  char *pos;
> -  size_t len;
> -
> -  if (l < sizeof bufs)
>      {
> -      /* At this point, there is still a chance that we can print the
> -         remaining part of the log into bufs and use that.  */
> -      pos = bufs + l;
> -      len = sizeof (bufs) - l;
> +      __printf_buffer_puts (&buf.base, timestamp);
> +      msgoff = buf.base.write_ptr - buf.base.write_base;
> +       __printf_buffer_puts (&buf.base, LogTag == NULL ? __progname : LogTag);
> +      if (pid != 0)
> +	__printf_buffer (&buf.base, "[%d]", pid);
> +      __printf_buffer_putc (&buf.base, ':');
> +      __printf_buffer_putc (&buf.base, ' ');
>      }
>    else
>      {
> -      buf = NULL;
> -      /* We already know that bufs is too small to use for this log message.
> -         The next vsnprintf into bufs is used only to calculate the total
> -         required buffer length.  We will discard bufs contents and allocate
> -         an appropriately sized buffer later instead.  */
> -      pos = bufs;
> -      len = sizeof (bufs);
> +      msgoff = buf.base.write_ptr - buf.base.write_base;
> +      __printf_buffer_putc (&buf.base, ':');
> +      __printf_buffer_putc (&buf.base, ' ');
>      }

Maybe move the ': ' appending after the if/else:

  if (has_ts)
    {
      [...]
    }
  else
    [...]
  __printf_buffer_puts (&buf.base, ": ");

>  
> -  {
> -    va_list apc;
> -    va_copy (apc, ap);
> -
> -    /* Restore errno for %m format.  */
> -    __set_errno (saved_errno);
> -
> -    vl = __vsnprintf_internal (pos, len, fmt, apc, mode_flags);
> -    va_end (apc);
> +  /* Do not count the bytes written to the buffer so far.  This value
> +     is negative and accounts for the existing buffer contents, which
> +     is not upposed to be visible to the caller.  */

s/upposed/supposed

> +  buf.base.written = buf.base.write_base - buf.base.write_ptr;

Maybe encapsulate this on a function (__printf_buffer_reset_pos or
something)?

>  
> -    if (vl < 0 || vl >= INT_MAX - l)
> -      goto out;
> +  errno = saved_errno;
> +  __vprintf_buffer (&buf.base, fmt, ap, mode_flags);
>  
> -    if (vl >= len)
> -      buf = NULL;
> -
> -    bufsize = l + vl;
> -  }
> -
> -  if (buf == NULL)
> -    {
> -      buf = malloc ((bufsize + 1) * sizeof (char));
> -      if (buf != NULL)
> -	{
> -	  /* Tell the cancellation handler to free this buffer.  */
> -	  clarg.buf = buf;
> +  /* We may need the terminator if we are sending over a SOCK_STREAM
> +     connection.  Add this unconditionally to simplify error handling.  */
> +  __printf_buffer_putc (&buf.base, '\0');
>  

Ok.

> -	  int cl;
> -	  if (has_ts)
> -	    cl = __snprintf (buf, l + 1,
> -			     SYSLOG_HEADER (pri, timestamp, &msgoff, pid));
> -	  else
> -	    cl = __snprintf (buf, l + 1,
> -			     SYSLOG_HEADER_WITHOUT_TS (pri, &msgoff));
> -	  if (cl != l)
> -	    goto out;
> -
> -	  va_list apc;
> -	  va_copy (apc, ap);
> -	  cl = __vsnprintf_internal (buf + l, bufsize - l + 1, fmt, apc,
> -				     mode_flags);
> -	  va_end (apc);
> -
> -	  if (cl != vl)
> -	    goto out;
> -	}
> -      else
> -        {
> -          int bl;
> -	  /* Nothing much to do but emit an error message.  */
> -          bl = __snprintf (bufs, sizeof bufs,
> -                           "out of memory[%d]", __getpid ());
> -          if (bl < 0 || bl >= sizeof bufs)
> -            goto out;
> -
> -          bufsize = bl;
> -          buf = bufs;
> -          msgoff = 0;
> -        }
> -    }
> +  if (__printf_buffer_has_failed (&buf.base))
> +    goto out;
>  
>    /* Output to stderr if requested. */
>    if (LogStat & LOG_PERROR)
> -    __dprintf (STDERR_FILENO, "%s%s", buf + msgoff,
> -	       "\n" + (buf[bufsize - 1] == '\n'));
> +    {
> +      /* The buffer always starts with '<' and a digit, so there are
> +	 at least two bytes, and -2 is valid offset from the next
> +	 to-be-written byte.  -2 accounts for the NUL byte.  */
> +      int has_nl = buf.base.write_ptr[-2] == '\n';
> +      __dprintf (STDERR_FILENO, "%s%s", buf.base.write_base + msgoff,
> +		 "\n" + has_nl);
> +    }
>  
>    /* Get connected, output the message to the local logger.  */
>    if (!connected)
>      openlog_internal (NULL, LogStat | LOG_NDELAY, LogFacility);
>  
> -  /* If we have a SOCK_STREAM connection, also send ASCII NUL as a record
> -     terminator.  */
> -  if (LogType == SOCK_STREAM)
> -    ++bufsize;
> -
> -  if (!connected || __send (LogFile, buf, bufsize, MSG_NOSIGNAL) < 0)
> +  if (!connected || __syslog_send (&buf.base) < 0)
>      {
>        if (connected)
>  	{
> @@ -297,7 +231,7 @@ __vsyslog_internal (int pri, const char *fmt, va_list ap,
>  	  openlog_internal (NULL, LogStat | LOG_NDELAY, LogFacility);
>  	}
>  
> -      if (!connected || __send (LogFile, buf, bufsize, MSG_NOSIGNAL) < 0)
> +      if (!connected || __syslog_send (&buf.base) < 0)
>  	{
>  	  closelog_internal ();	/* attempt re-open next time */
>  	  /*
> @@ -311,7 +245,7 @@ __vsyslog_internal (int pri, const char *fmt, va_list ap,
>  	      (fd = __open (_PATH_CONSOLE, O_WRONLY | O_NOCTTY
>  			    | O_CLOEXEC, 0)) >= 0)
>  	    {
> -	      __dprintf (fd, "%s\r\n", buf + msgoff);
> +	      __dprintf (fd, "%s\r\n", buf.base.write_base + msgoff);
>  	      __close (fd);
>  	    }
>  	}
> @@ -321,9 +255,7 @@ out:
>    /* End of critical section.  */
>    __libc_cleanup_pop (0);
>    __libc_lock_unlock (syslog_lock);
> -
> -  if (buf != bufs)
> -    free (buf);
> +  __printf_buffer_asprintf_free (&buf);
>  }
>  
>  /* AF_UNIX address of local logger  */