Disclaimer: Bài này dùng não, không dùng AI :shame:, tưởng ngắn mà dài vl

Sau một tuần sử dụng AI hư cmn não, đã định bụng là hôm nay TGIF chắc cũng vậy :byebye: lướt http://lobste.rs đọc được bài How we tracked down a 16-year-old SQLite bug và thật tình cờ trong vài tuần gần đây có đọc qua một số chủ đề liên quan đến SQLite. Vì là user của Tailscale, khá có thiện cảm với team Tailscale, nên lượt đọc đầu tiên đã thấy bài này viết rất ổn. Sau đó share lên một kênh và chợt nhận ra mọi người có thể sẽ chưa thấy được cái hay của bài như thế nào. Nên quyết định dùng nốt mớ nơ-ron não còn sót lại đọc cho đàng hoàng và ra được cái tóm tắt cho các fen lười đọc. Mớ tóm tắt này dùng não mất cmn buổi sáng và thêm hơn một tiếng buổi chiều mới xong :shame:

Điểm thú vị của bài này là hóa ra, worldclass engineer cũng có lúc không giải quyết được vấn đề và phải workaround hoặc phải tìm cách chống chế cho tới khi tìm ra được giải pháp cuối cùng. Nội dung tóm tắt như sau:

  • Bug này xuất hiện vào cuối năm ngoái, cỡ đâu đó T8, tới tận bây giờ sau khi đã cẩn thận điều tra, fix bug, họ mới share. Như họ chia sẻ, phải mất rất nhiều tháng điều tra, căng thẳng vl.
  • Về mặt sản phẩm, SQLite đc dùng để lưu info về tailnets cho mỗi shard, nó lưu config và metadata thoai, và có một Go process để giao tiếp với file này -> bug này gây ra corrupt data, nghe thì rén, nhưng trên use-case thì đâu đó vẫn chấp nhận đc, làm missing config/device đã đc add nếu data bị corrupt.
  • Bài này link tới một bài cũ, nói về việc họ dùng DB gì từ 2022, ban đầu từ json file as a DB, etcd, rồi nghĩ về vài CSDL khác và cuối cùng là SQLite, boring tech, well-known, reliable, and widely used. (mấy fen đọc thêm cũng thú vị tại sao ko dùng etcd tiếp =))))
  • Backup pipeline là take a snapshot mỗi vài phút, upload lên S3. Chạy từ 2023 tới giờ không lỗi. Tới tháng 08 năm ngoái khi một data pipeline đọc S3 backup và phát hiện error, chạy command PRAGMA integrity_check thì phát hiện corrupt -> mention là corrupt trong SQLite ko lạ, có thể xảy ra nhưng RẤT HIẾM và ko nên gặp trong điều kiện hoạt động bình thường.
  • Ở scale lớn, nên họ cũng aware là nó sẽ xảy ra thường xuyên hơn, và đâu đó là 19 lần trong vòng 6 tháng.
  • Ở Ops side, là khi phát hiện data bị corrupt, phải stop control plane và restore, tốn mất 1h đồng hồ để xử lý ở lần incident đầu tiên, hậu quả là control plane service ko available trong khoảng thời gian đó, sau này họ rút ngắn thời gian xử lý bằng cách detail runbook, train on-call để xử lý nhanh (nhưng đây là cách giải quyết ở mặt process, ko phải gốc).
  • Họ cũng thừa nhận vấn đề này rất serious và ảnh hưởng tới reliability, nên đã dành rất nhiều công sức để giải quyết vấn đề, nhưng ko dễ tí nào.

