Collectors not initializing if exporter is started before postgres

[Sticksman]

What did you do?

Tried to reproduce a reported bug where collectors were not outputting stats with the below docker-compose file:

version: "3.9"
services:
  postgres:
    restart: always
    image: postgres:14
    ports:
      - "5432:5432"
    environment:
      - POSTGRES_USER=root
      - POSTGRES_PASSWORD=password
      - POSTGRES_DB=dev
  exporter:
    restart: always
    image: quay.io/prometheuscommunity/postgres-exporter:v0.13.2
    ports:
      - 9187:9187
    environment:
      - DATA_SOURCE_NAME=postgresql://root:password@postgres:5432/dev?sslmode=disable
    command: --collector.stat_statements --log.level=debug

Afterwards ran curl 127.0.0.1:9187/metrics and noted that no metrics were appearing from collectors. After adding a depends_on attribute to the exporter block, the collectors behaved as expected.

See more here: #685 (comment)

What did you expect to see?

I expected that the collectors would emit metrics on the metrics endpoint.

What did you see instead? Under which circumstances?

The collectors did not emit metrics when the exporter started before postgres, and did if the collector was started after postgres.

Environment

• System information:

  Darwin 22.5.0 arm64

• postgres_exporter version:

  v0.13.2

• postgres_exporter flags:

--collector.stat_statements 
--log.level=debug

• PostgreSQL version:

  14

• Logs:

without depends_on

