Add log(9) support to witness

[ngie]

Summary

Add log(9) support to witness(4)

The goal of this change is to modify certain printouts (mostly stack traces
and LOR summaries) to avoid interspersing witness(4) output on /dev/console,
which can confuse brittle automation that interacts directly with it (and plus it
looks cleaner to end-users running debug builds).

The default log priority is LOG_DEBUG.

Allow the end-user to adjust the log priority at boot/runtime via
debug.witness.log_priority tunable/sysctl.

MFC after: 2 weeks
Sponsored by: EMC / Isilon Storage Division

Test Plan

• Verified that the output is still recorded in the kernel buffer by entering

ddb and executing "show msgbuf".

• Verified that the LOR output was still reported at reboot from UFS.
• Set debug.witness.log_priority (sysctl/tunable) to 0 (LOG_EMERG), -1,

7 (LOG_EMERG), and 42 to ensure that the log priority was validated properly.

[ngie]

sys/kern/subr_witness.c

109

Should add #ifdef WITNESS_USE_SYSLOG here.

[ngie]

This change isn't sufficient for fixing #ifdef STACK. I need to change kdb_backtrace to accept a callback function.

[kib]

If 'brittle automation' is confused by WITNESS output, why have WITNESS turned on ?

That said, it is heavy-weight to require recompile the kernel to turn off console output for witness. If doing this at all, loader tunable and sysctl should be enough, i.e. it should be presented unconditionally.

[wblock]

share/man/man4/witness.4

123

Suggestion:
s/printing out/displaying/
s/and lock order/and/

126

s/via/with/

128

Seems like this should be

using either
.Xr sysctl 8
or

132

I would write this as

The
.Va debug.witness.watch
value specifies...

136

s/but that can/but can/

137

New sentences should begin on new lines. (I know, this is just shown as diff context.)

[jhb]

WITNESS output can be logged from contexts where printf() is barely usable. log() is heavier weight, to it seems likely to be even more brittle. On the other hand, witness tracks known LORs (a new feature that came from Isilon already) which are reported via the 'badstacks' sysctl. Is that not sufficient for your tracking needs?

[kib]

In D1794#10, @jhb wrote:

WITNESS output can be logged from contexts where printf() is barely usable. log() is heavier weight, to it seems likely to be even more brittle.

I wanted to write a reply along these lines first, but it is not fair, it seems. log(9) appends a message to the msgbuf, which is half of the action of printf(9). The patch just cuts half of the actions to put the information out, since printf(9) appends to msgbuf and outputs to console.

[jhb]

Hmm, fair enough. I do agree with making this just be always on in that case. You should probably turn witness_log() into a function and then use vlog/vprintf.

[ngie]

In D1794#7, @kostikbel wrote:

If 'brittle automation' is confused by WITNESS output, why have WITNESS turned on ?

It's an unfortunate political battle that I don't have the energy to fight. Testing changes needed to make a single script is a bureaucratical quagmire, and (funny as this sounds), this was a considerably simpler solution to the problem.

That and toggling witness (1 -> 0, do sensitive /dev/console task, then set to 0 -> 1 afterwards) is broken in our project due to other kernel bugs, but that's an aside..

That said, it is heavy-weight to require recompile the kernel to turn off console output for witness. If doing this at all, loader tunable and sysctl should be enough, i.e. it should be presented unconditionally.

I've thought about this more extensibly and the printf(9)s should be converted to log(9) (or equivalent vlog calls... which I'll need to add).

I'll have to duplicate some kdb(4) KPIs for witness(9) for stack dumping, but fortunately they're tiny (I wish C supported lambdas like C++ and python -- it'd be so much easier *sigh*).

[kib]

In D1794#13, @ngie wrote:

In D1794#7, @kostikbel wrote:

If 'brittle automation' is confused by WITNESS output, why have WITNESS turned on ?

It's an unfortunate political battle that I don't have the energy to fight. Testing changes needed to make a single script is a bureaucratical quagmire, and (funny as this sounds), this was a considerably simpler solution to the problem.

That and toggling witness (1 -> 0, do sensitive /dev/console task, then set to 0 -> 1 afterwards) is broken in our project due to other kernel bugs, but that's an aside..

I cannot make any sense in relation to the FreeBSD project from what you are saying.

Why this should have any impact on the FreeBSD ?

That said, it is heavy-weight to require recompile the kernel to turn off console output for witness. If doing this at all, loader tunable and sysctl should be enough, i.e. it should be presented unconditionally.

I've thought about this more extensibly and the printf(9)s should be converted to log(9) (or equivalent vlog calls... which I'll need to add).

