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

max created this revision.Aug 14 2019, 3:20 PM
schrockn requested changes to this revision.Aug 14 2019, 3:22 PM

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
max added a comment.Aug 14 2019, 3:31 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 )

max added a comment.Aug 14 2019, 4:34 PM

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

max updated this revision to Diff 3700.Aug 14 2019, 6:05 PM

Rework

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)
schrockn added a comment.EditedAug 14 2019, 6:06 PM

what does dagster cli output look like on hello world?

max updated this revision to Diff 3701.Aug 14 2019, 6:06 PM

Fix tests

Harbormaster failed remote builds in B2964: Diff 3701!

what does dagster cli output look like on hello world?

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

max added a comment.Aug 14 2019, 8:09 PM
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"
alangenfeld added inline comments.Aug 14 2019, 8:28 PM
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

max updated this revision to Diff 3710.Aug 14 2019, 8:42 PM

Nits

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

me too

max updated this revision to Diff 3728.Aug 15 2019, 4:54 PM

Rewind

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

can you screenshot output of hello world tutorial?

max updated this revision to Diff 3730.Aug 15 2019, 5:08 PM

Assert