https://flyte.org logo
Channels
Powered by
#announcements
Title
# announcements
n

Nicholas LoFaso

01/10/2022, 3:43 PM
Hi All, is there an example for how to configure the python logging package for use with 
@tasks
? I’m configuring the root logger, but it seems like that code is only running at registration time not execution time? See thread for example
Copy code
from msat.logging import configure_logger
logger = configure_logger()

@task
def my_task():
  <http://logger.info|logger.info>("an info message")
configure_logger
seems to be called when I run pyflyte, but not when the 
@task
actually executes. This results in all default log settings like the log level = WARN
y

Yee

01/10/2022, 4:58 PM
what version of flytekit are you on?
and what is msat.logging?
the call to configure_logger should be happening on the loading of the .py file.
n

Nicholas LoFaso

01/10/2022, 5:05 PM
flytekit==0.30.0b2
and configure_logger is a custom function where I i configure the root logger to be a JSON logger using 
pythonjsonlogger
i agree it should be happening when the file is loaded
y

Yee

01/10/2022, 5:08 PM
what do the log statements look like?
can you copy paste some output?
that’s all we do wrt logging
we never touch the root logger
n

Nicholas LoFaso

01/10/2022, 5:16 PM
Ahh that’s helpful. Think I know what I did wrong
Fixed my issue. The getLogger call in loggers.py
Copy code
logger = logging.getLogger("flytekit")
Happened before my code so it configures a default root logger. I just needed to force my configure_logger function to overwrite the default root logger
thanks for your help
y

Yee

01/10/2022, 5:40 PM
interesting
configuring a non-root logger affects the root logger?
n

Nicholas LoFaso

01/11/2022, 2:44 PM
@Yee looking closer I think it’s not that particular line, but any call to the 
logging
package’s info() warning() , etc functions will add a basic root log handler if one doesn’t exist. For example
Copy code
import logging
<http://logging.info|logging.info>("hello")
calls
Copy code
def info(msg, *args, **kwargs):
    """
    Log a message with severity 'INFO' on the root logger. If the logger has
    no handlers, call basicConfig() to add a console handler with a pre-defined
    format.
    """
    if len(root.handlers) == 0:
        basicConfig()
    <http://root.info|root.info>(msg, *args, **kwargs)
y

Yee

01/11/2022, 8:52 PM
good to know
thank you
g

Greg Gydush

02/11/2022, 11:51 PM
Hi @Yee - I’m struggling to get user logs working on Flytekit >= 0.26 (tried both 0.26 and 0.30) and was wondering if you had ideas. I was expecting setting 
FLYTE_SDK_LOGGING_LEVEL_ROOT=20
would resolve, but still no user logs. I think it may come down to the statement on this line - if acting on 
flytekit_root_env_var
should that line be using the root logger (e.g., use 
logger.root.setLevel
)? If I set 
logging.root.setLevel(20)
at the top of my file, I can get logs to work. Without that, 
logging.root.level
is always set to 30
y

Yee

02/12/2022, 12:38 AM
what happens if you just do 
FLYTE_SDK_LOGGING_LEVEL=20
and run
Copy code
from flytekit import logger
<http://logger.info|logger.info>("This is info")
we try not to touch the root logger… since that can expose a bunch of other things
the idea is that the loggers are set where you want them. and the channel should basically be the min of them (which we assume is the FLYTE_SDK_LOGGING_LEVEL env var).
iirc
g

Greg Gydush

02/13/2022, 1:54 AM
setting 
FLYTE_SDK_LOGGING_LEVEL=20
and importing the logger from flytekit works - is that the recommended way for users to log? I would expect that it would be possible to set up my own logger like so, but this does not work currently:
Copy code
import logging

from flytekit import task, workflow

logging.basicConfig(
    level=<http://logging.INFO|logging.INFO>,
    format="%(asctime)s [%(levelname)s] %(message)s",
)

@task
def test_task(value: int) -> int:
    <http://logging.info|logging.info>("This is info")
    return value


@workflow
def test_workflow(input_integer: int) -> int:
    return test_task(value=input_integer)
After debugging, I found that inside the task, the root logger is still set to 30 (the default) - here is the output of 
logging.root.__dict__
when printed inside the task:
Copy code
{'filters': [], 'name': 'root', 'level': 30, 'parent': None, 'propagate': True, 'handlers': [<StreamHandler <stderr> (NOTSET)>], 'disabled': False, '_cache': {10: False, 20: False}}
This may or may not be useful, but logging using the above strategy (import logging, setup basicConfig) worked in Flytekit 0.25, but does not work on anything >= 0.26
y

Yee

02/14/2022, 6:22 PM
oh hi @Greg Gydush sorry meant to respond earlier.
can you help me repro this?
like
Copy code
In [1]: import logging

In [2]: logging.root.__dict__
Out[2]:
{'filters': [],
 'name': 'root',
 'level': 30,
 'parent': None,
 'propagate': True,
 'handlers': [],
 'disabled': False,
 '_cache': {}}

In [3]: logging.basicConfig(level=<http://logging.INFO|logging.INFO>)

In [4]: logging.root.__dict__
Out[4]:
{'filters': [],
 'name': 'root',
 'level': 20,
 'parent': None,
 'propagate': True,
 'handlers': [<StreamHandler <stderr> (NOTSET)>],
 'disabled': False,
 '_cache': {}}

In [5]: from flytekit import logger

In [6]: logging.root.__dict__
Out[6]:
{'filters': [],
 'name': 'root',
 'level': 20,
 'parent': None,
 'propagate': True,
 'handlers': [<StreamHandler <stderr> (NOTSET)>],
 'disabled': False,
 '_cache': {}}
seems to work.
though admittedly i haven’t run this inside a task yet. let me try that.
the goal of the changes post 0.26 was precisely to get out of the user’s way. to only configure loggers for flytekit and not interfere with any global settings.
g

Greg Gydush

02/14/2022, 6:27 PM
I just confirmed your example above (when running locally, the root logger is updated correctly) — this breaks down when running in a task / on Flyte though
If you run my example above in flyte-sandbox on flytekit >= 0.26, are you seeing logs?
y

Yee

02/14/2022, 7:23 PM
i see
improper isolation
basically, once you use the root logger, calling basic config has no effect
Copy code
In [1]: import logging

In [2]: <http://logging.info|logging.info>("fdjs")

In [3]: logging.basicConfig(level=<http://logging.INFO|logging.INFO>)

In [4]: logging.root.__dict__
Out[4]:
{'filters': [],
 'name': 'root',
 'level': 30,
 'parent': None,
 'propagate': True,
 'handlers': [<StreamHandler <stderr> (NOTSET)>],
 'disabled': False,
 '_cache': {20: False}}
because for whatever reason, basic config has 
if len(root.handlers) == 0:
in it
g

Greg Gydush

02/14/2022, 7:29 PM
very interesting - so should those be using their own logger rather than using the root?
y

Yee

02/14/2022, 7:29 PM
yeah
but also, i feel like you should add the 
force
option to your basicconfig
👍 1
cuz it seems like if you ever call any library that uses logging, it’ll render that command useless.
which seems weird but i guess that’s the case
yeah sorry, could you add force for now please? I’ll cut an issue from this but it’s used in a bunch of places - will take some time to rip out. but we will. give us a couple weeks
g

Greg Gydush

02/14/2022, 7:37 PM
of course! Thank you for digging into this, and using 
force
is totally fine!
117 Views
Powered by