Discrepency between flow and deployment when including custom package

Help
, ,
1

I’ve run into a bit of a troubling issue with prefect. Let’s say I have a in house python package called mtt

In my code, I have 1 line

import mtt

Everything is OK when I run the flow from the CLI:

> python prefect_pipeline/mtt_flows.py 
11:16:58.281 | DEBUG   | prefect.client - Connecting to API at http://0.0.0.0:4200/api/
11:16:58.306 | INFO    | prefect.engine - Created flow run 'neon-hyrax' for flow 'create mtt requests'
11:16:58.307 | DEBUG   | Flow run 'neon-hyrax' - Starting 'ConcurrentTaskRunner'; submitted tasks will be run concurrently...
11:16:58.307 | DEBUG   | prefect.task_runner.concurrent - Starting task runner...
11:16:58.313 | DEBUG   | prefect.client - Connecting to API at http://0.0.0.0:4200/api/
11:16:58.364 | DEBUG   | Flow run 'neon-hyrax' - Executing flow 'create mtt requests' for flow run 'neon-hyrax'...
11:16:58.365 | DEBUG   | Flow run 'neon-hyrax' - Beginning execution...
11:16:58.366 | INFO    | Flow run 'neon-hyrax' - Test
11:16:58.380 | INFO    | Flow run 'neon-hyrax' - Created task run 'hi-43256703-0' for task 'hi'
11:16:58.380 | INFO    | Flow run 'neon-hyrax' - Executing 'hi-43256703-0' immediately...
11:16:58.401 | DEBUG   | Task run 'hi-43256703-0' - Beginning execution...
11:16:58.401 | INFO    | Task run 'hi-43256703-0' - i am a task test me
11:16:58.414 | INFO    | Task run 'hi-43256703-0' - Finished in state Completed()
11:16:58.426 | DEBUG   | prefect.task_runner.concurrent - Shutting down task runner...
11:16:58.426 | INFO    | Flow run 'neon-hyrax' - Finished in state Completed('All states completed.')
11:16:58.432 | DEBUG   | prefect.client - Connecting to API at http://0.0.0.0:4200/api/

However when I deploy this file and try to run it from the Orion UI, nothing shows up in the logs nor agent console:

image
image1562×503 37.4 KB 

11:21:56.132 | INFO    | prefect.agent - Submitting flow run '80106657-d63e-4f98-91d4-0ef2c7762d9f'
11:21:56.162 | INFO    | prefect.infrastructure.process - Opening process 'eggplant-rottweiler'...
11:21:56.162 | DEBUG   | prefect.infrastructure.process - Process 'eggplant-rottweiler' running command: /home/adam/anaconda3/envs/mtt-prefect-env/bin/python -m prefect.engine in /tmp/tmpd3joeh6wprefect
11:21:56.172 | INFO    | prefect.agent - Completed submission of flow run '80106657-d63e-4f98-91d4-0ef2c7762d9f'
/home/adam/anaconda3/envs/mtt-prefect-env/lib/python3.9/runpy.py:127: RuntimeWarning: 'prefect.engine' found in sys.modules after import of package 'prefect', but prior to execution of 'prefect.engine'; this may result in unpredictable behaviour
  warn(RuntimeWarning(msg))
11:21:57.385 | DEBUG   | prefect.client - Connecting to API at http://0.0.0.0:4200/api/
11:21:57.625 | DEBUG   | Flow run 'eggplant-rottweiler' - Loading flow for deployment 'test'...
11:21:58.362 | INFO    | prefect.infrastructure.process - Process 'eggplant-rottweiler' exited cleanly.

BUT when I uncomment the import mtt line out, everything runs fine. (Except that i cannot use the mtt package)

image
image1558×854 89.8 KB

The agent also looks normal:

11:27:00.144 | INFO    | prefect.agent - Submitting flow run 'e06e41d0-269c-426f-852f-cc8595751743'
11:27:00.174 | INFO    | prefect.infrastructure.process - Opening process 'adept-parakeet'...
11:27:00.174 | DEBUG   | prefect.infrastructure.process - Process 'adept-parakeet' running command: /home/adam/anaconda3/envs/mtt-prefect-env/bin/python -m prefect.engine in /tmp/tmpsw803sy6prefect
11:27:00.184 | INFO    | prefect.agent - Completed submission of flow run 'e06e41d0-269c-426f-852f-cc8595751743'
11:27:01.086 | DEBUG   | prefect.agent - Checking for cancelled flow runs...
/home/adam/anaconda3/envs/mtt-prefect-env/lib/python3.9/runpy.py:127: RuntimeWarning: 'prefect.engine' found in sys.modules after import of package 'prefect', but prior to execution of 'prefect.engine'; this may result in unpredictable behaviour
  warn(RuntimeWarning(msg))
11:27:01.403 | DEBUG   | prefect.client - Connecting to API at http://0.0.0.0:4200/api/
11:27:01.641 | DEBUG   | Flow run 'adept-parakeet' - Loading flow for deployment 'test'...
11:27:01.691 | DEBUG   | Flow run 'adept-parakeet' - Starting 'ConcurrentTaskRunner'; submitted tasks will be run concurrently...
11:27:01.692 | DEBUG   | prefect.task_runner.concurrent - Starting task runner...
11:27:01.698 | DEBUG   | prefect.client - Connecting to API at http://0.0.0.0:4200/api/
11:27:01.749 | DEBUG   | Flow run 'adept-parakeet' - Executing flow 'mtt' for flow run 'adept-parakeet'...
11:27:01.750 | DEBUG   | Flow run 'adept-parakeet' - Beginning execution...
11:27:01.751 | INFO    | Flow run 'adept-parakeet' - Test
11:27:01.765 | INFO    | Flow run 'adept-parakeet' - Created task run 'hi-9325f8f8-0' for task 'hi'
11:27:01.765 | INFO    | Flow run 'adept-parakeet' - Executing 'hi-9325f8f8-0' immediately...
11:27:01.784 | DEBUG   | Task run 'hi-9325f8f8-0' - Beginning execution...
11:27:01.785 | INFO    | Task run 'hi-9325f8f8-0' - i am a task test me
11:27:01.795 | INFO    | Task run 'hi-9325f8f8-0' - Finished in state Completed()
11:27:01.807 | DEBUG   | prefect.task_runner.concurrent - Shutting down task runner...
11:27:01.807 | INFO    | Flow run 'adept-parakeet' - Finished in state Completed('All states completed.')
11:27:01.813 | DEBUG   | prefect.client - Connecting to API at http://0.0.0.0:4200/api/
11:27:02.032 | INFO    | prefect.infrastructure.process - Process 'adept-parakeet' exited cleanly.

The ONLY change was my importing of that particular package. This has caused quite me quite some deal of pain because I had no idea what was wrong in my original code…

Summary

  1. Running flow with package imported works
  2. Running flow from a deployment with package imported does NOT work
  3. Running flow from a deployment WITHOUT package imported works

Why??

2

I managed to trace it down further, turns out the custom package was overriding the logger_root level, so only critical logs would display :dizzy_face:

For future reference, double check the logging_config file and also don’t disable existing loggers. ← that’s set true by default.

Fix was just add the optional arg: config.fileConfig(logging_config, disable_existing_loggers=False) and make sure that the logger_root level is not CRITICAL :man_facepalming:

1 Like