В минувшую субботу мне пришлось в весьма напряженной обстановке разбираться с жалобами важного клиента на взаимодействие между нашим и их софтом (о чем коротко я написал). С самого начала были у меня сильные подозрения, что ошибка где-то на той стороне, поскольку у нас пули вылетали, но вот доказательств и объяснений не было. А, поскольку клиент очень большой и деньги платит, а мы хоть и гордые, но маленькие, то оправдываться нужно было нам :)
В конце-концов, где-то в 23:00 ко мне дошли достаточного размера фрагменты логов софта клиента для того, чтобы найти причину проблем (кстати, что еще раз доказывает старую истину о том, что логов много не бывает). Оказалось, что при некотором стечении обстоятельств цикл разбора бинарного пакета в их ПО превращается в бесконечный. И, к несчастью, именно с ночи пятницы и всю субботу эти обстоятельства стекались в самом худшем направлении очень часто :(
Но я написать хотел совсем не об этом. Самое замечательное – это то, как я заметил сам факт зацикливания. Вот уж где цепь нелепых случайностей!
У меня рабочий ноутбук – HP ProBook с влагонепронецаемой клавиатурой. Из-за чего зачастую клавиши не срабатывают – нажмешь какую-нибудь недостаточно сильно и никакого эффекта. Особенность неприятная (особенно при вводе паролей), но к ней я уже привык. Поэтому, если я что-то нажал, а ничего не произошло, то по привычке неосознанно повторяю комбинацию клавиш, подразумевая, что клавиатура опять не сработала.
Полученные от клиента логи я просматривал в FAR-е, в его стандартном FileViewer-е. Просматривал, просматривал, строчек там много, полезную информацию выискивать тяжело. Потом обнаружил, что интересующие меня строки начинаются с фразы “Получен пакет”. Ну, недолго думая, нажимаю в просмотрщике F7 (поиск подстроки), ввожу нужную фразу, жму OK, нахожу следующую нужную мне строку. А потом нажимаю Shift-F7 (продолжение того же поиска), потом еще и еще раз… И осознаю, что на экране-то ничего не меняется.
Ну, думаю, клавиатура опять глючит. Начинаю нажимать сильнее и аккуратнее. Опять ничего не меняется. Бля, думаю, только сломавшейся клавиатуры мне сейчас не хватает. В полном ахуе еще раз несколько раз Shift-F7 – опять ничего не изменилось! Уж не помню, какие матерные слова я тогда высказал в адрес всего света вообще и водонепроницаемых клавиатур HP в частности, но попытки “правильно” нажать Shift-F7 повторял. И вдруг краем глаза заметил, что на экране что-то изменилось. Что не понял, но что-то точно поменялось. Начал присматриваться повнимательнее, но ничего конкретного не замечал. Тем не менее Shift-F7 повторять продолжал. За что был вознагражден – внезапно сменилось время в строках лога на экране. До этого было, скажем, 14:23:18, а стало 14:23:19.
Тут-то до меня стало доходить. Оказывается, в логе постоянно дублировался один и тот же фрагмент из нескольких сотен полностью одинаковых строк. Началом фрагмента была как раз строка с фразой “Получен пакет”. После первого поиска эта фраза оказалась у меня в центре экрана. При последующих поисках FAR позиционировал новую найденную строку на том же самом месте. А поскольку фрагменты были одинаковые, то несколько предшествующих ей строк и несколько следующих за ней строк были точно такими же. Поэтому-то я разницы не видел.
В первый раз что-то изменилось на экране когда просмотрщик указал новый процент – в правом верхнем углу 6% сменилось на 7% :) А уже после этого поменялось время в записях лога.
Когда я понял, что в логе дублируются одинаковые строки с одинаковыми результатами разборов якобы разных пакетов стало очевидно, что причина в зацикливании. Ну а дальше уже было дело техники :)
Но вот сколько времени мне пришлось бы потратить, чтобы понять, что фрагменты лога повторяются, если бы FAR не позиционировал найденные строки на одном и том же месте экрана – вот этого уже не узнать :)
Кстати, адреналиновый заряд, который я получил в момент “прозрения” был одним из самых сильных за последнее время. Очень нехилая встряска, когда вдруг все фрагменты мозаики с калейдоскопической быстротой складываются в целостную картинку и ты понимаешь, что ты прав даже не разумом, а каждой клеточкой своего тела!
Ну а сегодня и клиент окончательно подтвердил правильность наших догадок.
PS. Еще одна мораль сей басни – время в логах нужно писать, по крайней мере, с миллисекундами. А то при нынешней технике одна секунда работы – это очень и очень много :)
Комментариев нет:
Отправить комментарий