PostgreSQL12减少日志量监控探测:incompletestartuppacket

作者

digoal

日期

2019-12-06

标签

PostgreSQL , incomplete startup packet , log

背景

In PostgreSQL, for each client connection request to Postmaster (listens on port 5432 by default), a backend process will 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 this 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 datacenter. There could be different monitoring solutions, security scanners, port scanners, HA Solutions, etc hitting on PostgreSQL Port 5432.

PostgreSQL starts processing these incoming connections for establishing a client-server communication channel. But many of these tools may have a different intention and won’t be participating in a good client-server protocol.

Historically, PostgreSQL generates a log entry for each of these suspected/bad hits. This can result in log files growing to a huge size and can cause unwanted log-related IO.

收到到客户端连接请求，等待client startup package，但是不同的客户端目的不同（有的只是看看远端数据库端口是否联通），不会发送startup报文给数据库，这种情况下，PG12以前的版本，数据库就会打印incomplete startup packet错误日志。

PostgreSQL 12 不再打印某些监控探测数据库是否存活导致的日志。(incomplete startup packet)

https://www.percona.com/blog/2019/12/03/postgresql-12-improvement-benign-log-entries-incomplete-startup-packet/

https://git.postgresql.org/gitweb/?p=postgresql.git;a=patch;h=342cb650e

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.

复现

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

pg 12以前的版本，日志中打印如下日志

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不再打印这些日志，但是需要注意，如果客户端不发送zero size package，pg 12依旧会记录日志如下：

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

tom lane解释：

" The agreed-to behavior change was to not 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."

如果你收到如下日志，说明客户端没有正常的关闭连接。

Such entries are also not going to go away. This happens when the server process tries to read packets (Refer: pq_recvbuf function in src/backend/libpq/pqcomm.c) sent from its client-side and then realizes that 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

如果是pg 12以前的版本，以上问题还会额外打印incomplete startup packet：

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

其他探测方法

```

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 &＃112;&＃103;&＃115;&＃113;&＃108;&＃45;&＃98;&＃117;&＃103;&＃115;&＃64;&＃112;&＃111;&＃115;&＃116;&＃103;&＃114;&＃101;&＃115;&＃113;&＃108;&＃46;&＃111;&＃114;&＃103;.

```

PostgreSQL 报文

https://www.postgresql.org/docs/12/protocol-message-formats.html

参考

https://www.postgresql.org/docs/12/protocol-message-formats.html

https://www.percona.com/blog/2019/12/03/postgresql-12-improvement-benign-log-entries-incomplete-startup-packet/

https://git.postgresql.org/gitweb/?p=postgresql.git;a=patch;h=342cb650e

PostgreSQL 许愿链接

您的愿望将传达给PG kernel hacker、数据库厂商等, 帮助提高数据库产品质量和功能, 说不定下一个PG版本就有您提出的功能点. 针对非常好的提议，奖励限量版PG文化衫、纪念品、贴纸、PG热门书籍等，奖品丰富，快来许愿。开不开森.

9.9元购买3个月阿里云RDS PostgreSQL实例

PostgreSQL 解决方案集合

德哥 / digoal's github - 公益是一辈子的事.