fix wrong logging behavior [RHELDST-3788]

[dichn]

Missing "logging.basicConfig" resulted in wrong logging behavior,
No handlers could be found for logger "altsrc", instead of showing
the real valuable info, e.g. "ERROR:altsrc:Missing config file:".

# before fixing it
[root@dichen-pub-iib rpmbuild]# alt-src --push c7 funny-tom-1.1-4.src.rpm -c xxxx
No handlers could be found for logger "altsrc"

# after adding basicConfig
[root@dichen-pub-iib rpmbuild]# alt-src --push c7 funny-tom-1.1-4.src.rpm -c xxxx
ERROR:altsrc:Missing config file: xxxx

[rohanpm]

Two issues with this:

• this shouldn't be done at the top level like this, because it means even just importing the file is going to change loggers (as is done e.g. by tests). If we'll call logging.basicConfig, then can you please have that inside of "main" somewhere?

• alt-src already has a setup_logging function and I'm not sure these are going to work together correctly. As I understand it, this logging.basicConfig is going to install a default handler, but then in setup_logging, another StreamHandler to sys.stdout is added.

Due to the second problem, I would suspect that this could result in duplicate log messages, i.e. some logs coming out twice instead of once. I haven't tested it though. Have you tried it?

[dichn]

@rohanpm, the trouble is the handlers of a logger are set up after options.config = get_config(options.cfile, options.copts),
but the get_config process can also be corrupted and need a logger to track this.
So if the something wrong happens in get_config, then there is no handler.
This PR is not ready.

[rohanpm]

Yeah, I understand that.

In another comment I've suggested changes to setup_logging which could make this work correctly. As well as that, a couple suggestions here:

• don't pass "filename". What's the point? CONFIG_DEFAULTS["log_file"] is always None.
• I think a comment explaining this would be worthwhile. Like "We don't know the desired log config until we've read the config file, but we might need to log something before then - so ensure there's at least some basic config (to be replaced later)."

[dichn]

updated the commit message to this

    fix wrong logging behavior
    
    Handler configuration based on the result of "get_config" in main function,
    but if something wrong happens in "get_config", the "logger.handlers" will
    be empty, and result in the error 'No handlers could be found for logger "altsrc"'.

[dichn]

@rohanpm for your second question:

alt-src/alt_src/alt_src.py

Line 2205 in 810c98a

tasks = [Stager(options)]

After this line, I tried print out this
print(logger.handlers), only got one handler,
[<logging.StreamHandler instance at 0x1f82ef0>]

[rohanpm]

@rohanpm for your second question:

alt-src/alt_src/alt_src.py

Line 2205 in 810c98a

tasks = [Stager(options)]

After this line, I tried print out this
print(logger.handlers), only got one handler,
[<logging.StreamHandler instance at 0x1f82ef0>]

You need to consider handlers on the root logger too.

I pulled this locally and confirmed that there is indeed a duplicate message problem:

2157 	    # TODO - setup koji's logger?
2158 	
2159 	    import pdb; pdb.set_trace()
2160 ->	    if config_warning:
2161 	        logger.warning(config_warning)

# PROBLEM: message is logged twice (with two different formats...)
(Pdb) logger.warning("test")
2020-11-02 08:27:17,866 [WARNING] test
WARNING:altsrc:test

# It's because both this logger and root logger have handlers
(Pdb) logging.getLogger().handlers
[<StreamHandler <stderr> (NOTSET)>]

(Pdb) logger.handlers
[<StreamHandler <stdout> (WARNING)>]

I would say the desired setup (which alt-src actually doesn't implement correctly right now) is:

• only the root logger has handlers
• it always has exactly one StreamHandler
• it may also have an additional FileHandler (if log_file is set)

Therefore I think an appropriate way to get this all working would be:

• keep your call to logging.basicConfig
• change logic in setup_logging so:
  • it removes existing handler on root logger
  • it adds handlers to root logger rather than "altsrc" logger

[dichn]

git commit message updated

fix wrong logging behavior
    
    1. Handler configuration based on the result of "get_config" in main function,
    but if something wrong happens in "get_config", the "logger.handlers" will
    be empty, and result in the error 'No handlers could be found for logger "altsrc"'.
    
    Add logging.basicConfig in main function for root logger's default handler creation,
    this is used to catch log before "setup_logging" is called.
    
    Update logic in setup_logging:
    - it removes existing handler on root logger.
    - it adds handlers to root logger based on the result of "get_config" function.
    
    2. Update unit tests for root logger handler cleaning.
    
    3. Replace "logger.warn" with "logger.warning" to avoid
    "DeprecationWarning: The 'warn' method is deprecated,
    use 'warning' instead".

[rohanpm]

I have not reviewed fully, but two points on this before completing review:

• for all those warn => warning changes. Can you please do that in a separate PR? I don't see a reason to combine it into this PR. Note if you did it separately, that could more easily pass review and not be blocked by other matters.
• why change it to use the root logger everywhere rather than the "altsrc" logger as it was before? I think this is not a good change as it makes the code less reusable across environments. For example, maybe we want to run this code directly within Pub and we may want to enable DEBUG logs just for altsrc without enabling them for everything else.

The second point is the main issue here, I don't want to review it fully until that is addressed in case undoing that change somehow breaks it again.

[rohanpm]

Hmm... sorry, I'm having a doubt that this makes sense (or at least the comment).

logger here is the "altsrc" logger.

logging.basicConfig is expected to install a handler on the root logger.

So, wouldn't logger.handlers already be empty here? Why would altsrc logger have handlers at all, at this point in the code?

Also: with the current approach then, this is still only fixing the setup correctly for altsrc logger. Messages from other loggers won't end up going to the stream or file handlers here since it's only being installed on the altsrc logger.

This is what I said in an earlier comment:

I would say the desired setup (which alt-src actually doesn't implement correctly right now) is:

• only the root logger has handlers
• it always has exactly one StreamHandler
• it may also have an additional FileHandler (if log_file is set)

I think that's still valid and it'd be preferable to implement it that way.

[rohanpm]

Overall looks fine, would be nice to fix that trivial formatting issue.

[dichn]

@rohanpm formatting issue fixed