Minor logging setup refactors

[nrwahl2]

I think this is everything I have queued up for logging. I did this work a few months ago and updated it just now.

I also really want to make sense of the callsite stuff. However, this setup/scaffolding code is the easier part, so I might as well make it less of an eyesore first.

I am not actively working on anything else in the Pacemaker logging code. I'm opening this PR to avoid conflicts with anything Chris is working on.

[clumens]

It looks like nothing has ever called crm_log_deinit aside from an old test program.

[nrwahl2]

Right. But since we have crm_log_init(), it seems reasonable to put the cleanup stuff in crm_log_deinit().

Or we could go ahead and deprecate it, and just have a private cleanup function.

[clumens]

Yeah I'm fine with using it. I was just curious about the historical context, as well as whether there's a way to determine whether you can find all references to a string throughout history using git.

[clumens]

Too many arguments for format string

[clumens]

You've done so much work to lib/common/logging.c that it would be nice to also run include-what-you-use and take care of that at the same time.

[clumens]

I mentioned this in slack the other day, but it's worth repeating here. I really dislike how i18n is configured at the end of crm_log_preinit. It's clearly its own setup step unrelated to logging.

First, its position in that function and file makes it feel like something that'll happen as part of library init (I don't think this code gets called anywhere but for command line programs, but it's hard to say with the logging stuff) which shouldn't be done.

Second, it needs to happen pretty much first thing in any command line program, earlier than logging setup. This is in case we ever get around to translating --help output. The basic order needs to be: i18n, argument processing, formatted output, logging. One wrinkle here is that i18n setup calls pcmk__assert which could end up calling logging functions. Oh well.

Anyway, I was wondering if you had any thoughts on this since you're in the area, or if this was something you were planning on looking at in an upcoming PR.

[clumens]

One last observation about logging in general. I hate that we have pcmk__cli_init_logging, crm_log_init, and crm_log_preinit. I hate that they call each other. I hate that daemons call pcmk__cli_init_logging (which calls the other two) and then call the others as well. I do like that command line tools only call pcmk__cli_init_logging... except for crm_shadow, which also calls crm_log_preinit, which I hate.

The whole stack is just so annoying.

[nrwahl2]

Anyway, I was wondering if you had any thoughts on this since you're in the area, or if this was something you were planning on looking at in an upcoming PR.

I have given this zero thought up to this point, and so it's not something I was specifically planning to address in an upcoming PR. Right now as far as refactors go, I'm focused on pacemaker-based and ACL/XML code.

[nrwahl2]

First, its position in that function and file makes it feel like something that'll happen as part of library init... which shouldn't be done.

What do you mean it shouldn't be done? Why not?

I don't think this code gets called anywhere but for command line programs, but it's hard to say with the logging stuff

It gets called by all of our CLI tools, yes, and also by all of our daemons. Nearly everything that Pacemaker runs as a process -- agents are the only exceptions that come to mind -- will call this, often via crm_log_init(). Further, crm_log_init() has been our de facto library init function. I think there's an upstream task to improve that situation.

Second, it needs to happen pretty much first thing in any command line program, earlier than logging setup.

Right, this is another motivation to improve the library init organization. I don't have much else to say about that. I agree that it's not great.

One wrinkle here is that i18n setup calls pcmk__assert which could end up calling logging functions.

Yeah, it makes sense that we can't log an internationalized message if internationalization has failed, unfortunately.

[clumens]

Oh, one more question I had. Have you tried any of the blackbox stuff, either before or after these patches? I haven't, so I'm curious if it works and if it's useful.

[nrwahl2]

Oh, one more question I had. Have you tried any of the blackbox stuff, either before or after these patches? I haven't, so I'm curious if it works and if it's useful.

I have not.

I think I've used blackbox once or twice in my life (several years ago at this point), and it was more out of curiosity than anything. I don't remember gaining anything useful from it. Which leads me to wonder when or if it's ever useful in practice. We could be either missing out on something that would save us time diagnosing crashes, etc., or maintaining clutter for no reason haha.

[nrwahl2]

Which leads me to wonder when or if it's ever useful in practice. We could be either missing out on something that would save us time diagnosing crashes, etc., or maintaining clutter for no reason haha.

Based on its description, it seems mostly intended for diagnosing crashes. (I don't know when a SIGTRAP would ever be relevant.) I've mostly used gdb combined with simple log analysis for that so far, and it's served me pretty well. Crashes and assertion failures typically dump a core.

I want to be charitable and think of ways this could help us, but I'm struggling to come up with anything that we can't get by simply reading /var/log/pacemaker/pacemaker.log. The only thing that's coming to mind, is that it avoids the need to explicitly enable debugging and tracing for specific components/functions/files -- the blackbox, once enabled, keeps log messages of all severities.

# Enable blackbox logging globally (yes or no) or by subsystem. A blackbox
# contains a rolling buffer of all logs (of all severities). Blackboxes are
# stored under /var/lib/pacemaker/blackbox by default, and their contents can
# be viewed using the qb-blackbox(8) command.
#
# The blackbox recorder can be enabled at start using this variable, or at
# runtime by sending a Pacemaker subsystem daemon process a SIGUSR1 or SIGTRAP
# signal, and disabled by sending SIGUSR2 (see kill(1)). The blackbox will be
# written after a crash, assertion failure, or SIGTRAP signal.