رجیستری تو ۴۵ میلی‌ثانیه جواب می‌داد. بیلد دو دقیقه بیشتر طول می‌کشید.

چند هفته بعد از این‌که GitLab ی self-hosted مون رو به یه اکانت جدید و یه host جدید منتقل کردیم، تیم solutions گزارش داد که npm install ها روی group package registry کند شده. بیلدهایی که ۱:۴۰ تا ۲:۰۰ طول می‌کشیدن حالا حدود ۳:۳۰ شده بودن. یه npm install --verbose با cache ی خالی شکل ماجرا رو نشون می‌داد: ۵۰۰ های پشت سر هم، که هر کدوم آخرش موفق می‌شدن. زمان‌ش دقیقاً به migration می‌خورد و regression هم پایدار بود، برای همین گزارش اومد به‌عنوان «از موقع جابه‌جایی کند شده». گزارش منطقی‌ای بود. ولی به یه شکل مشخص و آموزنده غلط بود.

یه interval ی ثابتِ اضافه‌شده یعنی retry ی کلاینت، نه مشکل منابع سرور

اولین چیزی که زمان گرفتم خودِ request ی fail‌شونده بود: ۵۰۰، تو ۴۵ میلی‌ثانیه. تک‌تک‌شون.

همین یه عدد کل تشخیصه. یه مشکل منابع، یه دیسک کند، یه CPU ی کم‌آورده، یه instance ی کوچیک، latency یی تولید می‌کنه که با لود بالا پایین می‌ره و آهسته بدتر می‌شه. ولی یه interval ی ثابتِ اضافه‌شده یه چیز دیگه‌ست: یه مکثِ ثابت که کلاینت بین تلاش‌ها می‌ذاره. retry policy ی npm یه backoff schedule رو طی می‌کنه، تقریباً T، بعد T+۱۰ ثانیه، بعد T+۷۰ ثانیه، و بعد endpoint رو رها می‌کنه. این مکث‌ها رو به request هایی که مجبور شدن retry بشن اضافه کنی، تقریباً دقیقاً به همون ۱۱۰ ثانیه‌ی اضافه‌ی گزارش‌شده می‌رسی. سرور هیچ‌وقت کند نبود. بیلدها کند بودن چون کلاینت بین شکست‌ها داشت مؤدبانه صبر می‌کرد.

می‌تونستم یه ساعت سر gp3 IOPS و سایز instance بمونم و هیچی پیدا نکنم، چون دیسک و CPU سالم بودن. درسش فراتر از npm ـه: وقتی «کندتر شده از X» رو می‌شه به یه interval ی ثابت برگردوند، نه یه جابه‌جایی تو توزیع زمان، دیگه سرور رو اندازه نگیر و بشین retry config ی کلاینت رو بخون. اول status code ها، بعد timing ها، بعد داشبوردها.

یه row تو ۶۳هزارتا

هر ۵۰۰ یی همون exception رو داشت:

RuntimeError: Object Storage is not enabled for Packages::Npm::MetadataCacheUploader

GitLab فراداده‌ی npm ی هر پکیج، همون packument، رو تو یه table به اسم packages_npm_metadata_caches کش می‌کنه. مثل هر چیزی که GitLab از طریق CarrierWave ذخیره می‌کنه، هر row یه ستون store داره: 1 یعنی دیسک local، 2 یعنی object storage. تو این instance ی ما object storage کلاً غیرفعال بود. یه row تو اون table اصرار داشت file_store = 2، پس هر request برای metadata ی اون پکیج از CarrierWave می‌خواست از یه backend ی بی‌وجود بخونه، و request با ۵۰۰ می‌مرد.

ما یه بار object storage رو امتحان کرده بودیم، تو تیر، و rollback زده بودیم. اون rollback از یه نظر کامل بود و از یه نظر کور، که می‌شه بخش بعد. چیزی که اینجا مهمه audit ـه: از information_schema همه‌ی table هایی که ستون store داشتن رو درآوردم، همه‌شون رو چک کردم، ۶۲ تا table و حدود ۶۳هزار row، و دقیقاً یه دونه row پیدا شد که به store ی remote اشاره می‌کرد. همون یه row کلِ incident بود. هر ۵۵۴ تا فایل واقعی پکیج local بودن، برای همین دانلود tarball ها از اول تا آخر ۲۰۰ تو ۶۰ میلی‌ثانیه برمی‌گردوند: registry واقعاً سالم بود. فقط مسیر خوندن metadata cache خراب بود، و اون هم فقط برای پکیج‌هایی که row ی کش‌شده‌شون flip شده بود.

چک بود؛ لیست نبود

بخش ناراحت‌کننده‌ش اینه که این خرابی قبلاً مستند شده بود. روال rollback مال تجربه‌ی object storage، که تیر نوشته شده بود، با assertion ی درست تموم می‌شه: چک کن object storage غیرفعاله و کوئری بزن که صفر row با file_store = 2 باشه. چک بود. حتی چک درستی هم بود.

خرابی از این بود که قدم قبلی‌ش یه لیست دست‌نویس از اسم model ها رو دور می‌زد. هر کی runbook رو نوشته، table هایی رو که یادش می‌اومد فایل نگه می‌دارن شمرده: upload ها، artifact ها، package file ها و از این‌جور. Packages::PackageFile تو لیست بود. Packages::Npm::MetadataCache نبود، چون تیر کسی metadata cache رو به‌عنوان یه file store تو ذهنش نداشت، پس هیچ‌وقت assert نشد، پس همون یه row ی flip‌شده‌ش از rollback جان سالم به در برد، و اشاره‌ش بود به باکتی که همون موقع‌ها قرار بود پاک بشه.

