Откиньтесь на спинку кресла и отдохните – пришло время рассказать об одном из моих самых любимых багов.
Это была моя самая первая работа в сфере IT – летняя практика в компании, разрабатывающей очень серьезное медицинское оборудование, в частности системы подачи анестезии и мониторы для пациентов больниц. Монитор для пациента – это такая попискивающая коробка рядом с лежачим больным, которая меряет пульс, давление, частоту дыхание и прочее, а также оповещает медсестер в случае неприятностей. Офис был полон двухметровых баллонов с веселящим газом, по нему расхаживали роскошнобородые гуру-эксперты по встраиваемым системам, и были целые комнаты-хранилища специально для документации, необходимой для сертификации различного оборудования. Народ до сих пор шепотом рассказывал об одном баге, пропущенном тестировщиками с десяток лет назад, из-за которого система подачи анестезии перезапустилась посреди операции. Стоит ли говорить, что зеленого сопляка-студента вроде меня и за километр бы не подпустили к боевым системам?
Вместо этого мне поручили проект-прототип с целью опробовать в действии самые горячие технологические новинки 1997 года – сервер на C++, который бы слушал мониторы по последовательному порту, сливал интересные данные в базу на SQL Server и отправлял их на Java-апплет через CORBA, чтобы доктора и родственники могли следить за самочувствием больного через интернет. Красота же! Особенно с учетом того, что практического опыта у меня не было ни с одной из этих систем и технологий!
После нескольких недель адского костылестроения, преимущественно потраченных на курение мануалов от Visibroker ORB и утомительное вылавливание ошибок приведения типов, моя система «Симпсон» была более-менее готова. Сервер «Гомер» сохранял и выдавал данные, а клиент «Барт» отображал их для пользователя. За это время я узнал, что CORBA – безнадежно перемудрена, AWT – это жесть (GridBagLayout-ы, бррр!), апплеты работают с черепашьей скоростью – но в остальном Java вроде неплохой язык. Беспокоил только один мелкий баг – время от времени сервер на С++ падал, и я решил выяснить причину.
Поскольку в соседней комнате у нас был тестовый стенд с настоящим монитором, во время разработки и тестирования я пользовался крайне удобным «демо-режимом», радостно воспроизводящим по кругу имитацию сердечного приступа. В этом режиме мой сервер ни разу не упал – он делал это иногда во время ручного управления монитором, особенно во время показов, но хоть ты тресни, я не мог добиться стабильного воспроизведения сбоя. Я добавил логирование ко всем событиям, бегал туда-сюда между монитором и своим рабочим местом, медленно и вдумчиво воспроизводя необходимые шаги («установите фильтр в X, поверните ручку управления ровно на три деления по часовой, нажмите сюда…»), но падение не воспроизводилось. Чем бы ни было это «злобное событие», как я его прозвал, оно избегало любого логирования! Может быть, проблема была в I/O или на уровне железа? Может быть, космические лучи сбрасывали биты в памяти моего компьютера?
Несколько недель бесплодных экспериментов привели меня в полное отчаянье. Я докатился до того, что добавил вывод printf после каждой чертовой строчки кода между получением данных из последовательного порта и записью их в базу данных… и в процессе, просмотрев каждую из этих строчек по много раз, до меня вдруг дошло.
Когда я описывал схему базы данных, в необъяснимой попытке сэкономить место, я по глупости и малолетству использовал timestamp события в качестве первичного ключа. Если два события придут в одну и ту же миллисекунду, база выкинет исключение о нарушении уникальности. Я обнаружил это довольно рано, но подумал, что это может произойти только в каких-то совсем странных случаях, когда кто-то копается во внутренних настройках монитора, и с чистой совестью обернул этот код в try/catchс логированием ошибки.
Но! Код логирования был написан в олдскульном стиле, и текст ошибки записывался в строковой буфер длиной 80 символов. Сообщение о нарушении уникальности ключа всегда было одинаковым, однако перед ним ставилась дата в расширенном формате на английском, типа такого:
Monday, July 17, 1997, 10:38:47.123
У названий дней на английском есть забавное свойство:
Уже догадались?
В среду, и только в среду, если кто-то изменял определенные настройки монитора определенным образом, два события могли произойти одновременно и вызвать сбой в базе данных. А сообщение об ошибке получалось длиной ровно 81 байт (включая нулевой символ), переполняло буфер и вызывало падение всей системы!
С тех пор я усвоил три вещи. Во-первых, всегда использовать автоинкрементный первичный ключ в любой потребовавшейся мне таблице. Во-вторых, логировать дату в формате ISO – YYYY-MM-DD, без дней недели. Но самое главное – даже у самого случайного и непредсказуемого бага есть логичное объяснение, и его можно найти, если копнуть достаточно глубоко.