0.14.0'ı durduran sürüm kapısı: iki ay saklanan bir Postgres hatası

23 Ekim'de 0.14.0 etiketini attık. Sürüm akışı her zamanki gibi önce kapılarını çalıştırdı. Bunlardan biri, tüm takımı en_US.utf8 sıralama kuralıyla kurulmuş gerçek bir Postgres'e karşı koşan kapı, kırmızı yandı. Yayın adımı kapılara bağlı olduğu için hiç çalışmadı. npm'e hiçbir şey gitmedi.

Hatayı düzelttik, etiketi düzeltilmiş commit'e taşıdık ve sürümü yeniden başlattık. Bu sefer yeşil geçti; 27 açık paketin hepsi provenance imzasıyla 0.14.0 olarak yayınlandı. Düzeltme 0.14.0 değişiklik notlarında.

Kırmızı yanan test, arka plan aracı takımındaki D4'tü. İki süreç aynı depoyu paylaşıyor. Biri bir kişi için uzun bir iş çalıştırıyor. Diğeri, iş sürerken o kişiyi siliyor. Ardından test geride bir şey kalmadığına bakıyor: ne run, ne sahiplik kaydı, ne de kişinin konuşmasında mesaj.

Yaklaşık on çalıştırmada bir, konuşmanın mesajları yerinde duruyordu. Run'lar ve sahiplik kayıtları silinmişti. Silme işlemi başarılı dönmüştü. Hiçbir yerde hata yoktu. C sıralama kuralında aynı test her seferinde geçiyordu.

Postgres deposundaki her önek sorgusu aslında bir aralıktır: key >= prefix AND key < prefix + U+FFFF. Bu yalnızca bayt sıralamasında bir önek demektir. en_US.utf8 gibi dile dayalı bir sıralama kuralında U+FFFF yokmuş gibi sıralanır ve aralık hiçbir satırı yakalamaz. Bunu Ağustos'ta bulmuştuk; çözüm bu karşılaştırmalara COLLATE "C" eklemekti. Depo bunu sabit yazmaz: açılırken veritabanına dizeleri nasıl karşılaştırdığını sorar ve bu ekin gerekip gerekmediğine karar verir.

Bu karar tek bir ortak nesnede duruyordu. Run günlüğü ve iş deposu bu nesneye bir referans tutuyor, sorgu kurarken ondan okuyordu. Sorun sıralamadaydı: metot önce SQL'ini kuruyordu, açılışı bekleyen ise yalnızca ardından gönderilen sorguydu. Yani yeni başlamış bir süreçte ilk önek sorgusu, nesne henüz boşken kuruluyordu.

/** Filled in by ensureReady's probe; shared BY REFERENCE with PgRunJournal (see PrefixShape). */
private prefixShape: PrefixShape = { collate: '' };

this.runs = new PgRunJournal(q, tx, this.prefixShape);

// in PgRunJournal
async listKeys(prefix: string, opts?: { limit?: number }): Promise<string[]> {
  const c = this.shape.collate;
  const rg = pgRange('key', c, prefix, 1);
  // ...
}

Boş bir collate, C kuralında doğrudur. en_US.utf8'de ise tam olarak Ağustos'taki hatadır: aralık hiçbir şey yakalamaz ve hata da vermez. Bu yüzden yeni bir sürecin ilk listKeys, readRange, sahiplik sorgusu, kimlik önekiyle run listesi, deletePrefix ya da deleteIdPrefix çağrısı "hiç yok" diye cevap veriyordu. Sonraki çağrıların hepsi doğruydu, çünkü o noktada açılış tamamlanmıştı. D4'te silme işlemi, silen sürecin yaptığı ilk iş olduğunda, kişinin konuşmasını bulan sorgu boş dönüyor ve konuşma yerinde kalıyordu.

Hata, ilk sıralama hatasını düzelten commit'in içinde, 17 Ağustos'ta doğdu. Ortaya çıkması 23 Ekim'i buldu. Onu dört şey sessiz tuttu.

• C kuralında görülecek bir şey yok. Yereldeki Postgres'imiz postgres:15-alpine; bu imaj bayt sıralamasıyla açılıyor. Orada boş collate doğru cevap olduğu için yerel çalıştırmaların hepsi geçiyordu.
• Yalnızca bir süreçteki ilk çağrı. Herhangi bir şey açılışı bir kez beklediyse nesne dolmuş ve bütün sorgular doğru kurulmuş oluyordu. Kendisine bir şey sorulmadan önce açılmış bir depo bu hatayı hiç göstermedi.
• Hatayı gösteren test yeni. D4, 12 Ekim'de eklendi. Bu testte yeni başlamış bir süreç bir kişiyi siliyor ve bu silme bazen sürecin yaptığı ilk iş oluyor.
• Bir kez gördük ve yanlış yeri düzelttik. 10 Ekim'de en_US.utf8 bir veritabanında gnl upgrade hiç organizasyon bulamadı; çünkü açılmamış bir deponun ilk listKeys çağrısı boş dönmüştü. Yükseltme komutunu, o adımdan önce depoyu açacak şekilde değiştirdik. Komut düzeldi. Depo düzelmedi.

Depolar artık nesnenin kendisini almıyor. settled alıyorlar: açılışı bekleyip ardından nesneyi döndüren bir fonksiyon. Bundan sorgu kuran her metot önce onu bekliyor.