یه چک که هست ولی اون چیزی که قراره بشکنه رو پوشش نمی‌ده از نداشتنش هم بدتره، چون اعتمادی می‌خره که لیاقتش رو نداره. حلش مکانیکیه: assertion های مربوط به coverage باید از schema لیست بکنن، نه از حافظه. یه کوئری information_schema همه‌ی table های کاندید رو پیدا می‌کنه، هر چقدرم که کسی موقع نوشتن runbook یادش نیومده باشه. اگه قدم verification ت یه لیست لفظی از اسم table ها داره، اون لیست یه حدسه و باید باهاش مثل یه حدس رفتار کرد.

تاریخ‌گذاری بمبِ زمینی

منسوب‌کردن outage سه دور طول کشید و دو دور اولش به دو جهت برعکس غلط بودن.

row هفت هفته قبل از کوچ سپتامبری قدمت داشت و تو هیچ‌کدوم از دو اکانت باکت object storage وجود نداشت، پس جواب اولم «احتمالاً قبل از جابه‌جایی خراب بوده» بود. بعد background job کل row رو برگردوند، با last_downloaded_at یی سه دقیقه بعد از updated_at. اون timestamp فقط تو مسیر موفق نوشته می‌شه، یعنی کش یه زمانی سرو شده بود، و من تصحیح کردم به «محرک احتمالاً همون جابه‌جاییه».

دفترچه قضاوت کرد. تجربه‌ی object storage و revert اش به ۲۴ تیر برمی‌گرده. آخرین خواندن موفق row مال ۲۲ تیره، دو روز زودتر، وقتی هنوز local بود. پس زنجیره این بود: migration ی تیر row رو remote کرد، rollback از روش رد شد، باکت پاک شد، و row هفت هفته بی‌خطر خوابید چون یه row با file_store = 2 فقط وقتی می‌ترکه که یه چیزی دقیقاً همون آبجکت رو بخونه. تا این هفته کسی اون پکیج رو pull نکرده بود. جابه‌جایی سپتامبر بی‌گناه بود؛ فقط یه دیتابیس رو حمل کرد که بمب زمینی رو از قبل توش داشت. هم‌بستگی تیم صادقانه و غلط بود، و من هم قبل از چک‌کردن بهش دامن زدم.

یه جزئیات لیاقت یه جمله‌ی جدا داره: flip شدن store با update_column انجام شده بود، که timestamp ها رو رد می‌کنه. پس updated_at ی اون row به فعالیت نامرتبط اشاره می‌کنه و هر کی بخواد تغییر رو فقط از رو row تاریخ‌گذاری کنه رو فعالانه گمراه می‌کنه. وقتی یه timestamp مهمه، اول نگاه کن اون ستون چطور نوشته شده، بعد بهش اعتماد کن.

بخش خطرناکش پاک‌کردنش بود

fix یه row بود، پس fix یه delete بود. اون delete تله‌ی خودش رو داشت: model های CarrierWave موقع destroy یه removal callback میزنن، و اون callback سعی می‌کنه فایل رو از backend ی کانفیگ‌شده‌اش پاک کنه، دقیقاً همون عملی که اروری رو بلند می‌کنه که داشتیم پاکش می‌کردیم. row باید با delete_all پاک می‌شد، که کلاً از callback ها رد می‌شه.

سه لایه بکاپ رفت جلو: یه RDS snapshot، که چیزیه که واقعاً row رو نگه داشته، snapshot از هر دو volume ی EBS، و یه dump از خودِ row با یه INSERT ی آماده. همه‌ش قبل از دست‌زدن به چیزی تأیید شد. API کش رو با metadata_cache&.file می‌خونه، پس نبودن row مستقیم می‌ره به مسیر regenerate: packument از روی فایل‌های پکیج دوباره ساخته و تازه ذخیره می‌شه.

verification اش بخش رضایت‌بخش بود. کش تازه با file_store = 1 روی دیسک local فرود اومد، با دقیقاً ۶۷۸۶ بایت، از نظر حجم یکی با کش تیر، که سند خوبیه برای این که محتوا سالم دور زده، نه این که فقط ارور دادن رو ول کرده. بعدش تو کل instance: صفر ۵xx، صفر row با store ی remote، و بیلدها برگشتن به زیر دو دقیقه.

چی باید موند

دو تا قانون از این ماجرا زنده بیرون اومدن. وقتی یه regression به شکل یه interval ی ثابتِ اضافه‌شده ظاهر شد، اول رفتار retry ی کلاینت رو بخون بعد برو سراغ منابع سرور؛ یه ۵۰۰ تو ۴۵ میلی‌ثانیه با دو دقیقه تأخیر دنبالش، یعنی کلاینت داره backoff ش رو قدم می‌زنه، نه این که سرور داره می‌جنگه. و وقتی قدم verification پوشش‌ش رو از رو حافظه لیست می‌کنه، لیست رو با یه کوئری رو schema عوض کن؛ table یی که یاد هیچ‌کی نیومده، جاییه که incident ی بعدی همین حالا توش نشسته.