2005-03-11 13:18:43

by Denis Vlasenko

[permalink] [raw]
Subject: [PATCH] sanitize logging subsystem

It seems like there are several ways to log messages or
display them on std{out,err} in nfs utils, more or less
similar to each other. Let's try to untangle them.

I'll start from cleaning up xlog.c:

* There is no external API to log to arbitrary FILE*,
we can drop code which supports this internally.
Patch converts xlog.c to directly use stderr.
* Print date/time in ISO (YYYY-MM-DD HH:MM:SS) format.
* Add support for disabling logging to syslog.

Patch does not introduce behavioral changes except for
making foregrounded mountd to really use stderr.
There was a bug which prevented this.

Patch is tested. Please comment/apply.
--
vda


Attachments:
(No filename) (646.00 B)
nfs-utils-1.0.7_log1.diff (4.79 kB)
Download all attachments

2005-03-15 14:38:35

by Denis Vlasenko

[permalink] [raw]
Subject: Re: [PATCH] sanitize logging subsystem #2

On Monday 14 March 2005 16:26, Denis Vlasenko wrote:
> > Otherwise the patch looks reasonably sane.
> > The only bit that bothers me is calling openlog in mountd where it
> > wasn't called before.
> > mountd (on debian at least) currently prefixes all log lines with
> > "rpc_mountd" as that is the program name. With this patch they will
> > be prefixes with "mountd".
> > This is a change and people who filter their log file (like me) might
> > notice. But it probably isn't a big concern..
> >
> > I've committed it to CVS.
>
> Your concern is indeed valid:
>
> /* Initialize logging. */
> if (!foreground) xlog_stderr(0);
> xlog_open("mountd");
> ...
> if (!foreground) {
> int fd = sysconf (_SC_OPEN_MAX);
> while (--fd > 2)
> (void) close(fd);
> }
>
> This could close a fd to syslog socket!
> If it indeed happens, just move xlog_open below fd
> closing loop. However, you may opt to just omit xlog_open().
> I will test this scenario.

glibc behaviour:

openlog() (inside xlog_open()) does not open fds per se.
syslog() will create and connect fd to /dev/log on first call.
Moreover, if syslog() gets -EBADF (i.e. somebody has closed fd)
it will recreate socket and reconnect to /dev/log.

IOW: glibc is pretty resilient to us closing syslog fd.

I will add a comment on this and submit a patch
after your feedback on previous ones.

Cheers,
--
vda



-------------------------------------------------------
SF email is sponsored by - The IT Product Guide
Read honest & candid reviews on hundreds of IT Products from real users.
Discover which products truly live up to the hype. Start reading now.
http://ads.osdn.com/?ad_id=6595&alloc_id=14396&op=click
_______________________________________________
NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

2005-03-19 15:54:28

by Steve Dickson

[permalink] [raw]
Subject: Re: [PATCH] sanitize logging subsystem

Denis Vlasenko wrote:
> Patch does not introduce behavioral changes except for
> making foregrounded mountd to really use stderr.
> There was a bug which prevented this.
hmm... I've always found that if a daemon lives
in background, that the best place to debug it...

steved.


-------------------------------------------------------
SF email is sponsored by - The IT Product Guide
Read honest & candid reviews on hundreds of IT Products from real users.
Discover which products truly live up to the hype. Start reading now.
http://ads.osdn.com/?ad_id=6595&alloc_id=14396&op=click
_______________________________________________
NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

2005-03-14 05:51:19

by NeilBrown

[permalink] [raw]
Subject: Re: [PATCH] sanitize logging subsystem

On Friday March 11, [email protected] wrote:
> It seems like there are several ways to log messages or
> display them on std{out,err} in nfs utils, more or less
> similar to each other. Let's try to untangle them.
>
> I'll start from cleaning up xlog.c:
>
> * There is no external API to log to arbitrary FILE*,
> we can drop code which supports this internally.
> Patch converts xlog.c to directly use stderr.
> * Print date/time in ISO (YYYY-MM-DD HH:MM:SS) format.
> * Add support for disabling logging to syslog.
>
> Patch does not introduce behavioral changes except for
> making foregrounded mountd to really use stderr.
> There was a bug which prevented this.
>
> Patch is tested. Please comment/apply.

