abseil interferes with python logging

[matteby]

I have a script where I'm importing a module that internally uses abseil logging. The rest of our code base is using standard python logging. This is leading to a situation where importing that module is interfering with the rest of the code base using standard logging and causing lost log messages.

See here for a description of the issue: tensorflow/hub#263

Have others run into this issue before?

[gpshead]

While this may not be the answer you want... they aren't lost, but anything below INFO is going to a log file by default with the absl logging handlers in place.

Call absl.logging.set_stderrthreshold('info') and you'll have log messages on stderr again. Though using absl's (Google's) standard log message format.

That is merely a workaround to get your messages in the console output again. I assume you aren't looking to depend on absl from your own code directly, that could be written conditionally within your main code after imports have been done:

# Work around TensorFlow's absl.logging depencency which alters the
# default Python logging output behavior when present.
if 'absl.logging' in sys.modules:
  import absl.logging
  absl.logging.set_stderrthreshold('info')  
  # and any other apis you want, if you want 

This is, for better or worse, currently working as intended, absl.logging installs logging handlers for the process at import time. Perhaps this should change so it could be a good citizen when used by libraries? We use it everywhere so we really hadn't given that (obvious in hingsight) idea a lot of thought.

[matteby]

@gpshead Thanks for the quick reply!

I tried the second workaround and that helped. For anyone else that has a similar situation, I also had to set the verbosity level:

# Work around TensorFlow's absl.logging depencency which alters the
# default Python logging output behavior when present.
import sys
if 'absl.logging' in sys.modules:
  import absl.logging
  absl.logging.set_verbosity('info')
  absl.logging.set_stderrthreshold('info')
  # and any other apis you want, if you want

+1 to your suggestion. I agree it would be nice to support use in libraries that may be used in code bases with existing logging mechanisms in place.

[dhalperi]

@gpshead have you now given any thought to this issue that you called "obvious in hindsight"?

As more and more Google-released libraries switched from not-abseil to abseil, this mucking with global state, removing existing logging handlers, overriding formats, etc. is getting really costly.

For my team, it's Capirca that's biting us. See also #102.

(cc: @tituswinters, if he's still leading Abseil)

[gpshead]

There's more to this in that library code often has no need to depend on absl.logging at all. I expect most library code can import logging (the stdlib library) and use that. (I'm assuming the function calls library code should be making are the standard debug/info/warn/warning/error APIs)

Regardless of that, getting all libraries using absl in the world to stop doing from absl import logging is probably intractable in the shorter term. Making our absl.logging._initialize() call lazy so that it is only ever done when first needed, or perhaps when explicitly desired (ie: what app._run_init() does) would be helpful. Prior to absl._initialize() the absl.logging functions should just be silent redirects to the stdlib functions.

[dhalperi]

The key issue however is that neither importing nor using absl.logging should reconfigure logging. I understand why Google internally configures logging on import or use but this does not make sense in open source. That should be moved to Google 3 main or whatever it's called.

…

On Fri, May 10, 2019 at 16:35 Gregory P. Smith ***@***.***> wrote: There's more to this in that library code often has no need to depend on absl.logging at all. I expect most library code can import logging (the stdlib library) and use that. (I'm assuming the function calls library code *should* be making are the standard debug/info/warn/warning/error APIs) Regardless of that, getting *all* libraries using absl in the world to stop doing from absl import logging is probably intractable in the shorter term. Making our absl.logging._initialize() call lazy so that it is only ever done when first needed, or perhaps when explicitly desired (ie: what app._run_init() does) would be helpful. Prior to absl._initialize() the absl.logging functions should just be silent redirects to the stdlib functions. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#99 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAEAQT3DKKRTJYUP72OK7YDPUYBFXANCNFSM4HCKQSUQ> .

[yilei]

One idea might make it better without affecting the existing user base too much.

absl.logging uses its own logger (absl.logging._absl_logger). Logs explicitly logged by absl.logging go through this logger, which propagates to root.

At import time, instead of attaching the absl.logging._absl_handler to root here, attach it to absl.logging._absl_logger and set _absl_logger.propagate = False initially.

