How are ABSL_RAW_LOG verbosity levels set?

[pradn]

Several users of the Cloud Pub/Sub Python GRPC library have reported huge spikes in logging. See here for more details.

The logs are coming from this line in mutex.cc. Which env variable or command line flag controls whether this line, which emits raw INFO logs, actually prints strings to stdout/stderr? How is it possible for the logs to be turned on without the users' knowledge? AFAIK, both env vars and cmd line flags are set at program start up. Is it possible for the verbosity level to change after the fact?

I'm waiting for the user to respond with the program's env vars and cmd flags. I hope that'll shed some light on the matter.

[derekmauro]

There is no control for ABSL_RAW_LOG. It always prints to stderr.

The only cause that I'm aware of is someone calling Mutex::EnableDebugLog() or CondVar::EnableDebugLog().

[pradn]

It looks like the logging is enabled if either:

1. the mutex has had Mutex::EnableDebugLog(string name) called on it.

   abseil-cpp/absl/synchronization/mutex.cc

   Line 741 in ec0d76f

   void Mutex::EnableDebugLog(const char *name) {

2. OR if mutex event recording is on in general for the particular mutex obj.

   abseil-cpp/absl/synchronization/mutex.cc

   Line 632 in ec0d76f

   static const intptr_t kMuEvent = 0x0010L; // record this mutex's events

If these logs were being emitted via path 1, I'd expect the string passed into EnableDebugLog to be visible in the debug log. We're seeing logs like 2021-11-03 15:08:55.861 EDT[mutex.cc : 435] RAW: Lock blocking 0x7f0c66b9cb78 @. The format for this line is specified here. The name would be the penultimate fragment in the line, before the @ but is instead absent. It's empty bc the ternary operator in the next line. So, I think it's likely the issue is b/c path 2.

I can't quite make out the logic for how kMuEvent is set. When is it set? Is it possible to change it on the fly? Is it plausible that an issue with setting it is what's causing the customer's issue?

[derekmauro]

We don't believe this is an issue on our side and and cannot investigate further without reproduction instructions.

[acocuzzo]

We have more customers experiencing this verbose logging: googleapis/python-pubsub#540
Are you able to answer @pradn's question as to how kMuEvent is set?

[derekmauro]

I'm not aware of any way for a well-behaved program to accidentally turn on the debug logging. Two possible explanations come to mind.

1. The program is experiencing memory corruption and is overwriting the bit. It seems unlikely that such a program would not crash or deadlock, so I doubt this is the case.

2. The program has an ODR violation (or a similar problem). If somehow there are two copies of the synch_event hash table, I could imagine it searching the wrong one.

Since all reports seem to be coming from programs wrapping C++ into another language, I would look into (2).

[acocuzzo]

Thanks @derekmauro