अलर्ट आया कि DB मर गया। DB कभी मरा ही नहीं था

सुबह स्लैक खोला तो चार CRITICAL अलर्ट जमा थे।

504 AppHttpException: The request timed out.
  POST /customer/practice/attempts

PrismaClientKnownRequestError
  Transaction already closed

500 DriverAdapterError: canceling statement due to statement timeout
  GET /admin/dashboard/stats

DATABASE 서비스 다운
  "error": "Database health check (retry) timeout after 2000ms"

आख़िरी लाइन सबसे डरावनी है। इसका मतलब है DB मर गया। चारों को एक ही स्क्रीन पर देखो तो एक कहानी बन जाती है। DB को तकलीफ़ हुई, इसलिए क्वेरी पिछड़ गईं, इसलिए रिक्वेस्ट टाइमआउट हुईं, और आख़िर में हेल्थ चेक तक फेल हो गया। कहानी जंचती है।

तो मैंने सबसे पहले DB के मेट्रिक खोले। वह कहानी पहली ही स्क्रीन पर ढह गई।

DB पूरे 21 घंटे ख़ाली बैठा था

ख़राबी के समय को समेटते हुए 21 घंटे के अंतराल के RDS मेट्रिक 5 मिनट के दाने में निकाले। 252 डेटा पॉइंट।

मेट्रिक	न्यूनतम	अधिकतम
CPU	4.6%	19.7%
कनेक्शन	53	73
CPU क्रेडिट बैलेंस	576	576
रीड लेटेंसी	0s	0.01s
राइट लेटेंसी	0.01s	0.08s

CPU कभी 20% के पार नहीं गया, और क्रेडिट बैलेंस का न्यूनतम और अधिकतम एक ही है। मतलब एक भी क्रेडिट ख़र्च नहीं हुआ। राइट लेटेंसी अधिकतम 80 मिलीसेकंड। RDS Proxy भी देखा। कनेक्शन बॉरो लेटेंसी अधिकतम 26 मिलीसेकंड, बैकएंड कनेक्शन अधिकतम 36। कहीं कोई ऐसा आंकड़ा नहीं जो 8 सेकंड या 10 सेकंड वाली क्वेरी को समझा सके।

DB मरा नहीं था। वह तो व्यस्त भी नहीं था।

एक रिक्वेस्ट पच्चीस बार अटलांटिक पार करती है

तो फिर 8 सेकंड वाली क्वेरी आई कहां से। ढांचे को देखो तो जवाब मिल जाता है।

हमारी सर्विस दो रीजन में चलती है: us-east और eu-west। primary DB सिर्फ़ एक है, us-east में। eu-west ऐप की रीड लोकल रेप्लिका संभाल लेती है, मगर राइट पूरी की पूरी अटलांटिक पार करके, RDS Proxy से होते हुए us-east primary तक जाती है।

समस्या राइट की संख्या थी। प्रैक्टिस रिकॉर्ड सेव करने वाली एक रिक्वेस्ट (POST /customer/practice/attempts) को कोड में क़दम-दर-क़दम गिना। एसेट upsert 1 बार, प्री-एग्रीगेट रीड 3 बार, लर्निंग अटेम्प्ट ट्रांज़ैक्शन 4 बार, रनर की दोबारा जांच 1 बार, प्रोग्रेस अपडेट 2-3 बार, स्ट्रीक ट्रांज़ैक्शन लगभग 6 बार, स्टैटिस्टिक्स ट्रांज़ैक्शन 2 बार, रिव्यू स्टेट अपडेट 2-3 बार। तीन अलग-अलग इंटरैक्टिव ट्रांज़ैक्शन गुच्छों में फैले हुए, कुल मिलाकर लगभग पच्चीस।

लॉग में वही आंकड़ा ज्यों का त्यों छपा हुआ था।

06:03:17  request_done  POST /customer/practice/attempts
          status=201  duration_ms=11695  query_count=25

25 क्वेरी, 11.7 सेकंड। यह रिक्वेस्ट फेल तक नहीं हुई। 11.7 सेकंड झेलने के बाद 201 के साथ कामयाब हो गई।

