postgresqlloggingormdatabase-administrationapplication-server

Problem found in postgres log file. Too much "user=[unknown],db=[unknown],app=[unknown]" rows

After enabling log_connection, the postgres log file starts logging many rows like these:

19:2021-09-17 00:00:00 CEST [26025]: user=[unknown],db=[unknown],app=[unknown],client=192.168.7.61 LOG:  connection received: host=192.168.7.61 port=56911
22:2021-09-17 00:00:00 CEST [26026]: user=[unknown],db=[unknown],app=[unknown],client=192.168.7.61 LOG:  connection received: host=192.168.7.61 port=56912
25:2021-09-17 00:00:00 CEST [26027]: user=[unknown],db=[unknown],app=[unknown],client=192.168.7.61 LOG:  connection received: host=192.168.7.61 port=56913
28:2021-09-17 00:00:00 CEST [26028]: user=[unknown],db=[unknown],app=[unknown],client=192.168.7.61 LOG:  connection received: host=192.168.7.61 port=56914
31:2021-09-17 00:00:00 CEST [26029]: user=[unknown],db=[unknown],app=[unknown],client=192.168.7.61 LOG:  connection received: host=192.168.7.61 port=56915
34:2021-09-17 00:00:00 CEST [26030]: user=[unknown],db=[unknown],app=[unknown],client=192.168.7.61 LOG:  connection received: host=192.168.7.61 port=56916
37:2021-09-17 00:00:00 CEST [26031]: user=[unknown],db=[unknown],app=[unknown],client=192.168.7.61 LOG:  connection received: host=192.168.7.61 port=56917
40:2021-09-17 00:00:00 CEST [26032]: user=[unknown],db=[unknown],app=[unknown],client=192.168.7.61 LOG:  connection received: host=192.168.7.61 port=56918
43:2021-09-17 00:00:00 CEST [26033]: user=[unknown],db=[unknown],app=[unknown],client=192.168.7.61 LOG:  connection received: host=192.168.7.61 port=56919
46:2021-09-17 00:00:00 CEST [26034]: user=[unknown],db=[unknown],app=[unknown],client=192.168.7.61 LOG:  connection received: host=192.168.7.61 port=56920
49:2021-09-17 00:00:00 CEST [26035]: user=[unknown],db=[unknown],app=[unknown],client=192.168.7.61 LOG:  connection received: host=192.168.7.61 port=56921

The client/host parameters happen to be the application server IP.

Yesterday I found 452.583 rows like these.

What could be the cause?

Thanks

an piece of log files

2021-09-17 01:55:04 CEST [3093]: user=[unknown],db=[unknown],app=[unknown],client=192.168.7.61 LOG:  connection received: host=192.168.7.61 port=54868
2021-09-17 01:55:04 CEST [3094]: user=[unknown],db=[unknown],app=[unknown],client=192.168.7.61 LOG:  connection received: ho/st=192.168.7.61 port=54869
2021-09-17 01:55:04 CEST [3093]: user=xxxxxxx,db=xxxxx,app=[unknown],client=192.168.7.61 LOG:  connection authorized: user=xxxxxxxdatabase=xxxxxxx
2021-09-17 01:55:04 CEST [3094]: user=xxxxxxx,db=xxxxxxx,app=[unknown],client=192.168.7.61 LOG:  connection authorized: user=xxxxxxxdatabase=xxxxxxx
2021-09-17 01:55:04 CEST [3093]: user=xxxxxxx,db=xxxxxxx,app=[unknown],client=192.168.7.61 LOG:  disconnection: session time: 0:00:00.013 user=supreme_web database=xxxxxxxhost=192.168.7.61 port=54868
2021-09-17 01:55:04 CEST [3094]: user=xxxxxxx,db=xxxxxxx,app=[unknown],client=192.168.7.61 LOG:  disconnection: session time: 0:00:00.014 user=xxxxxxxdatabase=xxxxxxxhost=192.168.7.61 port=54869
2021-09-17 01:55:04 CEST [3095]: user=[unknown],db=[unknown],app=[unknown],client=192.168.7.61 LOG:  connection received: host=192.168.7.61 port=54870
2021-09-17 01:55:04 CEST [3095]: user=xxxxxxx,db=xxxxxxx,app=[unknown],client=192.168.7.61 LOG:  connection authorized: user=xxxxxxxdatabase=xxxxxxx
2021-09-17 01:55:04 CEST [3095]: user=xxxxxxx,db=xxxxxxx,app=[unknown],client=192.168.7.61 LOG:  disconnection: session time: 0:00:00.062 user=xxxxxxxdatabase=xxxxxxxhost=192.168.7.61 port=54870
Solution

  • If you have log_connections enabled then for a successful connection attempt you will see two log entries.

    The first is when the client attempts to make a tcp/ip connection to the PostgreSQL socket. The second is when it connects to a database and authenticates.

    Those are the first log entry and the process is split into two steps so that you can deny connections in pg_hba.conf cheaply before needing to create a new server backend.