Deconstructing an Abstraction to Reconstruct an Outage (QCon London 2023 edition)

Abstractions are what allow us to build the complex applications that we all use day-to-day. For example, it's rare for us to care about the precise details of on-disk storage when building an application — that's why databases exist!

Debugging is different though. It forces us to break through those abstractions in order to understand what the computer is really doing.

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. Postgres Postgres Postgres Repl VIP Pacemaker Pacemaker Pacemaker API backend
29. Postgres Postgres Postgres Repl VIP Pacemaker Pacemaker Pacemaker Repl API backend
30. Note: One replica 
 always synchronous
31. So...
32. So... Unfortunately...
33. Postgres Postgres Postgres Repl Repl Pacemaker Pacemaker Pacemaker VIP API backend
34. Postgres Postgres Postgres Repl Repl Pacemaker Pacemaker Pacemaker VIP API backend
35. Postgres Postgres Postgres Repl Repl Pacemaker Pacemaker Pacemaker VIP API backend
36. Except it didn't
37. Our API was down
38. Fallback: fully manual setup
39. Postgres Postgres Postgres Pacemaker Pacemaker Pacemaker VIP API backend 👩💻
40. Postgres Postgres Postgres Pacemaker Pacemaker Pacemaker VIP API backend 👩💻
41. Postgres Postgres Postgres Pacemaker Pacemaker Pacemaker VIP API backend 👩💻 Repl
42. Postgres Postgres Postgres Pacemaker Pacemaker Pacemaker 👩💻 Repl API backend
43. Postgres Postgres Postgres Pacemaker Pacemaker Pacemaker 👩💻 Repl API backend Repl
44. https://gocardless.com/blog/incident-review-api-and-dashboard-outage-on-10th- october/
45. We're safe, for now...
46. But only one failure away from downtime
47. Mission: Recreate the outage
48. There's a lot We'll go step-by-step
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. 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
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. 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
55. 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
56. 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
57. 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
58. Everyone's favourite fault- injection tool
59. You know it well...
60. 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:
62. # on primary - hard kill kill -SIGKILL <main_pid> # on synchronous replica - subprocess crash kill -SIGABRT <subprocess_pid>
63. # on primary - hard kill kill -SIGKILL <main_pid> # on synchronous replica - subprocess crash kill -SIGABRT <subprocess_pid>
64. We kept our expectations low...
65. ...which was the right choice
66. 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
67. 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
68. 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
69. What do we mean by "log"?
70. [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
71. A different kind of log: binary logs
72. INSERT INTO users VALUES ('codd'); INSERT INTO users VALUES ('lovelace'); INSERT INTO users VALUES ('turing'); Some extremely boring SQL
75. Warning: simplifying lie ahead
76. 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)
77. Postgres calls these "Write Ahead Logs" (WALs)
78. But why bother doing that?
79. Crash safety
80. Index Table id username 1 codd 2 lovelace id 1 2
81. Index Table id username 1 codd 2 lovelace 3 turing id 1 2
82. Index Table id 1 2 💥 . id username 1 codd 2 lovelace 3 turing
83. Index Table id 1 2 ??? id username 1 codd 2 lovelace 3 turing
84. 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'
85. Index Table id 1 2 ??? id username 1 codd 2 lovelace 3 turing
86. Index Table id 1 2 3 id username 1 codd 2 lovelace 3 turing
87. Also: replication
88. Postgres Postgres Postgres Repl Repl API backend
89. Postgres Postgres Postgres Repl Repl API backend WALs
90. 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
91. 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
92. 2ways to replicate
93. Streaming replication & WAL archival
94. Postgres Postgres Postgres Repl Repl Streaming replication
95. WAL archival
96. Primary WAL archival
97. Primary WAL archival archive_command
98. Primary WAL archival Replica archive_command restore_command
99. Why use both?
100. Reduce in-cluster storage & Reduce bootstrap load
101. Suspicious log on synchronous replica 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
102. Issue restoring WAL ‑ Cause of failure to promote replica?
103. We already had those writes!
104. Just because something shouldn't happen doesn't mean it didn't happen
105. 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
106. I had zero experience working with binary formats
107. None of it is magic
108. We can cheat: Postgres is open source
109. But!
110. These techniques also work on closed source software
111. We just call that reverse engineering
112. $ 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
113. 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
114. 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
115. 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
116. src/include/access/xlog.h:58: #define SizeOfXLogRecord MAXALIGN(sizeof(XLogRecord)) Let's fi nd the error
117. Wouldn't it be convenient if we could make total_len == 0?
118. 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
119. src/include/access/xlog.h:41: 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
120. 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
122. 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?
123. 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; }
124. 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)
125. Let's see what they look like in practice
126. INSERT INTO users VALUES ('codd'); INSERT INTO users VALUES ('lovelace'); INSERT INTO users VALUES ('turing'); Some extremely boring SQL
127. Grab the binary log fi le, and...
128. A barely comprehensible 
 wall of data 😅