यहां एक बात ईमानदारी से बता देनी चाहिए। मैंने यह नहीं नापा कि इनमें से एक राउंड ट्रिप पर कितने मिलीसेकंड लगते हैं। कोड के एक कमेंट में रीजन के बीच का RTT 220 मिलीसेकंड लिखा था, और दूसरे कमेंट में प्रति वाक्य 80-100 मिलीसेकंड। दोनों में से कौन सही है, यह जांचे बिना ही मैंने इशू में "25 x 220ms = 5.5 सेकंड" वाला हिसाब लिख दिया। अब पीछे मुड़कर देखूं तो वह माप नहीं, हवाला था। सही बयान यह है: राउंड ट्रिप की संख्या मैंने गिनी (25), और प्रति राउंड ट्रिप की लागत मैंने नहीं नापी। फिर भी निष्कर्ष डगमगाता नहीं। अटलांटिक पच्चीस बार पार करोगे तो लागत सेकंडों में जमा होगी ही।

EU की सुबह वाली पीक (06:00-06:10 UTC) में 3 सेकंड से ऊपर जाने वाली 57 primary राइट एक साथ आ पड़ीं। LearningAttempt.create 8,989ms, UserActiveDate.upsert 9,070ms, LearningAttempt.findUnique 10,561ms। रिक्वेस्ट एक-दूसरे को पीछे धकेलती गईं और राउंड ट्रिप की देरी जमा होती गई।

दो अलर्ट उसी दरार से निकले।

अलर्ट 1 और 2: 5 सेकंड का ट्रांज़ैक्शन 9.3 सेकंड नहीं झेल पाया

स्ट्रीक अपडेट का कोड ऐसा दिखता है।

// streak.service.ts:254
const changed = await this.prisma.primary.$transaction(async (tx) => {
  // ... छह queries जो region की सीमा पार करती हैं ...
});

ऑप्शन ऑब्जेक्ट है ही नहीं। इसलिए Prisma का डिफ़ॉल्ट इंटरैक्टिव ट्रांज़ैक्शन टाइमआउट, यानी 5,000 मिलीसेकंड लागू होता है। आम दिनों में कोई दिक़्क़त नहीं। बशर्ते रीजन पार न करना पड़े।

Transaction API error: A query cannot be executed on an expired transaction.
The timeout for this transaction was 5000 ms,
however 9326 ms passed since the start of the transaction.

9,326 मिलीसेकंड। और यही आगे चलकर P2028 बनता है, और रिक्वेस्ट गेटवे पर 504 बन जाती है।

यह कोड हमारे पूरे कोडबेस में अकेला बिना कवच के खड़ा था। बाक़ी सारे ट्रांज़ैक्शन पाथ withTxRetry यूटिलिटी से होकर गुज़रते हैं, और वह यूटिलिटी टाइमआउट को 8 सेकंड कर देती है और P2028 को रीट्राई के लायक़ मानती है। सिर्फ़ स्ट्रीक अपडेट उस छतरी के बाहर रह गया था और डिफ़ॉल्ट 5 सेकंड इस्तेमाल कर रहा था।

अलर्ट 4: हेल्थ चेक ख़ुद उसी बॉटलनेक से गुज़रा जिस पर वह नज़र रखे था

सबसे डरावना "DATABASE सर्विस डाउन" असल में सबसे बेतुका निकला।

हेल्थ चेक का कोड अच्छा लिखा था। SELECT 1 को 2 सेकंड के टाइमआउट के साथ फेंकता है, फेल होने पर 500 मिलीसेकंड रुककर एक बार और कोशिश करता है, और वह भी फेल हो तो CRITICAL अलर्ट दाग़ता है। ऐप के Prisma पूल से न मिले, इसके लिए डेडिकेटेड कनेक्शन पूल (अधिकतम 2) भी अलग रखा था। मक़सद यह कि ऐप पूल ख़त्म हो जाए तब भी हेल्थ चेक ज़िंदा रहे।

मगर इस प्रोब का DB तक पहुंचने का रास्ता अलग-थलग नहीं था।

// health.service.ts:139
// अगर DIRECT_DATABASE_URL सेट है तो वही, वरना DATABASE_URL पर fallback

