Re: log.c use buffered IO
On Wed, Oct 18, 2023 at 11:34:09AM +0200, Claudio Jeker wrote:
> On Tue, Oct 17, 2023 at 10:06:54AM +0200, Sebastian Benoit wrote:
> > Theo Buehler(t...@theobuehler.org) on 2023.10.17 09:13:15 +0200:
> > > On Mon, Oct 16, 2023 at 12:19:17PM +0200, Claudio Jeker wrote:
> > > > I dislike how log.c does all these asprintf() calls with dubious
> > > > workaround calls in case asprintf() fails.
> > >
> > > You're not alone.
> > >
> > > > IMO it is easier to use the stdio provided buffers and fflush() to get
> > > > "atomic" writes on stderr. At least from my understanding this is the
> > > > reason to go all this lenght to do a single fprintf call.
> > >
> > > This makes sense, but I don't know the history here.
> >
> > as far as i can remember, it was done so it would still be able to work
> > somewhat when out of memeory.
> >
>
> After some input off-list here another idea.
> Require that logit() is called with a \n and by that simplify a lot of
> code around it. vsyslog() handles both so having the \n should not cause
> any breakage.
Really hard to say which is the lesser evil: requiring \n or the ugly
asprintf dances. I don't think it is flat out objectionable, but I can
see people disliking this. The churn you outline below seems indeed
rather limited, so I guess we can go this way.
Definitely ok with using a stack buffer rather than a static one.
>
> Now logit() is mostly used internally but in bgpd it is also used in
> logmsg.c and parse.y. Fixing those is simple.
>
> Also this uses a stack buffer for all the log_* cases now. This should
> make the code more thread safe.
>
> Also this removes vlog() from the API. I had a quick look at all the
> other log.c users and apart from ldapd this can be added to all of them
> without much issues. Nothing else uses vlog() and the logit() is also very
> minimal (mostly the same parse.y change as below).
>
> --
> :wq Claudio
>
> Index: log.c
> ===
> RCS file: /cvs/src/usr.sbin/bgpd/log.c,v
> retrieving revision 1.64
> diff -u -p -r1.64 log.c
> --- log.c 21 Mar 2017 12:06:55 - 1.64
> +++ log.c 18 Oct 2023 07:10:32 -
> @@ -26,6 +26,8 @@
>
> #include "log.h"
>
> +#define MAX_LOGLEN 4096
> +
> static intdebug;
> static intverbose;
> static const char*log_procname;
> @@ -68,30 +70,15 @@ void
> logit(int pri, const char *fmt, ...)
> {
> va_list ap;
> + int saved_errno = errno;
>
> va_start(ap, fmt);
> - vlog(pri, fmt, ap);
> - va_end(ap);
> -}
> -
> -void
> -vlog(int pri, const char *fmt, va_list ap)
> -{
> - char*nfmt;
> - int saved_errno = errno;
> -
> if (debug) {
> - /* best effort in out of mem situations */
> - if (asprintf(&nfmt, "%s\n", fmt) == -1) {
> - vfprintf(stderr, fmt, ap);
> - fprintf(stderr, "\n");
> - } else {
> - vfprintf(stderr, nfmt, ap);
> - free(nfmt);
> - }
> + vfprintf(stderr, fmt, ap);
> fflush(stderr);
> } else
> vsyslog(pri, fmt, ap);
> + va_end(ap);
>
> errno = saved_errno;
> }
> @@ -99,26 +86,18 @@ vlog(int pri, const char *fmt, va_list a
> void
> log_warn(const char *emsg, ...)
> {
> - char*nfmt;
> - va_list ap;
> - int saved_errno = errno;
> + charfmtbuf[MAX_LOGLEN];
> + va_list ap;
> + int saved_errno = errno;
>
> /* best effort to even work in out of memory situations */
> if (emsg == NULL)
> - logit(LOG_ERR, "%s", strerror(saved_errno));
> + logit(LOG_ERR, "%s\n", strerror(saved_errno));
> else {
> va_start(ap, emsg);
> -
> - if (asprintf(&nfmt, "%s: %s", emsg,
> - strerror(saved_errno)) == -1) {
> - /* we tried it... */
> - vlog(LOG_ERR, emsg, ap);
> - logit(LOG_ERR, "%s", strerror(saved_errno));
> - } else {
> - vlog(LOG_ERR, nfmt, ap);
> - free(nfmt);
> - }
> + (void)vsnprintf(fmtbuf, sizeof(fmtbuf), emsg, ap);
> va_end(ap);
> + logit(LOG_ERR, "%s: %s\n", fmtbuf, strerror(saved_errno));
> }
>
> errno = saved_errno;
> @@ -127,53 +106,65 @@ log_warn(const char *emsg, ...)
> void
> log_warnx(const char *emsg, ...)
> {
> - va_list ap;
> + charfmtbuf[MAX_LOGLEN];
> + va_list ap;
> + int saved_errno = errno;
>
> va_start(ap, emsg);
> - vlog(LOG_ERR, emsg, ap);
> + (void)vsnprintf(fmtbuf, sizeof(fmtbuf), emsg, ap);
> va_end(ap);
> + logit(LOG_ERR, "%s\n", fmtbuf);
> +
> + errno = saved_errno;
> }
>
> void
> log_info(const char *emsg, ...)
> {
> - va_list ap;
> + char
Re: log.c use buffered IO
On Tue, Oct 17, 2023 at 10:06:54AM +0200, Sebastian Benoit wrote:
> Theo Buehler(t...@theobuehler.org) on 2023.10.17 09:13:15 +0200:
> > On Mon, Oct 16, 2023 at 12:19:17PM +0200, Claudio Jeker wrote:
> > > I dislike how log.c does all these asprintf() calls with dubious
> > > workaround calls in case asprintf() fails.
> >
> > You're not alone.
> >
> > > IMO it is easier to use the stdio provided buffers and fflush() to get
> > > "atomic" writes on stderr. At least from my understanding this is the
> > > reason to go all this lenght to do a single fprintf call.
> >
> > This makes sense, but I don't know the history here.
>
> as far as i can remember, it was done so it would still be able to work
> somewhat when out of memeory.
>
After some input off-list here another idea.
Require that logit() is called with a \n and by that simplify a lot of
code around it. vsyslog() handles both so having the \n should not cause
any breakage.
Now logit() is mostly used internally but in bgpd it is also used in
logmsg.c and parse.y. Fixing those is simple.
Also this uses a stack buffer for all the log_* cases now. This should
make the code more thread safe.
Also this removes vlog() from the API. I had a quick look at all the
other log.c users and apart from ldapd this can be added to all of them
without much issues. Nothing else uses vlog() and the logit() is also very
minimal (mostly the same parse.y change as below).
--
:wq Claudio
Index: log.c
===
RCS file: /cvs/src/usr.sbin/bgpd/log.c,v
retrieving revision 1.64
diff -u -p -r1.64 log.c
--- log.c 21 Mar 2017 12:06:55 - 1.64
+++ log.c 18 Oct 2023 07:10:32 -
@@ -26,6 +26,8 @@
#include "log.h"
+#define MAX_LOGLEN 4096
+
static int debug;
static int verbose;
static const char *log_procname;
@@ -68,30 +70,15 @@ void
logit(int pri, const char *fmt, ...)
{
va_list ap;
+ int saved_errno = errno;
va_start(ap, fmt);
- vlog(pri, fmt, ap);
- va_end(ap);
-}
-
-void
-vlog(int pri, const char *fmt, va_list ap)
-{
- char*nfmt;
- int saved_errno = errno;
-
if (debug) {
- /* best effort in out of mem situations */
- if (asprintf(&nfmt, "%s\n", fmt) == -1) {
- vfprintf(stderr, fmt, ap);
- fprintf(stderr, "\n");
- } else {
- vfprintf(stderr, nfmt, ap);
- free(nfmt);
- }
+ vfprintf(stderr, fmt, ap);
fflush(stderr);
} else
vsyslog(pri, fmt, ap);
+ va_end(ap);
errno = saved_errno;
}
@@ -99,26 +86,18 @@ vlog(int pri, const char *fmt, va_list a
void
log_warn(const char *emsg, ...)
{
- char*nfmt;
- va_list ap;
- int saved_errno = errno;
+ charfmtbuf[MAX_LOGLEN];
+ va_list ap;
+ int saved_errno = errno;
/* best effort to even work in out of memory situations */
if (emsg == NULL)
- logit(LOG_ERR, "%s", strerror(saved_errno));
+ logit(LOG_ERR, "%s\n", strerror(saved_errno));
else {
va_start(ap, emsg);
-
- if (asprintf(&nfmt, "%s: %s", emsg,
- strerror(saved_errno)) == -1) {
- /* we tried it... */
- vlog(LOG_ERR, emsg, ap);
- logit(LOG_ERR, "%s", strerror(saved_errno));
- } else {
- vlog(LOG_ERR, nfmt, ap);
- free(nfmt);
- }
+ (void)vsnprintf(fmtbuf, sizeof(fmtbuf), emsg, ap);
va_end(ap);
+ logit(LOG_ERR, "%s: %s\n", fmtbuf, strerror(saved_errno));
}
errno = saved_errno;
@@ -127,53 +106,65 @@ log_warn(const char *emsg, ...)
void
log_warnx(const char *emsg, ...)
{
- va_list ap;
+ charfmtbuf[MAX_LOGLEN];
+ va_list ap;
+ int saved_errno = errno;
va_start(ap, emsg);
- vlog(LOG_ERR, emsg, ap);
+ (void)vsnprintf(fmtbuf, sizeof(fmtbuf), emsg, ap);
va_end(ap);
+ logit(LOG_ERR, "%s\n", fmtbuf);
+
+ errno = saved_errno;
}
void
log_info(const char *emsg, ...)
{
- va_list ap;
+ charfmtbuf[MAX_LOGLEN];
+ va_list ap;
+ int saved_errno = errno;
va_start(ap, emsg);
- vlog(LOG_INFO, emsg, ap);
+ (void)vsnprintf(fmtbuf, sizeof(fmtbuf), emsg, ap);
va_end(ap);
+ logit(LOG_INFO, "%s\n", fmtbuf);
+
+ errno = saved_errno;
}
void
log_debug(const char *emsg, ...)
{
- va_list ap;
+ charfmtbuf[MAX_LOGLEN];
+ va_list ap;
if (verbose) {
va_start(ap, emsg);
- vlog(LOG_DEBUG, emsg, ap);
+ (void
Re: log.c use buffered IO
Theo Buehler(t...@theobuehler.org) on 2023.10.17 09:13:15 +0200:
> On Mon, Oct 16, 2023 at 12:19:17PM +0200, Claudio Jeker wrote:
> > I dislike how log.c does all these asprintf() calls with dubious
> > workaround calls in case asprintf() fails.
>
> You're not alone.
>
> > IMO it is easier to use the stdio provided buffers and fflush() to get
> > "atomic" writes on stderr. At least from my understanding this is the
> > reason to go all this lenght to do a single fprintf call.
>
> This makes sense, but I don't know the history here.
as far as i can remember, it was done so it would still be able to work
somewhat when out of memeory.
> > We need this since in privsep daemons can log from multiple processes
> > concurrently and we want the log to be not too mangled.
> >
> > While there also use one static buffer to handle log_warn() and vfatalc()
> > where the error message is first expanded and then printed with
> > logit(LOG_ERR, "%s: %s", fmtbuf, strerror(saved_errno));
> >
> > Any opinions?
>
> I like this much better than the existing code.
>
> ok tb, one small request inline
>
> > --
> > :wq Claudio
> >
> > Index: log.c
> > ===
> > RCS file: /cvs/src/usr.sbin/bgpd/log.c,v
> > retrieving revision 1.64
> > diff -u -p -r1.64 log.c
> > --- log.c 21 Mar 2017 12:06:55 - 1.64
> > +++ log.c 16 Oct 2023 09:42:55 -
> > @@ -29,6 +29,7 @@
> > static int debug;
> > static int verbose;
> > static const char *log_procname;
> > +static char logbuf[4096], fmtbuf[4096];
> >
> > void
> > log_init(int n_debug, int facility)
> > @@ -41,6 +42,8 @@ log_init(int n_debug, int facility)
> >
> > if (!debug)
> > openlog(__progname, LOG_PID | LOG_NDELAY, facility);
> > + else
> > + setvbuf(stderr, logbuf, _IOFBF, sizeof(logbuf));
can you turn this around (if (debug) ...)
> > tzset();
> > }
> > @@ -77,18 +80,11 @@ logit(int pri, const char *fmt, ...)
> > void
> > vlog(int pri, const char *fmt, va_list ap)
> > {
> > - char*nfmt;
> > int saved_errno = errno;
> >
> > if (debug) {
>
> Could log_init() and vlog() either both use if (debug) or both if (!debug),
> please? Missing the ! in log_init() confused me for a few minutes since it
> looked wrong.
yes please :)
>
> > - /* best effort in out of mem situations */
> > - if (asprintf(&nfmt, "%s\n", fmt) == -1) {
> > - vfprintf(stderr, fmt, ap);
> > - fprintf(stderr, "\n");
> > - } else {
> > - vfprintf(stderr, nfmt, ap);
> > - free(nfmt);
> > - }
> > + vfprintf(stderr, fmt, ap);
> > + fprintf(stderr, "\n");
> > fflush(stderr);
> > } else
> > vsyslog(pri, fmt, ap);
> > @@ -99,7 +95,6 @@ vlog(int pri, const char *fmt, va_list a
> > void
> > log_warn(const char *emsg, ...)
> > {
> > - char*nfmt;
> > va_list ap;
> > int saved_errno = errno;
> >
> > @@ -108,16 +103,8 @@ log_warn(const char *emsg, ...)
> > logit(LOG_ERR, "%s", strerror(saved_errno));
> > else {
> > va_start(ap, emsg);
> > -
> > - if (asprintf(&nfmt, "%s: %s", emsg,
> > - strerror(saved_errno)) == -1) {
> > - /* we tried it... */
> > - vlog(LOG_ERR, emsg, ap);
> > - logit(LOG_ERR, "%s", strerror(saved_errno));
> > - } else {
> > - vlog(LOG_ERR, nfmt, ap);
> > - free(nfmt);
> > - }
> > + (void)vsnprintf(fmtbuf, sizeof(fmtbuf), emsg, ap);
> > + logit(LOG_ERR, "%s: %s", fmtbuf, strerror(saved_errno));
> > va_end(ap);
> > }
> >
> > @@ -159,21 +146,20 @@ log_debug(const char *emsg, ...)
> > static void
> > vfatalc(int code, const char *emsg, va_list ap)
> > {
> > - static char s[BUFSIZ];
> > const char *sep;
> >
> > if (emsg != NULL) {
> > - (void)vsnprintf(s, sizeof(s), emsg, ap);
> > + (void)vsnprintf(fmtbuf, sizeof(fmtbuf), emsg, ap);
> > sep = ": ";
> > } else {
> > - s[0] = '\0';
> > + fmtbuf[0] = '\0';
> > sep = "";
> > }
> > if (code)
> > logit(LOG_CRIT, "fatal in %s: %s%s%s",
> > - log_procname, s, sep, strerror(code));
> > + log_procname, fmtbuf, sep, strerror(code));
> > else
> > - logit(LOG_CRIT, "fatal in %s%s%s", log_procname, sep, s);
> > + logit(LOG_CRIT, "fatal in %s%s%s", log_procname, sep, fmtbuf);
> > }
> >
> > void
> >
>
Re: log.c use buffered IO
On Mon, Oct 16, 2023 at 12:19:17PM +0200, Claudio Jeker wrote:
> I dislike how log.c does all these asprintf() calls with dubious
> workaround calls in case asprintf() fails.
You're not alone.
> IMO it is easier to use the stdio provided buffers and fflush() to get
> "atomic" writes on stderr. At least from my understanding this is the
> reason to go all this lenght to do a single fprintf call.
This makes sense, but I don't know the history here.
> We need this since in privsep daemons can log from multiple processes
> concurrently and we want the log to be not too mangled.
>
> While there also use one static buffer to handle log_warn() and vfatalc()
> where the error message is first expanded and then printed with
> logit(LOG_ERR, "%s: %s", fmtbuf, strerror(saved_errno));
>
> Any opinions?
I like this much better than the existing code.
ok tb, one small request inline
> --
> :wq Claudio
>
> Index: log.c
> ===
> RCS file: /cvs/src/usr.sbin/bgpd/log.c,v
> retrieving revision 1.64
> diff -u -p -r1.64 log.c
> --- log.c 21 Mar 2017 12:06:55 - 1.64
> +++ log.c 16 Oct 2023 09:42:55 -
> @@ -29,6 +29,7 @@
> static intdebug;
> static intverbose;
> static const char*log_procname;
> +static char logbuf[4096], fmtbuf[4096];
>
> void
> log_init(int n_debug, int facility)
> @@ -41,6 +42,8 @@ log_init(int n_debug, int facility)
>
> if (!debug)
> openlog(__progname, LOG_PID | LOG_NDELAY, facility);
> + else
> + setvbuf(stderr, logbuf, _IOFBF, sizeof(logbuf));
>
> tzset();
> }
> @@ -77,18 +80,11 @@ logit(int pri, const char *fmt, ...)
> void
> vlog(int pri, const char *fmt, va_list ap)
> {
> - char*nfmt;
> int saved_errno = errno;
>
> if (debug) {
Could log_init() and vlog() either both use if (debug) or both if (!debug),
please? Missing the ! in log_init() confused me for a few minutes since it
looked wrong.
> - /* best effort in out of mem situations */
> - if (asprintf(&nfmt, "%s\n", fmt) == -1) {
> - vfprintf(stderr, fmt, ap);
> - fprintf(stderr, "\n");
> - } else {
> - vfprintf(stderr, nfmt, ap);
> - free(nfmt);
> - }
> + vfprintf(stderr, fmt, ap);
> + fprintf(stderr, "\n");
> fflush(stderr);
> } else
> vsyslog(pri, fmt, ap);
> @@ -99,7 +95,6 @@ vlog(int pri, const char *fmt, va_list a
> void
> log_warn(const char *emsg, ...)
> {
> - char*nfmt;
> va_list ap;
> int saved_errno = errno;
>
> @@ -108,16 +103,8 @@ log_warn(const char *emsg, ...)
> logit(LOG_ERR, "%s", strerror(saved_errno));
> else {
> va_start(ap, emsg);
> -
> - if (asprintf(&nfmt, "%s: %s", emsg,
> - strerror(saved_errno)) == -1) {
> - /* we tried it... */
> - vlog(LOG_ERR, emsg, ap);
> - logit(LOG_ERR, "%s", strerror(saved_errno));
> - } else {
> - vlog(LOG_ERR, nfmt, ap);
> - free(nfmt);
> - }
> + (void)vsnprintf(fmtbuf, sizeof(fmtbuf), emsg, ap);
> + logit(LOG_ERR, "%s: %s", fmtbuf, strerror(saved_errno));
> va_end(ap);
> }
>
> @@ -159,21 +146,20 @@ log_debug(const char *emsg, ...)
> static void
> vfatalc(int code, const char *emsg, va_list ap)
> {
> - static char s[BUFSIZ];
> const char *sep;
>
> if (emsg != NULL) {
> - (void)vsnprintf(s, sizeof(s), emsg, ap);
> + (void)vsnprintf(fmtbuf, sizeof(fmtbuf), emsg, ap);
> sep = ": ";
> } else {
> - s[0] = '\0';
> + fmtbuf[0] = '\0';
> sep = "";
> }
> if (code)
> logit(LOG_CRIT, "fatal in %s: %s%s%s",
> - log_procname, s, sep, strerror(code));
> + log_procname, fmtbuf, sep, strerror(code));
> else
> - logit(LOG_CRIT, "fatal in %s%s%s", log_procname, sep, s);
> + logit(LOG_CRIT, "fatal in %s%s%s", log_procname, sep, fmtbuf);
> }
>
> void
>
log.c use buffered IO
I dislike how log.c does all these asprintf() calls with dubious
workaround calls in case asprintf() fails.
IMO it is easier to use the stdio provided buffers and fflush() to get
"atomic" writes on stderr. At least from my understanding this is the
reason to go all this lenght to do a single fprintf call.
We need this since in privsep daemons can log from multiple processes
concurrently and we want the log to be not too mangled.
While there also use one static buffer to handle log_warn() and vfatalc()
where the error message is first expanded and then printed with
logit(LOG_ERR, "%s: %s", fmtbuf, strerror(saved_errno));
Any opinions?
--
:wq Claudio
Index: log.c
===
RCS file: /cvs/src/usr.sbin/bgpd/log.c,v
retrieving revision 1.64
diff -u -p -r1.64 log.c
--- log.c 21 Mar 2017 12:06:55 - 1.64
+++ log.c 16 Oct 2023 09:42:55 -
@@ -29,6 +29,7 @@
static int debug;
static int verbose;
static const char *log_procname;
+static char logbuf[4096], fmtbuf[4096];
void
log_init(int n_debug, int facility)
@@ -41,6 +42,8 @@ log_init(int n_debug, int facility)
if (!debug)
openlog(__progname, LOG_PID | LOG_NDELAY, facility);
+ else
+ setvbuf(stderr, logbuf, _IOFBF, sizeof(logbuf));
tzset();
}
@@ -77,18 +80,11 @@ logit(int pri, const char *fmt, ...)
void
vlog(int pri, const char *fmt, va_list ap)
{
- char*nfmt;
int saved_errno = errno;
if (debug) {
- /* best effort in out of mem situations */
- if (asprintf(&nfmt, "%s\n", fmt) == -1) {
- vfprintf(stderr, fmt, ap);
- fprintf(stderr, "\n");
- } else {
- vfprintf(stderr, nfmt, ap);
- free(nfmt);
- }
+ vfprintf(stderr, fmt, ap);
+ fprintf(stderr, "\n");
fflush(stderr);
} else
vsyslog(pri, fmt, ap);
@@ -99,7 +95,6 @@ vlog(int pri, const char *fmt, va_list a
void
log_warn(const char *emsg, ...)
{
- char*nfmt;
va_list ap;
int saved_errno = errno;
@@ -108,16 +103,8 @@ log_warn(const char *emsg, ...)
logit(LOG_ERR, "%s", strerror(saved_errno));
else {
va_start(ap, emsg);
-
- if (asprintf(&nfmt, "%s: %s", emsg,
- strerror(saved_errno)) == -1) {
- /* we tried it... */
- vlog(LOG_ERR, emsg, ap);
- logit(LOG_ERR, "%s", strerror(saved_errno));
- } else {
- vlog(LOG_ERR, nfmt, ap);
- free(nfmt);
- }
+ (void)vsnprintf(fmtbuf, sizeof(fmtbuf), emsg, ap);
+ logit(LOG_ERR, "%s: %s", fmtbuf, strerror(saved_errno));
va_end(ap);
}
@@ -159,21 +146,20 @@ log_debug(const char *emsg, ...)
static void
vfatalc(int code, const char *emsg, va_list ap)
{
- static char s[BUFSIZ];
const char *sep;
if (emsg != NULL) {
- (void)vsnprintf(s, sizeof(s), emsg, ap);
+ (void)vsnprintf(fmtbuf, sizeof(fmtbuf), emsg, ap);
sep = ": ";
} else {
- s[0] = '\0';
+ fmtbuf[0] = '\0';
sep = "";
}
if (code)
logit(LOG_CRIT, "fatal in %s: %s%s%s",
- log_procname, s, sep, strerror(code));
+ log_procname, fmtbuf, sep, strerror(code));
else
- logit(LOG_CRIT, "fatal in %s%s%s", log_procname, sep, s);
+ logit(LOG_CRIT, "fatal in %s%s%s", log_procname, sep, fmtbuf);
}
void
