Page MenuHomePhabricator

Promote some step events to INFO
ClosedPublic

Authored by max on Aug 14 2019, 3:20 PM.

Details

Reviewers
schrockn
Group Reviewers
Restricted Project
Commits
R1:ba17c716e752: Promote some step events to INFO
Summary

Fixes https://github.com/dagster-io/dagster/issues/1666 by ensuring some structured logs are
printed to the console on a naive hello-world invocation

Test Plan

Unit, manual

Diff Detail

Repository
R1 dagster
Branch
print-structured-events
Lint
Lint OK
Unit
No Unit Test Coverage

Event Timeline

Hmmm. I think maybe we should upgrade the emitted system events to INFO instead?

This revision now requires changes to proceed.Aug 14 2019, 3:22 PM

Just going to note that they are very, very noisy

Maybe we should have some be debug and some be info

Sent via Superhuman iOS ( https://sprh.mn/?vip=schrockn@elementl.com )

Alternatively, we could have a CLI-specific logger that did some cute display stuff (could print out something like . . . . or take verbose options)

max retitled this revision from Drop the default console logger log level to DEBUG to Promote some step events to INFO.Aug 14 2019, 6:05 PM
max edited the summary of this revision. (Show Details)
max edited the test plan for this revision. (Show Details)

what does dagster cli output look like on hello world?

what does dagster cli output look like on hello world?

ya can you include this or equivalent in your summary/test plan/a comment

13:08 $ dagster pipeline execute hello_world_pipeline
2019-08-14 13:08:29 - dagster - INFO - 
        orig_message = "Started execution of step \"hello_world.compute\"."
      log_message_id = "76a5859e-f570-4149-8abb-5827edb5dc88"
       log_timestamp = "2019-08-14T20:08:29.680115"
              run_id = "0d373766-6ca8-4f54-a558-8dc503cb285e"
            pipeline = "hello_world_pipeline"
execution_epoch_time = 1565813309.6636858
            step_key = "hello_world.compute"
               solid = "hello_world"
    solid_definition = "hello_world"
       dagster_event = {"event_specific_data": null, "event_type_value": "STEP_START", "logging_tags": {"execution_epoch_time": 1565813309.6636858, "pipeline": "hello_world_pipeline", "solid": "hello_world", "solid_definition": "hello_world", "step_key": "hello_world.compute"}, "message": "Started execution of step \"hello_world.compute\".", "pipeline_name": "hello_world_pipeline", "solid_handle": ["hello_world", "hello_world", null], "step_key": "hello_world.compute", "step_kind_value": "COMPUTE"}
       pipeline_name = "hello_world_pipeline"
2019-08-14 13:08:29 - dagster - INFO - 
        orig_message = "Yielded output \"result\" of type \"Any\". (Type check passed)."
      log_message_id = "c2e86805-48d0-4ff9-a319-259e028bc697"
       log_timestamp = "2019-08-14T20:08:29.685378"
              run_id = "0d373766-6ca8-4f54-a558-8dc503cb285e"
            pipeline = "hello_world_pipeline"
execution_epoch_time = 1565813309.6636858
            step_key = "hello_world.compute"
               solid = "hello_world"
    solid_definition = "hello_world"
       dagster_event = {"event_specific_data": [["hello_world.compute", "result"], null, [true, "result", null, []]], "event_type_value": "STEP_OUTPUT", "logging_tags": {"execution_epoch_time": 1565813309.6636858, "pipeline": "hello_world_pipeline", "solid": "hello_world", "solid_definition": "hello_world", "step_key": "hello_world.compute"}, "message": "Yielded output \"result\" of type \"Any\". (Type check passed).", "pipeline_name": "hello_world_pipeline", "solid_handle": ["hello_world", "hello_world", null], "step_key": "hello_world.compute", "step_kind_value": "COMPUTE"}
       pipeline_name = "hello_world_pipeline"
2019-08-14 13:08:29 - dagster - INFO - 
        orig_message = "Finished execution of step \"hello_world.compute\" in 0.92ms."
      log_message_id = "33ddba7c-b6c7-421f-a906-4a0f9f942169"
       log_timestamp = "2019-08-14T20:08:29.685813"
              run_id = "0d373766-6ca8-4f54-a558-8dc503cb285e"
            pipeline = "hello_world_pipeline"
execution_epoch_time = 1565813309.6636858
            step_key = "hello_world.compute"
               solid = "hello_world"
    solid_definition = "hello_world"
       dagster_event = {"event_specific_data": [0.9248830028809607], "event_type_value": "STEP_SUCCESS", "logging_tags": {"execution_epoch_time": 1565813309.6636858, "pipeline": "hello_world_pipeline", "solid": "hello_world", "solid_definition": "hello_world", "step_key": "hello_world.compute"}, "message": "Finished execution of step \"hello_world.compute\" in 0.92ms.", "pipeline_name": "hello_world_pipeline", "solid_handle": ["hello_world", "hello_world", null], "step_key": "hello_world.compute", "step_kind_value": "COMPUTE"}
       pipeline_name = "hello_world_pipeline"
python_modules/dagster/dagster/core/events/__init__.py
55–60

im on board with showing more in the cli case but its unclear to me what the right set of things to promote to info is

Nits

python_modules/dagster/dagster/core/events/__init__.py
55–60

me too

This revision is now accepted and ready to land.Aug 15 2019, 4:58 PM

can you screenshot output of hello world tutorial?

This revision was automatically updated to reflect the committed changes.