[CT-623] [Bug] JSON logging format outputs incorrect JSON for run_result

[jmriego]

Is there an existing issue for this?

• I have searched the existing issues

Current Behavior

The JSON logging format is outputting wrongly JSON formatted data for the key run_result inside the logs/dbt.log file. It might be that everything inside that key is being escaped as a string

Expected Behavior

I'm expecting to be able to extract data from data.run_result after running a dbt model. It seems like the data in run_result ends up being shown at the end of the run in the run results.json file, but we could use it without waiting to the end of the run for when we have long daily runs and we want to monitor the status of the load

Steps To Reproduce

Run the following from the command line (changing to what model you want to test). Then try to load the result

dbt --log-format json run --target uat --model any_model
cat logs/dbt.log | grep run_result | jq -r .data.run_result # this works
cat logs/dbt.log | grep run_result | jq -r .data.run_result | jq .status # this errors out not being able to load the previous log info

Relevant log output

{
  "code": "Q024",
  "data": {
    "run_result": "{'status': 'success', 'timing': \"[{'name': 'compile', 'started_at': '2022-05-10 10:33:26.552731', 'completed_at': '2022-05-10 10:33:26.942732'}, {'name': 'execute', 'started_at': '2022-05-10 10:33:26.947544', 'completed_at': '2022-05-10 10:34:19.984339'}]\", 'thread_id': 'Thread-1', 'execution_time': '53.43430256843567', 'adapter_response': \"{'_message': 'CREATE TABLE (34.6k rows, 3.3 MB processed)', 'code': 'CREATE TABLE', 'rows_affected': 34616, 'bytes_processed': 3468325}\", 'message': 'CREATE TABLE (34.6k rows, 3.3 MB processed)', 'failures': 'None', 'node': '{\\'raw_sql\\': \\'{{\\\\n  config(\\\\n    materialized = \"table\",\\\\n    partition_by={\\\\\\'field\\\\\\': \\\\\\'activity_date\\\\\\', \\\\\\'data_type\\\\\\': \\\\\\'date\\\\\\'},\\\\n    cluster_by = [\"from_currency\"]\\\\n  )\\\\n}}\\\\n\\\\n{% set source_columns = get_column_names_in_relation(rel=source(\\\\\\'source_raw\\\\\\', \\\\\\'tbl_currency_rates\\\\\\')) %}\\\\n{% set hide_columns = [\"_sdc_extracted_at\",\"_sdc_batched_at\",\"_sdc_deleted_at\"] %}\\\\n\\\\nWITH source_ AS (\\\\n\\\\n  SELECT * FROM {{ source(\\\\\\'source_raw\\\\\\', \\\\\\'tbl_currency_rates\\\\\\') }}\\\\n  WHERE\\\\n    _sdc_deleted_at IS NULL AND\\\\n    NOT is_deleted\\\\n\\\\n), renamed as (\\\\n\\\\n  SELECT\\\\n    DATE(activity_date) AS activity_date,\\\\n    from_currency,\\\\n    to_currency,\\\\n    exchange_rate,\\\\n    buy_rate,\\\\n    sell_rate,\\\\n    source,\\\\n    date_modified,\\\\n    row_hash,\\\\n    etl_updated_timestamp,\\\\n    etl_inserted_timestamp,\\\\n    etl_deleted_timestamp,\\\\n    is_deleted\\\\n  FROM source_\\\\n\\\\n), add_clean_rates as (\\\\n\\\\n  SELECT\\\\n    renamed.*,\\\\n    CASE WHEN from_currency = \\\\\\'JPY\\\\\\'\\\\n    THEN exchange_rate / 100000000\\\\n    ELSE exchange_rate / 1000000\\\\n    END AS to_usd\\\\n\\\\n  FROM\\\\n    renamed\\\\n\\\\n)\\\\n\\\\nSELECT * FROM add_clean_rates\\', \\'compiled\\': \\'True\\', \\'database\\': \\'my-uat-project-1234\\', \\'schema\\': \\'jvalenzuela\\', \\'fqn\\': \"[\\'slice\\', \\'staging\\', \\'source\\', \\'stg_source__tbl_currency_rates\\']\", \\'unique_id\\': \\'model.slice.stg_source__tbl_currency_rates\\', \\'package_name\\': \\'slice\\', \\'root_path\\': \\'/app\\', \\'path\\': \\'staging/source/stg_source__tbl_currency_rates.sql\\', \\'original_file_path\\': \\'models/staging/source/stg_source__tbl_currency_rates.sql\\', \\'name\\': \\'stg_source__tbl_currency_rates\\', \\'resource_type\\': \\'model\\', \\'alias\\': \\'stg_source__tbl_currency_rates\\', \\'checksum\\': \"{\\'name\\': \\'sha256\\', \\'checksum\\': \\'b1778439cfae472a1f5e3de31f7ca5619d6cf889b20afcd8eb192370d6b0d794\\'}\", \\'config\\': \\'{\\\\\\'_extra\\\\\\': \"{\\\\\\'grant_access_to\\\\\\': [{\\\\\\'project\\\\\\': \\\\\\'my-uat-project-1234\\\\\\', \\\\\\'dataset\\\\\\': \\\\\\'raw\\\\\\'}], \\\\\\'cluster_by\\\\\\': [\\\\\\'from_currency\\\\\\'], \\\\\\'partition_by\\\\\\': {\\\\\\'field\\\\\\': \\\\\\'activity_date\\\\\\', \\\\\\'data_type\\\\\\': \\\\\\'date\\\\\\'}}\", \\\\\\'enabled\\\\\\': \\\\\\'True\\\\\\', \\\\\\'alias\\\\\\': \\\\\\'None\\\\\\', \\\\\\'schema\\\\\\': \\\\\\'staging\\\\\\', \\\\\\'database\\\\\\': \\\\\\'None\\\\\\', \\\\\\'tags\\\\\\': \"[\\\\\\'staging\\\\\\']\", \\\\\\'meta\\\\\\': \"{\\\\\\'team_id\\\\\\': \\\\\\'enterprise-eda\\\\\\', \\\\\\'standard_filters_at_consumption\\\\\\': \\\\\\'None\\\\\\', \\\\\\'general_limitations\\\\\\': \\\\\\'None\\\\\\'}\", \\\\\\'materialized\\\\\\': \\\\\\'table\\\\\\', \\\\\\'persist_docs\\\\\\': \"{\\\\\\'relation\\\\\\': True, \\\\\\'columns\\\\\\': True}\", \\\\\\'post_hook\\\\\\': \"[{\\\\\\'sql\\\\\\': \\\\\\'{{ set_labels_post(this, model) }}\\\\\\', \\\\\\'transaction\\\\\\': \\\\\\'True\\\\\\', \\\\\\'index\\\\\\': \\\\\\'None\\\\\\'}]\", \\\\\\'pre_hook\\\\\\': \"[{\\\\\\'sql\\\\\\': \\\\\\'{{ set_labels_pre(this, model) }}\\\\\\', \\\\\\'transaction\\\\\\': \\\\\\'True\\\\\\', \\\\\\'index\\\\\\': \\\\\\'None\\\\\\'}]\", \\\\\\'quoting\\\\\\': \\\\\\'{}\\\\\\', \\\\\\'column_types\\\\\\': \\\\\\'{}\\\\\\', \\\\\\'full_refresh\\\\\\': \\\\\\'None\\\\\\', \\\\\\'on_schema_change\\\\\\': \\\\\\'ignore\\\\\\'}\\', \\'tags\\': \"[\\'staging\\']\", \\'refs\\': \\'[]\\', \\'sources\\': \"[[\\'source_raw\\', \\'tbl_currency_rates\\'], [\\'source_raw\\', \\'tbl_currency_rates\\']]\", \\'depends_on\\': \\'{\\\\\\'macros\\\\\\': \"[\\\\\\'macro.slice.get_column_names_in_relation\\\\\\', \\\\\\'macro.slice.set_labels_pre\\\\\\', \\\\\\'macro.slice.set_labels_post\\\\\\', \\\\\\'macro.dbt.run_hooks\\\\\\', \\\\\\'macro.dbt.statement\\\\\\', \\\\\\'macro.dbt.persist_docs\\\\\\']\", \\\\\\'nodes\\\\\\': \"[\\\\\\'source.slice.source_raw.tbl_currency_rates\\\\\\', \\\\\\'source.slice.source_raw.tbl_currency_rates\\\\\\']\"}\\', \\'description\\': \\'This table stores currency rates.\\', \\'columns\\': \"{\\'activity_date\\': {\\'name\\': \\'activity_date\\', \\'description\\': \\'Activity date\\', \\'meta\\': \\'{}\\', \\'data_type\\': \\'None\\', \\'quote\\': \\'None\\', \\'tags\\': \\'[]\\', \\'_extra\\': \\'{}\\'}, \\'from_currency\\': {\\'name\\': \\'from_currency\\', \\'description\\': \\'From currency\\', \\'meta\\': \\'{}\\', \\'data_type\\': \\'None\\', \\'quote\\': \\'None\\', \\'tags\\': \\'[]\\', \\'_extra\\': \\'{}\\'}, \\'to_currency\\': {\\'name\\': \\'to_currency\\', \\'description\\': \\'To currency\\', \\'meta\\': \\'{}\\', \\'data_type\\': \\'None\\', \\'quote\\': \\'None\\', \\'tags\\': \\'[]\\', \\'_extra\\': \\'{}\\'}, \\'exchange_rate\\': {\\'name\\': \\'exchange_rate\\', \\'description\\': \\'Exchange rate\\', \\'meta\\': \\'{}\\', \\'data_type\\': \\'None\\', \\'quote\\': \\'None\\', \\'tags\\': \\'[]\\', \\'_extra\\': \\'{}\\'}, \\'buy_rate\\': {\\'name\\': \\'buy_rate\\', \\'description\\': \\'Buy rate\\', \\'meta\\': \\'{}\\', \\'data_type\\': \\'None\\', \\'quote\\': \\'None\\', \\'tags\\': \\'[]\\', \\'_extra\\': \\'{}\\'}, \\'sell_rate\\': {\\'name\\': \\'sell_rate\\', \\'description\\': \\'Sell rate\\', \\'meta\\': \\'{}\\', \\'data_type\\': \\'None\\', \\'quote\\': \\'None\\', \\'tags\\': \\'[]\\', \\'_extra\\': \\'{}\\'}, \\'source\\': {\\'name\\': \\'source\\', \\'description\\': \\'Source\\', \\'meta\\': \\'{}\\', \\'data_type\\': \\'None\\', \\'quote\\': \\'None\\', \\'tags\\': \\'[]\\', \\'_extra\\': \\'{}\\'}, \\'date_modified\\': {\\'name\\': \\'date_modified\\', \\'description\\': \\'Date modified\\', \\'meta\\': \\'{}\\', \\'data_type\\': \\'None\\', \\'quote\\': \\'None\\', \\'tags\\': \\'[]\\', \\'_extra\\': \\'{}\\'}, \\'row_hash\\': {\\'name\\': \\'row_hash\\', \\'description\\': \\'Row Hash\\', \\'meta\\': \\'{}\\', \\'data_type\\': \\'None\\', \\'quote\\': \\'None\\', \\'tags\\': \\'[]\\', \\'_extra\\': \\'{}\\'}, \\'etl_updated_timestamp\\': {\\'name\\': \\'etl_updated_timestamp\\', \\'description\\': \\'the timestamp when this row was last updated or inserted\\', \\'meta\\': \\'{}\\', \\'data_type\\': \\'None\\', \\'quote\\': \\'None\\', \\'tags\\': \\'[]\\', \\'_extra\\': \\'{}\\'}, \\'etl_inserted_timestamp\\': {\\'name\\': \\'etl_inserted_timestamp\\', \\'description\\': \\'the timestamp when this row was inserted\\', \\'meta\\': \\'{}\\', \\'data_type\\': \\'None\\', \\'quote\\': \\'None\\', \\'tags\\': \\'[]\\', \\'_extra\\': \\'{}\\'}, \\'etl_deleted_timestamp\\': {\\'name\\': \\'etl_deleted_timestamp\\', \\'description\\': \\'the timestamp when this row was deleted\\', \\'meta\\': \\'{}\\', \\'data_type\\': \\'None\\', \\'quote\\': \\'None\\', \\'tags\\': \\'[]\\', \\'_extra\\': \\'{}\\'}, \\'is_deleted\\': {\\'name\\': \\'is_deleted\\', \\'description\\': \\'row meta-data if True, the row with this primary key can no longer be found in the source\\', \\'meta\\': \\'{}\\', \\'data_type\\': \\'None\\', \\'quote\\': \\'None\\', \\'tags\\': \\'[]\\', \\'_extra\\': \\'{}\\'}, \\'to_usd\\': {\\'name\\': \\'to_usd\\', \\'description\\': \\'conversion to usd\\', \\'meta\\': \\'{}\\', \\'data_type\\': \\'None\\', \\'quote\\': \\'None\\', \\'tags\\': \\'[]\\', \\'_extra\\': \\'{}\\'}}\", \\'meta\\': \\'{}\\', \\'docs\\': \"{\\'show\\': \\'True\\'}\", \\'patch_path\\': \\'slice://models/staging/source/stg_source__tbl_currency_rates.yml\\', \\'compiled_path\\': \\'target/compiled/slice/models/staging/source/stg_source__tbl_currency_rates.sql\\', \\'build_path\\': \\'target/run/slice/models/staging/source/stg_source__tbl_currency_rates.sql\\', \\'deferred\\': \\'False\\', \\'unrendered_config\\': \\'{\\\\\\'schema\\\\\\': \\\\\\'staging\\\\\\', \\\\\\'pre-hook\\\\\\': \\\\\\'{{ set_labels_pre(this, model) }}\\\\\\', \\\\\\'post-hook\\\\\\': \\\\\\'{{ set_labels_post(this, model) }}\\\\\\', \\\\\\'persist_docs\\\\\\': {\\\\\\'relation\\\\\\': True, \\\\\\'columns\\\\\\': True}, \\\\\\'grant_access_to\\\\\\': [{\\\\\\'project\\\\\\': \\\\\\'{{ \"my-dev-project-1234\" if target.name == \"dev\" else \"my-bq-project-1234\" if target.name == \"prod\" else \"my-uat-project-1234\" }}\\\\\\', \\\\\\'dataset\\\\\\': \\\\\\'raw\\\\\\'}], \\\\\\'tags\\\\\\': [\\\\\\'staging\\\\\\'], \\\\\\'materialized\\\\\\': \\\\\\'table\\\\\\', \\\\\\'partition_by\\\\\\': {\\\\\\'field\\\\\\': \\\\\\'activity_date\\\\\\', \\\\\\'data_type\\\\\\': \\\\\\'date\\\\\\'}, \\\\\\'cluster_by\\\\\\': [\\\\\\'from_currency\\\\\\']}\\', \\'created_at\\': \\'1652178801.3161182\\', \\'config_call_dict\\': \\'{}\\', \\'_event_status\\': \"{\\'node_status\\': <RunningStatus.Executing: \\'executing\\'>}\", \\'compiled_sql\\': \"\\\\n\\\\n\\\\n\\\\n\\\\nWITH source_ AS (\\\\n\\\\n  SELECT * FROM `my-bq-project-1234`.`raw_source`.`tbl_currency_rates`\\\\n  WHERE\\\\n    _sdc_deleted_at IS NULL AND\\\\n    NOT is_deleted\\\\n\\\\n), renamed as (\\\\n\\\\n  SELECT\\\\n    DATE(activity_date) AS activity_date,\\\\n    from_currency,\\\\n    to_currency,\\\\n    exchange_rate,\\\\n    buy_rate,\\\\n    sell_rate,\\\\n    source,\\\\n    date_modified,\\\\n    row_hash,\\\\n    etl_updated_timestamp,\\\\n    etl_inserted_timestamp,\\\\n    etl_deleted_timestamp,\\\\n    is_deleted\\\\n  FROM source_\\\\n\\\\n), add_clean_rates as (\\\\n\\\\n  SELECT\\\\n    renamed.*,\\\\n    CASE WHEN from_currency = \\'JPY\\'\\\\n    THEN exchange_rate / 100000000\\\\n    ELSE exchange_rate / 1000000\\\\n    END AS to_usd\\\\n\\\\n  FROM\\\\n    renamed\\\\n\\\\n)\\\\n\\\\nSELECT * FROM add_clean_rates\", \\'extra_ctes_injected\\': \\'True\\', \\'extra_ctes\\': \\'[]\\', \\'relation_name\\': \\'`my-uat-project-1234`.`jvalenzuela`.`stg_source__tbl_currency_rates`\\', \\'_pre_injected_sql\\': \\'None\\'}', 'agate_table': 'None'}",
    "unique_id": "model.slice.stg_source__tbl_currency_rates"
  },
  "invocation_id": "64606add-7985-4ff2-ad7b-6b8afb66588b",
  "level": "debug",
  "log_version": 1,
  "msg": "Finished running node model.slice.stg_source__tbl_currency_rates",
  "node_info": {
    "materialized": "table",
    "node_finished_at": "2022-05-10T10:34:19.992212",
    "node_name": "stg_source__tbl_currency_rates",
    "node_path": "staging/source/stg_source__tbl_currency_rates.sql",
    "node_started_at": "2022-05-10T10:33:26.548844",
    "node_status": "success",
    "resource_type": "model",
    "type": "node_status",
    "unique_id": "model.slice.stg_source__tbl_currency_rates"
  },
  "pid": 8,
  "thread_name": "Thread-1",
  "ts": "2022-05-10T10:34:19.997210Z",
  "type": "log_line"
}

Environment

- OS: Ubuntu 20.04
- Python: 3.8.10
- dbt: 1.0.1

What database are you using dbt with?

bigquery

Additional Context

I'm trying to upload these logs to ElasticSearch but having issues processing it

[jtcohen6]

I think this is fixed in v1.1, possibly thanks to #4505

[jmriego]

thanks! I'll have a look at that

[github-actions]

This issue has been marked as Stale because it has been open for 180 days with no activity. If you would like the issue to remain open, please remove the stale label or comment on the issue, or it will be closed in 7 days.

[github-actions]

Although we are closing this issue as stale, it's not gone forever. Issues can be reopened if there is renewed community interest; add a comment to notify the maintainers.