m

    Max Lei

    1 year ago
    Hi All, I only have one flow enabled at a single time using a local agent.
    [2021-05-12 12:26:05-0700] INFO - prefect.task_name | Waiting for next scheduled run at 2021-05-13T10:00:00+00:00
    2021-05-12 12:26:05,221 - prefect.task_name - INFO - Waiting for next scheduled run at 2021-05-13T10:00:00+00:00
    But the local agent somehow runs two of the same flow twice. How should I debug this issue?
    Kevin Kho

    Kevin Kho

    1 year ago
    Hi @Max Lei! How is this being run? “Quick Run” or scheduled?
    m

    Max Lei

    1 year ago
    @Kevin Kho They are being scheduled. The quick runs has no problem at all.
    Kevin Kho

    Kevin Kho

    1 year ago
    What does your schedule look like in the UI?
    Actually, this looks like it’s not a duplicate run, but two different loggers configured with Stream handlers.
    m

    Max Lei

    1 year ago
    Do you mean in the upcoming runs? They look consecutive like Monday/Tuesday, etc and never on the same day.
    I have a task that sends one email, but I’m getting two emails. Also the object in the memory location is also different, 0xf1 vs 0xf2
    This is also a fresh install of prefect 0.14.17, deleted previous docker containers
    I have a crontab that kills the previous flow task_name.py, does a git pull and reruns the same script again. I suspect that this has to do with the behavior. But checking ps -ef | grep task_name.py I only see one copy.
    Kevin Kho

    Kevin Kho

    1 year ago
    Do you cloud logs show doubles also?
    m

    Max Lei

    1 year ago
    No, only a single run. But if I output the flow to a file like task_name.py > log.txt. The log.txt shows a different result than the log on the UI.
    Kevin Kho

    Kevin Kho

    1 year ago
    We’re looking into this
    Michael Adkins

    Michael Adkins

    1 year ago
    Hey @Max Lei -- if you can reproduce this with debug level logs on we might get some more information.
    PREFECT__CLOUD__AGENT__LEVEL=DEBUG
    m

    Max Lei

    1 year ago
    Should I export this environment variable before running the agent or flow or both?
    I think I follow:
    prefect agent <AGENT TYPE> start --env KEY=VALUE --env KEY2=VALUE2
    In the docs
    Michael Adkins

    Michael Adkins

    1 year ago
    Before the command since you're setting it for your agent not the flow run
    m

    Max Lei

    1 year ago
    The log looks like:
    [2021-05-12 20:22:58,810] DEBUG - agent | Found flow runs ['734edd41-a9de-4ab9-86b4-aaf332fa1179'] (1 already submitting: ['734edd41-a9de-4ab9-86b4-aaf332fa1179'])
    [2021-05-12 20:22:58,810] DEBUG - agent | Next query for flow runs in 0.5 seconds
    [2021-05-12 20:22:59,311] DEBUG - agent | Querying for flow runs
    [2021-05-12 20:22:59,331] DEBUG - agent | Found flow runs ['734edd41-a9de-4ab9-86b4-aaf332fa1179'] (1 already submitting: ['734edd41-a9de-4ab9-86b4-aaf332fa1179'])
    [2021-05-12 20:22:59,331] DEBUG - agent | Next query for flow runs in 1.0 seconds
    [2021-05-12 20:23:00,001] DEBUG - agent | Updating states for flow run 734edd41-a9de-4ab9-86b4-aaf332fa1179
    [2021-05-12 20:23:00,006] DEBUG - agent | Flow run 734edd41-a9de-4ab9-86b4-aaf332fa1179 is in a Scheduled state, updating to Submitted
    [2021-05-12 20:23:00,046] INFO - agent | Deploying flow run 734edd41-a9de-4ab9-86b4-aaf332fa1179
    [2021-05-12 20:23:00,050] DEBUG - agent | Submitted flow run 734edd41-a9de-4ab9-86b4-aaf332fa1179 to process PID 31690
    [2021-05-12 20:23:00,068] DEBUG - agent | Completed flow run submission (id: 734edd41-a9de-4ab9-86b4-aaf332fa1179)
    Looks OK to me for now though. I think I’ll need to export this and just let it sit through tasks this week and see what happens.
    Michael Adkins

    Michael Adkins

    1 year ago
    Alright!
    m

    Max Lei

    1 year ago
    I do see a few [2021-05-11 20:37:00,431] ERROR - agent | HTTPConnectionPool(host=‘localhost’, port=4200): Max retries exceeded with url: / (Caused by NewConnectionError(‘<urllib3.connection.HTTPConnection object at 0x7f28c0dba110>: Failed to establish a new connection: [Errno 101] Ne twork is unreachable’)) And then the agent icon appears again, and then seems to restart itself? Could this cause multiple runners to be active at the same time?
    A little longer log:
    [2021-05-05 10:00:02,060] INFO - agent | Found 1 flow run(s) to submit for execution.
    [2021-05-05 10:00:02,176] INFO - agent | Deploying flow run 87e78b14-dcf5-44e0-b7dd-e8d07340356e
    [2021-05-05 22:11:45,212] ERROR - agent | HTTPConnectionPool(host='localhost', port=4200): Max retries exceeded with url: / (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7efdb49b8450>: Failed to establish a new connection: [Errno 111] Co
    nnection refused'))
    [2021-05-05 22:11:55,214] ERROR - agent | HTTPConnectionPool(host='localhost', port=4200): Max retries exceeded with url: / (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7efdb496fd90>: Failed to establish a new connection: [Errno 101] Ne
    twork is unreachable'))
    
     ____            __           _        _                    _
    |  _ \ _ __ ___ / _| ___  ___| |_     / \   __ _  ___ _ __ | |_
    | |_) | '__/ _ \ |_ / _ \/ __| __|   / _ \ / _` |/ _ \ '_ \| __|
    |  __/| | |  __/  _|  __/ (__| |_   / ___ \ (_| |  __/ | | | |_
    |_|   |_|  \___|_|  \___|\___|\__| /_/   \_\__, |\___|_| |_|\__|
                                               |___/
    
    [2021-05-05 22:14:19,077] INFO - agent | Starting LocalAgent with labels ['ml-build', 'azure-flow-storage', 'gcs-flow-storage', 's3-flow-storage', 'github-flow-storage', 'webhook-flow-storage', 'gitlab-flow-storage']
    [2021-05-05 22:14:19,078] INFO - agent | Agent documentation can be found at <https://docs.prefect.io/orchestration/>
    [2021-05-05 22:14:19,078] INFO - agent | Agent connecting to the Prefect API at <http://localhost:4200>
    [2021-05-05 22:14:19,085] INFO - agent | Waiting for flow runs...
    [2021-05-06 10:00:07,830] INFO - agent | Found 1 flow run(s) to submit for execution.
    [2021-05-06 10:00:07,869] INFO - agent | Deploying flow run 69433bdb-981a-4135-af51-a495c44eeecf
    [2021-05-06 14:00:02,978] INFO - agent | Found 1 flow run(s) to submit for execution.
    [2021-05-06 14:00:03,012] INFO - agent | Deploying flow run c75e4314-9edd-4168-81ac-4fd86efc8acb
    @Michael Adkins @Kevin Kho It seems that I was able to reproduce it. Nothing particular wrong about the agent logs. From starting the new agent, there wasn’t any disconnects, but still had two runs.
    Michael Adkins

    Michael Adkins

    1 year ago
    Can you post the log?
    Runs like this should be de-duplicated and the logs should shown where that's failing
    m

    Max Lei

    1 year ago
    [2021-05-12 20:22:58,499] DEBUG - agent | Querying for flow runs
    [2021-05-12 20:22:58,521] DEBUG - agent | Found flow runs ['734edd41-a9de-4ab9-86b4-aaf332fa1179']
    [2021-05-12 20:22:58,522] DEBUG - agent | Querying flow run metadata
    [2021-05-12 20:22:58,538] INFO - agent | Found 1 flow run(s) to submit for execution.
    [2021-05-12 20:22:58,538] DEBUG - agent | Next query for flow runs in 0.25 seconds
    [2021-05-12 20:22:58,789] DEBUG - agent | Querying for flow runs
    [2021-05-12 20:22:58,810] DEBUG - agent | Found flow runs ['734edd41-a9de-4ab9-86b4-aaf332fa1179'] (1 already submitting: ['734edd41-a9de-4ab9-86b4-aaf332fa1179'])
    [2021-05-12 20:22:58,810] DEBUG - agent | Next query for flow runs in 0.5 seconds
    [2021-05-12 20:22:59,311] DEBUG - agent | Querying for flow runs
    [2021-05-12 20:22:59,331] DEBUG - agent | Found flow runs ['734edd41-a9de-4ab9-86b4-aaf332fa1179'] (1 already submitting: ['734edd41-a9de-4ab9-86b4-aaf332fa1179'])
    [2021-05-12 20:22:59,331] DEBUG - agent | Next query for flow runs in 1.0 seconds
    [2021-05-12 20:23:00,001] DEBUG - agent | Updating states for flow run 734edd41-a9de-4ab9-86b4-aaf332fa1179
    [2021-05-12 20:23:00,006] DEBUG - agent | Flow run 734edd41-a9de-4ab9-86b4-aaf332fa1179 is in a Scheduled state, updating to Submitted
    [2021-05-12 20:23:00,046] INFO - agent | Deploying flow run 734edd41-a9de-4ab9-86b4-aaf332fa1179
    [2021-05-12 20:23:00,050] DEBUG - agent | Submitted flow run 734edd41-a9de-4ab9-86b4-aaf332fa1179 to process PID 31690
    [2021-05-12 20:23:00,068] DEBUG - agent | Completed flow run submission (id: 734edd41-a9de-4ab9-86b4-aaf332fa1179)
    [2021-05-12 20:23:00,332] DEBUG - agent | Querying for flow runs
    Michael Adkins

    Michael Adkins

    1 year ago
    So here we can see that the flow run is "found" 3 times but twice tracked as a run the agent was "already submitting" and you can see it is only "Submitted" once
    Basically: It looks like your flow run was only executed once in this log
    m

    Max Lei

    1 year ago
    Hmmm… Looking at the schematics that node in the dag that sends the email is only fired off once. But I’m getting two results, the text log and the UI log are different.
    If I click quick run, there’s no text log output from the flow, only UI logs are shown, and that there’s no duplicate runs.
    Could it be that the agent and also the local direct mode is running at the same time?
    Michael Adkins

    Michael Adkins

    1 year ago
    Do you call
    flow.run()
    in your flow script?
    You'll want to place that in a
    if __name__ == "__main__":
    block if so
    m

    Max Lei

    1 year ago
    Yes I do call
    flow.run()
    in the script, but it’s inside an
    if ___name___
    . For example:
    def run():
        with Flow() as flow:    
            flow.run()
    
    if __name__ == '__main__':
        run()
    Michael Adkins

    Michael Adkins

    1 year ago
    You'll want to structure it more like
    with Flow() as flow:
       my_task()
    
    if __name__ == '__main_':
       flow.run()