DIRECT_DATABASE_URL सेट ही नहीं था। फ़ॉलबैक लग गया, और DATABASE_URL ठीक उसी RDS Proxy की तरफ़ इशारा करता है जहां ऐप की राइट ट्रैफ़िक जमा है। यानी eu-west की हेल्थ प्रोब ने जो SELECT 1 फेंका, उसे अटलांटिक पार करके, ठीक उसी प्रॉक्सी से गुज़रकर जो अभी जाम है, us-east primary तक जाकर लौटना था। वह भी 2 सेकंड के अंदर।

कोड को यह बात मालूम थी। फ़ॉलबैक लगने पर वह ऐसी चेतावनी छोड़ता है।

DIRECT_DATABASE_URL is not set; DB health checks will use DATABASE_URL
and may still share proxy bottlenecks.

लॉग में यह लाइन ज्यों की त्यों छपी थी। बस किसी ने पढ़ी नहीं थी।

निर्णायक सबूत यह था कि दोनों रीजन एक ही वक़्त पर साथ-साथ फेल हुए। 12:02:17 पर us-east टास्क का हेल्थ चेक टाइमआउट। 12:02:18 पर eu-west टास्क का भी टाइमआउट। अगर यह इलाक़े की समस्या होती तो सिर्फ़ एक तरफ़ मरना चाहिए था। दोनों का साथ में मरना बताता है कि वजह वही है जो दोनों में साझा है, यानी प्रॉक्सी पाथ।

आगे जो हुआ वह तय क़दम थे। हेल्थ चेक दोनों बार फेल हुआ तो /public/health ने 503 उगला, और ऑर्केस्ट्रेटर ने इस टास्क को ख़राब मानकर बदल दिया। 4 मिनट बाद नया टास्क खड़ा हुआ। नया टास्क बूट होते ही वही हेल्थ चेक टाइमआउट दोबारा खा गया। टास्क बदलने से अटलांटिक तो सिकुड़ता नहीं।

"DATABASE सर्विस डाउन" ख़राबी का लक्षण नहीं था। निगरानी करने वाला यंत्र निगरानी के लक्ष्य की जाम पड़ी सड़क पर ख़ुद टहलकर आया, और फिर ख़बर दी कि उसे तकलीफ़ हो रही है।

एडमिन 500 अलग मामला था

यहां लालच आता है कि चारों अलर्ट को एक में बांध दिया जाए। शुरू में मैं भी वैसे ही समेटना चाहता था। मगर एडमिन 500 की जड़ अलग थी।

GET /admin/dashboard/stats लोकप्रिय शब्द निकालते वक़्त पिछले 7 दिन का फ़िल्टर लगाता है। मगर जिस टेबल (category_attempt) पर वह फ़िल्टर लगता है उसमें अपना कोई डेट कॉलम है ही नहीं। तारीख़ सिर्फ़ जुड़ने वाली learning_attempt की तरफ़ है। इसलिए Postgres के पास category_attempt को तारीख़ के हिसाब से पहले से काट देने का कोई तरीक़ा नहीं है, और उसे पूरा इतिहास खंगालना पड़ता है। इंडेक्स चाहे जितने अच्छे बिछा दो, इस फ़िल्टर को सेलेक्टिव नहीं बनाया जा सकता।

slow_query path=/admin/dashboard/stats
           label=CategoryAttempt.groupBy dur=8009ms

statement_timeout 8,000 मिलीसेकंड है। और यह 8,009 मिलीसेकंड। 9 मिलीसेकंड के फ़र्क़ से मौत। यह रीजन से बेपरवाह, ऐसा फ़ुल स्कैन था जो टेबल बढ़ने पर एक न एक दिन फटना ही था।

चार अलर्ट में से तीन की जड़ एक थी, और एक की अलग। चार अलर्ट एक ही स्क्रीन पर आ गए, इसका मतलब यह नहीं कि वजह एक है।

एक परिकल्पना जो ख़ारिज हुई

एक जंचता हुआ संदिग्ध था। 06:00 वाले बर्स्ट से ठीक पहले चलने वाला device-cleanup क्रॉन लॉक कंटेंशन पैदा कर रहा है - यह परिकल्पना। समय मेल खा रहा था तो यह काफ़ी दमदार लग रही थी।

