Incomplete startup packet errors
It's fairly common to see a lot of "Incomplete startup packet" in the
logfiles caused by monitoring or healthcheck connections.
I wonder if it would make sense to only log that error if *at least one
byte* has been received and then it becomes empty. Meaning that if the
client just connects+disconnects without sending anything, we don't log
anything. At least at the default log level (we could have a DEBUG level
that logged "connection closed immediately").
That would get rid of a lot of logspam.
Would that make sense?
--
Magnus Hagander
Me: http://www.hagander.net/
Work: http://www.redpill-linpro.com/
At 2016-04-13 10:02:22 +0200, magnus@hagander.net wrote:
I wonder if it would make sense to only log that error if *at least
one byte* has been received and then it becomes empty.
Yes, it would be very nice to eliminate that logspam, as you say.
-- Abhijit
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Wed, Apr 13, 2016 at 9:02 AM, Magnus Hagander <magnus@hagander.net> wrote:
It's fairly common to see a lot of "Incomplete startup packet" in the
logfiles caused by monitoring or healthcheck connections.I wonder if it would make sense to only log that error if *at least one
byte* has been received and then it becomes empty. Meaning that if the
client just connects+disconnects without sending anything, we don't log
anything. At least at the default log level (we could have a DEBUG level
that logged "connection closed immediately").That would get rid of a lot of logspam.
Would that make sense?
Absolutely. It would be very nice to get rid of such noise.
--
Dave Page
Blog: http://pgsnake.blogspot.com
Twitter: @pgsnake
EnterpriseDB UK: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Wed, Apr 13, 2016 at 1:02 AM, Magnus Hagander <magnus@hagander.net> wrote:
It's fairly common to see a lot of "Incomplete startup packet" in the
logfiles caused by monitoring or healthcheck connections.
I've also seen it caused by port scanning.
--
Peter Geoghegan
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Wed, Apr 13, 2016 at 10:24 AM, Peter Geoghegan <pg@heroku.com> wrote:
On Wed, Apr 13, 2016 at 1:02 AM, Magnus Hagander <magnus@hagander.net>
wrote:It's fairly common to see a lot of "Incomplete startup packet" in the
logfiles caused by monitoring or healthcheck connections.I've also seen it caused by port scanning.
Yes, definitely. Question there might be if that's actually a case when we
*want* that logging?
--
Magnus Hagander
Me: http://www.hagander.net/
Work: http://www.redpill-linpro.com/
Magnus Hagander <magnus@hagander.net> writes:
On Wed, Apr 13, 2016 at 10:24 AM, Peter Geoghegan <pg@heroku.com> wrote:
On Wed, Apr 13, 2016 at 1:02 AM, Magnus Hagander <magnus@hagander.net>
wrote:It's fairly common to see a lot of "Incomplete startup packet" in the
logfiles caused by monitoring or healthcheck connections.
I've also seen it caused by port scanning.
Yes, definitely. Question there might be if that's actually a case when we
*want* that logging?
I should think someone might. But I doubt we want to introduce another
GUC for this. Would it be okay to downgrade the message to DEBUG1 if
zero bytes were received?
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Wed, Apr 13, 2016 at 3:56 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Magnus Hagander <magnus@hagander.net> writes:
On Wed, Apr 13, 2016 at 10:24 AM, Peter Geoghegan <pg@heroku.com> wrote:
On Wed, Apr 13, 2016 at 1:02 AM, Magnus Hagander <magnus@hagander.net>
wrote:It's fairly common to see a lot of "Incomplete startup packet" in the
logfiles caused by monitoring or healthcheck connections.I've also seen it caused by port scanning.
Yes, definitely. Question there might be if that's actually a case when
we
*want* that logging?
I should think someone might. But I doubt we want to introduce another
GUC for this. Would it be okay to downgrade the message to DEBUG1 if
zero bytes were received?
Yeah, that was my suggestion - I think that's a reasonable compromise. And
yes, I agree that a separate GUC for it would be a huge overkill.
--
Magnus Hagander
Me: http://www.hagander.net/
Work: http://www.redpill-linpro.com/
I've also seen it caused by port scanning.
Yes, definitely. Question there might be if that's actually a case when we
*want* that logging?
Is it possible a user want the log because he/she wants to notice that
the system is being attacked?
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese:http://www.sraoss.co.jp
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Wed, Apr 13, 2016 at 10:30 AM, Tatsuo Ishii <ishii@postgresql.org> wrote:
I've also seen it caused by port scanning.
Yes, definitely. Question there might be if that's actually a case when we
*want* that logging?Is it possible a user want the log because he/she wants to notice that
the system is being attacked?
Yeah, but it doesn't seem very likely, because:
1. If the system is on the Internet, it's definitely being attacked, and
2. The attacks that connect to a port and then disconnect are not the
ones you should be most worried about, and
3. The right way to detect attacks is through OS-level monitoring or
firewall-level monitoring, and nothing we do in PG is going to come
close to the same value.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Is it possible a user want the log because he/she wants to notice that
the system is being attacked?Yeah, but it doesn't seem very likely, because:
1. If the system is on the Internet, it's definitely being attacked, and
2. The attacks that connect to a port and then disconnect are not the
ones you should be most worried about, and3. The right way to detect attacks is through OS-level monitoring or
firewall-level monitoring, and nothing we do in PG is going to come
close to the same value.
Ok, that makes sense.
Best regards,
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese:http://www.sraoss.co.jp
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Re: Magnus Hagander 2016-04-13 <CABUevEzq8_nSq7fwe0-fbOAK8S2YNN-PkfsamfEvy2-d3dRUoA@mail.gmail.com>
It's fairly common to see a lot of "Incomplete startup packet" in the
logfiles caused by monitoring or healthcheck connections.I've also seen it caused by port scanning.
Yes, definitely. Question there might be if that's actually a case when
we
*want* that logging?
I should think someone might. But I doubt we want to introduce another
GUC for this. Would it be okay to downgrade the message to DEBUG1 if
zero bytes were received?Yeah, that was my suggestion - I think that's a reasonable compromise. And
yes, I agree that a separate GUC for it would be a huge overkill.
There have been numerous complaints about that log message, and the
usual reply is always something like what Pavel said recently:
"It is garbage. Usually it means nothing, but better to work live
without this garbage." [1]/messages/by-id/CAFj8pRDtwsxj63=LaWSwA8u7NrU9k9+dJtz2gB_0f4SxCM1sQA@mail.gmail.com
[1]: /messages/by-id/CAFj8pRDtwsxj63=LaWSwA8u7NrU9k9+dJtz2gB_0f4SxCM1sQA@mail.gmail.com
Let's get rid of it.
Christoph
Attachments:
0001-Demote-incomplete-startup-packet-to-DEBUG1.patchtext/x-diff; charset=us-asciiDownload
From 19b4e489fdc974ad8414e960a721694b2c2ee9d5 Mon Sep 17 00:00:00 2001
From: Christoph Berg <christoph.berg@credativ.de>
Date: Thu, 28 Feb 2019 16:12:46 +0100
Subject: [PATCH] Demote "incomplete startup packet" to DEBUG1
---
src/backend/postmaster/postmaster.c | 6 +++---
1 file changed, 3 insertions(+), 3 deletions(-)
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index ccea231e98..2dfb7b6e0a 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -1907,7 +1907,7 @@ ProcessStartupPacket(Port *port, bool SSLdone)
* don't clutter the log with a complaint.
*/
if (!SSLdone)
- ereport(COMMERROR,
+ ereport(DEBUG1,
(errcode(ERRCODE_PROTOCOL_VIOLATION),
errmsg("incomplete startup packet")));
return STATUS_ERROR;
@@ -1919,7 +1919,7 @@ ProcessStartupPacket(Port *port, bool SSLdone)
if (len < (int32) sizeof(ProtocolVersion) ||
len > MAX_STARTUP_PACKET_LENGTH)
{
- ereport(COMMERROR,
+ ereport(DEBUG1,
(errcode(ERRCODE_PROTOCOL_VIOLATION),
errmsg("invalid length of startup packet")));
return STATUS_ERROR;
@@ -1938,7 +1938,7 @@ ProcessStartupPacket(Port *port, bool SSLdone)
if (pq_getbytes(buf, len) == EOF)
{
- ereport(COMMERROR,
+ ereport(DEBUG1,
(errcode(ERRCODE_PROTOCOL_VIOLATION),
errmsg("incomplete startup packet")));
return STATUS_ERROR;
--
2.20.1
On 2/28/19 10:13 AM, Christoph Berg wrote:
Re: Magnus Hagander 2016-04-13 <CABUevEzq8_nSq7fwe0-fbOAK8S2YNN-PkfsamfEvy2-d3dRUoA@mail.gmail.com>
It's fairly common to see a lot of "Incomplete startup packet" in the
logfiles caused by monitoring or healthcheck connections.I've also seen it caused by port scanning.
Yes, definitely. Question there might be if that's actually a case when
we
*want* that logging?
I should think someone might. But I doubt we want to introduce another
GUC for this. Would it be okay to downgrade the message to DEBUG1 if
zero bytes were received?Yeah, that was my suggestion - I think that's a reasonable compromise. And
yes, I agree that a separate GUC for it would be a huge overkill.There have been numerous complaints about that log message, and the
usual reply is always something like what Pavel said recently:"It is garbage. Usually it means nothing, but better to work live
without this garbage." [1][1] /messages/by-id/CAFj8pRDtwsxj63=LaWSwA8u7NrU9k9+dJtz2gB_0f4SxCM1sQA@mail.gmail.com
Let's get rid of it.
Right. This has annoyed me and a great many other people for years. I
think Robert Haas' argument 3 years ago (!) was on point, and disposes
of suggestions to keep it:
3. The right way to detect attacks is through OS-level monitoring or
firewall-level monitoring, and nothing we do in PG is going to come
close to the same value.
So I propose shortly to commit this patch unconditionally demoting the
message to DEBUG1.
cheers
andrew
--
Andrew Dunstan https://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Import Notes
Reply to msg id not found: d3a91d02-2551-e8a2-63ee-ccfa6b3ee949@2ndQuadrant.comReference msg id not found: d3a91d02-2551-e8a2-63ee-ccfa6b3ee949@2ndQuadrant.com | Resolved by subject fallback
Andrew Dunstan <andrew.dunstan@2ndquadrant.com> writes:
So I propose shortly to commit this patch unconditionally demoting the
message to DEBUG1.
No patch referenced, but I assume you mean only for the
zero-bytes-received case, right? No objection if so.
regards, tom lane
On 3/1/19 6:49 PM, Tom Lane wrote:
Andrew Dunstan <andrew.dunstan@2ndquadrant.com> writes:
So I propose shortly to commit this patch unconditionally demoting the
message to DEBUG1.No patch referenced, but I assume you mean only for the
zero-bytes-received case, right? No objection if so.
Patch proposed by Christoph Berg is here:
/messages/by-id/20190228151336.GB7550@msg.df7cb.de
cheers
andrew
--
Andrew Dunstan https://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Andrew Dunstan <andrew.dunstan@2ndquadrant.com> writes:
On 3/1/19 6:49 PM, Tom Lane wrote:
No patch referenced, but I assume you mean only for the
zero-bytes-received case, right? No objection if so.
Patch proposed by Christoph Berg is here:
/messages/by-id/20190228151336.GB7550@msg.df7cb.de
Meh. That doesn't silence only the zero-bytes case, and I'm also
rather afraid of the fact that it's changing COMMERROR to something
else. I wonder whether (if client_min_messages <= DEBUG1) it could
result in trying to send the error message to the already-lost
connection. It might be that that can't happen, but I think a fair
amount of rather subtle (and breakable) analysis may be needed.
regards, tom lane
I wrote:
Andrew Dunstan <andrew.dunstan@2ndquadrant.com> writes:
Patch proposed by Christoph Berg is here:
/messages/by-id/20190228151336.GB7550@msg.df7cb.de
Meh. That doesn't silence only the zero-bytes case, and I'm also
rather afraid of the fact that it's changing COMMERROR to something
else. I wonder whether (if client_min_messages <= DEBUG1) it could
result in trying to send the error message to the already-lost
connection. It might be that that can't happen, but I think a fair
amount of rather subtle (and breakable) analysis may be needed.
Concretely, what about doing the following instead? This doesn't provide
any mechanism for the DBA to adjust the logging behavior; but reducing
log_min_messages to DEBUG1 would not be a very pleasant way to monitor for
zero-data connections either, so I'm not that fussed about just dropping
the message period for that case. I kind of like that we no longer need
the weird special case for SSLdone.
regards, tom lane
Attachments:
alternate-fix-for-incomplete-packet-logging.patchtext/x-diff; charset=us-ascii; name=alternate-fix-for-incomplete-packet-logging.patchDownload
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index ccea231..fe59963 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -1899,17 +1899,34 @@ ProcessStartupPacket(Port *port, bool SSLdone)
MemoryContext oldcontext;
pq_startmsgread();
- if (pq_getbytes((char *) &len, 4) == EOF)
+
+ /*
+ * Grab the first byte of the length word separately, so that we can tell
+ * whether we have no data at all or an incomplete packet. (This might
+ * sound inefficient, but it's not really, because of buffering in
+ * pqcomm.c.)
+ */
+ if (pq_getbytes((char *) &len, 1) == EOF)
{
/*
- * EOF after SSLdone probably means the client didn't like our
- * response to NEGOTIATE_SSL_CODE. That's not an error condition, so
- * don't clutter the log with a complaint.
+ * If we get no data at all, don't clutter the log with a complaint;
+ * such cases often occur for legitimate reasons. An example is that
+ * we might be here after responding to NEGOTIATE_SSL_CODE, and if the
+ * client didn't like our response, it'll probably just drop the
+ * connection. Service-monitoring software also often just opens and
+ * closes a connection without sending anything. (So do port
+ * scanners, which may be less benign, but it's not really our job to
+ * notice those.)
*/
- if (!SSLdone)
- ereport(COMMERROR,
- (errcode(ERRCODE_PROTOCOL_VIOLATION),
- errmsg("incomplete startup packet")));
+ return STATUS_ERROR;
+ }
+
+ if (pq_getbytes(((char *) &len) + 1, 3) == EOF)
+ {
+ /* Got a partial length word, so bleat about that */
+ ereport(COMMERROR,
+ (errcode(ERRCODE_PROTOCOL_VIOLATION),
+ errmsg("incomplete startup packet")));
return STATUS_ERROR;
}
On 3/3/19 3:52 PM, Tom Lane wrote:
I wrote:
Andrew Dunstan <andrew.dunstan@2ndquadrant.com> writes:
Patch proposed by Christoph Berg is here:
/messages/by-id/20190228151336.GB7550@msg.df7cb.deMeh. That doesn't silence only the zero-bytes case, and I'm also
rather afraid of the fact that it's changing COMMERROR to something
else. I wonder whether (if client_min_messages <= DEBUG1) it could
result in trying to send the error message to the already-lost
connection. It might be that that can't happen, but I think a fair
amount of rather subtle (and breakable) analysis may be needed.Concretely, what about doing the following instead? This doesn't provide
any mechanism for the DBA to adjust the logging behavior; but reducing
log_min_messages to DEBUG1 would not be a very pleasant way to monitor for
zero-data connections either, so I'm not that fussed about just dropping
the message period for that case. I kind of like that we no longer need
the weird special case for SSLdone.
Looks good to me.
cheers
andrew
--
Andrew Dunstan https://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Re: Andrew Dunstan 2019-03-04 <7cc6d2c1-bd87-9890-259d-36739c247b6c@2ndQuadrant.com>
Looks good to me.
+1.
Christoph
On 3/4/19 7:42 AM, Christoph Berg wrote:
Re: Andrew Dunstan 2019-03-04 <7cc6d2c1-bd87-9890-259d-36739c247b6c@2ndQuadrant.com>
Looks good to me.
+1.
OK, I think we have agreement on Tom's patch. Do we want to backpatch
it? It's a change in behaviour, but I find it hard to believe anyone
relies on the existence of these annoying messages, so my vote would be
to backpatch it.
cheers
andrew
--
Andrew Dunstan https://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On Tue, Mar 5, 2019 at 5:35 PM Andrew Dunstan
<andrew.dunstan@2ndquadrant.com> wrote:
OK, I think we have agreement on Tom's patch. Do we want to backpatch
it? It's a change in behaviour, but I find it hard to believe anyone
relies on the existence of these annoying messages, so my vote would be
to backpatch it.
I don't think it's a bug fix, so I don't think it should be
back-patched. I think trying to guess which behavior changes are
likely to bother users is an unwise strategy -- it's very hard to know
what will actually bother people, and it's very easy to let one's own
desire to get a fix out the door lead to an unduly rosy view of the
situation. Plus, all patches carry some risk, because all developers
make mistakes; the fewer things we back-patch, the fewer regressions
we'll introduce.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
On 3/6/19 12:12 PM, Robert Haas wrote:
On Tue, Mar 5, 2019 at 5:35 PM Andrew Dunstan
<andrew.dunstan@2ndquadrant.com> wrote:OK, I think we have agreement on Tom's patch. Do we want to backpatch
it? It's a change in behaviour, but I find it hard to believe anyone
relies on the existence of these annoying messages, so my vote would be
to backpatch it.I don't think it's a bug fix, so I don't think it should be
back-patched. I think trying to guess which behavior changes are
likely to bother users is an unwise strategy -- it's very hard to know
what will actually bother people, and it's very easy to let one's own
desire to get a fix out the door lead to an unduly rosy view of the
situation. Plus, all patches carry some risk, because all developers
make mistakes; the fewer things we back-patch, the fewer regressions
we'll introduce.
OK, no back-patching it is.
cheers
andrew
--
Andrew Dunstan https://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On Thu, Mar 7, 2019 at 1:26 AM Andrew Dunstan <
andrew.dunstan@2ndquadrant.com> wrote:
On 3/6/19 12:12 PM, Robert Haas wrote:
On Tue, Mar 5, 2019 at 5:35 PM Andrew Dunstan
<andrew.dunstan@2ndquadrant.com> wrote:OK, I think we have agreement on Tom's patch. Do we want to backpatch
OK, no back-patching it is.
However, Checking whether the port is open is resulting in error log like:
2019-11-25 14:03:44.414 IST [14475] LOG: invalid length of startup packet
Yes, This is different from "Incomplete startup packet" discussed here.
Steps to reproduce:
$ telnet localhost 5432
Show quoted text
Jobin Augustine <jobinau@gmail.com> writes:
However, Checking whether the port is open is resulting in error log like:
2019-11-25 14:03:44.414 IST [14475] LOG: invalid length of startup packet
Yes, This is different from "Incomplete startup packet" discussed here.
Steps to reproduce:
$ telnet localhost 5432
Well, 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.
regards, tom lane
Greetings,
* Tom Lane (tgl@sss.pgh.pa.us) wrote:
Jobin Augustine <jobinau@gmail.com> writes:
However, Checking whether the port is open is resulting in error log like:
2019-11-25 14:03:44.414 IST [14475] LOG: invalid length of startup packet
Yes, This is different from "Incomplete startup packet" discussed here.Steps to reproduce:
$ telnet localhost 5432Well, 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.
Agreed.
Thanks,
Stephen