Then in absl.logging.use_absl_handler() (called by absl.app.run()), moves the handler to root and set _absl_logger.propagate = True again.

So if a user only uses absl.logging without absl.app.run() (that's the case for most of the users who depend on a library that uses absl.logging, but themselves don't use absl.app):

1. It doesn't affect their root log configs, i.e. logs from the standard logging module goes to their own config
2. Logs logged by absl.logging is still handled by absl, e.g. it has its own formatting, goes to its own destination. But that's what the library explicitly chooses to do so by using absl.logging instead of logging.

For existing absl.app users: they loose the formatting for logs from standard logging at import time. But logs from absl.logging at import time are not affected.

[gpshead]

That's a bit of a mixed-world compromise. I suspect that libraries using absl.logging don't care about absl specific logging properties at all and are just using it because that is the standard style they've adopted our of habit rather than just import logging. Update such projects copybara code transforms to use that outside of Google and see if anyone notices. :) I'm making the assumption that non-Google authored code is unlikely to bother using from absl import logging directly.

Having logs go to potentially multiple different places in different formats based on which part of the code called the logging statement in a process could just make a different set of peoples lives messier and lead to questions about that being an undesired behavior people file an issue about.

[KristianHolsheimer]

Is there any update on this? This is currently blocking updates to Tensorflow 1.14 and 2.0.

[gpshead]

Nobody is assigned to work on this so I don't recommend blocking on a resolution.

[KristianHolsheimer]

What would you suggest people do?

• To start using absl for logging everywhere isn't a solution. It merely passes the problem along downstream like a hot potato (as per the example of tensorflow).
• The workaround to remove the absl handler might break things that expect the handler to be there.

[KristianHolsheimer]

Also, what's wrong with the "mixed-world compromise" proposed by @yilei? Seems fine to me.

The alternative would be to provide a guide on "how to monkey-patch your codebase to fix a broken state caused by abseil logging", e.g. batfish/pybatfish#370.

[KristianHolsheimer]

FYI: tensorflow/tensorflow#26691 (comment)

[gpshead]

My earlier comment answered what was wrong with mixed-world. It is cleaner to have absl.run() or absltest.main() be the installer of the absl logging handlers. Because those are delcarations of intent to do things the absl way.

That should be less complicated, less surprising, and easier to support as an API.

[pwais]

Another fix suggestion for those like me who are finding this bug via Google:

try:
  # FIXME(https://github.com/abseil/abseil-py/issues/99)
  # FIXME(https://github.com/abseil/abseil-py/issues/102)
  # Unfortunately, many libraries that include absl (including Tensorflow)
  # will get bitten by double-logging due to absl's incorrect use of
  # the python logging library:
  #   2019-07-19 23:47:38,829 my_logger   779 : test
  #   I0719 23:47:38.829330 139904865122112 foo.py:63] test
  #   2019-07-19 23:47:38,829 my_logger   779 : test
  #   I0719 23:47:38.829469 139904865122112 foo.py:63] test
  # The code below fixes this double-logging.  FMI see:
  #   https://github.com/tensorflow/tensorflow/issues/26691#issuecomment-500369493
  
  import logging
  
  import absl.logging
  logging.root.removeHandler(absl.logging._absl_handler)
  absl.logging._warn_preinit_stderr = False
except Exception as e:
  print("Failed to fix absl logging bug", e)
  pass

[jklaise]

Is there any movement on this? This is a pretty huge bug to have...

[yilei]

We have a fix and should be pushed out in a week or two.

[Lothiraldan]

It doesn't seems to be an issue as long as we don't use the root logger. We define our logger like this in all our files:

LOGGER = logging.getLogger(__name__)

And then set the propagate to False on the package level logger:

logging.getLogger(__package__).propagate = False

If that can helps someone.

[yilei]

Version 0.8.0 is released on PyPI, absl.logging no longer registers itself at import time.

Relevant commits: 05c000a and d162b02

[KristianHolsheimer]

Thanks so much for fixing this @yilei