Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Bug] Structured log messages for test results are missing meta properties #10811

Open
2 tasks done
tomwphillips opened this issue Oct 2, 2024 · 1 comment · May be fixed by #10812
Open
2 tasks done

[Bug] Structured log messages for test results are missing meta properties #10811

tomwphillips opened this issue Oct 2, 2024 · 1 comment · May be fixed by #10812
Labels
bug Something isn't working logging

Comments

@tomwphillips
Copy link

tomwphillips commented Oct 2, 2024 •
edited by dbeatty10
Loading

Is this a new bug in dbt-core?

  • I believe this is a new bug in dbt-core
  • I have searched the existing issues, and I could not find an existing issue for this bug

Current Behavior

We add metadata to models using the meta config. We wanted to process the log messages downstream and noticed that messages about test failures didn't include the metadata.

Expected Behavior

I expect it to be in the log message, like the messages about models being created.

Steps To Reproduce

  1. Create my_model.sql: select null as id
  2. Create a model config:
models:
  - name: my_model
    meta:
      owner: analytics
    columns:
      - name: id
        tests:
          - not_null
  1. Run dbt build --log-level-file info --log-format-file json -s my_model

Relevant log output

grep 'error' logs/dbt.log | jq:

{
  "data": {
    "execution_time": 1.0578208,
    "index": 2,
    "name": "not_null_my_model_id",
    "node_info": {
      "materialized": "test",
      "meta": {},
      "node_finished_at": "2024-10-02T15:11:41.274736",
      "node_name": "not_null_my_model_id",
      "node_path": "not_null_my_model_id.sql",
      "node_relation": {
        "alias": "not_null_my_model_id",
        "database": "tom-phillips-9dc6",
        "relation_name": "",
        "schema": "dp_dev_dbt_test__audit"
      },
      "node_started_at": "2024-10-02T15:11:40.215570",
      "node_status": "fail",
      "resource_type": "test",
      "unique_id": "test.onb.not_null_my_model_id.43e0e9183a"
    },
    "num_failures": 1,
    "num_models": 2,
    "status": "fail"
  },
  "info": {
    "category": "",
    "code": "Q007",
    "extra": {},
    "invocation_id": "8d2bf85b-671d-4a76-8c62-1a0ceeab3168",
    "level": "error",
    "msg": "2 of 2 FAIL 1 not_null_my_model_id ............................................. [\u001b[31mFAIL 1\u001b[0m in 1.06s]",
    "name": "LogTestResult",
    "pid": 75984,
    "thread": "Thread-3 (worker)",
    "ts": "2024-10-02T15:11:41.275073Z"
  }
}
{
  "data": {
    "keyboard_interrupt": false,
    "num_errors": 1,
    "num_warnings": 0
  },
  "info": {
    "category": "",
    "code": "Z030",
    "extra": {},
    "invocation_id": "8d2bf85b-671d-4a76-8c62-1a0ceeab3168",
    "level": "info",
    "msg": "\u001b[31mCompleted with 1 error and 0 warnings:\u001b[0m",
    "name": "EndOfRunSummary",
    "pid": 75984,
    "thread": "MainThread",
    "ts": "2024-10-02T15:11:42.741499Z"
  }
}
{
  "data": {
    "node_info": {
      "materialized": "test",
      "meta": {},
      "node_finished_at": "",
      "node_name": "not_null_my_model_id",
      "node_path": "not_null_my_model_id.sql",
      "node_relation": {
        "alias": "not_null_my_model_id",
        "database": "tom-phillips-9dc6",
        "relation_name": "",
        "schema": "dp_dev_dbt_test__audit"
      },
      "node_started_at": "",
      "node_status": "None",
      "resource_type": "test",
      "unique_id": "test.onb.not_null_my_model_id.43e0e9183a"
    },
    "node_name": "not_null_my_model_id",
    "path": "models/_models.yaml",
    "resource_type": "test"
  },
  "info": {
    "category": "",
    "code": "Z022",
    "extra": {},
    "invocation_id": "8d2bf85b-671d-4a76-8c62-1a0ceeab3168",
    "level": "error",
    "msg": "\u001b[31mFailure in test not_null_my_model_id (models/_models.yaml)\u001b[0m",
    "name": "RunResultFailure",
    "pid": 75984,
    "thread": "MainThread",
    "ts": "2024-10-02T15:11:42.741866Z"
  }
}
{
  "data": {
    "msg": "Got 1 result, configured to fail if != 0",
    "node_info": {
      "materialized": "test",
      "meta": {},
      "node_finished_at": "",
      "node_name": "not_null_my_model_id",
      "node_path": "not_null_my_model_id.sql",
      "node_relation": {
        "alias": "not_null_my_model_id",
        "database": "tom-phillips-9dc6",
        "relation_name": "",
        "schema": "dp_dev_dbt_test__audit"
      },
      "node_started_at": "",
      "node_status": "None",
      "resource_type": "test",
      "unique_id": "test.onb.not_null_my_model_id.43e0e9183a"
    }
  },
  "info": {
    "category": "",
    "code": "Z024",
    "extra": {},
    "invocation_id": "8d2bf85b-671d-4a76-8c62-1a0ceeab3168",
    "level": "error",
    "msg": "  Got 1 result, configured to fail if != 0",
    "name": "RunResultError",
    "pid": 75984,
    "thread": "MainThread",
    "ts": "2024-10-02T15:11:42.742065Z"
  }
}
{
  "data": {
    "stats": {
      "error": 1,
      "pass": 1,
      "skip": 0,
      "total": 2,
      "warn": 0
    }
  },
  "info": {
    "category": "",
    "code": "Z023",
    "extra": {},
    "invocation_id": "8d2bf85b-671d-4a76-8c62-1a0ceeab3168",
    "level": "info",
    "msg": "Done. PASS=1 WARN=0 ERROR=1 SKIP=0 TOTAL=2",
    "name": "StatsLine",
    "pid": 75984,
    "thread": "MainThread",
    "ts": "2024-10-02T15:11:42.742696Z"
  }
}