type Settled = () => Promise<PrefixShape>;

const settled: Settled = () => this.ensureReady().then(() => this.prefixShape);
this.runs = new PgRunJournal(q, tx, settled);
this.work = new PgWorkStore(q, tx, settled);

// in PgRunJournal
async listKeys(prefix: string, opts?: { limit?: number }): Promise<string[]> {
  const shape = await this.settled();
  const c = shape.collate;
  const rg = pgRange('key', c, prefix, 1);
  // ...
}

Asıl mesele await değil. Mesele, deponun nesneye artık başka bir yoldan ulaşamaması; böylece hiçbir metot onu açılıştan önce okuyamıyor. Açılış yalnızca ham bağlantı havuzunu kullandığı için, depo içinden onu beklemek kendi kendini beklemeye dönüşemiyor.

Yeni test, sunucunun varsayılanı ne olursa olsun, kendi en_US.utf8 veritabanını kuruyor. Açılmış bir yazıcı onu dolduruyor. Ardından her durum, hiçbir şeyin açmadığı yeni bir depo açıp tam olarak tek bir çağrı yapıyor.

// A linguistic collation, whatever the server's default: this is the database the bug lives on.
await admin(`CREATE DATABASE ${NAME} ENCODING 'UTF8' LC_COLLATE 'en_US.utf8' LC_CTYPE 'en_US.utf8' TEMPLATE template0`);

/** A store over the same database that nothing has booted: no init, no call yet. */
const fresh = () => { const s = new PostgresStorage({ connectionString: url }); opened.push(s); return s; };

it('listKeys', async () => {
  expect(await (fresh().runs as any).listKeys('pfx-r1:')).toEqual(await (writer.runs as any).listKeys('pfx-r1:'));
});

it('countRuns by id prefix', async () => {
  expect(await (fresh().runs as any).countRuns({ runIdPrefix: 'pfx-' })).toBe(2);
});

Düzeltmeden önce 10 durumun 9'u kırmızıydı. Sonra 10'u da yeşil. D4'ün kendisi: düzeltmeden sonra Postgres'te 30 çalıştırmada 0 hata; öncesinde yaklaşık on çalıştırmada bir.

MySQL'de de aynı biçim vardı. Bir konuşmanın ekleme kilidi, adını veritabanından alıyor; veritabanı adını da açılış okuyor. Kilit adı, işlemin (transaction) argümanı olarak, yani işlem açılışı beklemeden önce kuruluyordu.

// before
private lock(threadId: string): TxOptions {
  return { lock: { name: lockName('t', this.shared.db, threadId), timeoutS: THREAD_LOCK_WAIT_S, what: `thread '${threadId}'` } };
}

// after
private async lock(threadId: string): Promise<TxOptions> {
  const { db } = await this.settled();
  return { lock: { name: lockName('t', db, threadId), timeoutS: THREAD_LOCK_WAIT_S, what: `thread '${threadId}'` } };
}

Sonuç olarak yeni bir sürecin bir konuşmaya ilk eklemesi, o konuşmaya yapılan sonraki eklemelerden farklı adlı bir kilit alıyordu. Aynı konuşmaya yazan iki yazıcı sıraya girmiyordu. Kilit adı artık açılıştan sonra kuruluyor. Bir test, ilk ve ikinci eklemenin aynı kilit adını aldığını doğruluyor; düzeltmeden önce kırmızıydı, sonra yeşil.

Bu kapı tesadüfen orada değildi. Sürüm akışı kendi kontrollerini tek tek saymaz; CI akışımızı çağırır. Böylece bir sürüm, main'e yapılan her push'un geçtiği kapıların aynısından geçer. Buna gerçek veritabanlarından oluşan bir matris de dahil; Postgres iki sıralama kuralıyla çalışır: C ve en_US.utf8.

Bu düzeni Ağustos'ta, ilk sıralama hatasından sonra kurduk. Etiket push'u ana CI'yı tetiklemez; o güne kadar yayın yolu kontrollerimizin yalnızca bir kısmını çalıştırıyordu. en_US.utf8 ayağı, yayınlananlar hariç her commit'e uygulanıyordu. Artık kırmızı bir kapı, sürümü npm'den önce durduruyor.

İki kural da kalıyor. en_US.utf8, yönetilen Postgres hizmetlerinin çoğunda gelen kural. C ise kendi sunucusunda alpine imajı kullananın aldığı kural. Yalnızca birinde çalışan bir düzeltme diğerini bozar.

Tek bir sıralama kuralında yeşil yanan CI bu hata hakkında bize hiçbir şey söylemedi. Kod C için doğruydu, en_US.utf8 için yanlıştı; üstelik yalnızca bir sürecin ilk çağrısında. On çalıştırmada bir kırılan bir teste "kararsız test" demek kolaydır. Bu ise bir silme işleminden sonra kişinin mesajlarını geride bırakan gerçek bir hataydı.

Buradan aldıklarımız: sürümü gerçek veritabanlarında, kullanıcıların gerçekten sahip olduğu her yapılandırmada çalıştırın. Seyrek bir kırılmayı, açıklanana kadar hata sayın. Bir hata tek bir çağrı noktasında bulunduğunda, o noktayı değil, bütün çağrı noktalarının okuduğu şeyi düzeltin.