Patroni: Switchover/Failover may not switch timelines.

[bradnicholson]

Take the following scenario:

1. A is the leader, B is the follower. A and B are on Timeline 1
2. A shuts down. Either a controlled switchover or failover happens and B is promoted. A is still on Timeline 1, B moves to Timeline 2
3. B shuts down, without A ever coming back as a subscriber to B
4. A starts up and becomes leader. A switches from Timeline 1 to Timeline 2 independent of

At this point, we have split-brain from a Postgres perspective. Both have independently promoted themselves from Timeline 1 to Timeline 2 with no knowledge of each other.

The reason we stumbled across this was due to archiving conflicts with pgBackRest (see issue 584 ). There is separate underlying issue there where the .partial files being generated on members A & B differ from the archived version (due, I think, to the immediate shutdown Patroni issues - but not conclusive yet. The data in the wal files is identical, but the sha sums are not). pgBackRest will catch this because it checksums the files. wal-e will not.

The pgBackRest folks have some specific recommendations for Patroni here

In addition, there really should never be two .partial files on the same timeline. The old primary should be made to follow the new primary and do the timeline switch before it gets promoted again. In that case it would promote to timeline 3 and there's no conflict. What we are seeing here is split-brain and it is not good. Patroni should be tracking the timeline of the primary and refusing to promote another node that has not made it to that timeline yet. If it does then some mitigation may be needed to get things working again.

This seems to be at odds with the goal ensuring a single primary can be running in the event of a network partition though... 🤔

[CyberDem0n]

