Thread
#prefect-community
    p

    Peter Peter

    1 year ago
    Hello, we are having some issues with Logging on k8s and Dask losing some messages. This is even occurring on a simple flow. Odd thing is that if I put a small delay(5sec) after what should be logged it appears in the log and anything before. Has anyone else noticed this?  Sample task will not print a message to the log:  
    @task(log_stdout=True)
    def print_msg():
        print("Will it work?")
     Sample task will print message to the log:  
    @task(log_stdout=True)
    def print_msg():
        print("Will it work? Yup!")
        time.sleep(5)
      Any help appreciated,   P
    Kevin Kho

    Kevin Kho

    1 year ago
    Hey @Peter Peter, messages shouldn’t be lost. There is possibility of a delay when showing up in the UI. Do these not show up in the UI after a while?
    p

    Peter Peter

    1 year ago
    Thanks for the quick response @Kevin Kho, No they never show up. But they show up with there is a small delay after.
    Kevin Kho

    Kevin Kho

    1 year ago
    Looks like there is a chance of a race condition here. A team member will look into it. Do you experience this also when you run Flows without Dask? Does it always happen for the first flow?
    p

    Peter Peter

    1 year ago
    If I run it locally there are no issues with logging. What do you mean by first flow? if you mean task if I have a number of tasks that print to the log it will not print them if there is no delay. If I have 3 print tasks and the second has a delay(after the print) then the first will print along with the second message.
    Kevin Kho

    Kevin Kho

    1 year ago
    Sorry I meant the first task*
    p

    Peter Peter

    1 year ago
    It seems to happen if the flow finishes too fast. It will happen fist, second, .... . First noticed it if a task fails there was no actual stack trace and no logging put in place.
    Kevin Kho

    Kevin Kho

    1 year ago
    Got it we’ll have a team member look into this
    p

    Peter Peter

    1 year ago
    @Kevin Kho Thanks! Keep me posted if you don't mind
    Kevin Kho

    Kevin Kho

    1 year ago
    Sure. I don’t have any updates for now, but a team member was running some tests on this.
    p

    Peter Peter

    1 year ago
    @Kevin Kho Any update on this?
    Kevin Kho

    Kevin Kho

    1 year ago
    Will check
    Michael Adkins

    Michael Adkins

    1 year ago
    Hey @Peter Peter -- do the logs never show up or do they eventually populate in the UI?
    p

    Peter Peter

    1 year ago
    @Michael Adkins If I add a delay in the task they will show up. It seems to be logging at the end of the flow(crash, or graceful finish) that are missing.
    Michael Adkins

    Michael Adkins

    1 year ago
    How are you viewing these logs?
    p

    Peter Peter

    1 year ago
    prefect ui
    Michael Adkins

    Michael Adkins

    1 year ago
    And if you refresh the page after the flow run is complete they do not appear still? The flow run state can be reported as complete before logs finish propagating.
    p

    Peter Peter

    1 year ago
    no they do not appear later or tomorrow. No refresh helps
    Michael Adkins

    Michael Adkins

    1 year ago
    If you use a
    logger
    instance instead of logging stdout, do you see the same behavior?
    I've never seen this so it may be quite specific to your setup. Some additional information on your executor configuration may be useful as well.
    p

    Peter Peter

    1 year ago
    I will need to try if it happens when using the logger as well
    Michael Adkins

    Michael Adkins

    1 year ago
    Thanks! Just trying to narrow down where things are going wrong.
    p

    Peter Peter

    1 year ago
    via logger they still do not show up.
    Michael Adkins

    Michael Adkins

    1 year ago
    Which dask executor and scheduler are you using?
    p

    Peter Peter

    1 year ago
    executor = DaskExecutor(cluster_class=lambda: KubeCluster(     make_pod_spec(image='theImageName')),                         adapt_kwargs={                             "minimum": 1,                             "maximum": 1                         })
    Michael Adkins

    Michael Adkins

    1 year ago
    👍
    Does this also occur when not using a
    KubeCluster
    dask cluster?
    p

    Peter Peter

    1 year ago
    still using daskexecutor?
    Michael Adkins

    Michael Adkins

    1 year ago
    Yeah, just with a local dask cluster
    (that the executor creates still)
    p

    Peter Peter

    1 year ago
    with "executor = DaskExecutor(adapt_kwargs={"minimum": 1, "maximum": 1})" logging is still missing
    Michael Adkins

    Michael Adkins

    1 year ago
    I cannot reproduce this with a simple flow
    If you use
    from prefect import Flow, task
    from prefect.executors import DaskExecutor
    
    @task(log_stdout=True)
    def print_msg():
        print("Will it work?")
    
    with Flow("test", executor=DaskExecutor()) as flow:
        print_msg()
    do you see the same behavior?
    I'm using
    prefect register -p flow.py --project test
    and
    prefect run --name test --execute
    but I also cannot reproduce this when using an agent.
    p

    Peter Peter

    1 year ago
    in my version it says -p is not a valid argument. Could this issue have been fixed in recent versions of prefect?
    we are using 0.14.6
    Michael Adkins

    Michael Adkins

    1 year ago
    Ah the register/run CLIs have been rehauled since then
    p

    Peter Peter

    1 year ago
    I have been registering using flow.register() and running from UI
    Michael Adkins

    Michael Adkins

    1 year ago
    I'm not sure what's causing your issue so I can't say if a new version will have resolved it. At the very least, you should try upgrading to the newest version within 0.14.x. I'd recommend moving to 0.15 when you get the chance 🙂
    The logging behavior should be the same whether you use the CLI or not.
    p

    Peter Peter

    1 year ago
    The above sample does not execute correctly on kubernetes. This is the sample I am using.
    from prefect import task
    from prefect.storage import Docker
    from prefect.run_configs import KubernetesRun
    from prefect.executors import DaskExecutor
    from prefect import Flow
    import prefect
    
    
    @task(log_stdout=True)
    def print_first():
        print("_First Message!")
        logger = prefect.context.get("logger")
        <http://logger.info|logger.info>("1234!")
        logger.error("5678!")
    
    
    with Flow("log_flow_delay_after_3rd"as flow:
        a1 = print_first()
    
    env_vars = {
        "PREFECT__LOGGING__LEVEL""DEBUG",
    }
    
    storage = Docker(registry_url="FILLIN",
                     image_name="IMAGENAME",
                     image_tag="0.1.36",
                     local_image=False,
                     env_vars=env_vars)
    
    executor = DaskExecutor(adapt_kwargs={"minimum"1"maximum"1})
    
    flow.executor = executor
    
    flow.run_config = KubernetesRun(
        labels=["DASK"],
        cpu_request=1,
        memory_request=1,
    )
    
    storage.add_flow(flow)
    flow.storage = storage
    
    flow.register(project_name="log_test", build=False)
    
    storage.build(push=True)
    Michael Adkins

    Michael Adkins

    1 year ago
    Can you clarify: Does your / my sample work without kubernetes?
    Are you seeing this behavior on Kubernetes without a Dask Executor?
    p

    Peter Peter

    1 year ago
    if I ran that as a local I do see all the log entries on the screen. See the same behaviour without the Dask Executor
    Michael Adkins

    Michael Adkins

    1 year ago
    So just to clarify, this is only an issue with the
    KubernetesRun
    ?
    p

    Peter Peter

    1 year ago
    Just tested on a local prefect server and no issues. Seems like the issue is only in Kubernetes
    Michael Adkins

    Michael Adkins

    1 year ago
    Great thanks! I'll try to reproduce and get back to you.
    p

    Peter Peter

    1 year ago
    @Michael Adkins Were you able to reproduce this issue?
    Michael Adkins

    Michael Adkins

    1 year ago
    Sorry Peter, this slipped off my radar
    Let me see if I can find someone to help me reproduce, I'm very busy lately.
    We've run this example in our cluster and the logs appear as they should 😕
    Tyler Wanner

    Tyler Wanner

    1 year ago
    Hi Peter. I've registered this flow on 0.14.6 with 1 minor change to the base_image and I still see the logs in Prefect Cloud. In my Docker storage I used
    base_image = "prefecthq/prefect:0.14.6-python3.8"
    but I don't believe this to be the problem. Anything interesting about the cluster it's running in?
    p

    Peter Peter

    1 year ago
    Hello, Not sure if there is anything interesting about the cluster. They are supposed to be updating the version of prefect to the latest. I Will test on that instance when it is complete.