दोनों रीजन के लॉग 05:30-06:15 के अंतराल में खंगाले। क्रॉन से जुड़ा एक भी लॉग नहीं मिला। धीमे पड़े Device.updateMany का पाथ जांचा तो वह क्रॉन का बल्क अपडेट नहीं, बल्कि /v2/public/auth/refresh था, यानी किसी आम यूज़र का टोकन रिफ़्रेश। परिकल्पना असल माप से ख़ारिज हो गई। समय का मेल खाना कोरिलेशन है, लॉग में न होना तथ्य है।

राउंड ट्रिप को मोड़ दिया

इलाज की दो राहें थीं। एक, लक्षण को झेलना: टाइमआउट 8 सेकंड कर दो, पूल बड़ा कर दो, रीट्राई लगा दो। दूसरी, लागत को ही ख़त्म कर देना: राउंड ट्रिप की संख्या घटा दो।

हमने दोनों किया। स्ट्रीक ट्रांज़ैक्शन पर withTxRetry चढ़ाना बैंडेज है, मगर ज़रूरी बैंडेज था। असली इलाज तो राउंड ट्रिप मोड़ना ही था।

वह औज़ार पहले से बना पड़ा था। 27 जून की माइग्रेशन में create_practice_attempt_v1 नाम का एक सर्वर-साइड फ़ंक्शन मौजूद था। सेशन लॉक, लुकअप, इंसर्ट, सेशन मेटा अपडेट और प्री-एग्रीगेट रीड - इन सबको एक ही SQL फ़ंक्शन में मोड़कर एक राउंड ट्रिप में निपटा देने वाला फ़ंक्शन। इडेम्पोटेंसी तक मौजूद (एक ही client attempt id से दो बार बुलाओ तो दूसरी बार मौजूदा रो लौटाकर inserted=false देता है)।

मगर इस फ़ंक्शन को चालू करने वाला फ़ीचर फ़्लैग PRACTICE_ATTEMPT_SINGLE_RT_ENABLED डिफ़ॉल्ट रूप से false था, यानी प्रोडक्शन में बंद पड़ा था।

रीजन ख़त्म करने या active-active पर जाने के बजाय हमने बस पहले से बना रखा स्विच ऑन किया।

कैनरी: फ़ैसला किस चीज़ को देखकर करेंगे

फ़्लैग सिर्फ़ eu-west में चालू किया। us-east को कंट्रोल ग्रुप के तौर पर बंद रखा। task definition 786 से 787 पर चढ़ाकर रोलिंग डिप्लॉय।

इस कहानी का दिल यही है कि फ़ैसले का मेट्रिक किसे बनाया जाए। लेटेंसी एक जाल है। कम ट्रैफ़िक वाले वक़्त पर डिप्लॉय करोगे तो बिना कुछ ठीक किए भी p95 सुधर जाएगा। और सच में लेटेंसी सुधरी भी। p50 2,784ms से गिरकर 2 हज़ार ms से नीचे आ गया। मगर वह कमज़ोर सबूत है।

इसके बजाय मैंने प्रति रिक्वेस्ट क्वेरी संख्या देखी।

deploy se pehle  n=85   avg query_count = 22.0
deploy ke baad  n=49   avg query_count = 15.3

क्वेरी संख्या एक ऐसा per-request मेट्रिक है जो लोड से बेपरवाह है। ट्रैफ़िक ज़्यादा हो या कम, एक रिक्वेस्ट कितनी क्वेरी फेंकेगी यह कोड पाथ तय करता है। 22 से 15.3, यानी लगभग 7 क्वेरी कम हुईं। और वे 7 ठीक-ठीक उन क्वेरी की गिनती से मेल खाती हैं जिन्हें हमने एक फ़ंक्शन में मोड़ा था (सेशन लॉक + लुकअप + इंसर्ट + सेशन मेटा + प्री-एग्रीगेट रीड)। कोड पाथ सच में बदला है, इसका सबूत यही आंकड़ा है। लेटेंसी नहीं।

