Skip to content

Support of Timestamp for Cloudwatch-based remote logging #15144

Description

@pavelhlushchanka

Description

CloudwatchTaskHandler doesn't parse log event timestamp. As result if Airflow uses Cloudwatch for remote logging, logs in Airflow UI miss timestamp. They just contain concatenated messages.

Use case / motivation

It's more convenient to have a timestamp next to the log message to better understand what and when happened.

Are you willing to submit a PR?

I can do that, but that would be my first pr.

Activity

  1. boring-cyborg commented on Apr 1, 2021

    @boring-cyborg

    Thanks for opening your first issue here! Be sure to follow the issue template!

  2. jhtimmins commented on Apr 1, 2021

    @jhtimmins
    Contributor

    @codenamestif could you include log output and/or images of what you see?

    If you're interested in taking on this PR, it sounds like a solid first one. I'm happy to answer any questions you have about getting started.

  3. pavelhlushchanka commented on Apr 1, 2021

    @pavelhlushchanka
    ContributorAuthor

    Here is an example of the current behaviour:

    *** Reading remote log from Cloudwatch log_group: my_log_group log_stream: item_sub_category_2_demand_dag_v1/item_sub_category_2_demand/2021-04-01T15_42_13.963961+00_00/1.log.
    Dependencies all met for <TaskInstance: item_sub_category_2_demand_dag_v1.item_sub_category_2_demand 2021-04-01T15:42:13.963961+00:00 [queued]>
    Dependencies all met for <TaskInstance: item_sub_category_2_demand_dag_v1.item_sub_category_2_demand 2021-04-01T15:42:13.963961+00:00 [queued]>
    
    --------------------------------------------------------------------------------
    Starting attempt 1 of 4
    
    --------------------------------------------------------------------------------
    Executing <Task(ECSOperator): item_sub_category_2_demand> on 2021-04-01T15:42:13.963961+00:00
    Started process 89 to run task
    Running <TaskInstance: item_sub_category_2_demand_dag_v1.item_sub_category_2_demand 2021-04-01T15:42:13.963961+00:00 [running]> on host xxx-xxx
    Exporting the following env vars:
    AIRFLOW_CTX_DAG_OWNER=airflow
    AIRFLOW_CTX_DAG_ID=item_sub_category_2_demand_dag_v1
    AIRFLOW_CTX_TASK_ID=item_sub_category_2_demand
    AIRFLOW_CTX_EXECUTION_DATE=2021-04-01T15:42:13.963961+00:00
    AIRFLOW_CTX_DAG_RUN_ID=manual__2021-04-01T15:42:13.963961+00:00
    

    After I adjusted the handler I have got the next one:

    *** Reading remote log from Cloudwatch log_group: my_log_group log_stream: item_sub_category_2_demand_dag_v1/item_sub_category_2_demand/2021-04-01T15_42_13.963961+00_00/1.log.
    [2021-04-01T17:42:15.351000+02:00] - Dependencies all met for <TaskInstance: item_sub_category_2_demand_dag_v1.item_sub_category_2_demand 2021-04-01T15:42:13.963961+00:00 [queued]>
    [2021-04-01T17:42:15.411000+02:00] - Dependencies all met for <TaskInstance: item_sub_category_2_demand_dag_v1.item_sub_category_2_demand 2021-04-01T15:42:13.963961+00:00 [queued]>
    [2021-04-01T17:42:15.411000+02:00] - 
    --------------------------------------------------------------------------------
    [2021-04-01T17:42:15.411000+02:00] - Starting attempt 1 of 4
    [2021-04-01T17:42:15.411000+02:00] - 
    --------------------------------------------------------------------------------
    [2021-04-01T17:42:15.432000+02:00] - Executing <Task(ECSOperator): item_sub_category_2_demand> on 2021-04-01T15:42:13.963961+00:00
    [2021-04-01T17:42:15.435000+02:00] - Started process 89 to run task
    [2021-04-01T17:42:15.613000+02:00] - Running <TaskInstance: item_sub_category_2_demand_dag_v1.item_sub_category_2_demand 2021-04-01T15:42:13.963961+00:00 [running]> on host xxx-xxx
    [2021-04-01T17:42:15.718000+02:00] - Exporting the following env vars:
    AIRFLOW_CTX_DAG_OWNER=airflow
    AIRFLOW_CTX_DAG_ID=item_sub_category_2_demand_dag_v1
    AIRFLOW_CTX_TASK_ID=item_sub_category_2_demand
    AIRFLOW_CTX_EXECUTION_DATE=2021-04-01T15:42:13.963961+00:00
    AIRFLOW_CTX_DAG_RUN_ID=manual__2021-04-01T15:42:13.963961+00:00
    

    I also made a formatting of the timestamp based on UI timezone. If timezone formatting is a good idea, then there is also an issue with ECSOperator, that fetches the logs from the Cloudwatch and prints them in UTC. But this is another thing that can be improved.

  4. jhtimmins commented on Apr 2, 2021

    @jhtimmins
    Contributor

    @codenamestif Thanks for including the output.

    Would you like to submit a PR for this?

  5. pavelhlushchanka commented on Apr 2, 2021

    @pavelhlushchanka
    ContributorAuthor

    @jhtimmins yes, i will prepare a pr

  6. pavelhlushchanka commented on Apr 3, 2021

    @pavelhlushchanka
    ContributorAuthor

    @jhtimmins i prepared a draft pr since i have a question about implementation details.

  7. eladkal commented on May 14, 2021

    @eladkal
    Contributor

    fixed by #15173

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions