Using _log instead of higher level interfaces like debug or info.

[YooSunYoung]

Currently, beamlime.core.application._LogMixin uses logger._log instead of higher interfaces like debug or info.
It is because

• It causes unexpected behavior of those high level interfaces with keyword arguments.
• When tossing *args, it is easy to accidentally unpack them, which causes TypeError: not all arguments converted during string formatting.

Here is the rough idea of what I initially tried to implement as a log wrapper,
with app_name keyword in the extra.

def info(msg, *args, **kwargs):
    logger.info(msg, *args, extra={'app_name': 'ApplicationName'})

info("sample message with arguments: %s", [1, 2, 3])

Then it had unexpected output:

ApplicationName sample message with arguments: [1, 2, 3]
sample message with arguments: [1, 2, 3]

Here are the code benchmarks for reproducing this issue.

Context

This context will apply for all following test cases.

import logging

logging.basicConfig(format="%(app_name)s  %(message)s")
logger = logging.getLogger()
logger.addHandler(logging.StreamHandler())
logger.setLevel(logging.INFO)

Key-word argument only

Passing key-word argument logs the same message twice, one with the extra-key-word app_name and one more without.
It seems like the logging is called twice as it updates the record. (Didn't really investigate deeply enough).

logger.info("sample message without arguments", extra={'app_name': 'ApplicationName'})

ApplicationName sample message without arguments
sample message without arguments

Unexpected unpacked arguments

Proper usage

arguments = ([1,2,3])
logger.info("sample message with arguments: %s %s %s", *arguments, extra={'app_name': 'ApplicationName'})

arguments = ([1,2,3], )
logger.info("sample message with arguments: %s", *arguments, extra={'app_name': 'ApplicationName'})

ApplicationName sample message with arguments: 1 2 3
sample message with arguments: 1 2 3
ApplicationName sample message with arguments: [1, 2, 3]
sample message with arguments: [1, 2, 3]

Wrong usage

It seems very obvious that it is wrong in this example, but when the *args type is general
and didn't expect any list-like object, it just happened, and took quite some time to figure out...!

arguments = ([1,2,3])
logger.info("sample message with arguments: %s", *arguments, extra={'app_name': 'ApplicationName'})

TypeError: not all arguments converted during string formatting

--- Logging error ---
Traceback (most recent call last):
File "/home/sunyoung/anaconda3/envs/lime-dev/lib/python3.9/logging/init.py", line 1083, in emit
msg = self.format(record)
File "/home/sunyoung/anaconda3/envs/lime-dev/lib/python3.9/logging/init.py", line 927, in format
return fmt.format(record)
File "/home/sunyoung/anaconda3/envs/lime-dev/lib/python3.9/logging/init.py", line 663, in format
record.message = record.getMessage()
File "/home/sunyoung/anaconda3/envs/lime-dev/lib/python3.9/logging/init.py", line 367, in getMessage
msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
File "/home/sunyoung/ESS/beamlime/test.py", line 14, in
logger.info("sample message with arguments: %s", *arguments, extra={'app_name': 'ApplicationName'})
Message: 'sample message with arguments: %s'
Arguments: (1, 2, 3)
--- Logging error ---
Traceback (most recent call last):
File "/home/sunyoung/anaconda3/envs/lime-dev/lib/python3.9/logging/init.py", line 1083, in emit
msg = self.format(record)
File "/home/sunyoung/anaconda3/envs/lime-dev/lib/python3.9/logging/init.py", line 927, in format
return fmt.format(record)
File "/home/sunyoung/anaconda3/envs/lime-dev/lib/python3.9/logging/init.py", line 663, in format
record.message = record.getMessage()
File "/home/sunyoung/anaconda3/envs/lime-dev/lib/python3.9/logging/init.py", line 367, in getMessage
msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
File "/home/sunyoung/ESS/beamlime/test.py", line 14, in
logger.info("sample message with arguments: %s", *arguments, extra={'app_name': 'ApplicationName'})
Message: 'sample message with arguments: %s'
Arguments: (1, 2, 3)