https://prefect.io logo
Channels
Powered by
k

Kevin Weiler

12/10/2020, 8:13 PM
Hi All! I’m trying to get stdout from my tasks to go to the UI (with the docker agent) and not having any luck. I’m setting the 
PREFECT__LOGGING__EXTRA_LOGGERS
environment variable both when launching my agent and injecting that variable into my docker container at runtime (with the 
-env
arg). Any advice on how to proceed?
z

Zanie

12/10/2020, 8:15 PM
Hi @Kevin Weiler — what are you setting EXTRA_LOGGERS to?
k

Kevin Weiler

12/10/2020, 8:15 PM
Copy code
PREFECT__LOGGING__EXTRA_LOGGERS="['research']"
research
is the name of the logger
(and for completeness) - the docker agent is run with this argument:
Copy code
--env PREFECT__LOGGING__EXTRA_LOGGERS=${PREFECT__LOGGING__EXTRA_LOGGERS}
z

Zanie

12/10/2020, 8:17 PM
Can you show me a minimal flow that reproduces this?
k

Kevin Weiler

12/10/2020, 8:18 PM
yep - good exercise for me to do - will take me a few…
whew - ok, I have a nice self-contained example, and put it here: https://github.com/aquanauts/prefect_logger_repro
research/flow.py
is what you’re looking for
z

Zanie

12/10/2020, 10:43 PM
I have to go so I can only give you a brief answer for now — some quick thoughts: • Make sure you’ve attached a stream handler to your logger to write to stdout • Try adding the 
log_stdout
flag to your task https://docs.prefect.io/core/concepts/logging.html#logging-stdout • Consider just using 
<http://prefect.context.logger.info|prefect.context.logger.info>("…")
If those don’t work/fit your use-case I can take a look again tomorrow morning!
k

Kevin Weiler

12/10/2020, 11:01 PM
thanks for looking @Zanie • that logger writes to stdout when I run it outside of prefect - does something need to happen in addition? • I’ve added that - it doesn’t work and I’m not entirely sure what it does as I’ve tried that before • this wouldn’t fit our use-case unfortunately
z

Zanie

12/10/2020, 11:03 PM
Alright I'll take a more thorough look tomorrow then!
k

Kevin Weiler

12/10/2020, 11:07 PM
thanks again!
for tomorrow - I tried explicitly adding a stream handler and adding 
log_stdout=True
to the task decorator … no dice: https://github.com/aquanauts/prefect_logger_repro/commit/4fd61a863c2bbeeb9f313278430c38f52a42a26a#
z

Zanie

12/11/2020, 4:40 PM
Here’s a minimal working example
Copy code
import os
import sys
import logging
import prefect
from prefect import task, Flow


def get_logger():
    logger = logging.getLogger("my-named-logger")
    logger.addHandler(logging.StreamHandler(sys.stdout))
    logger.setLevel(logging.DEBUG)
    return logger

@task()
def log_message():
    logger = get_logger()
    <http://logger.info|logger.info>("Hello world!")
    logger.error("Foo!")


with Flow('flow-with-extra-logger') as flow:
	log_message()
    
flow.register("first")
Agent run with: 
prefect agent local start --env PREFECT__LOGGING__EXTRA_LOGGERS="['my-named-logger']"
Changing to docker storage e.g.
Copy code
flow.storage = Docker()
flow.register("first")
and using the docker agent works as well
k

Kevin Weiler

12/11/2020, 7:12 PM
thanks so much @Zanie. The pattern we’re going for here is actually a part of this thread: https://prefect-community.slack.com/archives/CL09KU1K7/p1605737921090000 which perhaps I should have continued … @Dolor Oculus is my colleague
so, I’m adding 
research
because that’s the package name
lemme know if I should continue this in the prior thread
z

Zanie

12/11/2020, 7:15 PM
Yep this uses the logger for your package, I just named it 
my-named-logger
in my example instead of 
research
k

Kevin Weiler

12/11/2020, 7:15 PM
ahhhhhh - I see - I’ll give this a try - thanks!
z

Zanie

12/11/2020, 7:17 PM
This works fine as well
Copy code
import os
import sys
import logging
import prefect
from prefect import task, Flow
from prefect.environments.storage import Docker