Quá trình đi tìm bug ra sao (phần này các fen nên học hỏi):

  • Như mọi kỹ sư Đông Lào, xài từ 2023 ko lỗi mà giờ lỗi, thì phải đi check lại xem gần đây có thay đổi code gì liên quan đến lớp tương tác với SQLite không (bug ở đâu thì xem change ở đó trước) nhưng hầu hết thay đổi đã từ nhiều năm trước nên ko có tí hint nào, nên quay qua xem toàn bộ mã nguồn và cũng ko có gì khả thi.
  • Tìm ko đc, thì “nhìn” vào common factor của các lần corrupt, nhìn xem có điểm chung nào ko, để suy đoán đc nguyên nhân “kích hoạt” bug này, và ko thấy gì luôn, chả có pattern gì cả =))
  • Do ko tìm đc trigger conditions, dẫn tới ko thể reproduce trên môi trường development, căng rồi đây. Buộc họ phải triển khai forensic telemetry in our live environment để bắt event, chuẩn đoán. Mấy fen phải để ý chỗ này, quan trọng, họ xem đây là lựa chọn cuối cùng, ko muốn nhưng phải làm, serious ở security side thì rõ ràng ở đây có thu thập đc mấy cái “đáng ra ko đc phép” - :shame: đừng trách ae DevOps chúng tôi tại sao nhiều khi từ chối mấy giải pháp kiểu vầy nhé.
  • Cái khó là sự cố không xảy ra theo pattern thời gian nào cả, đôi khi cách nhau vài giờ, đôi khi cả tuần cả tháng, nên dù đã deploy forensic telemetry, nhưng quá trình đợi, chờ trong nhiều tuần là rất phiền phức.

Có vẻ như phần telemetry được triển khai cũng không giúp ích gì được nhiều.

Vì bug này quá khó, nên quyết định cuối cùng là collab với SQLite core developers thông qua professional support contract. Đồng thời improve lại quy trình recovery sao cho tự động, nhanh, rõ ràng, ai cũng có thể xử lý được (hard-stop control plane khi gặp corrupt, add thêm vào automated backup pipeline thêm bước kiểm tra data corrupt luôn, cải thiện quy trình on-call/runbooks tường minh, dễ dùng). Quá trình này giúp thời gian recovery sự cố xuống dưới 1h đồng hồ và vô tình khám phá ra một manh mối mới.

Một trong các cách để giảm thời gian recovery đó là phải tối ưu lại bước restore database. Khi restore, nếu lấy latest backup thì có thể data đã cách xa một đoạn rồi (ở trên nói là “we take a complete snapshot of the database every few minutes”), nên mấy thím này build transaction logging pipeline, đại khái là lưu lại mỗi statement modifed data ở dạng logfile, sau đó relay lại transaction log này lên bản backup gần nhất, là sẽ có latest data, món này ae nào đụng nhiều DB cũng sẽ thấy quen thuộc (AOF trong Redis, hay mấy cơ chế replication của DB), do SQLite là single-writer nên cái này dễ hơn các CSDL khác. Và nhờ cái flow này, mới túm được một manh mối

Trong 2 sự cố, khi cố gắng recovery lại theo runbook, transaction log bị lỗi khi replay Upon closer inspection, we discovered that data written and committed by one transaction was inexplicably invisible to later transactions. A write had vanished into thin air without raising an error. That should be impossible! -> Đại ý là data đã được ghi/committed bởi một trx trước đó, ko được nhìn thấy bởi trx sau, ko biết tại sao nó biến cmn mất vào hư không, vô lí vkl.

SQLite developers mần 1 cái debbuging tool, và nghi ngờ bug đâu đó ở checkpoint process, tool debug này giúp xem chuyện gì xảy ra trong checkpoint. Mấy fen đọc giải thích trong bài để biết checkpoint là gì (btw khái niệm này cũng khá phổ biến trong các database khác). Một điểm cần giải thích ở đây là SQLite bản thân nó sẽ tự quyết định khi nào chạy checkpoint và user/developer ko cần quan tâm về nó. Tailscale, để có thể chạy backup nhanh, consistent NÊN HỌ MANUAL CONTROL và đây là một cách KHÔNG CHÍNH THỐNG, và nghi cmn ngờ là đâu đó quanh đây. Nên SQLilte developers mần tiếp một cái debugging tool khác cho VFS layer, để xem chuyện gì xảy ra với faulty checkpoints. Sau đó deploy và chờ.

Chờ đợi bao ngày thì túm đc rare-data-race và đâu đó nó tồn tại 16 năm rồi, nhưng hiếm quá, nên mãi tới giờ mới có ông bị, sau đó fixbug, vá và release SQLite 3.52.0.