No, it shall not. The printf/log is already nicely structured.

I'll have to duplicate some kdb(4) KPIs for witness(9) for stack dumping, but fortunately they're tiny (I wish C supported lambdas like C++ and python -- it'd be so much easier *sigh*).

[ngie]

In D1794#14, @kostikbel wrote:

I cannot make any sense in relation to the FreeBSD project from what you are saying.

Why this should have any impact on the FreeBSD ?

You're right -- it doesn't impact FreeBSD. I should have been less vague and said "work project".

...

I've thought about this more extensibly and the printf(9)s should be converted to log(9) (or equivalent vlog calls... which I'll need to add).

No, it shall not. The printf/log is already nicely structured.

log(9) doesn't have a variadic analog. I suppose adding it doesn't matter though because it wouldn't solve my problem when printing out stack traces.

I'll have to duplicate some kdb(4) KPIs for witness(9) for stack dumping, but fortunately they're tiny (I wish C supported lambdas like C++ and python -- it'd be so much easier *sigh*).

[ngie]

• Update the stack printouts to call log(9) instead of printf(9)
• Apply review comments to always use log(9) instead of inventing a kernel option/fork-in-the-road in subr_witness to print out via syslog/printf
• Update witness(4) to better describe what's being delivered
• Convert some printf(9)'s to blatant log(9) (this should be discussed as I'm not entirely sure if everything that I converted to log(9) should be log(9) as opposed to printf(9)).

[ngie]

In D1794#14, @kostikbel wrote:

I cannot make any sense in relation to the FreeBSD project from what you are saying.

Why this should have any impact on the FreeBSD ?

You're right -- it doesn't impact FreeBSD. I should have been less vague and said "work project".

...

I've thought about this more extensibly and the printf(9)s should be converted to log(9) (or equivalent vlog calls... which I'll need to add).

No, it shall not. The printf/log is already nicely structured.

log(9) doesn't have a variadic analog. I suppose adding it doesn't matter though because it wouldn't solve my problem when printing out stack traces.

I'll have to duplicate some kdb(4) KPIs for witness(9) for stack dumping, but fortunately they're tiny (I wish C supported lambdas like C++ and python -- it'd be so much easier *sigh*).

In retrospect, this was easy to do.

share/man/man4/witness.4

119

printed out -> output

sys/kern/subr_kdb.c

395–400

XXX: go back and make sure that these functions won't fail with a non-zero return code.

sys/kern/subr_witness.c

1146–1162

XXX: should these be printfs (all of them precede potential panics, so my guess is yes..)?

[kib]

This is completely wrong patch. You break all usability of the witness for people who do read and react to the witness reports. 80% of this activity happens during the interaction with console, and it is highly probable that it happens in single-user mode and/or is followed by a panic.

It was noted to you earlier, that you have two choices: stop compiling witness into your kernel if you do not want to see its messages, or add a runtime knob to select log or printf for witness, with the default value pointing to printf.

[ngie]

In D1794#21, @kostikbel wrote:

This is completely wrong patch. You break all usability of the witness for people who do read and react to the witness reports. 80% of this activity happens during the interaction with console, and it is highly probable that it happens in single-user mode and/or is followed by a panic.

It was noted to you earlier, that you have two choices: stop compiling witness into your kernel if you do not want to see its messages, or add a runtime knob to select log or printf for witness, with the default value pointing to printf.

Some additional context that I didn't provide before: the attempt shown in this diff works on head, but not internally at Isilon (at least with some of the stack printing changes we have), so that's a non-starter. This diff seems to poke around a lot of subsystems unnecessarily too and it makes me less than happy.

Alternatively, I could add a sysctl/tunable to mute the printfs in witness_checkorder. That way we (Isilon) could look at debug.witness.badstacks, and after our brittle automation is run, we (Isilon) can unmute the printfs.

[ngie]

Closing CR that's been superseded by https://reviews.freebsd.org/D4183