Thread: Re: [HACKERS] Incomplete startup packet errors
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] https://www.postgresql.org/message-id/CAFj8pRDtwsxj63%3DLaWSwA8u7NrU9k9%2BdJtz2gB_0f4SxCM1sQA%40mail.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
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: https://www.postgresql.org/message-id/20190228151336.GB7550%40msg.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: > https://www.postgresql.org/message-id/20190228151336.GB7550%40msg.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: >> https://www.postgresql.org/message-id/20190228151336.GB7550%40msg.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 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: >>> https://www.postgresql.org/message-id/20190228151336.GB7550%40msg.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. > > 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
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
$ telnet localhost 5432
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 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. Agreed. Thanks, Stephen