https://prefect.io logo
Join Slack
Powered by
I'm having several issues setting up a logger for ...
# ask-community
c
I'm having several issues setting up a logger for my shared code; I've tried to follow the docs. 1. I've set the ENV 
PREFECT__LOGGING__LEVEL="DEBUG"
within the run_config (ECSRunner) and I've confirmed that this env is set as such in the running container. However, within my running flow, when I check 
os.environ
its set to INFO 2. I setup a logger in my shared code that I later import like a library: 
logger = logging.getLogger("dwh.utils.main")
. I've set 
PREFECT__CLOUD__SEND_FLOW_RUN_LOGS='true'
and 
PREFECT__LOGGING__EXTRA_LOGGERS="['dwh']"
. when I execute a flow that uses that shared code, I can't see it emit logs in CloudWatch or in Prefect cloud, however when I run the flow locally I do see the logging statement what am I missing?
k
So I just tested this. On the first one, I printed context and got that logging level was debug. I think that is the more important part. Did you see debug level logs in the UI? Here was my flow for reference:
Copy code
from prefect import task, Flow
from prefect.run_configs import ECSRun
from prefect.storage import S3
import prefect

@task
def abc():
    <http://prefect.context.logger.info|prefect.context.logger.info>(dict(prefect.context))
    return "hello"

with Flow("ecs_test") as flow:
    abc()

RUN_CONFIG = ECSRun(labels=['ecs_test'],
                    run_task_kwargs={'cluster': 'test-cluster'},
                    task_role_arn= 'arn:aws:iam::123456789:role/prefect-ecs',
                    execution_role_arn='arn:aws:iam::123456789:role/prefect-ecs',
                    image='prefecthq/prefect:latest-python3.8',
                    env={"PREFECT__LOGGING__LEVEL":"DEBUG"}
                            )

flow.storage=S3(bucket="coiled-prefect", add_default_labels=False)

flow.run_config = RUN_CONFIG 

flow.register("bristech")
The second one looks right. Is 
dwh
happening on the same process or a different process? Think like spinning up a Jupyter notebook to run. Did you set those in the RunConfig?
a
@Constantino Schillebeeckx regarding #2, you should use the Prefect logger to ensure that the logs will be available in the Prefect UI (and also in Cloudwatch logs). You can still configure it as you wish, but rather than customizing logger in your shared library, you should customize it on the Prefect config, e.g.:
Copy code
export PREFECT__LOGGING__LEVEL="DEBUG"
export PREFECT__LOGGING__FORMAT="%(levelname)s - %(name)s | %(message)s" # format the message as you wish
and then use the logger from context rather than importing from a custom module:
Copy code
logger = prefect.context.get("logger")
The extra loggers are meant to include logs from external libraries e.g. boto3. More on that here: https://docs.prefect.io/core/concepts/logging.html#extra-loggers
c
@Kevin Kho I'm setting my environment variables within the 
task_defefintion
section - that shouldn't matter right?
@Anna Geller I'd like to log within my library, that code doesn't have a prefect context. The docs warn against using the prefect logger in such a way.
Make sure to only access context while your task is running
Is 
dwh
 happening on the same process or a different process? Think like spinning up a Jupyter notebook to run. Did you set those in the RunConfig?
I"m not sure I follow. 
dwh
is a named logger which I can import directly from the container.
a
so in general, you can only log from within tasks, that’s why this line should also be used within tasks:
Copy code
logger = prefect.context.get("logger")
c
isn't that what 
extra_loggers
is for? I mean, how would I emit logs from other libraries I'm using?
a
I wouldn’t use the “dwh” logger - if you want the logs to be sent to the backend and displayed in the Prefect UI, you need to use the Prefect logger, which you can access from the context from a task. Have a look at the docs here - they say that extra loggers is only meant to get logs generated by extra external loggers from third party libraries like Snowflake connector or boto3: https://docs.prefect.io/core/concepts/logging.html#extra-loggers
c
but my code is acting like a third party library, it imports just like one. what do I need to do so that the logger behaves like one in boto3?
z
Hey @Constantino Schillebeeckx — can you share a simple example of how you’re using your library that you’d like to be logged?
Copy code
from fake_lib import function_that_logs
from prefect import Flow, task


