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.

What I am not sure if this is really the direction we want for internal
FILE usage.  I had the impression that the printf buffer internal API
was mainly meant to improve the old FILE implementation and its historical
drawnbacks and limitations.  For internal usage we would continue to use
standard FILE API, should we move to always use printf buffers instead?

I am asking because it is a lot of code and refactoring for a specific
code that I would like to avoid change due the recent issues.  Most of 
complication is the static buffer optimization, so maybe we should just
remove it?

Also, since the motivation for this change is just to remove the %n
requirement, maybe we can just not enable it on syslog instead (since
we now that the internal calls should not act as a gadget)?  

diff --git a/misc/syslog.c b/misc/syslog.c
index 68ee3aef5f..53a17e612b 100644
--- a/misc/syslog.c
+++ b/misc/syslog.c
@@ -122,6 +122,29 @@ __vsyslog_chk (int pri, int flag, const char *fmt, va_list ap)
   __vsyslog_internal (pri, fmt, ap, (flag > 0) ? PRINTF_FORTIFY : 0);
 }

+#if __USE_FORTIFY_LEVEL > 1
+static int
+syslog_snprintf_chk (char *s, size_t maxlen, size_t slen, const char *format,
+                    ...)
+{
+  if (__glibc_unlikely (slen < maxlen))
+    __chk_fail ();
+
+  /* Avoid the costly %n fortify check, so do not pass PRINTF_FORTIFY.  */
+  va_list ap;
+  va_start (ap, format);
+  int ret = __vsnprintf_internal (s, maxlen, format, ap, 0);
+  va_end (ap);
+
+  return ret;
+}
+# define syslog_snprintf(str, len, ...) \
+    syslog_snprintf_chk (str, len, __glibc_objsize (str), __VA_ARGS__)
+#else
+# define syslog_snprintf(str, len, ...) \
+    __snprintf (str, len, __VA_ARGS__)
+#endif
+
 void
 __vsyslog_internal (int pri, const char *fmt, va_list ap,
                    unsigned int mode_flags)
@@ -184,11 +207,11 @@ __vsyslog_internal (int pri, const char *fmt, va_list ap,

   int l, vl;
   if (has_ts)
-    l = __snprintf (bufs, sizeof bufs,
-                   SYSLOG_HEADER (pri, timestamp, &msgoff, pid));
+    l = syslog_snprintf (bufs, sizeof bufs,
+                        SYSLOG_HEADER (pri, timestamp, &msgoff, pid));
   else
-    l = __snprintf (bufs, sizeof bufs,
-                   SYSLOG_HEADER_WITHOUT_TS (pri, &msgoff));
+    l = syslog_snprintf (bufs, sizeof bufs,
+                        SYSLOG_HEADER_WITHOUT_TS (pri, &msgoff));
   if (l < 0)
     goto out;

@@ -242,11 +265,11 @@ __vsyslog_internal (int pri, const char *fmt, va_list ap,

          int cl;
          if (has_ts)
-           cl = __snprintf (buf, l + 1,
-                            SYSLOG_HEADER (pri, timestamp, &msgoff, pid));
+           cl = syslog_snprintf (buf, l + 1,
+                                 SYSLOG_HEADER (pri, timestamp, &msgoff, pid));
          else
-           cl = __snprintf (buf, l + 1,
-                            SYSLOG_HEADER_WITHOUT_TS (pri, &msgoff));
+           cl = syslog_snprintf (buf, l + 1,
+                                 SYSLOG_HEADER_WITHOUT_TS (pri, &msgoff));
          if (cl != l)
            goto out;

@@ -263,8 +286,8 @@ __vsyslog_internal (int pri, const char *fmt, va_list ap,
         {
           int bl;
          /* Nothing much to do but emit an error message.  */
-          bl = __snprintf (bufs, sizeof bufs,
-                           "out of memory[%d]", __getpid ());
+          bl = syslog_snprintf (bufs, sizeof bufs,
+                               "out of memory[%d]", __getpid ());
           if (bl < 0 || bl >= sizeof bufs)
             goto out;


> ---
>  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);
> +}
> +
>  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, ' ');
>      }
>  
> -  {
> -    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.  */
> +  buf.base.written = buf.base.write_base - buf.base.write_ptr;
>  
> -    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');
>  
> -	  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  */