Add database info to TimescaleDB background worker logs

dnk8n commented 2 weeks ago

What type of bug is this?

Configuration

What subsystems and features are affected?

Other

What happened?

I have many DBs, each with timescale installed. But logging is central, so it is very useful to include which database in the log lines. This works well using log_line_prefix and produces logs like:

2024-11-03 00:14:12.147 UTC [3375277] user_123@database_456 WARNING: there is already a transaction in progress

However this is not the case for background jobs. I miss the context of errors that might happen due to compression jobs for example.

Right now, I don't have any failures (which would be more interesting) but here is the start of a compression job for some context). I have no idea which database it applies to:

2024-11-03 00:14:09.843 UTC [3602182] DEBUG:  launching job 1000 "Compression Policy [1000]"
2024-11-03 00:14:09.853 UTC [3395848] DEBUG:  Executing policy_compression with parameters {"hypertable_id": 1, "compress_after": "3 days"}
2024-11-03 00:14:09.856 UTC [3395848] DEBUG:  rehashing catalog cache id 35 for pg_namespace; 9 tups, 4 buckets
2024-11-03 00:14:09.856 UTC [3395848] CONTEXT:  compilation of PL/pgSQL function "policy_compression" near line 1
2024-11-03 00:14:09.884 UTC [3395848] DEBUG:  rehashing catalog cache id 54 for pg_class; 257 tups, 128 buckets
2024-11-03 00:14:09.884 UTC [3395848] CONTEXT:  PL/pgSQL function _timescaledb_functions.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean,boolean) line 42 at FOR over SELECT rows
        SQL statement "CALL _timescaledb_functions.policy_compression_execute(
                job_id, htid, lag_value::INTERVAL,
                maxchunks, verbose_log, recompress_enabled, use_creation_time
              )"
        PL/pgSQL function _timescaledb_functions.policy_compression(integer,jsonb) line 60 at CALL
2024-11-03 00:14:09.887 UTC [3395848] DEBUG:  rehashing catalog cache id 55 for pg_class; 257 tups, 128 buckets

...

TimescaleDB version affected

2.13.1

PostgreSQL version used

15.4

What operating system did you use?

Ubuntu 22.04.3 LTS x64

What installation method did you use?

Deb/Apt

What platform did you run on?

Amazon Web Services (AWS)

Relevant log output and stack trace

No response

How can we reproduce the bug?

set for example: `log_line_prefix = '%m [%p] %q%u@%d '`
It applies only to application queries. Timescale background workers do not honor it.

akuzm commented 2 weeks ago

That's a general Postgres thing, %d means current database for interactive backends (ones that handle a user session). Background workers are not that, so %d for them is always empty.

We could improve the logging though by adding the DB name to the description of the job that is being started, or something like this.

dnk8n commented 2 weeks ago

Oh so @akuzm , if I understand correctly, this is not really a bug but a feature enhancement (edit: just noticed the labels edited, so that answers this question)?

Currently there is no existing way to have the database context of background tasks in logs?

timescale / timescaledb