@task
def foo():
    function_that_logs()


with Flow("extra-loggers-example") as flow:
    foo()


if __name__ == "__main__":
    flow.run()
Copy code
import logging


def function_that_logs():
    logger = logging.getLogger("foo.bar")
    <http://logger.info|logger.info>("Hello from fake_lib!")
Locally:
Copy code
❯ python extra-logger.py
[2021-11-23 14:53:32-0600] INFO - prefect.FlowRunner | Beginning Flow run for 'extra-loggers-example'
[2021-11-23 14:53:32-0600] INFO - prefect.TaskRunner | Task 'foo': Starting task run...
[2021-11-23 14:53:32-0600] INFO - prefect.TaskRunner | Task 'foo': Finished task run for task with final state: 'Success'
[2021-11-23 14:53:32-0600] INFO - prefect.FlowRunner | Flow run SUCCESS: all reference tasks succeeded

~/dev/support                                                                                                                                                                                                               prefect-dev-38
❯ PREFECT__LOGGING__EXTRA_LOGGERS='["foo"]' python extra-logger.py 
[2021-11-23 14:54:00-0600] INFO - prefect.FlowRunner | Beginning Flow run for 'extra-loggers-example'
[2021-11-23 14:54:00-0600] INFO - prefect.TaskRunner | Task 'foo': Starting task run...
[2021-11-23 14:54:00-0600] INFO - foo.bar | Hello from fake_lib!
[2021-11-23 14:54:00-0600] INFO - prefect.TaskRunner | Task 'foo': Finished task run for task with final state: 'Success'
[2021-11-23 14:54:00-0600] INFO - prefect.FlowRunner | Flow run SUCCESS: all reference tasks succeeded
With Cloud:
Copy code
❯ prefect agent local start --env PREFECT__LOGGING__EXTRA_LOGGERS='["foo"]'
Copy code
❯ prefect run --name "extra-loggers-example"
Copy code
(in the UI)
14:55:40
INFO
foo.bar
Hello from fake_lib!
c
sure, here's for example 
dwh/tils/main.py
Copy code
import logging
from decouple import config

logger = logging.getLogger("dwh.utils.main")

def get_aws_region() -> str:
    """Get the AWS region.

    Gets the AWS region from the ``AWS_REGION`` environment variable, defaults to 'us-west-2' if not set.

    Returns
    -------
    str
        AWS region
    """
    region = config("AWS_REGION", "us-west-2")
    <http://logger.info|logger.info>(f"Found AWS {region=}")
    return region
This code gets packaged in a docker container and is installed as a python library so that I can later import with it
z
Here’s another example that uses a run config environment variable instead of adding it to the agent
Copy code
from fake_lib import function_that_logs
from prefect import Flow, task
from prefect.run_configs import UniversalRun


@task
def foo():
    function_that_logs()


with Flow(
    "extra-loggers-example",
    run_config=UniversalRun(env={"PREFECT__LOGGING__EXTRA_LOGGERS": '["foo"]'}),
) as flow:
    foo()


if __name__ == "__main__":
    flow.run()
Copy code
❯ prefect register -p extra-logger.py --project example
Collecting flows...
Processing 'extra-logger.py':
  Building `Local` storage...
  Registering 'extra-loggers-example'... Done
  └── ID: 4921bd3f-646f-42b9-ac0d-0272b09d3140
  └── Version: 2
======================== 1 registered ========================

