`child=True` is not creating a logger?

[lorengordon]

What were you trying to accomplish?

Re-use a logger in a sub-module, using the child=True feature, per the documentation.

Expected Behavior

With the following setup, there should be two log entries, one with "service": "foo" and one with "service": "foo.bar".

cat foo.py:

$ cat foo.py
import aws_lambda_powertools
import bar

log = aws_lambda_powertools.Logger(service="foo")

log.info('hallelujah')
bar.bar()

cat bar.py:

import aws_lambda_powertools

log = aws_lambda_powertools.Logger(child=True)

def bar():
    log.info('doublestuff')

Current Behavior

$ python foo.py
{"timestamp": "2020-08-27 11:20:16,245", "level": "INFO", "location": "<module>:6", "service": "foo", "sampling_rate": 0.0, "message": "hallelujah"}

Even setting the service explicitly in the submodule to foo.bar, the service remains foo in the output, though at least now their are two log entries.

cat bar.py:

$ cat bar.py
import aws_lambda_powertools

log = aws_lambda_powertools.Logger(service="foo.bar", child=True)

def bar():
    log.info('doublestuff')

$ python foo.py
{"timestamp": "2020-08-27 11:26:05,330", "level": "INFO", "location": "<module>:6", "service": "foo", "sampling_rate": 0.0, "message": "hallelujah"}
{"timestamp": "2020-08-27 11:26:05,330", "level": "INFO", "location": "bar:6", "service": "foo", "sampling_rate": 0.0, "message": "doublestuff"}

Steps to Reproduce (for bugs)

See above.

Environment

• Powertools version used: 1.4.0
• Packaging format (Layers, PyPi): PyPi
• AWS Lambda function runtime: running locally, not in lambda yet

[michaelbrewer]

I would suspect this is at fault:

handlers = self._logger.parent.handlers if self.child else self._logger.handlers

[heitorlessa]

Hey Loren - Thanks for raising this issue.

If you set service="foo" in your child in the first example it should work.

We need to make the docs clearer here, so please allow me to explain what's going on (I'm on my phone so it'll be a longer response than usual)

Service is what defines what the function is responsible for, or part of (e.g payment service).

For Logger, the service is the logging key customers will use to search log operations for one or more functions, for example - "Search for all error, or messages like X, where service is payment".

That said, customers can set the service using explicit arguments, but typically use as an environment variable since it's used across all utilities and to avoid repetition - POWERTOOLS_SERVICE_NAME

With that hopefully explained, let's get to inheritance.

Python Logging hierarchy happens at the dot notation (service, service.child, service.child_2).
For that to work seamlessly, we name all parent Loggers, no child param, with the value defined in the service param.

For child Loggers we introspect the name of your module where Logger(child=True) is called, and name your Logger as "service.filename".

Once both Loggers are registered, and Python Logging recognises the dot notation, it fixes up the hierarchy and event propagation.

Why the first sample didn't work

Python Logger doesn't recognise as a parent + child loggers because their names are different, since service param value is different.

• Parent logger is named "foo"
• Child logger is named "service_undefined"

If you were to use the same service name in the Child logger that should work, as that will then be "foo.bar", where bar comes from bar.py

Why the service key isn't foo.bar

That's because of consistency. The service/application is still the same despite having multiple Loggers.

Sorry for the long explanation but hope that clarifies it - Lemme know otherwise :)

Thanks

[lorengordon]

@heitorlessa Ok, perhaps I'm just not using this library correctly then. All the examples assume service, where python loggers are more typically using the logger name in the record. So I just assumed service === name for the purposes of this library.

I suppose I don't particularly care about the service name for our use case. I do care about specifically where in the module the message was generated. It looks like this module is using the location for that purpose, but that is just bar instead of the logger name (foo.bar).

$ cat bar.py
import aws_lambda_powertools

log = aws_lambda_powertools.Logger(service="foo", child=True)

def bar():
    log.info('doublestuff')

$ python foo.py
{"timestamp": "2020-08-27 12:02:10,669", "level": "INFO", "location": "<module>:6", "service": "foo", "sampling_rate": 0.0, "message": "hallelujah"}
{"timestamp": "2020-08-27 12:02:10,669", "level": "INFO", "location": "bar:10", "service": "foo", "sampling_rate": 0.0, "message": "doublestuff"}

[heitorlessa]

That is correct - location is where funcName:lineNumber will be present, hence bar:lineNo

We didn't include the name parameter for brevity, and for preventing mistakes such as name==name which wouldn't work.

[michaelbrewer]

@heitorlessa personally I would prefer if "location" included the module it was benign logged from.

This would be similar to other logging libraries.

DEBUG - [method_name] package_name -  message

[lorengordon]

Gotcha. Yeah, the function name is definitely not enough info. Is there some way we can set location to something like package.module.function:line?

[heitorlessa]

@michaelbrewer I think it might be easier to have an option to override log record attributes.

When we started, we heard from beta customers the opposite, as the module wasn't always valuable.

[michaelbrewer]

Gotcha. Yeah, the function name is definitely not enough info. Is there some way we can set location to something like package.module.function:line?

Maybe we can allow for a custom pattern for this. As in some cases you don't want the location field to be too long.

[lorengordon]

Maybe we can allow for a custom pattern for this. As in some cases you don't want the location field to be too long.

That would be fine. Coming from python logging, we're used to setting the logformat with our custom preferences.