https://prefect.io logo
Join Slack
Powered by
Quietening down logs - if I'm mapping out to a lot...
# ask-community
p
Quietening down logs - if I'm mapping out to a lot of job, have a lot of params etc, it can be difficult to follow logs. Is there a way I can set logging such that I only see something if it's broken. If I 
export PREFECT__LOGGING__LEVEL=INFO
I see:
Copy code
python3 tmp/shell_task.py 
[2022-04-19 21:09:30+0100] INFO - prefect.FlowRunner | Beginning Flow run for 'My Flow'
[2022-04-19 21:09:30+0100] INFO - prefect.TaskRunner | Task 'MyShellTask': Starting task run...
[2022-04-19 21:09:30+0100] INFO - prefect.MyShellTask | lsto echo
[2022-04-19 21:09:30+0100] INFO - prefect.TaskRunner | Task 'MyShellTask': Finished task run for task with final state: 'Success'
[2022-04-19 21:09:30+0100] INFO - prefect.TaskRunner | Task 'problem': Starting task run...
[2022-04-19 21:09:30+0100] INFO - prefect.TaskRunner | FAIL signal raised: FAIL('Oh no!')
[2022-04-19 21:09:30+0100] INFO - prefect.TaskRunner | Task 'problem': Finished task run for task with final state: 'Failed'
[2022-04-19 21:09:30+0100] INFO - prefect.FlowRunner | Flow run FAILED: some reference tasks failed.
If I
Copy code
export PREFECT__LOGGING__LEVEL=ERROR
I see nothing. Ideally I'd like to only see messages about broken stuff. Ideas?
n
@Philip MacMenamin if you're raising a caught exception (as a 
FAIL
signal in this case), then its going to be 
INFO
level, as you can see in your logs
Copy code
[2022-04-19 21:09:30+0100] INFO - prefect.TaskRunner | FAIL signal raised: FAIL('Oh no!')
any unexpected errors should show up as 
ERROR
level logs - is that helpful?
p
so I expected that, but if I set: 
export PREFECT__LOGGING__LEVEL=ERROR
I see nothing. WF runs out, reports nothing at all.
a
based on this log, the info that a flow run failed is still an INFO-level log, so that's expected:
Copy code
[2022-04-19 21:09:30+0100] INFO - prefect.FlowRunner | Flow run FAILED: some reference tasks failed.
this is much easier to configure in Prefect 2.0 - perhaps a good reason to run your flow on 2.0 already? check out this example
upvote 1
p
@Anna Geller - I'm not sure I'm getting this. I raised a signal.FAIL in the task, and this elicited
Copy code
[2022-04-19 21:09:30+0100] INFO - prefect.TaskRunner | FAIL signal raised: FAIL('Oh no!')
Is is not expected behaviour that raising a FAIL would show up on an error level log?
a
nope - this only means that the task run ends with a failed state - the task runner log remains INFO. Can you explain what problem do you try to solve here?
p
Default settings generate a very large amount of logs along the lines of:
Copy code
[2022-04-19 12:56:09-0600] INFO - prefect.TaskRunner | Task 'log': Finished task run for task with final state: 'Success'
[2022-04-19 12:56:09-0600] INFO - prefect.TaskRunner | Task 'update_adoc': Starting task run...
[2022-04-19 12:56:09-0600] INFO - prefect.TaskRunner | Task 'update_adoc': Finished task run for task with final state: 'Mapped'
[2022-04-19 12:56:09-0600] INFO - prefect.TaskRunner | Task 'update_adoc[0]': Starting task run...
[2022-04-19 12:56:09-0600] INFO - prefect.TaskRunner | Task 'update_adoc[0]': Finished task run for task with final state: 'Success'
[2022-04-19 12:56:09-0600] INFO - prefect.TaskRunner | Task 'create_brt_command': Starting task run...
[2022-04-19 12:56:09-0600] INFO - prefect.TaskRunner | Task 'create_brt_command': Finished task run for task with final state: 'Mapped'
[2022-04-19 12:56:09-0600] INFO - prefect.TaskRunner | Task 'create_brt_command[0]': Starting task run...
[2022-04-19 12:56:09-0600] INFO - prefect.TaskRunner | Task 'create_brt_command[0]': Finished task run for task with final state: 'Success'
[2022-04-19 12:56:10-0600] INFO - prefect.TaskRunner | Task 'log': Starting task run...
which gets to be crippling if you're mapping over a lot of stuff. I don't want to be told about all of this, I just want to know if anything broke, and ideally some kind of clue about what broke.
I'm not going to paste in an actual large log, but if I'm mapping to a couple of hundred items it becomes huge. (I'm mapping to one in the above). I don't want to be told about every event, and every 'Success', I'd like some way to turn that down to help me keep logs at a size that I don't have to use grep etc to search them.
Aside, I tested
Copy code
from prefect import flow, task
from logging import getLogger

logger = getLogger("my-logger")
logger.setLevel("INFO")


@task
def my_task():
    <http://logger.info|logger.info>("Hello from the task")


@flow
def my_flow():
    <http://logger.info|logger.info>("Hello from the flow")
    my_task()


my_flow()
running with 
PREFECT_LOGGING_LEVEL=WARNING PREFECT_LOGGING_EXTRA_LOGGERS=my-logger python3 flow2.py
gives me:
Copy code
Traceback (most recent call last):
  File "flow2.py", line 1, in <module>
    from prefect import flow, task
ImportError: cannot import name 'flow' from 'prefect' (/home/macmenaminpe/.local/lib/python3.8/site-packages/prefect/__init__.py)
writing as:
Copy code
cat flow.py 
from prefect import Flow, task
from logging import getLogger

logger = getLogger("my-logger")
logger.setLevel("INFO")


@task
def my_task():
    <http://logger.info|logger.info>("Hello from the task")

with Flow("My Flow") as f:
    <http://logger.info|logger.info>("Hello from the flow")
    my_task()

f.run()
works, but gives me:
Copy code
$ PREFECT_LOGGING_LEVEL=WARNING PREFECT_LOGGING_EXTRA_LOGGERS=my-logger python3 flow.py
[2022-04-20 15:50:10+0100] INFO - prefect.FlowRunner | Beginning Flow run for 'My Flow'
[2022-04-20 15:50:10+0100] INFO - prefect.TaskRunner | Task 'my_task': Starting task run...
[2022-04-20 15:50:10+0100] INFO - prefect.TaskRunner | Task 'my_task': Finished task run for task with final state: 'Success'
[2022-04-20 15:50:10+0100] INFO - prefect.FlowRunner | Flow run SUCCESS: all reference tasks succeeded
Ie, same as previous, too much logging.
(In the above case I'm not even seeing "Hello from the flow")
Copy code
$ prefect version
1.2.0
n
with regard to this message about the failed import, that's because your prefect version is 1.2 but you're using the 
prefect>=2.0
syntax and imports, which aren't valid for 
prefect==1.x.x
upvote 1
p
right, I suspected that was some versioning thing. Thanks Nate.
a
I just want to know if anything broke, and ideally some kind of clue about what broke.
The best way of solving that problem would be through state handlers or failure notifications that you could configure through Automation. This blog post discusses both
p
@Anna Geller - this might be nice for a more final version. I'm just going through stuff coding and trying to work out bugs. Is this automation going to work on a locally hosted prefect server?
So, basically there isn't really a way of quietening down the logs I'm hearing, correct?
a
there is always a way to quiet down the logs - you could, e.g. use a log filter: https://prefect-community.slack.com/archives/C014Z8DPDSR/p1650365258707909?thread_ts=1650363875.537909&amp;cid=C014Z8DPDSR but I'm not sure if getting rid of logs is the right strategy. Logs are extremely helpful in troubleshooting, I think you need them! A better approach is to configure some hooks for failure notifications. Automations are Cloud only, but you could add a state handler on Server
p
Logs are very helpful in trouble shooting, but if I have thousands of lines of logs, and 99.999% of them say "... Success" and buried in there there's something that's not working, I'd have thought there'd be a simple way to surface this.
As in, if I explicitly raise a FAIL, why is this not in a diff category? Why is that grouped in with the thousands of Successes. At the end of the day I'll have full logging, but as I'm writing stuff it's useful to run flows and see if there's anything wrong, quickly.
I mean, I guess I can pipe everything through grep too, but it just seems weird.
a
actually can you try running the same with the backend? I think the actual error in your tasks will be displayed as ERROR level, only the Flow and Task Runner are displayed as INFO
p
I'm not following - what do you mean by running it with the backend?
registering it and running it through the web GUI?
a
yup exactly
11 Views
Open in Slack
PreviousNext
Powered by