Thread: streaming header too small
Hi, I was trying pg_basebackup on head, i used this command: """ postgres@jaime:/usr/local/pgsql/9.2$ bin/pg_basebackup -D $PWD/data2 -x stream -P -p 54392 """ i got this error """ 19093/19093 kB (100%), 1/1 tablespace pg_basebackup: streaming header too small: 17 pg_basebackup: child process exited with error 1 """ now, this streaming header size is defined in src/bin/pg_basebackup/receivelog.c as "#define STREAMING_HEADER_SIZE (1+8+8+8)", so WTF is this? what are these numbers? shouldn't be at least a comment explaining those? more important it's seems obvious something broke that, unless i misunderstood something which is completely possible, and that the way is do it it will broke again in the future if the header change -- Jaime Casanova www.2ndQuadrant.com Professional PostgreSQL: Soporte 24x7 y capacitación
On Mon, Jan 9, 2012 at 07:34, Jaime Casanova <jaime@2ndquadrant.com> wrote: > Hi, > > I was trying pg_basebackup on head, i used this command: > """ > postgres@jaime:/usr/local/pgsql/9.2$ bin/pg_basebackup -D $PWD/data2 > -x stream -P -p 54392 > """ > > i got this error > """ > 19093/19093 kB (100%), 1/1 tablespace > pg_basebackup: streaming header too small: 17 > pg_basebackup: child process exited with error 1 > """ > > now, this streaming header size is defined in > src/bin/pg_basebackup/receivelog.c as "#define STREAMING_HEADER_SIZE > (1+8+8+8)", so WTF is this? > what are these numbers? shouldn't be at least a comment explaining > those? more important it's seems obvious something broke that, unless Those numbers are the size of WalDataMessageHeader - a struct which is not available in the frontend, or at least wasn't at the time. > i misunderstood something which is completely possible, and that the > way is do it it will broke again in the future if the header change Without looking at the details, I'm pretty sure it's the keepalive message patch (64233902d22ba42846397cb7551894217522fad4).That one does introduce a new message that's exactly that size. pg_basebackup assumes the only kind of messages that can arrive are the data messages, and this is no longer true. But if you check the code for pg_basebackup, you'll see it checks the size of the message *before* it checks the type of the message, which is why you get a misleading error. I'll dig into the details later - but you could try backing out that patch to confirm if that's the problem. -- Magnus Hagander Me: http://www.hagander.net/ Work: http://www.redpill-linpro.com/
On Mon, Jan 9, 2012 at 11:09, Magnus Hagander <magnus@hagander.net> wrote: > On Mon, Jan 9, 2012 at 07:34, Jaime Casanova <jaime@2ndquadrant.com> wrote: >> Hi, >> >> I was trying pg_basebackup on head, i used this command: >> """ >> postgres@jaime:/usr/local/pgsql/9.2$ bin/pg_basebackup -D $PWD/data2 >> -x stream -P -p 54392 >> """ >> >> i got this error >> """ >> 19093/19093 kB (100%), 1/1 tablespace >> pg_basebackup: streaming header too small: 17 >> pg_basebackup: child process exited with error 1 >> """ >> >> now, this streaming header size is defined in >> src/bin/pg_basebackup/receivelog.c as "#define STREAMING_HEADER_SIZE >> (1+8+8+8)", so WTF is this? >> what are these numbers? shouldn't be at least a comment explaining >> those? more important it's seems obvious something broke that, unless > > Those numbers are the size of WalDataMessageHeader - a struct which is > not available in the frontend, or at least wasn't at the time. > >> i misunderstood something which is completely possible, and that the >> way is do it it will broke again in the future if the header change > > Without looking at the details, I'm pretty sure it's the keepalive > message patch (64233902d22ba42846397cb7551894217522fad4).That one does > introduce a new message that's exactly that size. > > pg_basebackup assumes the only kind of messages that can arrive are > the data messages, and this is no longer true. But if you check the > code for pg_basebackup, you'll see it checks the size of the message > *before* it checks the type of the message, which is why you get a > misleading error. > > I'll dig into the details later - but you could try backing out that > patch to confirm if that's the problem. Confirmed that is it, and attached are two patches to fix it. The first one I intend to backport to 9.1, since it just fixes the error message. The other one is for 9.2. I'll also look at a better way to get that structure size. comments? -- Magnus Hagander Me: http://www.hagander.net/ Work: http://www.redpill-linpro.com/
Attachment
On Mon, Jan 9, 2012 at 12:00, Magnus Hagander <magnus@hagander.net> wrote: > On Mon, Jan 9, 2012 at 11:09, Magnus Hagander <magnus@hagander.net> wrote: >> On Mon, Jan 9, 2012 at 07:34, Jaime Casanova <jaime@2ndquadrant.com> wrote: >>> Hi, >>> >>> I was trying pg_basebackup on head, i used this command: >>> """ >>> postgres@jaime:/usr/local/pgsql/9.2$ bin/pg_basebackup -D $PWD/data2 >>> -x stream -P -p 54392 >>> """ >>> >>> i got this error >>> """ >>> 19093/19093 kB (100%), 1/1 tablespace >>> pg_basebackup: streaming header too small: 17 >>> pg_basebackup: child process exited with error 1 >>> """ >>> >>> now, this streaming header size is defined in >>> src/bin/pg_basebackup/receivelog.c as "#define STREAMING_HEADER_SIZE >>> (1+8+8+8)", so WTF is this? >>> what are these numbers? shouldn't be at least a comment explaining >>> those? more important it's seems obvious something broke that, unless >> >> Those numbers are the size of WalDataMessageHeader - a struct which is >> not available in the frontend, or at least wasn't at the time. >> >>> i misunderstood something which is completely possible, and that the >>> way is do it it will broke again in the future if the header change >> >> Without looking at the details, I'm pretty sure it's the keepalive >> message patch (64233902d22ba42846397cb7551894217522fad4).That one does >> introduce a new message that's exactly that size. >> >> pg_basebackup assumes the only kind of messages that can arrive are >> the data messages, and this is no longer true. But if you check the >> code for pg_basebackup, you'll see it checks the size of the message >> *before* it checks the type of the message, which is why you get a >> misleading error. >> >> I'll dig into the details later - but you could try backing out that >> patch to confirm if that's the problem. > > Confirmed that is it, and attached are two patches to fix it. The > first one I intend to backport to 9.1, since it just fixes the error > message. The other one is for 9.2. I'll also look at a better way to > get that structure size. comments? Patch applied. Realized there is no need to backpatch, because this code didn't even exist in 9.1. The streaming mode of pg_basebackup (which is the only affected one) didn't exist then... -- Magnus Hagander Me: http://www.hagander.net/ Work: http://www.redpill-linpro.com/
Patch applied.On Mon, Jan 9, 2012 at 12:00, Magnus Hagander <magnus@hagander.net> wrote:
> On Mon, Jan 9, 2012 at 11:09, Magnus Hagander <magnus@hagander.net> wrote:
>> On Mon, Jan 9, 2012 at 07:34, Jaime Casanova <jaime@2ndquadrant.com> wrote:
>>> Hi,
>>>
>>> I was trying pg_basebackup on head, i used this command:
>>> """
>>> postgres@jaime:/usr/local/pgsql/9.2$ bin/pg_basebackup -D $PWD/data2
>>> -x stream -P -p 54392
>>> """
>>>
>>> i got this error
>>> """
>>> 19093/19093 kB (100%), 1/1 tablespace
>>> pg_basebackup: streaming header too small: 17
>>> pg_basebackup: child process exited with error 1
>>> """
>>>
>>> now, this streaming header size is defined in
>>> src/bin/pg_basebackup/receivelog.c as "#define STREAMING_HEADER_SIZE
>>> (1+8+8+8)", so WTF is this?
>>> what are these numbers? shouldn't be at least a comment explaining
>>> those? more important it's seems obvious something broke that, unless
>>
>> Those numbers are the size of WalDataMessageHeader - a struct which is
>> not available in the frontend, or at least wasn't at the time.
>>
>>> i misunderstood something which is completely possible, and that the
>>> way is do it it will broke again in the future if the header change
>>
>> Without looking at the details, I'm pretty sure it's the keepalive
>> message patch (64233902d22ba42846397cb7551894217522fad4).That one does
>> introduce a new message that's exactly that size.
>>
>> pg_basebackup assumes the only kind of messages that can arrive are
>> the data messages, and this is no longer true. But if you check the
>> code for pg_basebackup, you'll see it checks the size of the message
>> *before* it checks the type of the message, which is why you get a
>> misleading error.
>>
>> I'll dig into the details later - but you could try backing out that
>> patch to confirm if that's the problem.
>
> Confirmed that is it, and attached are two patches to fix it. The
> first one I intend to backport to 9.1, since it just fixes the error
> message. The other one is for 9.2. I'll also look at a better way to
> get that structure size. comments?
Realized there is no need to backpatch, because this code didn't even
exist in 9.1. The streaming mode of pg_basebackup (which is the only
affected one) didn't exist then...
pg_basebackup: starting background WAL receiver
pg_basebackup: streaming header too small: 25
On 20.02.2013 02:11, Selena Deckelmann wrote: > So, I just ran into a similar issue backing up a 9.2.1 server using > pg_basebackup version 9.2.3: > > pg_basebackup: starting background WAL receiver > pg_basebackup: streaming header too small: 25 > > > I've had it happen two times in a row. I'm going to try again... > > But -- what would be helpful here? I can recompile pg_basebackup with more > debugging... Hmm, 25 bytes would be the size of the WAL data packet, if it contains just the header and no actual WAL data. I think pg_basebackup should accept that - it's not unreasonable that the server might send such a packet sometimes. Looking at the walsender code, it's not supposed to ever send such a packet. But I suspect there's one corner-case where it might: if the current send location is at an xlogid boundary, so that we previously sent the last byte from the last WAL segment in the previous logical xlog file, and the WAL flush position points to byte 0 in the beginning of the new WAL file. Both of those positions are in fact the same thing, but we have two different ways to represent the same position. For example, if we've already sent up to WAL position (sentPtr in walsender.c): xlogid = 4 xrecoff = XLogFileSize and GetFlushRecPtr() returns: xlogid = 5 xrecoff = 0 Those both point to the same position. But the check in XLogSend that decides if there is any work to do uses XLByteLE() to check if they are equal, and XLByteLE() treats the latter to be greater than the former. So, in that situation, XLogSend() would decide that it has work to do, but there actually isn't, so it would send 0 bytes of WAL data. I'm not sure how GetFlushRecPtr() could return such a position, though. But I'm also not convinced that it can't happen. It would be fairly easy to fix walsender to not send anything in that situation. It would also be easy to fix pg_basebackup to not treat it as an error. We probably should do both. In 9.3, the XLogRecPtr representation changed so that there is only one value for a boundary position like that, so this is a 9.2-only issue. - Heikki
<p dir="ltr"><br /> On Feb 20, 2013 11:29 AM, "Heikki Linnakangas" <<a href="mailto:hlinnakangas@vmware.com">hlinnakangas@vmware.com</a>>wrote:<br /> ><br /> > On 20.02.2013 02:11, SelenaDeckelmann wrote:<br /> >><br /> >> So, I just ran into a similar issue backing up a 9.2.1 server using<br/> >> pg_basebackup version 9.2.3:<br /> >><br /> >> pg_basebackup: starting background WAL receiver<br/> >> pg_basebackup: streaming header too small: 25<br /> >><br /> >><br /> >> I've hadit happen two times in a row. I'm going to try again...<br /> >><br /> >> But -- what would be helpful here?I can recompile pg_basebackup with more<br /> >> debugging...<br /> ><br /> ><br /> > Hmm, 25 bytes wouldbe the size of the WAL data packet, if it contains just the header and no actual WAL data. I think pg_basebackup shouldaccept that - it's not unreasonable that the server might send such a packet sometimes.<br /> ><br /> > Lookingat the walsender code, it's not supposed to ever send such a packet. But I suspect there's one corner-case where itmight: if the current send location is at an xlogid boundary, so that we previously sent the last byte from the last WALsegment in the previous logical xlog file, and the WAL flush position points to byte 0 in the beginning of the new WALfile. Both of those positions are in fact the same thing, but we have two different ways to represent the same position.For example, if we've already sent up to WAL position (sentPtr in walsender.c):<br /> ><br /> > xlogid = 4<br/> > xrecoff = XLogFileSize<br /> ><br /> > and GetFlushRecPtr() returns:<br /> ><br /> > xlogid = 5<br/> > xrecoff = 0<br /> ><br /> > Those both point to the same position. But the check in XLogSend that decidesif there is any work to do uses XLByteLE() to check if they are equal, and XLByteLE() treats the latter to be greaterthan the former. So, in that situation, XLogSend() would decide that it has work to do, but there actually isn't,so it would send 0 bytes of WAL data.<br /> ><br /> > I'm not sure how GetFlushRecPtr() could return such a position,though. But I'm also not convinced that it can't happen.<br /> ><br /> > It would be fairly easy to fix walsenderto not send anything in that situation. It would also be easy to fix pg_basebackup to not treat it as an error.We probably should do both.<br /> ><br /> > In 9.3, the XLogRecPtr representation changed so that there is onlyone value for a boundary position like that, so this is a 9.2-only issue.<br /><p dir="ltr">That does sound like a reasonableexplanation and fix. Heck, probably enough to just put the fix in pg_basebackup since it's gone in 9.3 anyway.<p dir="ltr">But I'd really like to confirm this is the actual situation before considering it fixed, since it's clearlyvery intermittent. <p dir="ltr">Selena, was this reasonably reproducible for you? Would it be possible to get a networktrace of it to show of that's the kind of package coming across, or by hacking up pg_basebackup to print the exactposition it was at when the problem occurred? <p dir="ltr">/Magnus <br />
On Feb 20, 2013 11:29 AM, "Heikki Linnakangas" <hlinnakangas@vmware.com> wrote:
>
> On 20.02.2013 02:11, Selena Deckelmann wrote:
>>
>> So, I just ran into a similar issue backing up a 9.2.1 server using
>> pg_basebackup version 9.2.3:
>>
>> pg_basebackup: starting background WAL receiver
>> pg_basebackup: streaming header too small: 25
>>
>>
>> I've had it happen two times in a row. I'm going to try again...
>>
>> But -- what would be helpful here? I can recompile pg_basebackup with more
>> debugging...
>
>
> Hmm, 25 bytes would be the size of the WAL data packet, if it contains just the header and no actual WAL data. I think pg_basebackup should accept that - it's not unreasonable that the server might send such a packet sometimes.
>
> Looking at the walsender code, it's not supposed to ever send such a packet. But I suspect there's one corner-case where it might: if the current send location is at an xlogid boundary, so that we previously sent the last byte from the last WAL segment in the previous logical xlog file, and the WAL flush position points to byte 0 in the beginning of the new WAL file. Both of those positions are in fact the same thing, but we have two different ways to represent the same position. For example, if we've already sent up to WAL position (sentPtr in walsender.c):
>
> xlogid = 4
> xrecoff = XLogFileSize
>
> and GetFlushRecPtr() returns:
>
> xlogid = 5
> xrecoff = 0
>
> Those both point to the same position. But the check in XLogSend that decides if there is any work to do uses XLByteLE() to check if they are equal, and XLByteLE() treats the latter to be greater than the former. So, in that situation, XLogSend() would decide that it has work to do, but there actually isn't, so it would send 0 bytes of WAL data.
>
> I'm not sure how GetFlushRecPtr() could return such a position, though. But I'm also not convinced that it can't happen.
>
> It would be fairly easy to fix walsender to not send anything in that situation. It would also be easy to fix pg_basebackup to not treat it as an error. We probably should do both.
>
> In 9.3, the XLogRecPtr representation changed so that there is only one value for a boundary position like that, so this is a 9.2-only issue.
Thanks for the debugging, Heikki!
That does sound like a reasonable explanation and fix. Heck, probably enough to just put the fix in pg_basebackup since it's gone in 9.3 anyway.
But I'd really like to confirm this is the actual situation before considering it fixed, since it's clearly very intermittent.
Selena, was this reasonably reproducible for you? Would it be possible to get a network trace of it to show of that's the kind of package coming across, or by hacking up pg_basebackup to print the exact position it was at when the problem occurred?
This is happening with a very busy 700 GB system, so I'm going to rule out a network trace out for the moment. The error is occurring "sometime" in the middle of the backup. Last time it was at least 30-40 minutes into a 2 hr backup.
On Wed, Feb 20, 2013 at 4:53 PM, Selena Deckelmann <selena@chesnok.com> wrote: > > > > On Wed, Feb 20, 2013 at 6:23 AM, Magnus Hagander <magnus@hagander.net> > wrote: >> >> >> On Feb 20, 2013 11:29 AM, "Heikki Linnakangas" <hlinnakangas@vmware.com> >> wrote: >> > >> > On 20.02.2013 02:11, Selena Deckelmann wrote: >> >> >> >> So, I just ran into a similar issue backing up a 9.2.1 server using >> >> pg_basebackup version 9.2.3: >> >> >> >> pg_basebackup: starting background WAL receiver >> >> pg_basebackup: streaming header too small: 25 >> >> >> >> >> >> I've had it happen two times in a row. I'm going to try again... >> >> >> >> But -- what would be helpful here? I can recompile pg_basebackup with >> >> more >> >> debugging... >> > >> > >> > Hmm, 25 bytes would be the size of the WAL data packet, if it contains >> > just the header and no actual WAL data. I think pg_basebackup should accept >> > that - it's not unreasonable that the server might send such a packet >> > sometimes. >> > >> > Looking at the walsender code, it's not supposed to ever send such a >> > packet. But I suspect there's one corner-case where it might: if the current >> > send location is at an xlogid boundary, so that we previously sent the last >> > byte from the last WAL segment in the previous logical xlog file, and the >> > WAL flush position points to byte 0 in the beginning of the new WAL file. >> > Both of those positions are in fact the same thing, but we have two >> > different ways to represent the same position. For example, if we've already >> > sent up to WAL position (sentPtr in walsender.c): >> > >> > xlogid = 4 >> > xrecoff = XLogFileSize >> > >> > and GetFlushRecPtr() returns: >> > >> > xlogid = 5 >> > xrecoff = 0 >> > >> > Those both point to the same position. But the check in XLogSend that >> > decides if there is any work to do uses XLByteLE() to check if they are >> > equal, and XLByteLE() treats the latter to be greater than the former. So, >> > in that situation, XLogSend() would decide that it has work to do, but there >> > actually isn't, so it would send 0 bytes of WAL data. >> > >> > I'm not sure how GetFlushRecPtr() could return such a position, though. >> > But I'm also not convinced that it can't happen. >> > >> > It would be fairly easy to fix walsender to not send anything in that >> > situation. It would also be easy to fix pg_basebackup to not treat it as an >> > error. We probably should do both. >> > >> > In 9.3, the XLogRecPtr representation changed so that there is only one >> > value for a boundary position like that, so this is a 9.2-only issue. > > > Thanks for the debugging, Heikki! > >> >> That does sound like a reasonable explanation and fix. Heck, probably >> enough to just put the fix in pg_basebackup since it's gone in 9.3 anyway. >> >> But I'd really like to confirm this is the actual situation before >> considering it fixed, since it's clearly very intermittent. >> >> Selena, was this reasonably reproducible for you? Would it be possible to >> get a network trace of it to show of that's the kind of package coming >> across, or by hacking up pg_basebackup to print the exact position it was at >> when the problem occurred? > > > This is happening with a very busy 700 GB system, so I'm going to rule out a > network trace out for the moment. The error is occurring "sometime" in the > middle of the backup. Last time it was at least 30-40 minutes into a 2 hr > backup. Yikes. Yeah, that doesn't seem like the best choice of method :) > I'll see about hacking up pg_basebackup. I'm doing nightly backups so > hopefully (?) it will happen again in the next few days. Thanks! -- Magnus HaganderMe: http://www.hagander.net/Work: http://www.redpill-linpro.com/
On 20.02.2013 17:53, Selena Deckelmann wrote: > On Wed, Feb 20, 2013 at 6:23 AM, Magnus Hagander<magnus@hagander.net>wrote: > >> Selena, was this reasonably reproducible for you? Would it be possible to >> get a network trace of it to show of that's the kind of package coming >> across, or by hacking up pg_basebackup to print the exact position it was >> at when the problem occurred? > > This is happening with a very busy 700 GB system, so I'm going to rule out > a network trace out for the moment. The error is occurring "sometime" in > the middle of the backup. Last time it was at least 30-40 minutes into a 2 > hr backup. If you could pinpoint the WAL position where the error happens, that would already help somewhat. For starters, put pg_receivexlog to verbose mode, so that it will print a line after each WAL segment. If my theory is correct, the error should happen at xlogid boundaries, ie. just after finishing a WAL segment whose filename ends with "FE". - Heikki
On Wed, Feb 20, 2013 at 5:02 PM, Heikki Linnakangas <hlinnakangas@vmware.com> wrote: > On 20.02.2013 17:53, Selena Deckelmann wrote: >> >> On Wed, Feb 20, 2013 at 6:23 AM, Magnus >> Hagander<magnus@hagander.net>wrote: >> >>> Selena, was this reasonably reproducible for you? Would it be possible to >>> get a network trace of it to show of that's the kind of package coming >>> across, or by hacking up pg_basebackup to print the exact position it was >>> at when the problem occurred? >> >> >> This is happening with a very busy 700 GB system, so I'm going to rule out >> a network trace out for the moment. The error is occurring "sometime" in >> the middle of the backup. Last time it was at least 30-40 minutes into a 2 >> hr backup. > > > If you could pinpoint the WAL position where the error happens, that would > already help somewhat. For starters, put pg_receivexlog to verbose mode, so > that it will print a line after each WAL segment. If my theory is correct, > the error should happen at xlogid boundaries, ie. just after finishing a WAL > segment whose filename ends with "FE". Your theory is correct, it happens at xlogid boundaries. The missing information is that AFAICT it can only happen if pg_basebackup is run against a slave, and never on the master. I've applied a patch that just accepts this case, and ignores it. Originally I had pg_basebackup write a warning in that case, but on second thought I think that's just wrong - it will send out warning messages in cases that are absolutely normal. I'm not going to bother with a backend side patch, since this is mostly harmless (it sends a single packet of an extra 25 bytes in what's usually a large backup, so it doesn't matter), and it's all gone in 9.3 anyway. And in 9.1 and earlier, the support isn't there. -- Magnus HaganderMe: http://www.hagander.net/Work: http://www.redpill-linpro.com/