meltano invoke logs hard to parse and swallow INFO messages
Problem to solve
(Summarize the problem we are trying to solve in the form of we need to do [A], so that [B] can [C])
When @pnadolny13 and I were helping a user debug a problem with tap-csv, we noticed the debug logs weren't the most helpful.
## nicely formatted debug messages
time=2022-04-12 16:38:29 name=tap-csv level=INFO message=tap-csv v0.0.3, Meltano SDK v0.4.5)
time=2022-04-12 16:38:29 name=tap-csv level=INFO message=Skipping parse of env var settings...
time=2022-04-12 16:38:29 name=tap-csv level=INFO message=Config validation passed with 0 errors and 0 warnings.
time=2022-04-12 16:38:29 name=root level=INFO message=Operator '__else__=None' was not found. Unmapped streams will be included in output.
Traceback (most recent call last):
File "/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/bin/tap-csv", line 8, in <module>
sys.exit(TapCSV.cli())
File "/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/lib/python3.8/site-packages/click/core.py", line 1130, in __call__
return self.main(*args, **kwargs)
File "/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/lib/python3.8/site-packages/click/core.py", line 1055, in main
rv = self.invoke(ctx)
File "/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/lib/python3.8/site-packages/click/core.py", line 1404, in invoke
return ctx.invoke(self.callback, **ctx.params)
File "/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/lib/python3.8/site-packages/click/core.py", line 760, in invoke
return __callback(*args, **kwargs)
File "/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/lib/python3.8/site-packages/singer_sdk/tap_base.py", line 467, in cli
tap = cls( # type: ignore # Ignore 'type not callable'
File "/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/lib/python3.8/site-packages/singer_sdk/tap_base.py", line 92, in __init__
self.input_catalog or self._singer_catalog
File "/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/lib/python3.8/site-packages/singer_sdk/tap_base.py", line 235, in _singer_catalog
for stream in self.streams.values()
File "/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/lib/python3.8/site-packages/singer_sdk/tap_base.py", line 118, in streams
for stream in self.load_streams():
File "/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/lib/python3.8/site-packages/singer_sdk/tap_base.py", line 267, in load_streams
for stream in self.discover_streams():
File "/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/lib/python3.8/site-packages/tap_csv/tap.py", line 65, in discover_streams
return [
File "/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/lib/python3.8/site-packages/tap_csv/tap.py", line 66, in <listcomp>
CSVStream(
File "/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/lib/python3.8/site-packages/tap_csv/client.py", line 20, in __init__
super().__init__(*args, **kwargs)
File "/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/lib/python3.8/site-packages/singer_sdk/streams/core.py", line 137, in __init__
if not self.schema:
File "/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/lib/python3.8/site-packages/tap_csv/client.py", line 98, in schema
for file_path in self.get_file_paths():
File "/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/lib/python3.8/site-packages/tap_csv/client.py", line 49, in get_file_paths
raise Exception(f"File path does not exist {file_path}")
Exception: File path does not exist /extract/accounts.csv
2022-04-12T21:38:29.374047Z [debug ] Deleted configuration at /Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/run/tap-csv/tap.d51d2c39-c30d-4ad8-b468-554c023b1c98.config.json
2022-04-12T21:38:29.375720Z [debug ] Catalog discovery failed: command ['/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/bin/tap-csv', '--config', '/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/run/tap-csv/tap.d51d2c39-c30d-4ad8-b468-554c023b1c98.config.json', '--discover'] returned 1
Traceback (most recent call last):
File "/Users/taylormurphy/Documents/Projects/dev/meltano/src/meltano/cli/__init__.py", line 47, in main
cli(obj={"project": None})
File "/Users/taylormurphy/Library/Caches/pypoetry/virtualenvs/meltano-AqYjSFXr-py3.8/lib/python3.8/site-packages/click/core.py", line 829, in __call__
return self.main(*args, **kwargs)
File "/Users/taylormurphy/Library/Caches/pypoetry/virtualenvs/meltano-AqYjSFXr-py3.8/lib/python3.8/site-packages/click/core.py", line 782, in main
rv = self.invoke(ctx)
File "/Users/taylormurphy/Library/Caches/pypoetry/virtualenvs/meltano-AqYjSFXr-py3.8/lib/python3.8/site-packages/click/core.py", line 1259, in invoke
return _process_result(sub_ctx.command.invoke(sub_ctx))
File "/Users/taylormurphy/Library/Caches/pypoetry/virtualenvs/meltano-AqYjSFXr-py3.8/lib/python3.8/site-packages/click/core.py", line 1066, in invoke
return ctx.invoke(self.callback, **ctx.params)
File "/Users/taylormurphy/Library/Caches/pypoetry/virtualenvs/meltano-AqYjSFXr-py3.8/lib/python3.8/site-packages/click/core.py", line 610, in invoke
return callback(*args, **kwargs)
File "/Users/taylormurphy/Documents/Projects/dev/meltano/src/meltano/cli/params.py", line 23, in decorate
return func(*args, **kwargs)
File "/Users/taylormurphy/Documents/Projects/dev/meltano/src/meltano/cli/params.py", line 56, in decorate
func(project, *args, **kwargs)
File "/Users/taylormurphy/Documents/Projects/dev/meltano/src/meltano/cli/invoke.py", line 88, in invoke
exit_code = run_async(
File "/Users/taylormurphy/Documents/Projects/dev/meltano/src/meltano/core/utils/__init__.py", line 50, in run_async
loop.run_until_complete(future)
File "/Users/taylormurphy/.pyenv/versions/3.8.10/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
return future.result()
File "/Users/taylormurphy/Documents/Projects/dev/meltano/src/meltano/cli/invoke.py", line 131, in _invoke
handle = await invoker.invoke_async(*plugin_args, command=command_name)
File "/Users/taylormurphy/Documents/Projects/dev/meltano/src/meltano/core/plugin_invoker.py", line 388, in invoke_async
async with self._invoke(*args, **kwargs) as (
File "/Users/taylormurphy/Library/Caches/pypoetry/virtualenvs/meltano-AqYjSFXr-py3.8/lib/python3.8/site-packages/async_generator/_util.py", line 34, in __aenter__
return await self._agen.asend(None)
File "/Users/taylormurphy/Documents/Projects/dev/meltano/src/meltano/core/plugin_invoker.py", line 364, in _invoke
async with self.plugin.trigger_hooks("invoke", self, args):
File "/Users/taylormurphy/Library/Caches/pypoetry/virtualenvs/meltano-AqYjSFXr-py3.8/lib/python3.8/site-packages/async_generator/_util.py", line 34, in __aenter__
return await self._agen.asend(None)
File "/Users/taylormurphy/Documents/Projects/dev/meltano/src/meltano/core/behavior/hookable.py", line 87, in trigger_hooks
await self.__class__.trigger(self, f"before_{hook_name}", *args, **kwargs)
File "/Users/taylormurphy/Documents/Projects/dev/meltano/src/meltano/core/behavior/hookable.py", line 115, in trigger
raise err
File "/Users/taylormurphy/Documents/Projects/dev/meltano/src/meltano/core/behavior/hookable.py", line 107, in trigger
await hook_func(target, *args, **kwargs)
File "/Users/taylormurphy/Documents/Projects/dev/meltano/src/meltano/core/plugin/singer/tap.py", line 271, in discover_catalog_hook
await self.discover_catalog(plugin_invoker)
File "/Users/taylormurphy/Documents/Projects/dev/meltano/src/meltano/core/plugin/singer/tap.py", line 316, in discover_catalog
await self.run_discovery(plugin_invoker, catalog_path)
File "/Users/taylormurphy/Documents/Projects/dev/meltano/src/meltano/core/plugin/singer/tap.py", line 382, in run_discovery
raise PluginExecutionError(
meltano.core.plugin.error.PluginExecutionError: Catalog discovery failed: command ['/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/bin/tap-csv', '--config', '/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/run/tap-csv/tap.d51d2c39-c30d-4ad8-b468-554c023b1c98.config.json', '--discover'] returned 1
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/Users/taylormurphy/Documents/Projects/dev/meltano/src/meltano/cli/__init__.py", line 55, in main
raise CliError(str(err)) from err
meltano.cli.utils.CliError: Catalog discovery failed: command ['/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/bin/tap-csv', '--config', '/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/run/tap-csv/tap.d51d2c39-c30d-4ad8-b468-554c023b1c98.config.json', '--discover'] returned 1
Catalog discovery failed: command ['/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/bin/tap-csv', '--config', '/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/run/tap-csv/tap.d51d2c39-c30d-4ad8-b468-554c023b1c98.config.json', '--discover'] returned 1
There's several INFO
level messages that would be good to pass to the command line. All that a user currently gets w/o the debug flag is:
❯ meltano invoke tap-csv
time=2022-04-12 16:38:29 name=tap-csv level=INFO message=tap-csv v0.0.3, Meltano SDK v0.4.5)
time=2022-04-12 16:38:29 name=tap-csv level=INFO message=Skipping parse of env var settings...
time=2022-04-12 16:38:29 name=tap-csv level=INFO message=Config validation passed with 0 errors and 0 warnings.
time=2022-04-12 16:38:29 name=root level=INFO message=Operator '__else__=None' was not found. Unmapped streams will be included in output.
I would want to see
❯ meltano invoke tap-csv
### ALL INFO logs
### Some tap-level error showing the exception
Exception: File path does not exist /extract/accounts.csv
Catalog discovery failed: command ['/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/extractors/tap-csv/venv/bin/tap-csv', '--config', '/Users/taylormurphy/Documents/Projects/dev/meltano/csvtest/.meltano/run/tap-csv/tap.624fc81f-a823-4c78-9ebc-92a258d418d0.config.json', '--discover'] returned 1
Or something like that. Basically it's the difference between getting the full debug and getting some helpful context on what failed.
Proposal
(How are we going to solve the problem? Try to include the user journey)
At a minimum passing the INFO level log messages to the command line during meltano invoke
woudl be good. They're sent during meltano run
appropriately.
An nice addition would be better showing of the tap error.
What does success look like, and how can we measure that?
(Define both the success metrics and acceptance criteria. Note that success metrics indicate the desired business outcomes, while acceptance criteria indicate when the solution is working correctly. If there is no way to measure success, link to an issue that will implement a way to measure this)
Regression test
(Ensure the feature doesn't cause any regressions)
-
Write adequate test cases and submit test results -
Test results should be reviewed by a person from the team
Links / references
Please note that this was taken from GitLab, to be changed accordingly