abseil/abseil-py

Logging disappeared after switching from app.run(main) to main()

unacao opened this issue · 5 comments

There are two logging methods in our code:

import logging
logging.info('my logging msg')

or

import logging
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
logger.info('my logger msg')

When we first used app.run(main), everything is fine. All the log lines are output in absl.logging format.

Then we needed to combine absl.flags with argparse, and used your solution in #27 (Let one parser parse "known flags", and the other parse the rest. Example 2) It works great except that we need to run main() instead of app.run(main) And all the logging were gone.
So we tried to add absl.logging.use_absl_handler() in __init__.py following #148 Now we are able to see content from logger.xxx in absl.logging format, but not those from logging.xxx no matter it is from python logging or absl logging.

Did I miss anything from app.run() or not using logging correctly?

yilei commented

could you please provide a minimal repro with a full .py file? there are many nuances how and when the library is imported and the functions are called, that can result in different behaviors. so a full minimal example can help here.

# !/bin/env python3

import argparse
import logging
import sys
from absl import app, flags
import absl.logging
absl.logging.use_absl_handler()

logger = logging.getLogger('test')
logger.setLevel(logging.DEBUG)

def main(args=None):
    if args is None:
        args = sys.argv

    unparsed = flags.FLAGS(args, known_only=True)  # Let absl.flags parse known flags first
    parser = argparse.ArgumentParser()
    args = parser.parse_args(unparsed[1:])  # Let argparse parse the rest of flags
    # args = parser.parse_args(args[1:])
    
    print('print: Finish parsing')
    logging.info('logging: Finish parsing')
    absl.logging.info('absl logging: Finish parsing')
    logger.info('logger: Finish parsing')

if __name__ == "__main__":
    # app.run(main)
    main()

Thanks! This script should be able to reproduce the issue.

print: Finish parsing
I0718 13:39:39.888040 140067313977152 main.py:23] logging: Finish parsing
I0718 13:39:39.888194 140067313977152 main.py:24] absl logging: Finish parsing
I0718 13:39:39.888281 140067313977152 main.py:25] logger: Finish parsing
print: Finish parsing
I0718 13:41:15.937640 140668410611520 main.py:25] logger: Finish parsing

I think it is related to verbosity, but thought absl.logging.use_absl_handler() already handled it in _update_logging_levels()?

yilei commented

Yes, this is caused by verbosity.

The default verbosity when not using app.run(main) is WARNING, matching the standard logging behavior. absl sets its own default verbosity to INFO here, which isn't called by your code.

So you can either set the --verbosity flag or the root logger's verbosity explicitly.

That being said, if you only need to run main() instead of app.run(main) because you want to use argparse, you can use the absl.flags.argparse_flags.ArgumentParser drop-in replacement together with app.run like this:

def parse_flags(argv):
  parser = absl.flags.argparse_flags.ArgumentParser(...)
  # Add your own argparse flags, this parser understands the flags defined using `absl.flags`.
  return parser.parse_args(argv[1:])

if __name__ == "__main__":
    app.run(main, flags_parser=parse_flags)

Hope this helps.

Thanks!