Это была моя самая первая работа в сфере 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
У названий дней на английском есть забавное свойство:
| Название | Длина в символах |
|---|---|
| Sunday | 6 |
| Monday | 6 |
| Friday | 6 |
| Tuesday | 7 |
| Thursday | 8 |
| Saturday | 8 |
| Wednesday | 9 |
В среду, и только в среду, если кто-то изменял определенные настройки монитора определенным образом, два события могли произойти одновременно и вызвать сбой в базе данных. А сообщение об ошибке получалось длиной ровно 81 байт (включая нулевой символ), переполняло буфер и вызывало падение всей системы!
С тех пор я усвоил три вещи. Во-первых, всегда использовать автоинкрементный первичный ключ в любой потребовавшейся мне таблице. Во-вторых, логировать дату в формате ISO –
YYYY-MM-DD, без дней недели. Но самое главное – даже у самого случайного и непредсказуемого бага есть логичное объяснение, и его можно найти, если копнуть достаточно глубоко.
Комментарии (39)
Klaster
30.07.2015 18:25+2>>и его можно найти, если копнуть достаточно глубоко
Например потратить неделю на отладку. Почти всегда это непозволительная роскошь.
impwx Автор
30.07.2015 18:30+3Автор говорит, что можно, а уж нужно или нет — решать вам.
Klaster
30.07.2015 18:37+1ну если ресурсы не ограничены, то тут так то да, вообще никаких преград нет. Нет исходных кодов? Есть дизасемблер, не знаешь асм, не беда его можно изучить и вернуться к вопросу. Слишком много кода? Можно нанять помощников, ну и тд
BlessMaster
02.08.2015 19:47+4Если в результате багов будут теряться миллионы, или хуже того — умирать люди, о «непозволительной роскоши» придётся рассказывать не в комментариях
Colwin
04.08.2015 11:01+1
Насколько я помню, для такого рода систем даже вводят формальные доказательства корректности программ. Что очень накладно по времени.
grossws
05.08.2015 07:40Зачастую верификация просто невозможна. Если говорить за life-critical embedded, то, например, когда программа работает на неидельной железке (что всегда так, вопрос вероятностей сбоев) у которой есть пачка аппаратных багов, бывают flip'ы битов памяти и т. п. казусы, защищаются всякими watchdog'ами, дополнительным контролем, использую мажоритарное принятие решения системой и прочее. А от части человеческих ошибок стараются защититься всякими стандартами типа MISRA C.
Self_Perfection
30.07.2015 18:36+29Из той же серии: OpenOffice не печатает по вторникам bugs.launchpad.net/ubuntu/+source/cupsys/+bug/255161/comments/28
sim-dev
30.07.2015 18:50+3Честно говоря, теперь страшно ложиться в больницу — оно-то и раньше было не особо спокойно было, а теперь и на технику надежды нет… Вдруг и сегодня кто-то использует последнее слово в программировании?!
Muzzy0
04.08.2015 10:01+1Если б вы знали, как делается промышленная автоматика (и, собственно, не только промышленная, а в целом) — вам было бы страшно выходить на улицу вообще
bak
30.07.2015 20:07+7и его можно найти, если копнуть достаточно глубоко.
Самого главного не усвоил — копать надо экскаватором или на худой конец лопатой. Для поиска причины падений обычно используют core-dumps / отладчик / стек-трейс. Такая элементарная ошибка была бы видна на первом же трейсе — segfault во время вызова printf (использования printf при разработке на c++ — вообще отдельный вопрос).
vsb
30.07.2015 20:08-4Жаль тогда не было valgrind-а, шикарный инструмент, такие баги влёт отлавливает.
mayorovp
30.07.2015 20:17+21Раз начали делиться историями, то и я напишу. Однажды перестал собираться проект в TFS. Причем как перестал — очень странно. Билд просто не начинался, ошибка возникала непосредственно при попытке запуска, выдавая диалоговое окно, сообщающее про конфликт первичного ключа. Причем иногда все-таки работал — так и жили. Пытались запустить до тех пор, пока вдруг не получалось.
Искал я причину в интернете долго (два месяца) — но в итоге догадался декомпилировать код сервера, чтобы посмотреть где же он падает. Выяснил, что падает в хранимой процедуре. Декомпилировать хранимую процедуру было куда сложнее: она была шифрованной, а программа для расшифровки — шароварной. А триальном же режиме программа расшифровывала лишь первые 200 байт — и в них не вмещался даже заголовок хранимки.
Что мешало программу купить — уже не помню. То ли были серьезные подозрения на кота в мешке, то ли не было возможности перевести автору деньги, то ли денег не было, но наверное просто жаба душила платить довольно крупную сумму за программу для разовой работы с неизвестной заранее пользой. Коллега за ночь взломал защиту той программы, и удалось продолжить исследования.
Выяснилось, что все билды в TFS лежат в одной таблице, первичным ключом билда при этом является его имя. И это самое имя присваивается билду аж три раза. Сначала создается запись в БД с автоинкрементным числом вместо имени, потом это число заменяется на временное имя вида BuildDefinitionName.20150730.5
Третий раз имя билда меняется уже в процессе самого построения, в процессе выполнения задачи AssignBuildName.
Второе имя билда еще может промелькнуть в интерфейсе — а в случае серьезных проблем со сборкой даже остаться там — но первое имя билда увидеть практически невозможно, поэтому его существование стало сюрпризом.
Теперь в чем была проблема. Дело в том, что мы присваивали нашим билдам имена на основе нашего собственного автоинкрементного счетчика версий. Причем, поскольку мы мигрировали с другой системы построения, а не начинали проект сразу в TFS — наши номера билдов начинались где-то с 1900. И, спустя полгода после миграции, внутренний счетчик билда TFS дошел до этой цифры. Тогда-то все и началось!
Когда причина проблемы стала ясна, решилась проблема очень просто: я просто стал добавлять префикс «b» всем билдам, плюс добавил его всем старым билддам в БД простым UPDATE. После этого все заработало. С тех пор я полюбил смотреть в чужие исходники, и часто обращаюсь именно к этому способу решения мистических проблем…
quux
30.07.2015 21:15+21Эта статья могла уместиться в 3-4 предложения. Бывают же такие любители рассказать поинтересней.
Mishok2000
31.07.2015 00:49Когда читал: «Несколько недель бесплодных экспериментов привели меня в полное отчаянье. Я докатился до того, что добавил вывод printf после каждой чертовой строчки кода между получением данных из серийного порта и записью их в базу данных… » — я прям представлял, как вы злились и чувствовали себя.
К сожалению, подобного рода ситуации встречаются с каждым программистов, даже при использовании уже отточенной для себя технологии.
Igor_Sib
31.07.2015 08:18-6Поведаю об одном интересном баге, который правил недавно, и в котором отчасти виноват лично ДА Медведев:
Игра, в игре есть арена. Раньше все работало хорошо, потом вдруг в некоторых на первый взгляд произвольных случаях вызов на арену перестал работать.
Отправляется заявка на сервер, в ней передается время. Если в течении минуты никто не вызвал игрока — то заявка снимается. Долго не мог понять, дело оказало в следующем: оказалось что UTC time в один и тот же момент времени возвращает разные значения. В зависимости от версии iOS. На старых iOS был еще перевод на летнее время, потом этот балбес Медведев начал крутить стрелки, вышла новая версия, потом еще из думы руки приложили переведя стрелки еще раз. Естесвенно программисты в Apple это предугадать не могли и каждая версия iOS переходит (или не переходит) на летнее время по разному. В результате всякие уведомления и напоминания на старой версии приходят с разницей в час, ну и в игре у нас заявка приходила уже устаревшей (на час) и сразу снималась. То, что GetTimeUTC может вернуть разные значения и его нельзя использовать для синхронизации — для меня было открытием.
Рассказал жене — они грит на работе у них программисты сталкивались с похожим багом, тоже нелестно отзывались о крутителях стрелок.
norlin
31.07.2015 09:06+4То есть, вы на веру принимаете время, переданное с клиента?
Igor_Sib
31.07.2015 09:59Там используется Photon (который не сервер, обычный) — то есть там обеспечивается взаимодействие и обмен данными между клиентами, сервера как такового нет. Сервер просто тиражирует заявку всем клиентам, передает её. Получается что да, но там иначе не сделаешь, или надо лицензию на сервер покупать.
norlin
31.07.2015 10:20+1Отправляется заявка на сервер, в ней передается время. Если в течении минуты никто не вызвал игрока — то заявка снимается
Тогда вопрос – заявка снимается кем именно? Самим клиентом? или «тиражирующим» сервером?
Если самим клиентом – тогда в чём проблема, в пределах одного клиента время будет правильным.
Если сервером – то снова встаёт вопрос о том, зачем нужно передавать время с клиента.Igor_Sib
31.07.2015 10:38+1Сервера нет (вернее он просто соединяет клиентов, пересылая данные). У каждого клиента она считается не актуальной — так наверно правильнее сказать.
olegy
04.08.2015 12:07Бгг, когда то столкнулся с кодом, который начинал падать после пары недель работы, коллега который к тому времени уже уволился, любил писать код:
char buffer[48]; sprintf(buffer, "insert into aaa(f1,f2,f3) values(%d,%d,%d)", index1, index2, index3);
Он не учитывал, что 32битный инт в десятичном представлении мог занимать до 11 символов (-2147483647).
Acuna
04.08.2015 14:08Повезло Вам с летней практикой! Я вот сотню ADSL-модемов тестировал на работоспособность, просто выходя через них в инет(
putnik
Всё равно 1 августа программа превратилась бы в тыкву, чего уж тут на среды жаловаться.
mark_ablov
Неа.
Friday всего 6 символов, даже если бы выводилось «01» вместо «1», то краша всё равно не было бы.
А вот 2ое или 3ье августа, это да.
TimsTims
Дело не в пятнице.
1е августа 2015- суббота.
Saturday = 8символов.
Да еще и название месяца не короткое July(4), а длинное August(6). Про September(9) я вообще молчу
mark_ablov
А 1е августа 1997?
putnik
Да, вы правы. В августе программа бы работала аж три дня в неделю. А вот в сентябре её бы окончательно накрыло.
Вывод: не затягивайте со сроками сдачи =)