~/dev/support                           
❯ prefect run --name "extra-loggers-example" --watch   
Looking up flow metadata... Done
Creating run for flow 'extra-loggers-example'... Done
└── Name: graceful-kangaroo
└── UUID: 5bd86a3f-7441-4127-ab5c-9b60565977d5
└── Labels: ['Michaels-MacBook-Pro.local']
└── Parameters: {}
└── Context: {}
└── URL: <https://staging.prefect.io/michael-staging/flow-run/5bd86a3f-7441-4127-ab5c-9b60565977d5>
Watching flow run execution...
└── 14:58:32 | INFO    | Entered state <Scheduled>: Flow run scheduled.
└── 14:58:41 | INFO    | Entered state <Submitted>: Submitted for execution
└── 14:58:41 | INFO    | Submitted for execution: PID: 25150
└── 14:58:42 | INFO    | Entered state <Running>: Running flow.
└── 14:58:41 | INFO    | Beginning Flow run for 'extra-loggers-example'
└── 14:58:43 | INFO    | Task 'foo': Starting task run...
└── 14:58:43 | INFO    | Hello from fake_lib!
└── 14:58:44 | INFO    | Task 'foo': Finished task run for task with final state: 'Success'
└── 14:58:44 | INFO    | Flow run SUCCESS: all reference tasks succeeded
└── 14:58:45 | INFO    | Entered state <Success>: All reference tasks succeeded.
Flow run succeeded!
c
@Zanie what if you moved the line 
logger = logging.getLogger("foo.bar")
to the top of your library file?
z
Moving my 
logger = logging.getLogger("foo.bar")
call out of the function and into the top-level (as you do) also works.
c
sad
z
😄 on it haha. It logs as you would expect.
How are you importing this function?
Shuffling the import order also does not change anything:
Copy code
from prefect import Flow, task
from prefect.run_configs import UniversalRun

from fake_lib import function_that_logs
c
as usual with a 
from dwh.utils.main import get_aws_region
z
Have you confirmed that the extra loggers is actually set?
For example:
Copy code
@task(log_stdout=True)
def show_extra_loggers():
    print(config.logging.extra_loggers)
c
lemme double check
z
Your other questions make it seem like your environment variables are not being respected as currently configured.
Some things are hard-coded to respect settings on the agent, for example https://github.com/PrefectHQ/prefect/blob/0.15.9/src/prefect/agent/ecs/agent.py#L500
Note we also set the logging level such that it can be overridden by run_config.env but not task definition environment variables https://github.com/PrefectHQ/prefect/blob/0.15.9/src/prefect/agent/ecs/agent.py#L480-L490
c
oh!
that might answer point 1 then
just triggered my test flow again, the fargate task shows me
from the test flow, I'm dumping the prefect.config and I see
Copy code
'logging': {'level': 'INFO', 'format': '%(levelname)s - %(name)s | %(message)s', 'log_attributes': [], 'datefmt': '%Y-%m-%d %H:%M:%S%z', 'extra_loggers': ['dwh'], 'log_to_cloud': True}
z
Very peculiar. What happens if: after importing your function, you call prefect.utilities.logging.configure_extra_loggers() ?
Or call that from within a task even
Also note you have 
log_to_cloud
there and not 
send_flow_run_logs
(the first was deprecated)
Guessing the other exists under the ‘cloud’ section though
c
here's my run config that is use to do 
ECSRun(**run_config)
, you can see that i'm also setting 
send_flow_run_logs
there
should I not set the environment varaibles within 
containerDefinitions
?
here's my container definition - is prefect overwritting this ENV?
z
Can you try setting the environment variables at the top-level instead of the container definition?
Some of them may be overridden, yes.
The extra loggers is loading though (as demonstrated from your task run)
c
Can you try setting the environment variables at the top-level instead of the container definition?
trying that now
looks like that was it!
z
Wonderful!
c
could you explain 
PREFECT__CLOUD__SEND_FLOW_RUN_LOGS
- if I set this to False, are the custom logs NOT sent to the cloud?
z
SEND_FLOW_RUN_LOGS
disable all emission of logs to the cloud API
(so yes / correct)
c
wünderbar!
z
It’s just there so people can disable it if they don’t want us to get any private logs
Now if you’re feeling really motivated and want to make my life easier, you can open a PR to the ECSRun docs saying not to set Prefect config environment variables like that 😄
c
I was just gonna ask if I should submit a PR to improve the docs - will do 😄
🙌 1
16 Views
Open in Slack
PreviousNext
Powered by