Cơ mà cuộc đời nó đâu có dễ dàng như thế :yaomin:, dù đã xác định được bug, confirmed, nhưng vẫn phải release cẩn cmn thận, patch một vài shard, chạy smoothly một thời gian mới dám deploy hết cả đám. Nhưng ko, khi deploy hết cả cụm thì monitoring tool hét vào mặt, 13 shard DB corrupt :yaomin: quéo cmnl, nên thôi cứ apply quy trình recovery như cũ đã, bug điều tra tiếp sau =)) nhưng sau đó phát hiện ra, hóa ra ko phải data bị corrupt, nhưng nó lại lòi ra cái bug thứ 2, cuộc đời nó phải thế chứ =)) có một con gián, kiểu gì chẳng phát hiện ra con tiếp theo.

Bug tiếp theo được mô tả đại khái là nếu tạo index trên một computed value, mà sau đó computation change -> index sẽ chứa mismatched value -> Nên cái command PRAGMA integrity_check để report corrupt sẽ lỗi, đó là lý do có 13 cái shard DB ở trên bị báo lỗi. Cụ thể case của họ là lưu high-precision timestamp as text, convert to floating-point number trong VIRTUAL generated column, bản SQLite 3.52.0 tiện tay có thêm cái optimisation này, và canary shards lúc deploy ko có cái nào trigger liên quan tới cái timestamp họ lưu, nên miss cmn mất. ĐEN

Nên sau đó SQLite giúp họ release bản 3.51.3 chứa mỗi cái WAL-reset bug (kinh nghiệm để đời là có upgrade thì cũng từ từ, minor thôi, :shame: nhảy version là kiểu gì cũng ăn hành), về phía system của Tailscale, họ cũng fixbug timestamp trên bằng cách giảm độ chính xác sang integer second (thay vì float), và converting text -> int.

Như các kỹ sư Đông Lào overthinking, sau khi rollout hết lại bản 3.51.3, có tí mừng thầm nhưng dek dám ăn mừng, vì ko thấy xuất hiện corrupt data cũng chưa chắc là bug đã được fix :shame: đời mà, biết đâu vẫn còn con gián nào đó.

Và vì đã hiểu rõ nguyên nhân, cách xảy ra bug (manual control checkpoint process, collision between a write transaction and a WAL-reset) nên mấy thím này mới quyết định là patch SQLite driver để add một cái log warning. Đại ý là nếu 2 operation write transaction và WAL reset bị overlap thì bắn một cái alert, nếu alert xuất hiện, nhưng database ko bị corrupt, tức là bug đã được fix -> thông minh, thật là thông minh :smart: :smart:. Deploy và chờ thôi, khúc này chờ hết MỘT TUẦN vẫn ko thấy gì, bắt đầu thấy hơi quéo quéo, hay là :sadbug: nó vẫn còn đó nhưng nó trốn kỹ quá :shake:

sqlite-alert

Clm, đợi suốt 2 tháng thì cuối cùng cái log warning nó cũng fire =)) móa, thở phào nhẹ nhõm, ít ra đã chứng minh được là bản patch đã fix đc bug và sau cái alert đó, đợi tiếp 4 THÁNG mà ko gặp thêm sự cố nào, thì mới đẻ ra đc cái bài này, :shame: má siêu cẩn trọng, sự cẩn trọng này phải tới từ một mớ hành trong quá khứ đây. Tốn một đống workload của một mớ kỹ sư :3-friends::3-friends::3-friends::3-friends::3-friends::3-friends:

Chốt lại một kinh nghiệm xương máu, là running boring technology in a non-standard way is a risk. :yaomin: chia sẻ trải nghiệm cá nhân là cái này vô cùng xương máu, cứ vẽ ra cái gì ngoài SGK là trước sau gì cũng ăn hành.

Câu cuối cùng Hopefully there won’t be another database incident like this—but if there is, we’ll be ready. Rõ ràng câu này phải là từ một người đã trải qua rất nhiều hành và xương máu trong việc vận hành, fixbug :shame: :shame: :shame: