ntpd: really enable debug messages

Discussion:

Brent Cook

2016-01-20 12:31:44 UTC

Since the relatively recent logging unification, log_init needs a
debug level > 1 in order for log_debug to print anything. This change
makes it so 'ntpd -d' stays in the foreground but doesn't log much
(the current behavior, different than previous releases though), 'ntpd
-dd' actually prints more verbose debug messages.

Index: ntpd.8
===================================================================
RCS file: /cvs/src/usr.sbin/ntpd/ntpd.8,v
retrieving revision 1.40
diff -u -p -u -p -r1.40 ntpd.8
--- ntpd.8 30 Oct 2015 16:41:53 -0000 1.40
+++ ntpd.8 20 Jan 2016 12:31:16 -0000
@@ -50,6 +50,7 @@ If this option is specified,
.Nm
will run in the foreground and log to
.Em stderr .
+It may be specified again to enable more verbose debug logs.
.It Fl f Ar file
Use
.Ar file
Index: ntpd.c
===================================================================
RCS file: /cvs/src/usr.sbin/ntpd/ntpd.c,v
retrieving revision 1.103
diff -u -p -u -p -r1.103 ntpd.c
--- ntpd.c 11 Jan 2016 15:30:56 -0000 1.103
+++ ntpd.c 20 Jan 2016 12:31:16 -0000
@@ -137,7 +137,7 @@ main(int argc, char *argv[])
while ((ch = getopt(argc, argv, "df:nsSv")) != -1) {
switch (ch) {
case 'd':
- lconf.debug = 1;
+ lconf.debug++;
log_verbose(1);
break;
case 'f':

Sebastian Benoit

2016-01-20 13:23:04 UTC

Permalink

in relayd we use -v for that, so you need to run -dvvvv to get lots of
output. check main() there?

i think thats more intuitive, but maybe i'm just used to it.

Post by Brent Cook
Since the relatively recent logging unification, log_init needs a
debug level > 1 in order for log_debug to print anything. This change
makes it so 'ntpd -d' stays in the foreground but doesn't log much
(the current behavior, different than previous releases though), 'ntpd
-dd' actually prints more verbose debug messages.
Index: ntpd.8
===================================================================
RCS file: /cvs/src/usr.sbin/ntpd/ntpd.8,v
retrieving revision 1.40
diff -u -p -u -p -r1.40 ntpd.8
--- ntpd.8 30 Oct 2015 16:41:53 -0000 1.40
+++ ntpd.8 20 Jan 2016 12:31:16 -0000
@@ -50,6 +50,7 @@ If this option is specified,
.Nm
will run in the foreground and log to
.Em stderr .
+It may be specified again to enable more verbose debug logs.
.It Fl f Ar file
Use
.Ar file
Index: ntpd.c
===================================================================
RCS file: /cvs/src/usr.sbin/ntpd/ntpd.c,v
retrieving revision 1.103
diff -u -p -u -p -r1.103 ntpd.c
--- ntpd.c 11 Jan 2016 15:30:56 -0000 1.103
+++ ntpd.c 20 Jan 2016 12:31:16 -0000
@@ -137,7 +137,7 @@ main(int argc, char *argv[])
while ((ch = getopt(argc, argv, "df:nsSv")) != -1) {
switch (ch) {
- lconf.debug = 1;
+ lconf.debug++;
log_verbose(1);
break;

Brent Cook

2016-01-23 18:39:19 UTC

Permalink

I'm going with this instead. That way it works like the manual
specifies already (-v enables logging debug messages)

cvs server: Diffing .
Index: ntpd.c
===================================================================
RCS file: /cvs/src/usr.sbin/ntpd/ntpd.c,v
retrieving revision 1.103
diff -u -p -r1.103 ntpd.c
--- ntpd.c 11 Jan 2016 15:30:56 -0000 1.103
+++ ntpd.c 23 Jan 2016 18:36:52 -0000
@@ -138,7 +138,7 @@ main(int argc, char *argv[])
switch (ch) {
case 'd':
lconf.debug = 1;
- log_verbose(1);
+ log_verbose(2);
break;
case 'f':
conffile = optarg;
@@ -153,7 +153,7 @@ main(int argc, char *argv[])
lconf.settime = 0;
break;
case 'v':
- log_verbose(1);
+ log_verbose(2);
break;
default:
usage();

Post by Sebastian Benoit
in relayd we use -v for that, so you need to run -dvvvv to get lots of
output. check main() there?
i think thats more intuitive, but maybe i'm just used to it.

Reyk Floeter

2016-01-23 19:48:22 UTC

Permalink

Post by Brent Cook
I'm going with this instead. That way it works like the manual
specifies already (-v enables logging debug messages)

Yes, the -v flag is better, but see below.

Post by Brent Cook
cvs server: Diffing .
Index: ntpd.c
===================================================================
RCS file: /cvs/src/usr.sbin/ntpd/ntpd.c,v
retrieving revision 1.103
diff -u -p -r1.103 ntpd.c
--- ntpd.c 11 Jan 2016 15:30:56 -0000 1.103
+++ ntpd.c 23 Jan 2016 18:36:52 -0000
@@ -138,7 +138,7 @@ main(int argc, char *argv[])
switch (ch) {
lconf.debug = 1;
- log_verbose(1);
+ log_verbose(2);

This will get overridden by the various log_init() calls later.

You should better set a "verbose" variable in the switch statements
and call log_verbose() after the various log_init() calls later
(ntpd's puristic privsep has to call it in various places).

log_init(..)
log_verbose(verbose)

Splitting log_init() and log_verbose() allowed us to change the
verbose flag during runtime; for example "relayctl verbose" allows to
toggle the flag and calls log_verbose() internally. Maybe ntpctl is
too minimalistic for it, but I would prefer if ntpd could follow the
same/similar semantics in its main().

Reyk

Post by Brent Cook
break;
conffile = optarg;
@@ -153,7 +153,7 @@ main(int argc, char *argv[])
lconf.settime = 0;
break;
- log_verbose(1);
+ log_verbose(2);
break;
usage();

Post by Sebastian Benoit
in relayd we use -v for that, so you need to run -dvvvv to get lots of
output. check main() there?
i think thats more intuitive, but maybe i'm just used to it.

Brent Cook

2016-01-24 19:10:34 UTC

Permalink

Post by Reyk Floeter

Post by Brent Cook
I'm going with this instead. That way it works like the manual
specifies already (-v enables logging debug messages)

Yes, the -v flag is better, but see below.

This will get overridden by the various log_init() calls later.
You should better set a "verbose" variable in the switch statements
and call log_verbose() after the various log_init() calls later
(ntpd's puristic privsep has to call it in various places).
log_init(..)
log_verbose(verbose)
Splitting log_init() and log_verbose() allowed us to change the
verbose flag during runtime; for example "relayctl verbose" allows to
toggle the flag and calls log_verbose() internally. Maybe ntpctl is
too minimalistic for it, but I would prefer if ntpd could follow the
same/similar semantics in its main().

How's this? It makes the logic look just like relayd. This was a good
exercise, because I found a nice bug while trying to exercise the
log_debug messages. ok?

Index: ntpd.h
===================================================================
RCS file: /cvs/src/usr.sbin/ntpd/ntpd.h,v
retrieving revision 1.127
diff -u -p -r1.127 ntpd.h
--- ntpd.h 19 Dec 2015 20:44:35 -0000 1.127
+++ ntpd.h 24 Jan 2016 19:07:25 -0000
@@ -213,9 +213,10 @@ struct ntpd_conf {
struct ntp_status status;
struct ntp_freq freq;
u_int32_t scale;
+ int debug;
+ int verbose;
u_int8_t listen_all;
u_int8_t settime;
- u_int8_t debug;
u_int8_t noaction;
u_int8_t filters;
time_t constraint_last;
Index: ntpd.c
===================================================================
RCS file: /cvs/src/usr.sbin/ntpd/ntpd.c,v
retrieving revision 1.103
diff -u -p -r1.103 ntpd.c
--- ntpd.c 11 Jan 2016 15:30:56 -0000 1.103
+++ ntpd.c 24 Jan 2016 19:07:25 -0000
@@ -132,18 +132,16 @@ main(int argc, char *argv[])

memset(&lconf, 0, sizeof(lconf));

- log_init(1, LOG_DAEMON); /* log to stderr until daemonized */
-
while ((ch = getopt(argc, argv, "df:nsSv")) != -1) {
switch (ch) {
case 'd':
- lconf.debug = 1;
- log_verbose(1);
+ lconf.debug = 2;
break;
case 'f':
conffile = optarg;
break;
case 'n':
+ lconf.debug = 2;
lconf.noaction = 1;
break;
case 's':
@@ -153,7 +151,7 @@ main(int argc, char *argv[])
lconf.settime = 0;
break;
case 'v':
- log_verbose(1);
+ lconf.verbose++;
break;
default:
usage();
@@ -161,6 +159,9 @@ main(int argc, char *argv[])
}
}

+ /* log to stderr until daemonized */
+ log_init(lconf.debug ? lconf.debug : 1, LOG_DAEMON);
+
argc -= optind;
argv += optind;
if (argc > 0)
@@ -190,6 +191,7 @@ main(int argc, char *argv[])
reset_adjtime();
if (!lconf.settime) {
log_init(lconf.debug, LOG_DAEMON);
+ log_verbose(lconf.verbose);
if (!lconf.debug)
if (daemon(1, 0))
fatal("daemon");
@@ -269,6 +271,7 @@ main(int argc, char *argv[])
lconf.settime = 0;
timeout = INFTIM;
log_init(lconf.debug, LOG_DAEMON);
+ log_verbose(lconf.verbose);
log_warnx("no reply received in time, skipping initial "
"time setting");
if (!lconf.debug)
@@ -395,6 +398,7 @@ dispatch_imsg(struct ntpd_conf *lconf, c
if (!lconf->settime)
break;
log_init(lconf->debug, LOG_DAEMON);
+ log_verbose(lconf->verbose);
memcpy(&d, imsg.data, sizeof(d));
ntpd_settime(d);
/* daemonize now */