You are right, at the moment there is no protection from such scenario :(
Node A decides to promote because its absolute wal position is within maximum_lag_on_failover and it doesn't take into account that some other node managed to generate a new timeline.
It wouldn't be too hard to implement such check, DCS already has everything we need in the /history key.

However, there is one thing I would like you to check for me, did node B managed to archive the history file?

[bradnicholson]

However, there is one thing I would like you to check for me, did node B managed to archive the history file?

Yes, B archives the history file.

[CyberDem0n]

Ok, will prepare a PR for that tomorrow.

[CyberDem0n]

@bradnicholson it would be great if you check https://github.com/zalando/patroni/pull/892

[bradnicholson]

@CyberDem0n - I will. I probably won't have time until tomorrow though. Thanks.

[bradnicholson]

I presume that if the timelines are out of sync, and Patroni refuses to failover, the operator will still be able to force the failover just like if the member is lagging too much, right?

[ants]

I don't think #892 is a good solution. Here's what I think is going on.

1. Start : A is master on timeline 1, xlog position somewhere in segment 23, B is standby
2. A shuts down.
3. B promotes, this archives segment 00000001...23.partial and 00000002.history
4. B dies before archiving segment 00000002...23
5. Patroni on A starts up, starts postgres.
6. Postgres doesn't look for the partial segment, recovers until own shutdown record.
7. Patroni promotes A
8. A picks timeline 3, wants to archive end of last segment as 00000001...23.partial, which makes pgBackRest throw a fit because that file already exists in the archive.

This is not something I would call a split brain. This is distributed transactions 101. On failover transaction log position can go backwards. If users care about all transactions being durable they should use synchronous_mode, in which case we make sure to not go backwards further than the latest acknowledged commit. Note that the described situation can happen with no acknowledged transactions being lost.

Just throwing our hands up and letting the admin sort things out doesn't seem like a great design from a HA system. This is indeed not a normal situation to be in, but the whole point of HA system is to deal with abnormal situations without human interaction while retaining some guarantees. With async replication the guarantee the documentation hint at seems to be that we don't lose more than maximum_lag_on_failover + ttl seconds of commits.

I think a better approach would be for archiving to deal with the fact that multiple nodes might want to archive .partial files.

What makes it much more complex is that history files and WAL can replicate between nodes over streaming replication connections. For example:

1. Nodes A, B, C. A is master
2. A dies
3. B promotes, picks timeline 2
4. C connects to B receives timeline 2
5. B dies before archiver gets to archiving timeline history
6. C goes down for a bit
7. A comes back, promtoes itself, doesn't see timeline 2 in archive, so picks timeline 2 again.
8. C comes back wants to replicate from A, hopefully getting an error, but looking at postgres and patroni code for validating timeline histories it probably will not happen.

So a complete solution would require somehow creating consensus about timeline assignment.

[CyberDem0n]

Thank you @ants, you made absolutely valid points, #892 will help with only a limited amount of cases, but probably will make a bigger damage on self-recover capabilities :(

[sfrost]

In the specific case being discussed here, both nodes were ending up on timeline 2, which is clearly wrong even if B dies after being promoted. That also shows that this scenario isn't what's actually happening and therefore we need to consider this an independent case from that.

Has it been shown that A will actually try to archive the 1..23.partial file after following the .history and reaching timeline 3? If that's the case then maybe that should be changed in PG because, clearly, there was already a .partial file archived for timeline 1.

Regarding the other scenario- once B promotes and C starts following B, it absolutely should NOT be allowed to follow A again because the ON DISK DATA on C is now some mix of changes from A AND B, and therefore if it followed A it'd possibly end up corrupting the ON DISK data. At that point, A is dead and MUST be rebuilt. There is also the point that this scenario seems to contemplate all three nodes being down at the same time.

When it comes to timing of the changes being made in etcd vs. things reaching the WAL archive, I agree that there is some risk that a node goes down between updating etcd, getting promoted, and the WAL archive getting the history files. I can certainly see it making sense to contemplate that case and to consider how we might improve patroni to address that situation, but at least the specific case which was brought up and discussed here sounds like it's solved by the change being proposed here and if we pick a healthy node to promote and it immediately fails, then maybe something more serious is going on and we aren't able to automate this completely.

[ants]

Both nodes ending up on the same timeline implies to me that the history file was not archived. StartupXLOG() does ThisTimeLineID = findNewestTimeLine(recoveryTargetTLI) + 1; which will probe the archive for history files. If 2.history was in the archive A should have arrived at 3. It's possible that A was promoted between B archiving the partial segment and history file. It's quite a tight window to hit, so I discounted this option earlier.

The order of archival is not deterministic. Startup process writes history file, then notifies archiver, then writes the partial file. Archiver will archive files in alphabetical order, so if pgarch_readyXlog() finds both, it will archive partial first, but if it happens to run before the .partial is created the history files gets archived.

I didn't actually test any of this, it's completely based on looking at the source for REL_11_STABLE. But based on the source, there is nothing that would stop a second attempt at archiving a .partial file.

I disagree that just giving up on HA if a node fails too soon after promote is a good solution. It's basically just giving up on making this safe and instead putting the responsibility on the cluster operator, who may not be promptly available to make a decision and more often than not, does not understand nuances of timelines well enough to make an educated decision. Especially because we are talking about asynchronous clusters that can lose transactions on failover anyway. We have synchronous_mode if losing data is not an option.

One more thing that caught my eye while looking at this - I don't see anything that would enforce applying all available WAL from archive. We will not consider a node healthy until it is within maximum_lag_on_failover from last known master position, but after that it's a race between applying WAL and Patroni pulling the trigger on the promote. While technically this behavior is correct it sure would be nice to not throw away WAL because we couldn't be bothered to finish applying it.

[sfrost]

I agree that it's a very tight window, which is part of why I wonder if maybe we hit that window or if possibly the node A came up without reading anything from the archive.

Archiving .partial files multiple times is just fine. David is working on testing this scenario to see what actually happens if PG follows the archive (or presumably another system) and gets to timeline 3. I still believe that it would be wrong of PG, at that point, to archive a .partial file from a timeline other than the one it was being promoted from. That really doesn't make any sense.

I do feel that it's wrong for patroni to promote when there is WAL in the archive available for it to replay and I suspect that this might actually be the root of this whole issue- patroni is deciding that the node is "close enough" even though the promotion puts it on the same timeline that the other node is on and there already exists a .partial and a .history file in the archive.

Regarding at what point we decide that the DBA needs to get involved- there HAS to be a point. Patroni isn't going to function at all if enough things fail, so the only question is where do we draw that line. Typically the line is drawn, quite sensibly in my view, at 'single failure' cases- build a system which can survive one failure at a time. Once we've solved that, then maybe it's worthwhile to look at multiple simultaneous failure cases, but those grow very quickly and trying to plan for every possible combination of failures leads to a much more complex system that ends up not managing to deal with the single-failure case properly.

[sfrost]

David and I were chatting and testing things and we do see an opportunity for pgBackRest to be improved, so that valid situations (which do not involve a split-brain situation with two primaries archiving to the repository at the same time) will work cleanly.

Specifically, I want to make it very clear that the situation which Brad ran into did involve a split-brain case due to both systems being on the same timeline and therefore it will not be helped by the changes we're discussing for pgBackRest. We continue to feel that Patroni needs to monitor timelines and potentially the archive to avoid ending up in a situation where two independent systems are on the same timeline, as Brad saw.

Let me first describe what we consider to be a valid use-case, but where pgBackRest will still end up throwing archive-push errors.

Here we have two servers: Alice and Bob:

1. Alice starts as primary on timeline 1
2. Bob starts as replica, following Alice, also on timeline 1
3. Alice runs for a while and recycles WAL
4. Bob follows Alice and also recycles WAL
5. Bob ends up getting out of sync with Alice with regard to WAL recycling.
6. Alice shuts down cleanly, all WAL makes it to Bob and to the archive.
7. Bob is promoted and begins on timeline 2
8. Bob pushes to the archive the 01.partial, but it has garbage at the end
9. Bob pushes to the archive the .history file.
10. Bob crashes/terminates before any other WAL is pushed to the archive.
11. Alice is started up as a replica
12. Alice follows the archive and discovers the .history file
13. Alice is promoted
14. Alice moves to timeline 3 because of the .history file
15. Alice pushes to archive the 01.partial, with different ending garbage
16. pgBackRest complains that the 01.partial files don't match.
17. Subsequent attempts to archive by Alice fail due to this.

In this specific case, the two 01.partial files contain technically the same data but there is some garbage at the end which differs between the two. There's a lot of cases where this won't happen, but there are also many cases where it can.

We are currently contemplating two specific changes to pgBackRest to avoid having it error in this case.

The first is to always push the .history file to the archive first, thus making it clear that a timeline change has been made, and allowing us to detect and throw an error if there is ever a case where two systems attempt to promote themselves to the same timeline (which would indicate a split-brain case where at least one of them is not following the archive).

The second is to add to the end of the .partial file which is pushed the ID of the timeline which the promotion is going to.

In the example above, this would mean that the .partial file pushed by Alice would be recorded in the pgBackRest repo as '01.partial.02' (notionally). The .partial file pushed by Bob would be recorded in the pgBackRest repo as '01.partial.03' (notionally), thus avoiding a conflict in this case.

With these changes, the above case where Alice ends up on timeline 3 should work just fine and without any data loss (except possibly some transactions accepted by Bob and written to Bob's WAL but never archived).

Note that in this case, Bob would have to be rebuilt (using pgBackRest or pg_rewind) due to having on-disk differences from Alice because Bob accepted writes after being promoted and wasn't cleanly shut down (and therefore those writes weren't in the archive for Alice to follow).

Also note that if Alice is not cleanly shut down, but Bob was promoted, then Alice would have to be rebuilt because, similairly, Alice could have on-disk differences from Bob.

[jberkus]

At this point, we have split-brain from a Postgres perspective. Both have independently promoted themselves from Timeline 1 to Timeline 2 with no knowledge of each other.

Not quite. What we have is data loss, not split-brain. It's an important distinction.

Carry the situation out further. If you were to bring B back up, it would refuse to start because it cannot re-master from A (unless the timing is short enough that pg-rewind works). In any case, there is never more than one master running at the same time.

However, Patroni has always been designed to prioritize availability over consistency in a default configuration. It behaves that way because, at the moment that A comes back up and B is down, Patroni has no way to know that B is ever coming back; it might be physically gone.

If you want to move the availability-consistency slider, you can use a non-default configuration. There are two main ways to do this:

1. Set up and require synchronous replication between failover nodes.
2. Configure Patroni to never re-use storage, but always respawn new nodes from either replication or archival backup. This will slow down failover situations, but avoid the problem described at the beginning of the issue.

[sfrost]

Having two nodes independently promoted to another timeline is the very definition of a split-brain case.

Also, that's incorrect- B would (try to) start following A once A moved forward far enough in that new timeline to be past the point B was at.

The situation where A come back up and B is down and we don't know if B will ever come back is actually handled perfectly well- provided that A follows the archive and reads the .history files there because then A will switch to timeline 3 and skip over the timeline which B started on. If B never gets to the point of archiving the .history file or the .partial file, then there won't be any problem either since there won't be any conflict.

Given that, based on our understanding, the situation Brad saw was one in a controlled fail-over, this is even more important for Patroni to fix, since there also shouldn't be any data loss in that scenario (unless there also happens to be an independent failure at the same time).

[jberkus]

The situation described at the start of the issue is not a controlled failover. You may have information that's not in the issue, but I don't.

Anyway, Patroni provides you with the tools to always bootstrap from the archive. That's not the default configuration, but it's certainly possible, and I think that Zalando even supplies an example plugin that does just that. That sounds like what you want, so why not set it up that way?

[sfrost]

If pgbackrest allowed two independent nodes to archive the same .history file, how would we bootstrap from the archive?

[jberkus]

If pgBackrest allows that, how is it Patroni's bug?

[sfrost]

that's exactly the point, pgbackrest doesn't allow that. That's what started this whole issue.

[jberkus]

These all sound like issues with whatever pgbackrest plugin for Patroni you're using. Which isn't part of this repo.

[sfrost]

Any archiving tool which prevents overwriting materially different files (ones which have different checksums), as you suggest it would be a bug to not do about 6 minutes ago, would exhibit the same behavior.

The problem here is that Patroni is promoting a system, without it following through the archive completely, which causes it to try and push a file into the archive which already exists but has a different checksum.

[bradnicholson]

Here are logs from a production occurrence:

 m-1's promotion

 m-1| 2018-11-19 11:41:54.993252-05 | INFO: cleared rewind state after becoming the leader
 m-1| 2018-11-19 11:41:56.199046-05 | [26]: [11-1] user=,db=,client= LOG:  received promote request
 m-1| 2018-11-19 11:41:56.199065-05 | [26]: [12-1] user=,db=,client= LOG:  redo done at 6/F8000028
 m-1| 2018-11-19 11:41:56.19907-05  | [26]: [13-1] user=,db=,client= LOG:  last completed transaction was at log time 2018-11-19 16:36:30.998464+00
 m-1| 2018-11-19 11:41:58.704983-05 | [26]: [14-1] user=,db=,client= LOG:  selected new timeline ID: 16
 m-1| 2018-11-19 11:41:58.791189-05 | [26]: [15-1] user=,db=,client= LOG:  archive recovery complete
 m-1| 2018-11-19 11:41:59.351032-05 | [26]: [16-1] user=,db=,client= LOG:  restored log file "0000000F.history" from archive
 m-1| 2018-11-19 11:41:59.360803-05 | [52]: [10792-1] user=,db=,client= LOG:  checkpoint starting: force 
 m-1| 2018-11-19 11:41:59.367111-05 | [23]: [4-1] user=,db=,client= LOG:  database system is ready to accept connections
 m-1| 2018-11-19 11:42:10.052771-05 | INFO: no action.  i am the leader with the lock

m-1 shuts down

 m-1| 2018-11-19 11:42:18.567659-05 | [23]: [5-1] user=,db=,client= LOG:  received fast shutdown request
 m-1| 2018-11-19 11:42:18.569609-05 | [23]: [6-1] user=,db=,client= LOG:  aborting any active transactions
 m-1| 2018-11-19 11:42:18.569631-05 | [60]: [3-1] user=postgres,db=postgres,client=127.0.0.1 FATAL:  terminating connection due to administrator command
 m-1| 2018-11-19 11:42:18.569642-05 | [23]: [7-1] user=,db=,client= LOG:  worker process: logical replication launcher (PID 1119) exited with exit code 1
 m-1| 2018-11-19 11:42:18.571068-05 | [52]: [10794-1] user=,db=,client= LOG:  shutting down
 m-1| 2018-11-19 11:42:18.646233-05 | [52]: [10795-1] user=,db=,client= LOG:  checkpoint starting: shutdown immediate
 m-1| 2018-11-19 11:42:18.658327-05 | [52]: [10796-1] user=,db=,client= LOG:  checkpoint complete: wrote 0 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.000 s, sync=0.000 s, total=0.007 s; sync files=0, longest=0.000 s, average=0.000 s; distance=16383 kB, estimate=16383 kB  
 m-1| 2018-11-19 11:42:20.671321-05 | [23]: [8-1] user=,db=,client= LOG:  database system is shut down

m-0 starts up

 m-0| 2018-11-19 11:42:54.580161-05 | [24]: [1-1] user=,db=,client= LOG:  database system was shut down at 2018-11-19 16:41:50 UTC
 m-0| 2018-11-19 11:42:54.58725-05  | [25]: [2-1] user=postgres,db=postgres,client=127.0.0.1 FATAL:  the database system is starting up
m-0| 2018-11-19 11:42:55.209947-05 | [24]: [2-1] user=,db=,client= LOG:  restored log file "00000010.history" from archive
m-0| 2018-11-19 11:42:55.74255-05  | [24]: [3-1] user=,db=,client= LOG:  entering standby mode                                                                                                                                                                                                         

 m-0| 2018-11-19 11:42:56.355399-05 | [24]: [4-1] user=,db=,client= LOG:  restored log file "00000010.history" from archive                                                                                                                                                                             

 m-0| 2018-11-19 11:42:56.635627-05 | [50]: [2-1] user=postgres,db=postgres,client=127.0.0.1 FATAL:  the database system is starting up                                                                                                                                                                      

m-0| 2018-11-19 11:42:56.63654-05  | [51]: [2-1] user=postgres,db=postgres,client=127.0.0.1 FATAL:  the database system is starting up
m-0| 2018-11-19 11:42:59.37311-05  | [24]: [5-1] user=,db=,client= LOG:  restored log file "0000000F.history" from archive                                                                                                                                                                             
 m-0| 2018-11-19 11:42:59.377-05    | [24]: [6-1] user=,db=,client= LOG:  consistent recovery state reached at 6/F8000098                                                                                                                                                                               
m-0| 2018-11-19 11:42:59.377024-05 | [24]: [7-1] user=,db=,client= LOG:  invalid record length at 6/F8000098: wanted 24, got 0                                                                                                                                                                         
m-0| 2018-11-19 11:42:59.37703-05  | [22]: [3-1] user=,db=,client= LOG:  database system is ready to accept read only connections
m-0| 2018-11-19 11:42:59.78349-05  | INFO: promoted self to leader by acquiring session lock
m-0| 2018-11-19 11:43:03.099693-05 | [24]: [8-1] user=,db=,client= LOG:  received promote request                                                                                                                                                                                                      
 m-0| 2018-11-19 11:43:03.099712-05 | [24]: [9-1] user=,db=,client= LOG:  redo is not required
 m-0| 2018-11-19 11:43:04.828468-05 | INFO: promoted self to leader because i had the session lock
 m-0| 2018-11-19 11:43:07.704235-05 | [24]: [10-1] user=,db=,client= LOG:  selected new timeline ID: 17                                                                                                                                                                                                 
 m-0| 2018-11-19 11:43:07.798287-05 | [24]: [11-1] user=,db=,client= LOG:  archive recovery complete                                                                                                                                                                                                    
 m-0| 2018-11-19 11:43:08.370475-05 | [24]: [12-1] user=,db=,client= LOG:  restored log file "00000010.history" from archive
 m-0| 2018-11-19 11:43:08.383426-05 | [66]: [1-1] user=,db=,client= LOG:  checkpoint starting: force                                                                                                                                                                                                    
 m-0| 2018-11-19 11:43:08.385212-05 | [22]: [4-1] user=,db=,client= LOG:  database system is ready to accept connections
m-0| 2018-11-19 11:43:10.393302-05 | [148]: [2-1] user=,db=,client= DETAIL:  The failed archive command was: /usr/bin/pgbackrest ... archive-push pg_wal/0000000F00000006000000F8.partial >> /dev/null 
 m-0| 2018-11-19 11:43:11.499416-05 | [148]: [3-1] user=,db=,client= LOG:  archive command failed with exit code 45

[sfrost]

Thanks for sharing those logs! As discussed on Slack, that looks like the case which David and I outlined above, where there's two different promotions, to two different timelines, but the same .partial WAL ends up getting archived.

This is the case where the changes we discussed making to pgbackrest should address that case, and we may also push to have changes made to PG to have it choose a better name for the .partial file, to avoid conflicts that way too.

[jberkus]

@sfrost has S3 latency been eliminated as part of the problem?

[dwsteele]

@jberkus I'd say latency is almost certainly part of the problem. I've submitted a patch to archive history files before .partial files to try and reduce the latency but there's no way to know if that will be back-patched.

[dwsteele]

The patch to archive .history files first has been committed and back-patched to 9.5: https://postgr.es/m/[email protected]. This should significantly reduce the window where a promotion might choose a duplicate timeline.