129. A barely comprehensible 
 wall of data 😅 Hex ASCII
130. Same data, rendered differently Decimal Hexadecimal Character 62 3E > 63 3F ? 64 40 @ 65 41 A 66 42 B
131. Decimal Hexadecimal Character 62 3E > 63 3F ? 64 40 @ 65 41 A 66 42 B Same data, rendered differently
132. Hex ASCII Some good news
133. Some good news We can see our users!!
134. How can we fi nd xl_tot_len?
135. 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
136. Look for a fi eld increasing 
 by 1
137. Guesswork incoming!
138. Guesswork incoming! The data we inserted
139. A little help: ASCII codes Decimal Hexadecimal Character 62 3E > 63 3F ? 64 40 @ 65 41 A 66 42 B
140. Notice anything? The data we inserted
141. Notice anything? The data we inserted Familiar characters
142. Notice anything? Decimal Hexadecimal Character 63 3F ? 64 40 @ 65 41 A The data we inserted Familiar characters
143. Notice anything? The data we inserted Familiar characters
144. Notice anything? The data we inserted Familiar characters
145. Notice anything? The data we inserted Familiar characters Familiar characters (hex) The data we inserted (hex)
146. Wouldn't it be convenient if we could make total_len == 0?
147. We could import the Postgres structs and do this properly...
148. ...or we could write a regex 🤔
149. Let's write a regex
151. Let's break this one
152. 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
153. 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
154. Let's break this one
155. Broken!!
156. And if we give it to a Postgres 
 replica?
157. 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!
158. Success 😄
159. Success, with a caveat...😔
160. This wasn't enough to reproduce the outage
161. 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
162. 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. ...
163. Postgres Postgres Postgres Repl Repl Pacemaker Pacemaker Pacemaker VIP API backend
164. Postgres Postgres Postgres Repl Repl Pacemaker Pacemaker Pacemaker VIP API backend Backup VIP
165. 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
166. We added it to the cluster
167. Ran the repro script
168. and...
169. Success (no caveats) 😄
170. Abstraction: deconstructed Outage: recreated
171. but... why?
172. Background: how Pacemaker schedules resources
173. 2relevant settings
174. By default: reschedule without penalty
175. Postgres Postgres Postgres Repl Repl Pacemaker Pacemaker Pacemaker VIP API backend
176. Postgres Postgres Postgres Repl VIP Pacemaker Pacemaker Pacemaker Repl API backend
177. Setting: default-resource-stickiness
178. By default: resources can run anywhere
179. Setting: colocation
180. default-resource-stickiness = 100 & colocation -inf: BackupVIP Primary
181. default-resource-stickiness = 100 & colocation -inf: BackupVIP Primary
182. default-resource-stickiness = 100 & colocation -inf: BackupVIP Primary
183. A very subtle semantic difference
184. -1000 -inf
185. -1000 -inf "Avoid scheduling these together"
186. -1000 -inf "Avoid scheduling these together" "Literally never schedule these together"
187. default-resource-stickiness = 100 & colocation -inf: BackupVIP Primary
188. default-resource-stickiness = 100 & colocation -1000: BackupVIP Primary
189. Failover works properly
190. P.S. The WAL error was a red herring
191. Sorry
192. I know it was the most interesting part
193. and it would have been kinda cool
194. but it was part of the debugging process
195. 💖
196. 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
197. What can we learn?
198. None of the stack is magic
199. None of the stack is magic 😁
200. None of the stack is magic 😁 😰
201. "It's just someone else's computer"
202. "It's just someone else's abstraction"
203. Read other people's code...
204. ...and try to modify it
205. Automation erodes knowledge
206. Game days are a partial fi x
207. "What if we had to recover our database server manually?"
208. Don't stop questioning your repro
209. 1. No magic in the stack 2. Automation erodes knowledge 3. Always question the repro
211. JSON over HTTP
212. Binary formats are coming to web development
213. Protobuf over HTTP/2
214. Protobuf over HTTP/2 (e.g. gRPC)
215. There is tooling help
216. https://buf.build/blog/buf-curl/
217. https://github.com/wader/fq
218. Hex: the lowest common denominator
219. It's worth getting familiar
220. One last thing to ask of you
221. Most computing happens successfully
222. The 0.00001% * not a real statistic
223. Outsized negative impact
224. It's a shame not to learn
225. "We noticed a problem." "We fi xed the problem." "We'll make sure the problem doesn't happen again."
226. 3good examples
227. https://slack.engineering/slacks-outage-on-january-4th-2021/
228. https://incident.io/blog/intermittent-downtime
229. https://about.gitlab.com/blog/2017/02/10/postmortem-of-database-outage-of- january-31/
230. Please Share the dif fi cult stories too
231. Thank you ✌❤ @planetscaledata sinjo.dev
233. 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/
234. 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
235. Questions? ✌❤ @planetscaledata sinjo.dev