LOGGER = logging.getLogger("my-named-logger")
LOGGER.addHandler(logging.StreamHandler(sys.stdout))
LOGGER.setLevel(logging.DEBUG)

@task()
def log_message():
    <http://LOGGER.info|LOGGER.info>("Hello world!")
    LOGGER.error("Foo!")


with Flow('flow-with-extra-logger') as flow:
	log_message()


flow.storage = Docker()
flow.register("first")
k

Kevin Weiler

12/11/2020, 8:49 PM
so indeed this works if 
_LOGGER
is used in the task definition. But if I import a function that has 
_LOGGER
defined in it’s file - I don’t get the output
z

Zanie

12/11/2020, 9:08 PM
I can’t test within your MRE
Copy code
❯ python research/flow.py
Traceback (most recent call last):
  File "research/flow.py", line 6, in <module>
    from research.example_pkg import things
ModuleNotFoundError: No module named 'research'
Are you adding it to your python_path? I noticed you’re not doing that in your docker storage. I’m surprised your flow would run at all?
Apologies — 
PYTHONPATH
not 
PYTHON_PATH
haha — I should be able to run your code
k

Kevin Weiler

12/11/2020, 9:43 PM
heh - cool cool - I’m not fond of our pattern of shoving stuff into a container and then setting 
PYTHONPATH
but it’s what happened (with this repo anyway)
z

Zanie

12/11/2020, 9:49 PM
Figured it out 🙂
Sort of — I can reproduce your issue. This appears to be an issue with the 
LocalDaskExecutor(scheduler="processes")
when I switch to using a 
LocalExecutor
the logs work as expected!
Additionally 
LocalDaskExecutor()
without using the processes scheduler works
k

Kevin Weiler

12/11/2020, 9:56 PM
IIIIIINteresting…..!
z

Zanie

12/11/2020, 9:58 PM
cc @Jim Crist-Harif — is extra_loggers expected to fail when using the process based scheduler like this?
j

Jim Crist-Harif

12/11/2020, 10:01 PM
Sorry, there's a lot going on in this thread, what example isn't working properly? Can I get a quick summary?
k

Kevin Weiler

12/11/2020, 10:06 PM
I think the (very) short story is that 
extra_loggers
doesn’t work as expected when using 
LocalDaskExecutor(scheduler="processes")
in fact - with a few small modifications to @Zanie’s most recent example, I have a self-contained example:
Copy code
import sys
import logging

from prefect import task, Flow
from prefect.engine.executors import LocalDaskExecutor
from prefect.environments import LocalEnvironment


LOGGER = logging.getLogger("my-named-logger")
LOGGER.addHandler(logging.StreamHandler(sys.stdout))
LOGGER.setLevel(logging.DEBUG)

@task()
def log_message():
    <http://LOGGER.info|LOGGER.info>("Hello world!")
    LOGGER.error("Foo!")


with Flow('flow-with-extra-logger') as flow:
    log_message()
flow.environment = LocalEnvironment(executor=LocalDaskExecutor(scheduler="processes"))

flow.run()
🙌 1
even with 
PREFECT__LOGGING__EXTRA_LOGGERS="['my-named-logger']"
- this example does not log the expected output to the GUI
j

Jim Crist-Harif

12/11/2020, 10:16 PM
Ah, cool. I may not get to this today, but thanks for the reproducible example
k

Kevin Weiler

12/11/2020, 10:18 PM
cheers - thanks so much to you both for looking at this @Jim Crist-Harif - let me know if you’d like an issue in github with the repro
j

Jim Crist-Harif

12/11/2020, 10:19 PM
That'd be great actually, just to make sure this isn't lost.
k

Kevin Weiler

12/11/2020, 10:35 PM
all set guys - thanks again!
👍 1
Hey guys - just a gentle bump on this one as it’s a bit of a deal-breaker for us - any chance someone can take a look at this?
d

Dylan

01/11/2021, 8:30 PM
Hey @Kevin Weiler thanks for checking in! The fix here is planned, stay tuned 👍
k

Kevin Weiler

01/11/2021, 8:31 PM
thanks!
d

Dolor Oculus

01/22/2021, 3:58 AM
saw this PR went out today! https://github.com/PrefectHQ/prefect/pull/3989 🙏
Powered by