diff --git a/metaflow/metaflow_config.py b/metaflow/metaflow_config.py index 066e5659216..385dfa98f5f 100644 --- a/metaflow/metaflow_config.py +++ b/metaflow/metaflow_config.py @@ -540,6 +540,7 @@ "userconf", "conda", "package", + "card", ] for typ in DEBUG_OPTIONS: diff --git a/metaflow/plugins/cards/card_creator.py b/metaflow/plugins/cards/card_creator.py index 597c25096de..ec5f5389141 100644 --- a/metaflow/plugins/cards/card_creator.py +++ b/metaflow/plugins/cards/card_creator.py @@ -5,6 +5,7 @@ import sys import os from metaflow import current +from metaflow.debug import debug from typing import Callable, Tuple, Dict @@ -87,6 +88,10 @@ def create( component_strings = current.card._serialize_components(card_uuid) # Since the mode is a render, we can check if we need to write to the metadata store. save_metadata, metadata_dict = self._should_save_metadata(card_uuid) + debug.card_exec( + "create card_uuid=%s mode=%s final=%s sync=%s runtime_card=%s save_metadata=%s" + % (card_uuid, mode, final, sync, runtime_card, save_metadata) + ) data = current.card._get_latest_data(card_uuid, final=final, mode=mode) runspec = "/".join([current.run_id, current.step_name, current.task_id]) self._run_cards_subprocess( @@ -179,6 +184,7 @@ def _run_cards_subprocess( if save_metadata: cmd += ["--save-metadata", json.dumps(metadata_dict)] + debug.card_exec(cmd) response, fail = self._run_command( cmd, card_uuid, @@ -219,9 +225,28 @@ def _run_command(self, cmd, card_uuid, env, wait=True, timeout=None): except subprocess.CalledProcessError as e: rep = e.output fail = True + if debug.card and rep is not None: + debug.card_exec( + "render subprocess for %s %s output:\n%s" + % ( + card_uuid, + "FAILED" if fail else "succeeded", + rep.decode("utf-8"), + ) + ) except subprocess.TimeoutExpired as e: rep = e.output fail = True + if debug.card and rep is not None: + debug.card_exec( + "render subprocess for %s %s output:\n%s" + % ( + card_uuid, + "FAILED" if fail else "succeeded", + rep.decode("utf-8"), + ) + ) + return rep, fail else: _async_proc, _async_started = CardProcessManager._get_card_process( @@ -238,8 +263,13 @@ def _run_command(self, cmd, card_uuid, env, wait=True, timeout=None): else: # silently refuse to run an async process if a previous one is still running # and timeout hasn't been reached + debug.card_exec( + "skipping async render for %s: previous process still running" + % card_uuid + ) return "".encode(), False else: + debug.card_exec("launching async render for %s" % card_uuid) CardProcessManager._register_card_process( card_uuid, subprocess.Popen( diff --git a/metaflow/plugins/cards/card_decorator.py b/metaflow/plugins/cards/card_decorator.py index daa667fa2a7..9c2ec1ff4b1 100644 --- a/metaflow/plugins/cards/card_decorator.py +++ b/metaflow/plugins/cards/card_decorator.py @@ -10,6 +10,7 @@ from metaflow.user_configs.config_options import ConfigInput from metaflow.user_configs.config_parameters import dump_config_values from metaflow.util import to_unicode +from metaflow.debug import debug from .component_serializer import CardComponentCollector, get_card_class from .card_creator import CardCreator @@ -241,6 +242,17 @@ def task_pre_step( self._is_editable = True self._is_runtime_card = card_class.RUNTIME_UPDATABLE + debug.card_exec( + "task_pre_step step=%s type=%s found=%s editable=%s runtime=%s" + % ( + step_name, + card_type, + card_class is not None, + self._is_editable, + self._is_runtime_card, + ) + ) + # We have a step counter to ensure that on calling the final card decorator's `task_pre_step` # we call a `finalize` function in the `CardComponentCollector`. # This can help ensure the behaviour of the `current.card` object is according to specification. @@ -322,6 +334,16 @@ def task_finished( card_options=self.card_options, logger=self._logger, ) + debug.card_exec( + "task_finished step=%s card_uuid=%s type=%s is_task_ok=%s -> %s" + % ( + step_name, + self._card_uuid, + self.attributes["type"], + is_task_ok, + "rendering" if is_task_ok else "skipping (task failed)", + ) + ) if is_task_ok: self.card_creator.create(mode="render", final=True, **create_options) self.card_creator.create(mode="refresh", final=True, **create_options)