Deconstructing an Abstraction to Reconstruct an Outage (SREcon EMEA 2023 edition)

We all rely on abstractions to build the applications we use day-to-day. It's easy for those abstractions to feel like impenetrable walls, hiding scary low-level parts of the system - especially for a complex piece of software like a database. That needn't be the case!

In this talk, we'll explore the aftermath of a complex outage in a Postgres cluster. We'll retrace the steps we took to reliably reproduce the failure in a local environment and pull out lessons about debugging complex systems along the way. At one point, we'll dive into the depths of how Postgres represents data on disk and realise that even unfamiliar layers of a system don't need to be scary.

Transcript

1. Deconstructing an Abstraction to Reconstruct an Outage sinjo.dev
2. A familiar story 📚
7. 2xx 5xx Percentage Time API response status
8. DB::ConnectionFailure - could 
 not connect to server: 
 Connection refused 💥
10. Hi
11. sinjo.dev
12. sinjo.dev
13. Infra Engineer
14. Databases & Distributed Systems 😍
17. Deconstructing an Abstraction to Reconstruct an Outage sinjo.dev
18. First: Our cluster setup
19. Postgres API backend
20. Postgres Postgres Postgres Repl Repl API backend
21. Postgres Postgres Postgres Repl Repl Pacemaker Pacemaker Pacemaker API backend
22. Postgres Postgres Postgres Repl Repl Pacemaker Pacemaker Pacemaker VIP API backend
23. Postgres Postgres Postgres Repl Repl Pacemaker Pacemaker Pacemaker VIP API backend
24. Postgres Postgres Postgres Repl Repl Pacemaker Pacemaker Pacemaker VIP API backend
25. Postgres Postgres Postgres Repl Pacemaker Pacemaker Pacemaker API backend VIP
26. Postgres Postgres Postgres Repl VIP Pacemaker Pacemaker Pacemaker API backend
27. Postgres Postgres Postgres Repl VIP Pacemaker Pacemaker Pacemaker API backend
28. Note: One replica 
 always synchronous