डिप्लॉय के बाद का सैंपल 15 मिनट में 49 रिक्वेस्ट का है। उस विंडो में न कोई 5xx था न कोई P2028, मगर उसी दिन उतनी ही लंबाई की "डिप्लॉय से पहले" वाली एरर गिनती मैंने साथ-साथ नाप कर नहीं रखी। यह फ़्लैग सिर्फ़ attempt सेव करने वाले हिस्से को मोड़ता है। स्ट्रीक ट्रांज़ैक्शन अब भी रीजन पार करता है। उस दिन उस विंडो में P2028 शून्य रहा, इसका मतलब क़िस्मत अच्छी थी - यह कोई प्रमाण नहीं है।

डिप्लॉय तो कामयाब रहा, मगर फ़्लैग ग़ायब होते-होते बचा

कैनरी चालू करने के हमारे तरीक़े की एक क़ीमत थी। 787 वह task definition है जिसे कंसोल से सीधे रजिस्टर किया गया था। अगली नियमित डिप्लॉय चलते ही CD पाइपलाइन उसे बिना फ़्लैग वाली task definition से ओवरराइट कर देगी। यह जानलेवा नहीं है (ओवरराइट होने पर सुरक्षित OFF पर लौट आता है)। बस सुधार चुपचाप ग़ायब हो जाता है।

तो इसे terraform में प्रमोट करना था, और यहीं दूसरा जाल निकला। terraform वर्कफ़्लो develop push पर सिर्फ़ staging apply करता है, और production सिर्फ़ main push पर apply होता है। मगर staging में eu-west रीजन है ही नहीं। यानी प्रोडक्शन के eu-west बदलाव वाला PR develop में मर्ज करो तो कुछ भी नहीं होगा। base को main करना पड़ा।

तीसरा जाल भी था। सीधे main में मर्ज करोगे तो develop पिछड़ जाता है, और वापस मर्ज न किया तो अगली रिलीज़ इस बदलाव को revert कर देगी। अलग से back-merge PR बनाना पड़ा।

"terraform apply कामयाब रहा" और "प्रोडक्शन में लागू हो गया" - ये दो अलग वाक्य हैं।

जो बचा

"DB डाउन" वाला अलर्ट आए तो सबसे पहले DB के मेट्रिक खोलने चाहिए। अलर्ट का नाम उस कोड ने रखा है जिसने अलर्ट दाग़ा, वजह ने नहीं रखा। हमारे हेल्थ चेक ने ऐप पूल से अलग डेडिकेटेड पूल तक बना रखा था, फिर भी DB तक जाने का रास्ता एक होने की वजह से वह ऐप के साथ ही जाम हो गया। अलग-थलग करने के लिए सिर्फ़ संसाधन बांटना काफ़ी नहीं, रास्ता भी बांटना पड़ता है।

टाइमआउट 5 सेकंड से 8 सेकंड कर दो तो उस दिन के अलर्ट रुक जाएंगे। मगर रिक्वेस्ट अब भी पच्चीस बार अटलांटिक पार करेगी। ट्रैफ़िक थोड़ा भी बढ़ा तो 8 सेकंड भी कम पड़ेंगे। लक्षण झेलना है या लागत मिटानी है, यह पहले से तय कर लेना बेहतर है। अगर लागत की असलियत "संख्या x दूरी" है, तो घटानी संख्या ही है।

लेटेंसी लोड के साथ हिलती है, per-request मेट्रिक नहीं हिलता। परफ़ॉर्मेंस फ़िक्स डिप्लॉय करके p95 सुधरा देखकर निश्चिंत होने से पहले यह देखना चाहिए कि एक रिक्वेस्ट जितना काम करती है उसकी गिनती सच में घटी या नहीं। वह आंकड़ा तड़के डिप्लॉय करो या दोपहर में, एक ही रहता है।

मैंने राउंड ट्रिप की संख्या गिनी, और प्रति राउंड ट्रिप की देरी कोड के कमेंट से उठाकर इस्तेमाल कर ली। वे दो कमेंट आपस में अलग-अलग वैल्यू बता रहे थे। इस बार निष्कर्ष नहीं बदला, यह अच्छा हुआ, मगर अगली बार निष्कर्ष बदल भी सकता है। जो नहीं नापा, उसे नहीं नापा लिखो।