DBT Error: Unused components in ISO String

[sryza]

Discussed in #24472

^{Originally posted by fredonia88 September 13, 2024}
I keep hitting these intermittent ISO errors (stack trace below), which completely stops my dbt runs. The error is very difficult to reproduce, as it happens unpredictably.

In resources_v2.py, it looks like Dagster tries to stream events via self.stream_raw_events() by instantiating a single event from DbtCliEventMessage with the raw_event from the stdout log. I think the event is instantiating properly, but once it calls event.to_default_asset_events() it breaks cause the date in event_node_info has an extra digit or something.

@rexledesma have you seen this before? Any suggestions on how to handle this? I'm currently catching the error and restarting the stream in my dbt_assets definition; it works OK but its really hacky.

I'm using Redshift with dagster-dbt==0.23.3. I'm using a postgres database for my event storage.

ValueError: Unused components in ISO string
  File "/usr/local/lib/python3.11/site-packages/dagster/_core/execution/plan/utils.py", line 54, in op_execution_error_boundary
    yield
  File "/usr/local/lib/python3.11/site-packages/dagster/_utils/__init__.py", line 465, in iterate_with_context
    next_output = next(iterator)
                  ^^^^^^^^^^^^^^
  File "/opt/dagster/app/dagsterdbt/assets.py", line 15, in dbt_analytics_assets
    yield from dbt.cli(['build', '--indirect-selection=buildable'], context=context).stream()
  File "/usr/local/lib/python3.11/site-packages/dagster_dbt/core/resources_v2.py", line 390, in stream
    yield from event.to_default_asset_events(
  File "/usr/local/lib/python3.11/site-packages/dagster_dbt/core/resources_v2.py", line 151, in to_default_asset_events
    started_at = dateutil.parser.isoparse(event_node_info["node_started_at"])
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/dateutil/parser/isoparser.py", line 37, in func
    return f(self, str_in, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/dateutil/parser/isoparser.py", line 138, in isoparse
    components += self._parse_isotime(dt_str[pos + 1:])
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/dateutil/parser/isoparser.py", line 374, in _parse_isotime
    raise ValueError('Unused components in ISO string')
```</div>

[fredonia88]

Hey @sryza @rexledesma -- is there an upcoming release in the works that will address this? Thanks!

[garethbrickman]

@fredonia88 Not yet, are you able to reproduce it?

[fredonia88]

Hey @garethbrickman and @sryza -- I have solved the issue. Explanation below:

I configured my dbt profiles.yml to mask all database connection environment variables via the special prefix DBT_ENV_SECRET, including the Redshift/Postgres port number 5439. This means, any value written to the dbt.log file that matches one of the masked environment variables would be scrubbed with *****.

There were cases where a node would finish, and the microseconds would match the port number exactly. Consequently, the value would be scrubbed from the logs:

{"data": {"execution_time": 0.51501274, "index": 18, "name": "my_dbt_test", "node_info": {"materialized": "test", "meta": {}, "node_finished_at": "2025-03-11T14:44:49.31*****"

When Dagster tries to consume the log to output to the UI, it tries to load node_finished_at into dateutil, but it freaks out because of the *****.

Removing the special prefix for the port number resolved the issue. You can mark this as resolved!