# HELP pg_stat_database_conflicts_confl_bufferpin Number of queries in this database that have been canceled due to pinned buffers
# TYPE pg_stat_database_conflicts_confl_bufferpin counter
pg_stat_database_conflicts_confl_bufferpin{datid="1",datname="template1",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_bufferpin{datid="13779",datname="template0",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_bufferpin{datid="13780",datname="postgres",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_bufferpin{datid="16384",datname="dev",server="postgres:5432"} 0
# HELP pg_stat_database_conflicts_confl_deadlock Number of queries in this database that have been canceled due to deadlocks
# TYPE pg_stat_database_conflicts_confl_deadlock counter
pg_stat_database_conflicts_confl_deadlock{datid="1",datname="template1",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_deadlock{datid="13779",datname="template0",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_deadlock{datid="13780",datname="postgres",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_deadlock{datid="16384",datname="dev",server="postgres:5432"} 0
# HELP pg_stat_database_conflicts_confl_lock Number of queries in this database that have been canceled due to lock timeouts
# TYPE pg_stat_database_conflicts_confl_lock counter
pg_stat_database_conflicts_confl_lock{datid="1",datname="template1",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_lock{datid="13779",datname="template0",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_lock{datid="13780",datname="postgres",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_lock{datid="16384",datname="dev",server="postgres:5432"} 0
# HELP pg_stat_database_conflicts_confl_snapshot Number of queries in this database that have been canceled due to old snapshots
# TYPE pg_stat_database_conflicts_confl_snapshot counter
pg_stat_database_conflicts_confl_snapshot{datid="1",datname="template1",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_snapshot{datid="13779",datname="template0",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_snapshot{datid="13780",datname="postgres",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_snapshot{datid="16384",datname="dev",server="postgres:5432"} 0
# HELP pg_stat_database_conflicts_confl_tablespace Number of queries in this database that have been canceled due to dropped tablespaces
# TYPE pg_stat_database_conflicts_confl_tablespace counter
pg_stat_database_conflicts_confl_tablespace{datid="1",datname="template1",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_tablespace{datid="13779",datname="template0",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_tablespace{datid="13780",datname="postgres",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_tablespace{datid="16384",datname="dev",server="postgres:5432"} 0

with depends_on

# HELP pg_stat_database_blk_read_time Time spent reading data file blocks by backends in this database, in milliseconds
# TYPE pg_stat_database_blk_read_time counter
pg_stat_database_blk_read_time{datid="0",datname="unknown"} 0
pg_stat_database_blk_read_time{datid="1",datname="template1"} 0
pg_stat_database_blk_read_time{datid="13779",datname="template0"} 0
pg_stat_database_blk_read_time{datid="13780",datname="postgres"} 0
pg_stat_database_blk_read_time{datid="16384",datname="dev"} 0
# HELP pg_stat_database_blk_write_time Time spent writing data file blocks by backends in this database, in milliseconds
# TYPE pg_stat_database_blk_write_time counter
pg_stat_database_blk_write_time{datid="0",datname="unknown"} 0
pg_stat_database_blk_write_time{datid="1",datname="template1"} 0
pg_stat_database_blk_write_time{datid="13779",datname="template0"} 0
pg_stat_database_blk_write_time{datid="13780",datname="postgres"} 0
pg_stat_database_blk_write_time{datid="16384",datname="dev"} 0
# HELP pg_stat_database_blks_hit Number of times disk blocks were found already in the buffer cache, so that a read was not necessary (this only includes hits in the PostgreSQL buffer cache, not the operating system's file system cache)
# TYPE pg_stat_database_blks_hit counter
pg_stat_database_blks_hit{datid="0",datname="unknown"} 1189
pg_stat_database_blks_hit{datid="1",datname="template1"} 0
pg_stat_database_blks_hit{datid="13779",datname="template0"} 0
pg_stat_database_blks_hit{datid="13780",datname="postgres"} 8410
pg_stat_database_blks_hit{datid="16384",datname="dev"} 22086
# HELP pg_stat_database_blks_read Number of disk blocks read in this database
# TYPE pg_stat_database_blks_read counter
pg_stat_database_blks_read{datid="0",datname="unknown"} 108
pg_stat_database_blks_read{datid="1",datname="template1"} 0
pg_stat_database_blks_read{datid="13779",datname="template0"} 0
pg_stat_database_blks_read{datid="13780",datname="postgres"} 378
pg_stat_database_blks_read{datid="16384",datname="dev"} 1595
# HELP pg_stat_database_conflicts Number of queries canceled due to conflicts with recovery in this database. (Conflicts occur only on standby servers; see pg_stat_database_conflicts for details.)
# TYPE pg_stat_database_conflicts counter
pg_stat_database_conflicts{datid="0",datname="unknown"} 0
pg_stat_database_conflicts{datid="1",datname="template1"} 0
pg_stat_database_conflicts{datid="13779",datname="template0"} 0
pg_stat_database_conflicts{datid="13780",datname="postgres"} 0
pg_stat_database_conflicts{datid="16384",datname="dev"} 0
# HELP pg_stat_database_conflicts_confl_bufferpin Number of queries in this database that have been canceled due to pinned buffers
# TYPE pg_stat_database_conflicts_confl_bufferpin counter
pg_stat_database_conflicts_confl_bufferpin{datid="1",datname="template1",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_bufferpin{datid="13779",datname="template0",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_bufferpin{datid="13780",datname="postgres",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_bufferpin{datid="16384",datname="dev",server="postgres:5432"} 0
# HELP pg_stat_database_conflicts_confl_deadlock Number of queries in this database that have been canceled due to deadlocks
# TYPE pg_stat_database_conflicts_confl_deadlock counter
pg_stat_database_conflicts_confl_deadlock{datid="1",datname="template1",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_deadlock{datid="13779",datname="template0",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_deadlock{datid="13780",datname="postgres",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_deadlock{datid="16384",datname="dev",server="postgres:5432"} 0
# HELP pg_stat_database_conflicts_confl_lock Number of queries in this database that have been canceled due to lock timeouts
# TYPE pg_stat_database_conflicts_confl_lock counter
pg_stat_database_conflicts_confl_lock{datid="1",datname="template1",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_lock{datid="13779",datname="template0",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_lock{datid="13780",datname="postgres",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_lock{datid="16384",datname="dev",server="postgres:5432"} 0
# HELP pg_stat_database_conflicts_confl_snapshot Number of queries in this database that have been canceled due to old snapshots
# TYPE pg_stat_database_conflicts_confl_snapshot counter
pg_stat_database_conflicts_confl_snapshot{datid="1",datname="template1",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_snapshot{datid="13779",datname="template0",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_snapshot{datid="13780",datname="postgres",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_snapshot{datid="16384",datname="dev",server="postgres:5432"} 0
# HELP pg_stat_database_conflicts_confl_tablespace Number of queries in this database that have been canceled due to dropped tablespaces
# TYPE pg_stat_database_conflicts_confl_tablespace counter
pg_stat_database_conflicts_confl_tablespace{datid="1",datname="template1",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_tablespace{datid="13779",datname="template0",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_tablespace{datid="13780",datname="postgres",server="postgres:5432"} 0
pg_stat_database_conflicts_confl_tablespace{datid="16384",datname="dev",server="postgres:5432"} 0
# HELP pg_stat_database_deadlocks Number of deadlocks detected in this database
# TYPE pg_stat_database_deadlocks counter
pg_stat_database_deadlocks{datid="0",datname="unknown"} 0
pg_stat_database_deadlocks{datid="1",datname="template1"} 0
pg_stat_database_deadlocks{datid="13779",datname="template0"} 0
pg_stat_database_deadlocks{datid="13780",datname="postgres"} 0
pg_stat_database_deadlocks{datid="16384",datname="dev"} 0
# HELP pg_stat_database_numbackends Number of backends currently connected to this database. This is the only column in this view that returns a value reflecting current state; all other columns return the accumulated values since the last reset.
# TYPE pg_stat_database_numbackends gauge
pg_stat_database_numbackends{datid="0",datname="unknown"} 0
pg_stat_database_numbackends{datid="1",datname="template1"} 0
pg_stat_database_numbackends{datid="13779",datname="template0"} 0
pg_stat_database_numbackends{datid="13780",datname="postgres"} 0
pg_stat_database_numbackends{datid="16384",datname="dev"} 2
# HELP pg_stat_database_stats_reset Time at which these statistics were last reset
# TYPE pg_stat_database_stats_reset counter
pg_stat_database_stats_reset{datid="0",datname="unknown"} 1.690824995e+09
pg_stat_database_stats_reset{datid="1",datname="template1"} 0
pg_stat_database_stats_reset{datid="13779",datname="template0"} 0
pg_stat_database_stats_reset{datid="13780",datname="postgres"} 1.690824995e+09
pg_stat_database_stats_reset{datid="16384",datname="dev"} 1.690825004e+09
# HELP pg_stat_database_temp_bytes Total amount of data written to temporary files by queries in this database. All temporary files are counted, regardless of why the temporary file was created, and regardless of the log_temp_files setting.
# TYPE pg_stat_database_temp_bytes counter

[Sticksman]

Here's the actual error line in the logs ts=2023-07-28T22:16:31.825Z caller=main.go:142 level=warn msg="Failed to create PostgresCollector" err="dial tcp 172.18.0.3:5432: connect: connection refused"

[CarlosGitto]

Hi, I found the same bug some days ago. To fix it, I simply restart the containers, and then it works fine.

The command I used was docker compose -f $COMPOSEFILE restart;, where $COMPOSEFILE is the path to your Docker Compose file (e.g., ./docker/docker-compose.yml).

This should help you get the service up and running again.
If you found a better solution please let me know!

[sysadmind]

The problem stems from collector.newInstance(). This sets up the database connection and queries the version information. The database connection setup happens correctly, but the version query fails. That error is then returned up the stack and the collector package is never registered for metrics collection. I think collector.newInstance() needs to change, but I think that may necessitate wider changes.

If the sql.Open() call errors, this error should be returned up the stack because there is no way to continue if we don't have a valid database connection string. sql.Open does not mean that we have actually connected to the database. The call to queryVersion however would almost certainly only error on a transient error, or an error that we could only ever treat as transient (i.e. incorrect hostname in connection string).

Now the question is, if the version query fails, what happens? How does calling code know that the version isn't populated yet? I think we probably want to have a goroutine that polls for the version. This would also help for the case where the postgres server is upgraded to a different version. The goroutine would also fill in the version information on the next interval after a transient connection problem is resolved. I don't think that this solution is complete though. What happens when in this docker-compose example, postgres was just a bit slower to be ready than the exporter? Should the exporter only have the correct metrics after a full poll interval has elapsed? A goroutine also brings the challenge of signaling when the program has received a signal from the OS to shutdown (i.e. SIGTERM). I think that we could handle this with a context. Prometheus uses a channel, but this code is quite old and the signal package now has NotifyContext so we would only need to work with a context.
'

[abh]

Thanks for fixing this, @sysadmind ! It'd be nice to get a 0.13.3 release out :-)

[algchoo]

I would also like to extend my thanks, for fixing this @sysadmind. Is there an ETA on when we can expect the next release? I'm asking so I might convey this to my peers instead of continuing to say that it just hasn't been released yet, but if not, no worries. Hope you're having a great day!

[sysadmind]

See #910 and #906. Once both are merged, we should have a v0.14.0

[sysadmind]

0.14.0 has been released
https://github.com/prometheus-community/postgres_exporter/releases/tag/v0.14.0