Page MenuHomePhabricator

Promote some step events to INFO
ClosedPublic

Authored by max on Wed, Aug 14, 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
Lint
Automatic diff as part of commit; lint not applicable.
Unit
Automatic diff as part of commit; unit tests not applicable.

Event Timeline

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

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

This revision now requires changes to proceed.Wed, Aug 14, 3:22 PM
max added a comment.Wed, Aug 14, 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.Wed, Aug 14, 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.Wed, Aug 14, 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.Wed, Aug 14, 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.EditedWed, Aug 14, 6:06 PM

what does dagster cli output look like on hello world?

max updated this revision to Diff 3701.Wed, Aug 14, 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.Wed, Aug 14, 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.Wed, Aug 14, 8:28 PM
python_modules/dagster/dagster/core/events/__init__.py
55–60 ↗(On Diff #3701)

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.Wed, Aug 14, 8:42 PM

Nits

python_modules/dagster/dagster/core/events/__init__.py
55–60 ↗(On Diff #3701)

me too

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

Rewind

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

can you screenshot output of hello world tutorial?

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

Assert