feat(receiver/sqlquery): add debug log when running SQL query #29672

andrzej-stencel · 2023-12-06T12:04:15Z

This tiny enhancement should help with investigating issues when logs are not being collected.

It has already helped me uncover a small issue with the receiver:

[receiver/sqlquery] initial_delay setting is not supported for logs #29671

This tiny enhancement should help with investigating issues when logs are not being collected.

crobert-1 · 2023-12-06T16:56:44Z

receiver/sqlqueryreceiver/db_client.go

@@ -38,6 +38,7 @@ func newDbClient(db db, sql string, logger *zap.Logger) dbClient {
 }

 func (cl dbSQLClient) queryRows(ctx context.Context, args ...any) ([]stringMap, error) {
+	cl.logger.Debug("Running query", zap.String("query", cl.sql), zap.Any("parameters", args))


Can you share an example of the output of this log message? Just curious to see what information is held in the arguments being logged here.

Sure, great question. Here's the output:

2023-12-07T08:24:56.780+0100 debug sqlqueryreceiver@v0.90.1/db_client.go:41 Running query {"kind": "receiver", "name": "sqlquery/metrics", "data_type": "metrics", "query": "select *\n from my_metrics", "parameters": null} 2023-12-07T08:25:05.780+0100 debug sqlqueryreceiver@v0.90.1/db_client.go:41 Running query {"kind": "receiver", "name": "sqlquery/logs", "data_type": "logs", "query": "select id, body from simple_logs where id > $1", "parameters": ["0"]} 2023-12-07T08:25:15.781+0100 debug sqlqueryreceiver@v0.90.1/db_client.go:41 Running query {"kind": "receiver", "name": "sqlquery/logs", "data_type": "logs", "query": "select id, body from simple_logs where id > $1", "parameters": ["6"]}

For the logs collection, there are 6 rows in the simple_logs table, so the first query is run with 0 as the value for the query parameter, and the second logs query is run with 6 as the value for the query parameter.

This is for the following Otelcol config:

config.yaml

exporters: debug/basic: verbosity: basic receivers: sqlquery/logs: datasource: "postgresql://postgres:postgres@localhost:5432/postgres?sslmode=disable" driver: postgres queries: - sql: select id, body from simple_logs where id > $$1 tracking_column: id tracking_start_value: 0 logs: - body_column: body sqlquery/metrics: datasource: "postgresql://postgres:postgres@localhost/postgres?sslmode=disable" driver: postgres queries: - sql: |- select * from my_metrics metrics: - metric_name: somemetric value_column: value service: pipelines: logs: exporters: - debug/basic receivers: - sqlquery/logs metrics: exporters: - debug/basic receivers: - sqlquery/metrics telemetry: logs: level: debug

And here's the full Otelcol logs output:

$ ./bin/otelcontribcol_linux_amd64 --config config.yaml

2023-12-07T08:24:55.777+0100 info service@v0.90.2-0.20231201205146-6e2fdc755b34/telemetry.go:86 Setting up own telemetry... 2023-12-07T08:24:55.778+0100 info service@v0.90.2-0.20231201205146-6e2fdc755b34/telemetry.go:203 Serving Prometheus metrics {"address": ":8888", "level": "Basic"} 2023-12-07T08:24:55.778+0100 info exporter@v0.90.2-0.20231201205146-6e2fdc755b34/exporter.go:275 Development component. May change in the future. {"kind": "exporter", "data_type": "logs", "name": "debug/basic"} 2023-12-07T08:24:55.778+0100 debug exporter@v0.90.2-0.20231201205146-6e2fdc755b34/exporter.go:273 Alpha component. May change in the future. {"kind": "exporter", "data_type": "logs", "name": "file"} 2023-12-07T08:24:55.778+0100 info exporter@v0.90.2-0.20231201205146-6e2fdc755b34/exporter.go:275 Development component. May change in the future. {"kind": "exporter", "data_type": "metrics", "name": "debug/basic"} 2023-12-07T08:24:55.778+0100 debug receiver@v0.90.2-0.20231201205146-6e2fdc755b34/receiver.go:294 Alpha component. May change in the future. {"kind": "receiver", "name": "sqlquery/metrics", "data_type": "metrics"} 2023-12-07T08:24:55.778+0100 info receiver@v0.90.2-0.20231201205146-6e2fdc755b34/receiver.go:296 Development component. May change in the future. {"kind": "receiver", "name": "sqlquery/logs", "data_type": "logs"} 2023-12-07T08:24:55.780+0100 info service@v0.90.2-0.20231201205146-6e2fdc755b34/service.go:145 Starting otelcontribcol... {"Version": "0.90.1-dev", "NumCPU": 16} 2023-12-07T08:24:55.780+0100 info extensions/extensions.go:34 Starting extensions... 2023-12-07T08:24:55.780+0100 debug sqlqueryreceiver@v0.90.1/logs_receiver.go:80 starting... {"kind": "receiver", "name": "sqlquery/logs", "data_type": "logs"} 2023-12-07T08:24:55.780+0100 debug sqlqueryreceiver@v0.90.1/logs_receiver.go:101 started. {"kind": "receiver", "name": "sqlquery/logs", "data_type": "logs"} 2023-12-07T08:24:55.780+0100 info service@v0.90.2-0.20231201205146-6e2fdc755b34/service.go:171 Everything is ready. Begin running and processing data. 2023-12-07T08:24:56.780+0100 debug sqlqueryreceiver@v0.90.1/db_client.go:41 Running query {"kind": "receiver", "name": "sqlquery/metrics", "data_type": "metrics", "query": "select *\n from my_metrics", "parameters": null} 2023-12-07T08:24:56.789+0100 info MetricsExporter {"kind": "exporter", "data_type": "metrics", "name": "debug/basic", "resource metrics": 1, "metrics": 2, "data points": 2} 2023-12-07T08:25:05.780+0100 debug sqlqueryreceiver@v0.90.1/db_client.go:41 Running query {"kind": "receiver", "name": "sqlquery/logs", "data_type": "logs", "query": "select id, body from simple_logs where id > $1", "parameters": ["0"]} 2023-12-07T08:25:05.791+0100 info LogsExporter {"kind": "exporter", "data_type": "logs", "name": "debug/basic", "resource logs": 1, "log records": 6} 2023-12-07T08:25:06.781+0100 debug sqlqueryreceiver@v0.90.1/db_client.go:41 Running query {"kind": "receiver", "name": "sqlquery/metrics", "data_type": "metrics", "query": "select *\n from my_metrics", "parameters": null} 2023-12-07T08:25:06.782+0100 info MetricsExporter {"kind": "exporter", "data_type": "metrics", "name": "debug/basic", "resource metrics": 1, "metrics": 2, "data points": 2} 2023-12-07T08:25:15.781+0100 debug sqlqueryreceiver@v0.90.1/db_client.go:41 Running query {"kind": "receiver", "name": "sqlquery/logs", "data_type": "logs", "query": "select id, body from simple_logs where id > $1", "parameters": ["6"]} 2023-12-07T08:25:16.781+0100 debug sqlqueryreceiver@v0.90.1/db_client.go:41 Running query {"kind": "receiver", "name": "sqlquery/metrics", "data_type": "metrics", "query": "select *\n from my_metrics", "parameters": null} 2023-12-07T08:25:16.782+0100 info MetricsExporter {"kind": "exporter", "data_type": "metrics", "name": "debug/basic", "resource metrics": 1, "metrics": 2, "data points": 2} 2023-12-07T08:25:25.781+0100 debug sqlqueryreceiver@v0.90.1/db_client.go:41 Running query {"kind": "receiver", "name": "sqlquery/logs", "data_type": "logs", "query": "select id, body from simple_logs where id > $1", "parameters": ["6"]} 2023-12-07T08:25:26.781+0100 debug sqlqueryreceiver@v0.90.1/db_client.go:41 Running query {"kind": "receiver", "name": "sqlquery/metrics", "data_type": "metrics", "query": "select *\n from my_metrics", "parameters": null} 2023-12-07T08:25:26.781+0100 info MetricsExporter {"kind": "exporter", "data_type": "metrics", "name": "debug/basic", "resource metrics": 1, "metrics": 2, "data points": 2} ^C2023-12-07T08:25:27.714+0100 info otelcol@v0.90.2-0.20231201205146-6e2fdc755b34/collector.go:258 Received signal from OS {"signal": "interrupt"} 2023-12-07T08:25:27.714+0100 info service@v0.90.2-0.20231201205146-6e2fdc755b34/service.go:185 Starting shutdown... 2023-12-07T08:25:27.714+0100 debug sqlqueryreceiver@v0.90.1/logs_receiver.go:175 stopping... {"kind": "receiver", "name": "sqlquery/logs", "data_type": "logs"} 2023-12-07T08:25:27.714+0100 debug sqlqueryreceiver@v0.90.1/logs_receiver.go:187 stopped. {"kind": "receiver", "name": "sqlquery/logs", "data_type": "logs"} 2023-12-07T08:25:27.714+0100 info extensions/extensions.go:59 Stopping extensions... 2023-12-07T08:25:27.714+0100 info service@v0.90.2-0.20231201205146-6e2fdc755b34/service.go:199 Shutdown complete.

That's perfect, thanks for sharing all of that! Looks good 👍

@astencel-sumo any concerns around the query containing potentially sensitive information?

Oh that's a very good point @codeboten, thanks for mentioning this.

I suppose a better approach would be to not log queries (and parameter values) by default, but instead expose a configuration that would allow user to explicitly enable this?

I'm thinking something like this:

receivers: sqlquery: debug: log_query: true # default: false log_query_parameters: true # default: same value as `log_query`

What do you think?

I went with the following configuration:

receivers: sqlquery: telemetry: logs: query: true # default: false

My thinking is this is consistent with the service.telemetry naming, making it easy to comprehend and natural to use by the users. If other components also want to make their logging configurable, they can use similar structure of adding custom configuration keys under the telemetry.logs property. Metrics customizations could go into telemetry.metrics, etc.

I also exposed just one property query, which when enabled, logs both the query and its parameters. I can change it to expose a separate property for query parameters if you think that's useful.

@codeboten can you take a look?

codeboten

just one question, otherwise it looks good

codeboten · 2023-12-08T16:05:40Z

receiver/sqlqueryreceiver/db_client.go

@@ -38,6 +38,7 @@ func newDbClient(db db, sql string, logger *zap.Logger) dbClient {
 }

 func (cl dbSQLClient) queryRows(ctx context.Context, args ...any) ([]stringMap, error) {
+	cl.logger.Debug("Running query", zap.String("query", cl.sql), zap.Any("parameters", args))


@astencel-sumo any concerns around the query containing potentially sensitive information?

github-actions · 2023-12-29T05:19:39Z

This PR was marked stale due to lack of activity. It will be closed in 14 days.

…elemetry#29672) This tiny enhancement should help with investigating issues when logs are not being collected. It has already helped me uncover a small issue with the receiver: - open-telemetry#29671

github-actions bot added the receiver/sqlquery SQL query receiver label Dec 6, 2023

feat(receiver/sqlquery): add debug log when running SQL query

347d7b1

This tiny enhancement should help with investigating issues when logs are not being collected.

andrzej-stencel force-pushed the sqlquery-debug-logs branch from b2f6155 to 347d7b1 Compare December 6, 2023 12:05

andrzej-stencel marked this pull request as ready for review December 6, 2023 12:07

andrzej-stencel requested a review from dmitryax as a code owner December 6, 2023 12:07

andrzej-stencel requested a review from a team December 6, 2023 12:07

github-actions bot assigned djaglowski Dec 6, 2023

Merge branch 'main' into sqlquery-debug-logs

d92f30b

crobert-1 approved these changes Dec 6, 2023

View reviewed changes

Merge branch 'main' into sqlquery-debug-logs

0886b3c

atoulme approved these changes Dec 8, 2023

View reviewed changes

Merge branch 'main' into sqlquery-debug-logs

edfd544

andrzej-stencel added the ready to merge Code review completed; ready to merge by maintainers label Dec 8, 2023

codeboten approved these changes Dec 8, 2023

View reviewed changes

atoulme removed the ready to merge Code review completed; ready to merge by maintainers label Dec 8, 2023

andrzej-stencel added 3 commits December 11, 2023 16:59

Merge branch 'main' into sqlquery-debug-logs

5482239

feat: add option to configure query logging

c54a3f1

fix linter

e35a61a

github-actions bot added the Stale label Dec 29, 2023

Merge branch 'main' into sqlquery-debug-logs

85c6668

github-actions bot removed the Stale label Jan 3, 2024

andrzej-stencel added 2 commits January 10, 2024 18:12

Merge branch 'main' into sqlquery-debug-logs

5e3be2e

Merge branch 'main' into sqlquery-debug-logs

ff92388

andrzej-stencel added the ready to merge Code review completed; ready to merge by maintainers label Jan 11, 2024

bogdandrutu merged commit 26cf981 into open-telemetry:main Jan 11, 2024
89 of 90 checks passed

github-actions bot added this to the next release milestone Jan 11, 2024

andrzej-stencel deleted the sqlquery-debug-logs branch May 27, 2024 09:10

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat(receiver/sqlquery): add debug log when running SQL query #29672

feat(receiver/sqlquery): add debug log when running SQL query #29672

andrzej-stencel commented Dec 6, 2023 •

edited

Loading

crobert-1 Dec 6, 2023

andrzej-stencel Dec 7, 2023 •

edited

Loading

crobert-1 Dec 7, 2023

codeboten Dec 8, 2023

andrzej-stencel Dec 12, 2023

andrzej-stencel Dec 14, 2023 •

edited

Loading

andrzej-stencel Jan 2, 2024

codeboten left a comment

codeboten Dec 8, 2023

github-actions bot commented Dec 29, 2023

feat(receiver/sqlquery): add debug log when running SQL query #29672

feat(receiver/sqlquery): add debug log when running SQL query #29672

Conversation

andrzej-stencel commented Dec 6, 2023 • edited Loading

crobert-1 Dec 6, 2023

Choose a reason for hiding this comment

andrzej-stencel Dec 7, 2023 • edited Loading

Choose a reason for hiding this comment

crobert-1 Dec 7, 2023

Choose a reason for hiding this comment

codeboten Dec 8, 2023

Choose a reason for hiding this comment

andrzej-stencel Dec 12, 2023

Choose a reason for hiding this comment

andrzej-stencel Dec 14, 2023 • edited Loading

Choose a reason for hiding this comment

andrzej-stencel Jan 2, 2024

Choose a reason for hiding this comment

codeboten left a comment

Choose a reason for hiding this comment

codeboten Dec 8, 2023

Choose a reason for hiding this comment

github-actions bot commented Dec 29, 2023

andrzej-stencel commented Dec 6, 2023 •

edited

Loading

andrzej-stencel Dec 7, 2023 •

edited

Loading

andrzej-stencel Dec 14, 2023 •

edited

Loading