29. So...
30. So... Unfortunately...
31. Postgres Postgres Postgres Repl Repl Pacemaker Pacemaker Pacemaker VIP API backend
32. Postgres Postgres Postgres Repl Repl Pacemaker Pacemaker Pacemaker VIP API backend
33. Postgres Postgres Postgres Repl Repl Pacemaker Pacemaker Pacemaker VIP API backend
34. Except it didn't
35. Our API was down
36. Fallback: fully manual setup
37. Postgres Postgres Postgres Pacemaker Pacemaker Pacemaker VIP API backend 👩💻
38. Postgres Postgres Postgres Pacemaker Pacemaker Pacemaker VIP API backend 👩💻
39. Postgres Postgres Postgres Pacemaker Pacemaker Pacemaker VIP API backend 👩💻 Repl
40. Postgres Postgres Postgres Pacemaker Pacemaker Pacemaker 👩💻 Repl API backend
41. Postgres Postgres Postgres Pacemaker Pacemaker Pacemaker 👩💻 Repl API backend Repl
42. We're safe, for now...
43. But only one failure away from downtime
44. Mission: Recreate the outage
45. There's a lot We'll go step-by-step
46. 1. RAID array loses disks 2. Kernel sets fi lesystem read-only 3. Pacemaker detects primary failure 4. Synchronous replica crash 5. Suspicious log on synchronous replica
47. 1. RAID array loses disks 2. Kernel sets fi lesystem read-only 3. Pacemaker detects primary failure 4. Synchronous replica crash 5. Suspicious log on synchronous replica
48. 1. RAID array loses disks 2. Kernel sets fi lesystem read-only 3. Pacemaker detects primary failure 4. Synchronous replica crash 5. Suspicious log on synchronous replica
49. 1. RAID array loses disks 2. Kernel sets fi lesystem read-only 3. Pacemaker detects primary failure 4. Synchronous replica crash 5. Suspicious log on synchronous replica
50. 1. RAID array loses disks 2. Kernel sets fi lesystem read-only 3. Pacemaker detects primary failure 4. Synchronous replica crash 5. Suspicious log on synchronous replica
51. 2023-02-24 17:23:01 GMT LOG: restored log file "000000020000000000000003" from archive 2023-02-24 17:23:02 GMT LOG: invalid record length at 0/3000180 Suspicious log on synchronous replica
52. 1. RAID array loses disks 2. Kernel sets fi lesystem read-only 3. Pacemaker detects primary failure 4. Synchronous replica crash 5. Suspicious log on synchronous replica
53. 1. RAID array loses disks 2. Kernel sets fi lesystem read-only 3. Pacemaker detects primary failure 4. Synchronous replica crash 5. Suspicious log on synchronous replica
54. 1. RAID array loses disks 2. Kernel sets fi lesystem read-only 3. Pacemaker detects primary failure 4. Synchronous replica crash 5. Suspicious log on synchronous replica
55. Everyone's favourite fault- injection tool
56. You know it well...
57. KILL(1) General Commands Manual KILL(1) NAME kill – terminate or signal a process SYNOPSIS kill [-s signal_name] pid ... kill -l [exit_status] kill -signal_name pid ... kill -signal_number pid ... DESCRIPTION The kill utility sends a signal to the processes specified by the pid operands. Only the super-user may send signals to other users' processes. The options are as follows:
59. # on primary - hard kill kill -SIGKILL <main_pid> # on synchronous replica - subprocess crash kill -SIGABRT <subprocess_pid>
60. # on primary - hard kill kill -SIGKILL <main_pid> # on synchronous replica - subprocess crash kill -SIGABRT <subprocess_pid>
61. We kept our expectations low...
62. ...which was the right choice
63. 1. RAID array loses disks 2. Kernel sets fi lesystem read-only 3. Pacemaker detects primary failure 4. Synchronous replica crash 5. Suspicious log on synchronous replica
64. 1. RAID array loses disks 2. Kernel sets fi lesystem read-only 3. Pacemaker detects primary failure 4. Synchronous replica crash 5. Suspicious log on synchronous replica
65. 2023-02-24 17:23:01 GMT LOG: restored log file "000000020000000000000003" from archive 2023-02-24 17:23:02 GMT LOG: invalid record length at 0/3000180 Suspicious log on synchronous replica
66. What do we mean by "log"?
67. [2023-02-26 23:02:37Z] GET / - 200 [2023-02-26 23:02:49Z] GET /favicon.ico - 200 [2023-02-26 23:02:52Z] POST /login - 200 [2023-02-26 23:33:52Z] POST /posts - 201 [2023-02-26 23:33:57Z] GET /posts/binary-logs—talk - 200 What we normally mean by logs
68. A different kind of log: binary logs
69. INSERT INTO users VALUES ('codd'); INSERT INTO users VALUES ('lovelace'); INSERT INTO users VALUES ('turing'); Some extremely boring SQL
72. Warning: simplifying lie ahead
73. INSERT INTO users VALUES ('codd'); INSERT INTO users VALUES ('lovelace'); INSERT INTO users VALUES ('turing'); ‑ Wrote 'codd' into table 'users' Wrote 'lovelace' into table 'users' Wrote 'turing' into table 'users' A different kind of logs 
 (if they were textual)