How well was it tested :-)

> + fprintf(stderr, "%s[%d] %04d-%02d-%02d %02d:%02d:%02d %s\n",
> + log_name, log_pid,
> + tm->tm_year, tm->tm_mon + 1, tm->tm_mday,
> + tm->tm_hour, tm->tm_min, tm->tm_sec,
> + buff);

tm_year is "number of years since 1900", which isn't what you want to
print out. It needs a "+1900", which I have given it.

Otherwise the patch looks reasonably sane.
The only bit that bothers me is calling openlog in mountd where it
wasn't called before.
mountd (on debian at least) currently prefixes all log lines with
"rpc_mountd" as that is the program name. With this patch they will
be prefixes with "mountd".
This is a change and people who filter their log file (like me) might
notice. But it probably isn't a big concern..

I've committed it to CVS.

Thanks,
NeilBrown


-------------------------------------------------------
SF email is sponsored by - The IT Product Guide
Read honest & candid reviews on hundreds of IT Products from real users.
Discover which products truly live up to the hype. Start reading now.
http://ads.osdn.com/?ad_id=6595&alloc_id=14396&op=click
_______________________________________________
NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

2005-03-14 14:28:11

by Denis Vlasenko

[permalink] [raw]
Subject: [PATCH] sanitize logging subsystem #2

> > Patch does not introduce behavioral changes except for
> > making foregrounded mountd to really use stderr.
> > There was a bug which prevented this.
> >
> > Patch is tested. Please comment/apply.
>
> How well was it tested :-)

> > + fprintf(stderr, "%s[%d] %04d-%02d-%02d %02d:%02d:%02d %s\n",
> > + log_name, log_pid,
> > + tm->tm_year, tm->tm_mon + 1, tm->tm_mday,
> > + tm->tm_hour, tm->tm_min, tm->tm_sec,
> > + buff);

Good spotting.
Totally overlooked because this thing normally is NOT compiled in.
It sits in #ifdef VERBOSE_PRINTF. VERBOSE_PRINTF is #undef'ed.

> tm_year is "number of years since 1900", which isn't what you want to
> print out. It needs a "+1900", which I have given it.
>
> Otherwise the patch looks reasonably sane.
> The only bit that bothers me is calling openlog in mountd where it
> wasn't called before.
> mountd (on debian at least) currently prefixes all log lines with
> "rpc_mountd" as that is the program name. With this patch they will
> be prefixes with "mountd".
> This is a change and people who filter their log file (like me) might
> notice. But it probably isn't a big concern..
>
> I've committed it to CVS.

Your concern is indeed valid:

/* Initialize logging. */
if (!foreground) xlog_stderr(0);
xlog_open("mountd");
...
if (!foreground) {
int fd = sysconf (_SC_OPEN_MAX);
while (--fd > 2)
(void) close(fd);
}

This could close a fd to syslog socket!
If it indeed happens, just move xlog_open below fd
closing loop. However, you may opt to just omit xlog_open().
I will test this scenario.

Meanwhile, here are two patches to be applied on top of
first one:

nfs-utils-1.0.7_log12.diff:

* Remove unneded '\n' from xlog messages. They were discarded
by xlog anyway.
* Remove inconsistently used trailing periods and the like.

nfs-utils-1.0.7_log23.diff:

* Convert statd to use xlog. Kill log.[ch] from statd/ subdir.
* Change verbose logging in xlog.c to match one used by statd.
NB: by default stderr logging no longer includes timestamp and PID.
#define VERBOSE_PRINTF in xlog.h to revert to previous behaviour.
This will make mountd and statd logging output formats uniform.
* Remove trailing '\n' and periods from messages. Convert %m to %s+strerror(errno)

Comments?
--
vda


Attachments:
(No filename) (2.31 kB)
nfs-utils-1.0.7_log12.diff (7.06 kB)
nfs-utils-1.0.7_log23.diff (39.33 kB)
Download all attachments