Logging
SDF provides several options for configuring log output. Furthermore, the SDF DB can be used to query and analyze logs.
SDF outputs valuable context to stdout by default, but rich trace logs are also available for debugging and monitoring.
The following guide will go through the different logging options available in SDF and how to use them. See the reference for details on log formats, levels, and properties.
Guide
Open an SDF workspace
Let’s use our moms_flower_shop_completed sample workspace as a base for this guide. If you don’t have it, you can create it by running:
Explore Log Levels
By default, SDF logs progress, warnings, and errors.
We can filter this down by specifying --log-level warn or --log-level error to only see warnings or errors, respectively.
To see more in-depth logs, we can use the --log-level info flag. This will expose logs that capture the internal steps that sdf follows to compile and run a workspace.
Let’s say we want to view info logs along with error and warn logs, we can run:
{“_ts”:“2024-12-18T19:43:39.018356747+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/main.rs:105”,“ev”:“sdf”}
{“_ts”:“2024-12-18T19:43:39.018417822+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/main.rs:106”,“ev”:“sdf”,“set”:“job_id”,“val_s”:“a72d8b49-1140-478d-851a-10e2a6de3f35”}
{“_ts”:“2024-12-18T19:43:39.018426488+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/main.rs:107”,“ev”:“sdf”,“set”:“args”,“val_as”:[“compile”,“moms_flower_shop.raw.raw_inapp_events”,“—log-level”,“info”,“—show”,“none”]}
{“_ts”:“2024-12-18T19:43:39.019767570+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/utils/initializing.rs:120”,“ev”:“initialize”}
{“_ts”:“2024-12-18T19:43:39.020657063+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/utils/initializing.rs:300”,“ev”:“initialize.load_workspace”}
{“_ts”:“2024-12-18T19:43:39.037274561+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/utils/initializing.rs:369”,“ev”:“initialize.load_workspace”,“st_dur_ms”:16}
{“_ts”:“2024-12-18T19:43:39.037288517+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/utils/initializing.rs:371”,“ev”:“initialize.load_dependencies”}
{“_ts”:“2024-12-18T19:43:39.037301251+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/utils/initializing.rs:502”,“ev”:“initialize.load_dependencies”,“st_dur_ms”:0}
{“_ts”:“2024-12-18T19:43:39.037310238+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/utils/initializing.rs:504”,“ev”:“initialize.load_prelude”}
{“_ts”:“2024-12-18T19:43:39.040359964+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/utils/initializing.rs:540”,“ev”:“initialize.load_prelude”,“st_dur_ms”:3}
We used --show none to avoid displaying stdout output. The --show flag controls the standard out, things like “compiling <table>”, and is separate from info, debug, and trace logs.
Nice! We’ve lifted up the hood on SDF and are seeing info logs in action.
debug and trace logs are also available, and are more detailed than info logs. Let’s try trace, the most detailed log level:
{“_ts”:“2024-12-18T19:43:40.696861588+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/utils/initializing.rs:579”,“ev”:“initialize.prep_env.resolve_env.build_env”,“st_dur_ms”:509}
{“_ts”:“2024-12-18T19:43:40.696924025+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/context/env.rs:900”,“message”:“Reading jinja file: sdf_test at sdftarget/dbg/.lib/sdf_test/macros/test.jinja”}
{“_ts”:“2024-12-18T19:43:40.697171901+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/context/env.rs:900”,“message”:“Reading jinja file: sdf_utils at sdftarget/dbg/.lib/sdf_utils/macros/date_spine.jinja”}
{“_ts”:“2024-12-18T19:43:40.697241472+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/context/env.rs:900”,“message”:“Reading jinja file: sdf_utils at sdftarget/dbg/.lib/sdf_utils/macros/generate_integer_values.jinja”}
{“_ts”:“2024-12-18T19:43:40.697280035+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/context/env.rs:900”,“message”:“Reading jinja file: sdf_utils at sdftarget/dbg/.lib/sdf_utils/macros/generate_surrogate_key.jinja”}
{“_ts”:“2024-12-18T19:43:40.697317054+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/context/env.rs:900”,“message”:“Reading jinja file: sdf_utils at sdftarget/dbg/.lib/sdf_utils/macros/group_by.jinja”}
{“_ts”:“2024-12-18T19:43:40.697354124+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/context/env.rs:900”,“message”:“Reading jinja file: sdf_utils at sdftarget/dbg/.lib/sdf_utils/macros/generate_date_values.jinja”}
{“_ts”:“2024-12-18T19:43:40.697390352+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/context/env.rs:900”,“message”:“Reading jinja file: sdf_mat at sdftarget/dbg/.lib/sdf_mat/macros/dialect/trino/materialize.jinja”}
{“_ts”:“2024-12-18T19:43:40.697754588+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/utils/initializing.rs:755”,“ev”:“initialize.prep_env.resolve_env”,“st_dur_ms”:510}
{“_ts”:“2024-12-18T19:43:40.698414950+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:521”,“ev”:“cmd.prepare.read_makefile”,“set”:“verdict”,“val_s”:“full-rebuild”}
{“_ts”:“2024-12-18T19:43:40.698423896+00:00”,“_ll”:“DEBUG”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:577”,“ev”:“cmd.prepare.read_makefile”,“set”:“analyze_with_sources”,“val_b”:false}
{“_ts”:“2024-12-18T19:43:40.698435829+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:582”,“ev”:“cmd.prepare.read_makefile”,“set”:“resolved_table_names”,“val_s”:”[]”}
{“_ts”:“2024-12-18T19:43:40.698442301+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:588”,“ev”:“cmd.prepare.read_makefile”,“set”:“seen_these_files”,“val_s”:”[]”}
{“_ts”:“2024-12-18T19:43:40.698448653+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:594”,“ev”:“cmd.prepare.read_makefile”,“set”:“sources”,“val_s”:”[]”}
{“_ts”:“2024-12-18T19:43:40.698454975+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:605”,“ev”:“cmd.prepare.read_makefile”,“st_dur_ms”:0}
{“_ts”:“2024-12-18T19:43:40.705758034+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:1654”,“ev”:“cmd.schedule.prep”}
{“_ts”:“2024-12-18T19:43:40.705789884+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:1677”,“ev”:“cmd.schedule”,“set”:“deps”,“val_as”:{“moms_flower_shop.raw.raw_inapp_events”:[]}}
{“_ts”:“2024-12-18T19:43:40.705821132+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:1757”,“ev”:“cmd.schedule.prep”,“st_dur_ms”:0}
{“_ts”:“2024-12-18T19:43:40.705830089+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:1854”,“ev”:“cmd.schedule”,“set”:“resolved_tables”,“val_as”:{}}
{“_ts”:“2024-12-18T19:43:40.705838134+00:00”,“_ll”:“DEBUG”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:1860”,“ev”:“cmd.schedule”,“set”:“sources_defined_by_providers”,“val_as”:[]}
{“_ts”:“2024-12-18T19:43:40.705847752+00:00”,“_ll”:“DEBUG”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:1906”,“ev”:“cmd.schedule”,“set”:“to_be_downloaded”,“val_as”:[]}
{“_ts”:“2024-12-18T19:43:40.705886155+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:2079”,“ev”:“cmd.schedule.dag”}
{“_ts”:“2024-12-18T19:43:40.705895963+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:2081”,“ev”:“cmd.schedule.dag”,“set”:“dag.deps”,“val_s”:“{"moms_flower_shop.raw.raw_inapp_events":[]}”}
{“_ts”:“2024-12-18T19:43:40.705910701+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:2095”,“ev”:“cmd.schedule.dag”,“set”:“dag.initial”,“val_s”:“{"moms_flower_shop.raw.raw_inapp_events":[]}”}
{“_ts”:“2024-12-18T19:43:40.705919588+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:2107”,“ev”:“cmd.schedule.dag”,“set”:“dag.cleaned”,“val_s”:“{"moms_flower_shop.raw.raw_inapp_events":[]}”}
{“_ts”:“2024-12-18T19:43:40.705925408+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:2113”,“ev”:“cmd.schedule.dag”,“set”:“missing_defs”,“val_s”:”[]”}
{“_ts”:“2024-12-18T19:43:40.705940336+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:2191”,“ev”:“cmd.schedule.dag”,“set”:“dag.resolved_targets”,“val_s”:“["moms_flower_shop.raw.raw_inapp_events"]”}
{“_ts”:“2024-12-18T19:43:40.705951678+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:2219”,“ev”:“cmd.schedule.dag”,“set”:“dag.targeted”,“val_s”:“{"moms_flower_shop.raw.raw_inapp_events":[]}”}
{“_ts”:“2024-12-18T19:43:40.705984169+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:2278”,“ev”:“cmd.schedule.dag”,“set”:“dag.acyclic”,“val_s”:“{"moms_flower_shop.raw.raw_inapp_events":[]}”}
{“_ts”:“2024-12-18T19:43:40.705990802+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:2284”,“ev”:“cmd.schedule.dag”,“set”:“cycles”,“val_s”:”[]”}
{“_ts”:“2024-12-18T19:43:40.705997003+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:2290”,“ev”:“cmd.schedule.dag”,“set”:“cut_points”,“val_s”:”[]”}
{“_ts”:“2024-12-18T19:43:40.706004076+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:2296”,“ev”:“cmd.schedule.dag”,“set”:“order.initial”,“val_s”:“["moms_flower_shop.raw.raw_inapp_events"]”}
{“_ts”:“2024-12-18T19:43:40.706032269+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:2565”,“ev”:“cmd.schedule.dag”,“set”:“showable_root_tables”,“val_s”:”[]”}
{“_ts”:“2024-12-18T19:43:40.706050053+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:2854”,“ev”:“cmd.schedule.dag”,“set”:“order.without_providers”,“val_s”:“["moms_flower_shop.raw.raw_inapp_events"]”}
{“_ts”:“2024-12-18T19:43:40.706059+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:2880”,“ev”:“cmd.schedule.dag”,“st_dur_ms”:0}
{“_ts”:“2024-12-18T19:43:40.706073166+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:2887”,“ev”:“cmd.do”}
{“_ts”:“2024-12-18T19:43:40.706082734+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:2913”,“ev”:“cmd.do”,“set”:“order.without_providers_or_cached”,“val_s”:“["moms_flower_shop.raw.raw_inapp_events"]”}
{“_ts”:“2024-12-18T19:43:40.706091901+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:2930”,“ev”:“cmd.do.sources”}
{“_ts”:“2024-12-18T19:43:40.706724869+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:4342”,“ev”:“cmd.do.derived.wave_1.mat”,“ev_tb”:“moms_flower_shop.raw.raw_inapp_events”,“ev_tb_catalog”:“moms_flower_shop”,“ev_tb_schema”:“raw”,“ev_tb_table”:“raw_inapp_events”}
{“_ts”:“2024-12-18T19:43:40.707564020+00:00”,“_ll”:“DEBUG”,“_fn”:“crates/sdf-cli/src/subcommands/describe.rs:261”,“ev”:“cmd.do.derived.wave_1.meta_analysis”,“ev_tb”:“moms_flower_shop.raw.raw_inapp_events”,“ev_tb_catalog”:“moms_flower_shop”,“ev_tb_schema”:“raw”,“ev_tb_table”:“raw_inapp_events”}
{“_ts”:“2024-12-18T19:43:40.707581082+00:00”,“_ll”:“DEBUG”,“_fn”:“crates/sdf-cli/src/subcommands/describe.rs:284”,“ev”:“cmd.do.derived.wave_1.meta_analysis”,“ev_tb”:“moms_flower_shop.raw.raw_inapp_events”,“ev_tb_catalog”:“moms_flower_shop”,“ev_tb_schema”:“raw”,“ev_tb_table”:“raw_inapp_events”,“st_dur_ms”:0}
{“_ts”:“2024-12-18T19:43:40.707627450+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:4466”,“ev”:“cmd.do.derived.wave_1.mat”,“ev_tb”:“moms_flower_shop.raw.raw_inapp_events”,“ev_tb_catalog”:“moms_flower_shop”,“ev_tb_purpose”:“model”,“ev_tb_schema”:“raw”,“ev_tb_table”:“raw_inapp_events”,“st_code”:“succeeded”,“st_done”:“executed”,“st_dur_ms”:0}
{“_ts”:“2024-12-18T19:43:40.707666663+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:4326”,“ev”:“cmd.do.derived”,“st_dur_ms”:1}
{“_ts”:“2024-12-18T19:43:40.708027940+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/utils/dep_cache.rs:1890”,“message”:“Saving table cache: moms_flower_shop.raw.raw_inapp_events, sdftarget/dbg/table/moms_flower_shop/raw/raw_inapp_events.sdf.yml”}
{“_ts”:“2024-12-18T19:43:40.708321295+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:3509”,“ev”:“cmd.do.gen_makefile”}
{“_ts”:“2024-12-18T19:43:40.708537301+00:00”,“_ll”:“TRACE”,“_fn”:“crates/sdf-cli/src/utils/dep_cache.rs:2300”,“ev”:“written_makefile”,“set”:“makefile”,“val_m”:{“contents”:{“cli_vars”:“99914b932bd37a50b983c5e7c90ae93b”,“credentials”:“99914b932bd37a50b983c5e7c90ae93b”,“env_vars”:“d751713988987e9331980363e24189ce”},“prelude”:[{“file”:“workspace.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“metadata/raw/raw_customers.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“metadata/staging/inapp_events.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“metadata/raw/raw_addresses.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“metadata/staging/app_installs.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“metadata/analytics/dim_marketing_campaigns.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“metadata/analytics/agg_installs_and_campaigns.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“metadata/raw/raw_marketing_campaign_events.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“metadata/raw/raw_inapp_events.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“classifications/column_classifiers.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“classifications/table_classifiers.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“metadata/raw/raw_customers.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“metadata/staging/inapp_events.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“metadata/raw/raw_addresses.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“metadata/staging/app_installs.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“metadata/analytics/dim_marketing_campaigns.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“metadata/analytics/agg_installs_and_campaigns.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“metadata/raw/raw_marketing_campaign_events.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“metadata/raw/raw_inapp_events.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“sdftarget/dbg/.lib/sdf_test/workspace.sdf.yml”,“mtime”:“2024-12-18T19:43:40.180881806Z”},{“file”:“sdftarget/dbg/.lib/sdf_utils/workspace.sdf.yml”,“mtime”:“2024-12-18T19:43:40.180881806Z”},{“file”:“sdftarget/dbg/.lib/sdf_mat/workspace.sdf.yml”,“mtime”:“2024-12-18T19:43:40.180881806Z”},{“file”:“sdftarget/dbg/.lib/sdf_test/macros/test.jinja”,“mtime”:“2024-12-18T19:43:40.180881806Z”},{“file”:“sdftarget/dbg/.lib/sdf_utils/macros/date_spine.jinja”,“mtime”:“2024-12-18T19:43:40.180881806Z”},{“file”:“sdftarget/dbg/.lib/sdf_utils/macros/generate_integer_values.jinja”,“mtime”:“2024-12-18T19:43:40.180881806Z”},{“file”:“sdftarget/dbg/.lib/sdf_utils/macros/generate_surrogate_key.jinja”,“mtime”:“2024-12-18T19:43:40.180881806Z”},{“file”:“sdftarget/dbg/.lib/sdf_utils/macros/group_by.jinja”,“mtime”:“2024-12-18T19:43:40.180881806Z”},{“file”:“sdftarget/dbg/.lib/sdf_utils/macros/generate_date_values.jinja”,“mtime”:“2024-12-18T19:43:40.180881806Z”},{“file”:“sdftarget/dbg/.lib/sdf_mat/macros/dialect/trino/materialize.jinja”,“mtime”:“2024-12-18T19:43:40.180881806Z”}],“deps”:[{“target”:“moms_flower_shop.raw.raw_inapp_events”,“deps”:[]}],“source_files”:{“values”:{“moms_flower_shop.raw.raw_inapp_events”:[{“file”:“metadata/raw/raw_inapp_events.sdf.yml”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“models/raw/raw_inapp_events.sql”,“mtime”:“2024-12-18T19:43:38.704861327Z”},{“file”:“seeds/parquet/inapp_events.parquet”,“mtime”:“2024-12-18T19:43:38.704861327Z”}]}},“incomplete_source_files”:{“values”:[]},“target_status”:{“values”:{“moms_flower_shop.raw.raw_inapp_events”:{“purpose”:“model”,“status”:“succeeded”,“draft”:false}}}}}
{“_ts”:“2024-12-18T19:43:40.708695485+00:00”,“_ll”:“INFO”,“_fn”:“crates/sdf-cli/src/subcommands/build.rs:3523”,“ev”:“cmd.do.gen_makefile”,“st_dur_ms”:0}
Notice that the trace logs include info, debug, and trace logs. Furthermore, the trace log is very very long. Trace logs are typically used for internal use cases, such as debugging SDF itself. As such, we recommend using info or debug logs for most use cases.
Writing Logs to Files
By default, SDF logs to stdout. However, we can write logs to a file by specifying the --log-file flag.
Let’s write the logs to a file named sdf.log:
This command will produce no output, but if we inspect the new file sdf.log, we’ll see the logs output to the file.
The logs outputted to the file respect the --log-level flag you’ve set.
Bonus: Analyze the Logs with SDF DB
As mentioned earlier, SDF’s in-memory database can be used to query and analyze logs, right from the terminal on your machine.
Let’s start by gathering up all the info logs from a fresh compile.
First, let’s clean the workspace cache:
Now, let’s compile the workspace and output the logs to a file called logs/compile_info.json:
Now that we have the logs written to a file, let’s include them in our SDF workspace by adding the following to the includes block in your workspace.sdf.yml:
Finally, let’s compile our new logs model to ensure SDF can process it:
Working set 12 model files, 1 seed file, 19 .sdf files
Finished 1 model [1 succeeded] in 0.837 secs
Schema moms_flower_shop.pub.compile_info
┌───────────────┬────────────────┬────────────┬─────────────┐
│ column_name ┆ data_type ┆ classifier ┆ description │
╞═══════════════╪════════════════╪════════════╪═════════════╡
│ _ts ┆ varchar ┆ ┆ │
│ _ll ┆ varchar ┆ ┆ │
│ _fn ┆ varchar ┆ ┆ │
│ ev ┆ varchar ┆ ┆ │
│ set ┆ varchar ┆ ┆ │
│ val_s ┆ varchar ┆ ┆ │
│ val_as ┆ array<varchar> ┆ ┆ │
│ st_dur_ms ┆ bigint ┆ ┆ │
│ ev_fn ┆ varchar ┆ ┆ │
│ st_code ┆ varchar ┆ ┆ │
│ ev_tb ┆ varchar ┆ ┆ │
│ ev_tb_catalog ┆ varchar ┆ ┆ │
│ ev_tb_schema ┆ varchar ┆ ┆ │
│ ev_tb_table ┆ varchar ┆ ┆ │
│ ev_tb_purpose ┆ varchar ┆ ┆ │
│ st_done ┆ varchar ┆ ┆ │
│ err_msg ┆ varchar ┆ ┆ │
│ exit_code ┆ bigint ┆ ┆ │
└───────────────┴────────────────┴────────────┴─────────────┘
Awesome! SDF can process the logs model. Let’s run a quick inline query to select some properties from the logs:
Working set 13 model files, 1 seed file, 19 .sdf files
Running moms_flower_shop.pub.query (./sdftarget/dbg/query.sql)
Finished 2 models [2 succeeded] in 0.862 secs
Table moms_flower_shop.pub.query
┌─────────────────────────────────────┬──────────────────────────────┬────────────────┐
│ timestamp ┆ event ┆ duration_in_ms │
╞═════════════════════════════════════╪══════════════════════════════╪════════════════╡
│ 2024-12-18T19:43:42.167423926+00:00 ┆ sdf ┆ │
│ 2024-12-18T19:43:42.167606359+00:00 ┆ sdf ┆ │
│ 2024-12-18T19:43:42.167770337+00:00 ┆ sdf ┆ │
│ 2024-12-18T19:43:42.169050855+00:00 ┆ initialize ┆ │
│ 2024-12-18T19:43:42.169986866+00:00 ┆ initialize.load_workspace ┆ │
│ 2024-12-18T19:43:42.186585554+00:00 ┆ initialize.load_workspace ┆ 16 │
│ 2024-12-18T19:43:42.186686073+00:00 ┆ initialize.load_dependencies ┆ │
│ 2024-12-18T19:43:42.186769340+00:00 ┆ initialize.load_dependencies ┆ 0 │
│ 2024-12-18T19:43:42.186860972+00:00 ┆ initialize.load_prelude ┆ │
│ 2024-12-18T19:43:42.190051192+00:00 ┆ initialize.load_prelude ┆ 3 │
└─────────────────────────────────────┴──────────────────────────────┴────────────────┘
60 rows, showing only 10 rows.
Run with —limit 0 to show all rows.
Nice! We’ve successfully queried the logs using the SDF DB. Any models you create from the logs can be used to analyze and query the logs further. To learn more about the SDF DB, visit our SDF DB Guide.
Reference
As a quick reference, let’s review the different log levels, format, and properties within a log:
Log Levels
info- general information about the execution of the commanddebug- more detailed information about the execution of the commandtrace- very detailed information about the execution of the command
Log Properties:
_ts- the timestamp of the log_lvl- the log level (info, debug, trace, etc.)id- the ID of the variable being loggedval_s- the value of a variable being logged if it’s a stringval_a*- the value of a variable being logged if it’s an array, the*represents the value type of the array. I.e.asfor an array of stringsval_m*- the value of a variable being logged if it’s a map, the*represents the value type of the map. I.e.mssfor a map of string to stringval_b- the value of a variable being logged if it’s a booleanval_i- the value of a variable being logged if it’s an integerith- the index of the wave being loggednum_files- the number of files being processed by an operationfile- the filename being processednum_errors- the number of errors encountered during an operationnum_statements- the number of statements being processed by an operationnum_tables- the number of tables being processed by an operationtable- the table being processed by an operationmessage- a message associated with the logerror_code- the error code associated with the log (0if no error)_src- the source of the log in the Rust codebaseev- the event name corresponding to this log. Used to mapopenandcloseeventsev_type- the type of the event (see reference below)ev_dur_ms- the duration of the event in millisecondsstatus- the status of the event (see reference below)
Why all the val_ properties? SDF logs are designed to be queryable by engines that support structured types. As such, we map the Rust variable types to structured types like so:
So, msas is map of string to array of string
Event Types:
open- the start of an eventclose- the end of an event. Use theevproperty to map this to the correspondingopeneventstate- a summary of state at a given point in time for an eventwave- represents a batch operation operating on a subset of a dag or process. Waves have state, duration, and status properties
Status:
succeeded- the event was successfulfailed- the event failedskipped- the event was skipped