74. Postgres calls these "Write Ahead Logs" (WALs)
75. But why bother doing that?
76. Crash safety
77. Index Table id username 1 codd 2 lovelace id 1 2
78. Index Table id username 1 codd 2 lovelace 3 turing id 1 2
79. Index Table id 1 2 💥 . id username 1 codd 2 lovelace 3 turing
80. Index Table id 1 2 ??? id username 1 codd 2 lovelace 3 turing
81. We can replay this operation INSERT INTO users VALUES ('codd'); INSERT INTO users VALUES ('lovelace'); INSERT INTO users VALUES ('turing'); ‑ Wrote 'codd' into table 'users' Wrote 'lovelace' into table 'users' Wrote 'turing' into table 'users'
82. Index Table id 1 2 ??? id username 1 codd 2 lovelace 3 turing
83. Index Table id 1 2 3 id username 1 codd 2 lovelace 3 turing
84. Also: replication
85. Postgres Postgres Postgres Repl Repl API backend
86. Postgres Postgres Postgres Repl Repl API backend WALs
87. 2023-02-24 17:23:01 GMT LOG: restored log file "000000020000000000000003" from archive 2023-02-24 17:23:02 GMT LOG: invalid record length at 0/3000180 Suspicious log on synchronous replica
88. Primary WAL archival Replica archive_command restore_command
89. Issue restoring WAL ‑ Cause of failure to promote replica?
90. We already had those writes!
91. Just because something shouldn't happen doesn't mean it didn't happen
92. 2023-02-24 17:23:01 GMT LOG: restored log file "000000020000000000000003" from archive 2023-02-24 17:23:02 GMT LOG: invalid record length at 0/3000180 Suspicious log on synchronous replica
93. I had zero experience working with binary formats
94. None of it is magic
95. We can cheat: Postgres is open source
96. But!
97. These techniques also work on closed source software
98. We just call that reverse engineering
99. $ git checkout REL9_4_26 # we were running 9.4 $ git grep -n "invalid record length" src/backend/access/transam/xlogreader.c:295: [...] src/backend/access/transam/xlogreader.c:604: [...] src/backend/access/transam/xlogreader.c:678: [...] Let's fi nd the error
100. src/backend/access/transam/xlogreader.c:291-300: { /* XXX: more validation should be done here */ if (total_len < SizeOfXLogRecord) { report_invalid_record(state, "invalid record length at %X/%X", (uint32) (RecPtr >> 32), (uint32) RecPtr); goto err; } gotheader = false; } Let's fi nd the error
101. src/backend/access/transam/xlogreader.c:291-300: { /* XXX: more validation should be done here */ if (total_len < SizeOfXLogRecord) { report_invalid_record(state, "invalid record length at %X/%X", (uint32) (RecPtr >> 32), (uint32) RecPtr); goto err; } gotheader = false; } Let's fi nd the error
102. src/backend/access/transam/xlogreader.c:291-300: { /* XXX: more validation should be done here */ if (total_len < SizeOfXLogRecord) { report_invalid_record(state, "invalid record length at %X/%X", (uint32) (RecPtr >> 32), (uint32) RecPtr); goto err; } gotheader = false; } Let's fi nd the error
103. src/include/access/xlog.h:58: #define SizeOfXLogRecord MAXALIGN(sizeof(XLogRecord)) Let's fi nd the error
104. Wouldn't it be convenient if we could make total_len == 0?
105. src/backend/access/transam/xlogreader.c:272-273: record = (XLogRecord *) (state->readBuf + RecPtr % XLOG_BLCKSZ); total_len = record->xl_tot_len; Let's fi nd the error
106. src/include/access/xlog.h:41-56: typedef struct XLogRecord { uint32 xl_tot_len; /* total len of entire record */ TransactionId xl_xid; /* xact id */ uint32 xl_len; /* total len of rmgr data */ uint8 xl_info; /* flag bits, see below */ RmgrId xl_rmid; /* resource manager for this record */ /* 2 bytes of padding here, initialize to zero */ XLogRecPtr xl_prev; /* ptr to previous record in log */ pg_crc32 xl_crc; /* CRC for this record */ /* If MAXALIGN==8, there are 4 wasted bytes here */ /* ACTUAL LOG DATA FOLLOWS AT END OF STRUCT */ } XLogRecord; Let's fi nd the error
107. src/include/access/xlog.h:41-56: typedef struct XLogRecord { uint32 xl_tot_len; /* total len of entire record */ TransactionId xl_xid; /* xact id */ uint32 xl_len; /* total len of rmgr data */ uint8 xl_info; /* flag bits, see below */ RmgrId xl_rmid; /* resource manager for this record */ /* 2 bytes of padding here, initialize to zero */ XLogRecPtr xl_prev; /* ptr to previous record in log */ pg_crc32 xl_crc; /* CRC for this record */ /* If MAXALIGN==8, there are 4 wasted bytes here */ /* ACTUAL LOG DATA FOLLOWS AT END OF STRUCT */ } XLogRecord; Let's fi nd the error
109. src/backend/access/transam/xlogreader.c:291-300: { /* XXX: more validation should be done here */ if (total_len < SizeOfXLogRecord) { report_invalid_record(state, "invalid record length at %X/%X", (uint32) (RecPtr >> 32), (uint32) RecPtr); goto err; } gotheader = false; } What was that check doing?
110. What was that check doing? Size the record says it is Smallest possible size it can be src/backend/access/transam/xlogreader.c:291-300: { /* XXX: more validation should be done here */ if (total_len < SizeOfXLogRecord) { report_invalid_record(state, "invalid record length at %X/%X", (uint32) (RecPtr >> 32), (uint32) RecPtr); goto err; } gotheader = false; }
111. INSERT INTO users VALUES ('codd'); INSERT INTO users VALUES ('lovelace'); INSERT INTO users VALUES ('turing'); ‑ Wrote 'codd' into table 'users' Wrote 'lovelace' into table 'users' Wrote 'turing' into table 'users' A different kind of logs 
 (if they were textual)
