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([email protected]) 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 -0000 1.64
> +++ log.c 18 Oct 2023 07:10:32 -0000
> @@ -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;
> + char fmtbuf[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;
> + char fmtbuf[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 fmtbuf[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;
> + char fmtbuf[MAX_LOGLEN];
> + va_list ap;
>
> if (verbose) {
> va_start(ap, emsg);
> - vlog(LOG_DEBUG, emsg, ap);
> + (void)vsnprintf(fmtbuf, sizeof(fmtbuf), emsg, ap);
> va_end(ap);
> + logit(LOG_DEBUG, "%s\n", fmtbuf);
> }
> }
>
> static void
> vfatalc(int code, const char *emsg, va_list ap)
> {
> - static char s[BUFSIZ];
> + char fmtbuf[MAX_LOGLEN];
> 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));
> + logit(LOG_CRIT, "fatal in %s: %s%s%s\n",
> + 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\n", log_procname, sep, fmtbuf);
> }
>
> void
> Index: log.h
> ===================================================================
> RCS file: /cvs/src/usr.sbin/bgpd/log.h,v
> retrieving revision 1.20
> diff -u -p -r1.20 log.h
> --- log.h 21 Oct 2020 06:48:33 -0000 1.20
> +++ log.h 18 Oct 2023 07:05:17 -0000
> @@ -36,8 +36,6 @@ void log_debug(const char *, ...)
> __attribute__((__format__ (printf, 1, 2)));
> void logit(int, const char *, ...)
> __attribute__((__format__ (printf, 2, 3)));
> -void vlog(int, const char *, va_list)
> - __attribute__((__format__ (printf, 2, 0)));
> __dead void fatal(const char *, ...)
> __attribute__((__format__ (printf, 1, 2)));
> __dead void fatalx(const char *, ...)
> Index: logmsg.c
> ===================================================================
> RCS file: /cvs/src/usr.sbin/bgpd/logmsg.c,v
> retrieving revision 1.10
> diff -u -p -r1.10 logmsg.c
> --- logmsg.c 14 Oct 2023 09:46:14 -0000 1.10
> +++ logmsg.c 18 Oct 2023 07:04:57 -0000
> @@ -68,7 +68,7 @@ log_peer_info(const struct peer_config *
> if (vasprintf(&msg, emsg, ap) == -1)
> fatal(NULL);
> va_end(ap);
> - logit(LOG_INFO, "%s: %s", p, msg);
> + logit(LOG_INFO, "%s: %s\n", p, msg);
> free(msg);
> free(p);
> }
> @@ -82,13 +82,13 @@ log_peer_warn(const struct peer_config *
>
> p = log_fmt_peer(peer);
> if (emsg == NULL) {
> - logit(LOG_ERR, "%s: %s", p, strerror(saved_errno));
> + logit(LOG_ERR, "%s: %s\n", p, strerror(saved_errno));
> } else {
> va_start(ap, emsg);
> if (vasprintf(&msg, emsg, ap) == -1)
> fatal(NULL);
> va_end(ap);
> - logit(LOG_ERR, "%s: %s: %s", p, msg, strerror(saved_errno));
> + logit(LOG_ERR, "%s: %s: %s\n", p, msg, strerror(saved_errno));
> free(msg);
> }
> free(p);
> @@ -105,7 +105,7 @@ log_peer_warnx(const struct peer_config
> if (vasprintf(&msg, emsg, ap) == -1)
> fatal(NULL);
> va_end(ap);
> - logit(LOG_ERR, "%s: %s", p, msg);
> + logit(LOG_ERR, "%s: %s\n", p, msg);
> free(msg);
> free(p);
> }
> @@ -126,7 +126,7 @@ log_statechange(struct peer *peer, enum
>
> peer->lasterr = 0;
> p = log_fmt_peer(&peer->conf);
> - logit(LOG_INFO, "%s: state change %s -> %s, reason: %s",
> + logit(LOG_INFO, "%s: state change %s -> %s, reason: %s\n",
> p, statenames[peer->state], statenames[nstate], eventnames[event]);
> free(p);
> }
> @@ -189,20 +189,20 @@ log_notification(const struct peer *peer
> break;
> default:
> logit(LOG_ERR, "%s: %s notification, unknown errcode "
> - "%u, subcode %u", p, dir, errcode, subcode);
> + "%u, subcode %u\n", p, dir, errcode, subcode);
> free(p);
> return;
> }
>
> if (uk)
> - logit(LOG_ERR, "%s: %s notification: %s, unknown subcode %u",
> + logit(LOG_ERR, "%s: %s notification: %s, unknown subcode %u\n",
> p, dir, errnames[errcode], subcode);
> else {
> if (suberrname == NULL)
> - logit(LOG_ERR, "%s: %s notification: %s", p,
> + logit(LOG_ERR, "%s: %s notification: %s\n", p,
> dir, errnames[errcode]);
> else
> - logit(LOG_ERR, "%s: %s notification: %s, %s",
> + logit(LOG_ERR, "%s: %s notification: %s, %s\n",
> p, dir, errnames[errcode], suberrname);
> }
> free(p);
> @@ -215,7 +215,7 @@ log_conn_attempt(const struct peer *peer
>
> if (peer == NULL) { /* connection from non-peer, drop */
> if (log_getverbose())
> - logit(LOG_INFO, "connection from non-peer %s refused",
> + logit(LOG_INFO, "connection from non-peer %s refused\n",
> log_sockaddr(sa, len));
> } else {
> /* only log if there is a chance that the session may come up */
> @@ -223,7 +223,7 @@ log_conn_attempt(const struct peer *peer
> return;
> p = log_fmt_peer(&peer->conf);
> logit(LOG_INFO, "Connection attempt from %s while session is "
> - "in state %s", p, statenames[peer->state]);
> + "in state %s\n", p, statenames[peer->state]);
> free(p);
> }
> }
> Index: parse.y
> ===================================================================
> RCS file: /cvs/src/usr.sbin/bgpd/parse.y,v
> retrieving revision 1.455
> diff -u -p -r1.455 parse.y
> --- parse.y 16 Aug 2023 08:26:35 -0000 1.455
> +++ parse.y 18 Oct 2023 07:20:46 -0000
> @@ -3477,7 +3477,7 @@ yyerror(const char *fmt, ...)
> if (vasprintf(&msg, fmt, ap) == -1)
> fatalx("yyerror vasprintf");
> va_end(ap);
> - logit(LOG_CRIT, "%s:%d: %s", file->name, yylval.lineno, msg);
> + logit(LOG_CRIT, "%s:%d: %s\n", file->name, yylval.lineno, msg);
> free(msg);
> return (0);
> }
