Community

Blog Events Webinars Tutorials Forum
  1. Blog
  2. Events
  3. Webinars
  4. Tutorials
  5. Forum
Create Account
×
Community Blog How PostgreSQL 12 Generates Less Log Data When Monitoring and Detecting Incomplete Startup Packet

How PostgreSQL 12 Generates Less Log Data When Monitoring and Detecting Incomplete Startup Packet

In this article, the author explains how PostgreSQL 12 does not create log entries for activity related to monitoring and checking whether the database is alive.

By digoal

Background

For each client connection request to Postmaster in PostgreSQL (listened to on port 5432 by default), a backend process would be created. It then processes the startup packet from the client. Refer to src/backend/postmaster/postmaster.c for the source code.

Each client connection request is expected to send a startup message to the PostgreSQL server, and the information in the startup packet is used for setting up the backend process. But there are many more things happening when we deploy PostgreSQL in a data center. There could be different monitoring solutions, security scanners, port scanners, and HA solutions, among others hitting on PostgreSQL Port 5432.

PostgreSQL starts processing these incoming connections for establishing a client-server communication channel. But these tools can have different intentions and may not participate in a good client-server protocol.

Historically, PostgreSQL generates a log entry for each of these suspected or bad hits. This can result in log files becoming huge and unwanted log-related IO.

After receiving a connection request from the client, wait for the client startup package. However, different clients have different purposes (some clients only check whether the remote database ports are connected) and will not send the startup packet to the database. In this case, the database would print the incomplete startup packet error logs in versions earlier than PG12.

PostgreSQL 12, however, no longer prints logs generated from monitoring and checking whether the database is alive (incomplete startup packet).

This will stop logging cases where, for example, a monitor opens a connection and immediately closes it. If the packet contains any data, an incomplete packet will still be logged.

Reproduction

for i in {1..100}; do  
     nc -zv localhost 5432 ;  
done

For versions earlier than PG12, the logs printed are as follows:

2019-11-28 13:24:26.501 UTC [15168] LOG: incomplete startup packet  
2019-11-28 13:24:26.517 UTC [15170] LOG: incomplete startup packet  
2019-11-28 13:24:26.532 UTC [15172] LOG: incomplete startup packet  
2019-11-28 13:24:26.548 UTC [15174] LOG: incomplete startup packet  
2019-11-28 13:24:26.564 UTC [15176] LOG: incomplete startup packet  
2019-11-28 13:24:26.580 UTC [15178] LOG: incomplete startup packet  
2019-11-28 13:24:26.595 UTC [15180] LOG: incomplete startup packet  
2019-11-28 13:24:26.611 UTC [15182] LOG: incomplete startup packet  
2019-11-28 13:24:26.627 UTC [15184] LOG: incomplete startup packet  
2019-11-28 13:24:26.645 UTC [15186] LOG: incomplete startup packet  
2019-11-28 13:24:26.666 UTC [15188] LOG: incomplete startup packet  
2019-11-28 13:24:26.687 UTC [15190] LOG: incomplete startup packet  
2019-11-28 13:24:26.710 UTC [15192] LOG: incomplete startup packet  
2019-11-28 13:24:26.729 UTC [15194] LOG: incomplete startup packet  
2019-11-28 13:24:26.748 UTC [15196] LOG: incomplete startup packet  
...

PG12 no longer prints these logs. Note that if the client does not send a zero size package, PG12 still records the logs as follows:

2019-11-28 14:27:49.728 UTC [17982] LOG: invalid length of startup packet  
2019-11-28 14:28:14.907 UTC [17983] LOG: invalid length of startup packet  
2019-11-28 14:28:18.236 UTC [17984] LOG: invalid length of startup packet

Explanation from Tom Lane:

"The agreed-to behavior change was not to log anything if the connection is closed without any data having been sent. If the client does send something, and it doesn't look like a valid connection request, I think we absolutely should log that."

If the following logs are received, it indicates that the client did not close the connection normally.

Such entries are also not going away. This happens when the server process tries to read packets (Refer to the pq_recvbuf function in src/backend/libpq/pqcomm.c) sent from its client-side and then realizes that the client-side is already lost, which means that the client ended communication without a good handshake.

2019-11-28 14:11:45.273 UTC [17951] LOG: could not receive data from client: Connection reset by peer  
2019-11-28 14:11:47.328 UTC [17953] LOG: could not receive data from client: Connection reset by peer  
2019-11-28 14:11:48.425 UTC [17955] LOG: could not receive data from client: Connection reset by peer  
2019-11-28 14:27:11.870 UTC [17978] LOG: could not receive data from client: Connection reset by peer

For versions earlier than PG12, the incomplete startup packet is also printed if the preceding issues are reported:

2019-11-28 13:53:31.721 UTC [15446] LOG: could not receive data from client: Connection reset by peer  
2019-11-28 13:53:31.721 UTC [15446] LOG: incomplete startup packet  
2019-11-28 13:54:04.014 UTC [15450] LOG: could not receive data from client: Connection reset by peer  
2019-11-28 13:54:04.014 UTC [15450] LOG: incomplete startup packet  
2019-11-28 14:01:55.514 UTC [15479] LOG: could not receive data from client: Connection reset by peer  
2019-11-28 14:01:55.514 UTC [15479] LOG: incomplete startup packet

Other Detection Methods

postgres@pg11-test-> pg_isready --help  
pg_isready issues a connection check to a PostgreSQL database.  
  
Usage:  
  pg_isready [OPTION]...  
  
Options:  
  -d, --dbname=DBNAME      database name  
  -q, --quiet              run quietly  
  -V, --version            output version information, then exit  
  -?, --help               show this help, then exit  
  
Connection options:  
  -h, --host=HOSTNAME      database server host or socket directory  
  -p, --port=PORT          database server port  
  -t, --timeout=SECS       seconds to wait when attempting connection, 0 disables (default: 3)  
  -U, --username=USERNAME  user name to connect as  
  
Report bugs to <pgsql-bugs@postgresql.org>.

PostgreSQL Packet

References

PostgreSQL Database monitoring Log Data Incomplete Startup Packet
0 0 0
Share on

Read previous post:

PostgreSQL v12: NBtree Index v4 Kernel Improvement Analysis

Read next post:

PostgreSQL v12 Performance: Alibaba Cloud ECS Local SSD vs. ESSD PL3

digoal

281 posts | 24 followers

You may also like

Comments

digoal

281 posts | 24 followers

Related Products

More Posts by digoal

See All