112. Let's see what they look like in practice
113. INSERT INTO users VALUES ('codd'); INSERT INTO users VALUES ('lovelace'); INSERT INTO users VALUES ('turing'); Some extremely boring SQL
114. Grab the binary log fi le, and...
115. A barely comprehensible 
 wall of data 😅
116. A barely comprehensible 
 wall of data 😅 Hex ASCII
117. Same data, rendered differently Decimal Hexadecimal Character 62 3E > 63 3F ? 64 40 @ 65 41 A 66 42 B
118. Decimal Hexadecimal Character 62 3E > 63 3F ? 64 40 @ 65 41 A 66 42 B Same data, rendered differently
119. Hex ASCII Some good news
120. Some good news We can see our users!!
121. How can we fi nd xl_tot_len?
122. INSERT INTO repro VALUES ('A'); INSERT INTO repro VALUES ('AB'); INSERT INTO repro VALUES ('ABC'); INSERT INTO repro VALUES ('ABCD'); INSERT INTO repro VALUES ('ABCDE'); ... Some even more boring SQL
123. Look for a fi eld increasing 
 by 1
124. Guesswork incoming!
125. Guesswork incoming! The data we inserted
126. A little help: ASCII codes Decimal Hexadecimal Character 62 3E > 63 3F ? 64 40 @ 65 41 A 66 42 B
127. Notice anything? The data we inserted
128. Notice anything? The data we inserted Familiar characters
129. Notice anything? Decimal Hexadecimal Character 63 3F ? 64 40 @ 65 41 A The data we inserted Familiar characters
130. Notice anything? The data we inserted Familiar characters
131. Notice anything? The data we inserted Familiar characters
132. Notice anything? The data we inserted Familiar characters Familiar characters (hex) The data we inserted (hex)
133. Wouldn't it be convenient if we could make total_len == 0?
134. We could import the Postgres structs and do this properly...
135. ...or we could write a regex 🤔
136. Let's write a regex
138. Let's break this one
139. wal_file_name = ARGV[0] puts wal_file_name wal_contents = IO.read(wal_file_name, encoding: "BINARY") hex = wal_contents.unpack("H*").first replaced = hex.gsub(/3f(000000.+41424300)/, "00\\1") bindata = [replaced].pack("H*") File.write(wal_file_name + ".broken", bindata) break_wal.rb
140. wal_file_name = ARGV[0] puts wal_file_name wal_contents = IO.read(wal_file_name, encoding: "BINARY") hex = wal_contents.unpack("H*").first replaced = hex.gsub(/3f(000000.+41424300)/, "00\\1") # Replaces 'ABC' size bindata = [replaced].pack("H*") File.write(wal_file_name + ".broken", bindata) break_wal.rb
141. Let's break this one
142. Broken!!
143. And if we give it to a Postgres 
 replica?