In contrast, we have the metadata in these messages, via grep 'analytics' logs/dbt.log | jq :

{
  "data": {
    "description": "sql view model dp_dev.my_model",
    "index": 1,
    "node_info": {
      "materialized": "view",
      "meta": {
        "owner": "analytics"
      },
      "node_finished_at": "",
      "node_name": "my_model",
      "node_path": "my_model.sql",
      "node_relation": {
        "alias": "my_model",
        "database": "tom-phillips-9dc6",
        "relation_name": "`tom-phillips-9dc6`.`dp_dev`.`my_model`",
        "schema": "dp_dev"
      },
      "node_started_at": "2024-10-02T15:11:39.023650",
      "node_status": "started",
      "resource_type": "model",
      "unique_id": "model.onb.my_model"
    },
    "total": 2
  },
  "info": {
    "category": "",
    "code": "Q011",
    "extra": {},
    "invocation_id": "8d2bf85b-671d-4a76-8c62-1a0ceeab3168",
    "level": "info",
    "msg": "1 of 2 START sql view model dp_dev.my_model .................................... [RUN]",
    "name": "LogStartLine",
    "pid": 75984,
    "thread": "Thread-1 (worker)",
    "ts": "2024-10-02T15:11:39.024499Z"
  }
}
{
  "data": {
    "description": "sql view model dp_dev.my_model",
    "execution_time": 1.1846421,
    "index": 1,
    "node_info": {
      "materialized": "view",
      "meta": {
        "owner": "analytics"
      },
      "node_finished_at": "2024-10-02T15:11:40.209614",
      "node_name": "my_model",
      "node_path": "my_model.sql",
      "node_relation": {
        "alias": "my_model",
        "database": "tom-phillips-9dc6",
        "relation_name": "`tom-phillips-9dc6`.`dp_dev`.`my_model`",
        "schema": "dp_dev"
      },
      "node_started_at": "2024-10-02T15:11:39.023650",
      "node_status": "success",
      "resource_type": "model",
      "unique_id": "model.onb.my_model"
    },
    "status": "CREATE VIEW (0 processed)",
    "total": 2
  },
  "info": {
    "category": "",
    "code": "Q012",
    "extra": {},
    "invocation_id": "8d2bf85b-671d-4a76-8c62-1a0ceeab3168",
    "level": "info",
    "msg": "1 of 2 OK created sql view model dp_dev.my_model ............................... [\u001b[32mCREATE VIEW (0 processed)\u001b[0m in 1.18s]",
    "name": "LogModelResult",
    "pid": 75984,
    "thread": "Thread-1 (worker)",
    "ts": "2024-10-02T15:11:40.212467Z"
  }
}

Environment

- OS: macOS 14.6.1
- Python: 3.11.6
- dbt: 1.8.7

Which database adapter are you using with dbt?

bigquery

Additional Context

I have a fix and will open a PR.
@tomwphillips tomwphillips added bug Something isn't working triage labels Oct 2, 2024
@tomwphillips tomwphillips linked a pull request Oct 2, 2024 that will close this issue
Open
5 tasks
@dbeatty10
Copy link
Contributor

Hey @tomwphillips thank you for raising this issue and putting up an associated PR (complete with testing!) 🏆

I was able to reproduce the same you described by using your instructions.

Agreed that we'd categorize this as a bug since our documentation says that node_info fields are intended to include the user-configured meta dictionary (which should apply to generic data tests).

@dbeatty10 dbeatty10 removed the triage label Oct 7, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working logging
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Add meta config to test log messages oaknorthbank/dbt-core
2 participants
@tomwphillips @dbeatty10