144. 2023-02-28 19:24:11 GMT LOG: restored log file "000000020000000000000003" from archive 2023-02-28 19:24:11 GMT LOG: invalid record length at 0/3000148 We reproduced the error!
145. Success 😄
146. Success, with a caveat...😔
147. This wasn't enough to reproduce the outage
148. 1. RAID array loses disks 2. Kernel sets fi lesystem read-only 3. Pacemaker detects primary failure 4. Synchronous replica crash 5. Suspicious log on synchronous replica
149. 1. RAID array loses disks 2. Kernel sets fi lesystem read-only 3. Pacemaker detects primary failure 4. Synchronous replica crash 5. Suspicious log on synchronous replica 6. ...
150. Postgres Postgres Postgres Repl Repl Pacemaker Pacemaker Pacemaker VIP API backend
151. Postgres Postgres Postgres Repl Repl Pacemaker Pacemaker Pacemaker VIP API backend Backup VIP
152. 1. RAID array loses disks 2. Kernel sets fi lesystem read-only 3. Pacemaker detects primary failure 4. Synchronous replica crash 5. Suspicious log on synchronous replica 6. Backup VIP on synchronous replica
153. We added it to the cluster
154. Ran the repro script
155. and...
156. Success (no caveats) 😄
157. but... why?
158. Background: how Pacemaker schedules resources
159. 2relevant settings
160. By default: reschedule without penalty
161. Postgres Postgres Postgres Repl Repl Pacemaker Pacemaker Pacemaker VIP API backend
162. Postgres Postgres Postgres Repl VIP Pacemaker Pacemaker Pacemaker Repl API backend
163. Setting: default-resource-stickiness
164. By default: resources can run anywhere
165. Setting: colocation
166. default-resource-stickiness = 100 & colocation -inf: BackupVIP Primary
167. default-resource-stickiness = 100 & colocation -inf: BackupVIP Primary
168. default-resource-stickiness = 100 & colocation -inf: BackupVIP Primary
169. A very subtle semantic difference
170. -1000 -inf
171. -1000 -inf "Avoid scheduling these together"
172. -1000 -inf "Avoid scheduling these together" "Literally never schedule these together"
173. default-resource-stickiness = 100 & colocation -inf: BackupVIP Primary
174. default-resource-stickiness = 100 & colocation -1000: BackupVIP Primary
175. Failover works properly
176. P.S. The WAL error was a red herring
177. Sorry
178. I know it was the most interesting part
179. and it would have been kinda cool
180. but it was part of the debugging process
181. 💖
182. 1. RAID array loses disks 2. Kernel sets fi lesystem read-only 3. Pacemaker detects primary failure 4. Synchronous replica crash 5. Suspicious log on synchronous replica 6. Backup VIP on synchronous replica
183. What can we learn?
184. None of the stack is magic
185. None of the stack is magic 😁
186. None of the stack is magic 😁 😰
187. "It's just someone else's computer"
188. "It's just someone else's abstraction"
189. Read other people's code...
190. ...and try to modify it
191. Automation erodes knowledge
192. Game days are a partial fi x
193. "What if we had to recover our database server manually?"
194. Don't stop questioning your repro
195. 1. No magic in the stack 2. Automation erodes knowledge 3. Always question the repro
197. JSON over HTTP
198. Binary formats are coming to web development
199. Protobuf over HTTP/2
200. Protobuf over HTTP/2 (e.g. gRPC)
201. It's worth getting familiar
202. One last thing to ask of you
203. Most computing happens successfully
204. The 0.00001% * not a real statistic
205. Outsized negative impact
206. It's a shame not to learn
207. "We noticed a problem." "We fi xed the problem." "We'll make sure the problem doesn't happen again."
208. 3good examples
209. https://slack.engineering/slacks-outage-on-january-4th-2021/
210. https://incident.io/blog/intermittent-downtime
211. https://about.gitlab.com/blog/2017/02/10/postmortem-of-database-outage-of- january-31/
212. Please Share the dif fi cult stories too
213. Thank you ✌❤ @planetscaledata sinjo.dev
215. Image credits • Programmer's Laptop - Wall Boat - Public Domain - https://www. fl ickr.com/photos/ wallboat/36819065315/ • Pouring Latte Art - Craft Coffee Spot - CC-BY - https://www. fl ickr.com/photos/ 195403219@N08/52200966448/ • microscope - Milosz1 - CC-BY - https://www. fl ickr.com/photos/mikolski/3269906279 • Hard Disk Guts - CC-BY - https://www. fl ickr.com/photos/mattandkim/97533589/ • Corsair ForceGT 180GB - CC-BY - https://www. fl ickr.com/photos/ruocaled/8173124575/
216. Image credits • Server - The Noun Project (via WikiMedia) - CC0 - https://commons.wikimedia.org/wiki/ File:Server_-_The_Noun_Project.svg • Rope - Robo Android - CC-BY - https://www. fl ickr.com/photos/ 49140926@N07/6798304070/ • Stargazing - Max Delaquis - CC-BY - https://www. fl ickr.com/photos/ 115000114@N07/28861043652
217. Questions? ✌❤ @planetscaledata sinjo.dev