Перезапуск по Watchdog

[san]

В последнее время участились случаи перезапусков блоков по WD, похоже на системную проблему.
Не хочется всё мешать в кучу, но создавать отдельный тикет на каждый WD reset, мне кажется не разумно, предлагаю обсуждать случаи непонятных WD reset-ов в этой теме.

Проделал одинаковые действия с двумя блоками последовательно, на обоих получил перезапуск по ватчдогу.
Действия

1. На вкладке разное, нажал на значок "очистить конфиг" и согласился на перезапуск swd.
2. Зашел в окно конфигурации платы SM-01 на 16-м месте, настроил плату, нажал применить и согласился на перезапуск.
3. После перезапуска SM или во время, точно не заметил, swd перезапустился по ватчдогу

• Перезапуски в 17-05 и 17-09 23.10.2017 (Время Екб.)
• r1607
• Логи с блоков разместил в xchange\alx\SW-01_test_and_bugs\перезапуск_WD\на_столе\

[alx]

Проделал описанную процедуру много раз. Воспроизвести перезапуск платы не удалось. Вероятно, в описании упущены какие-то существенные детали.

Саша, можешь уточнить свои действия, чтобы удалось воспроизвести ситуацию?

[alx]

Только сейчас заметил одну странность. Вот фрагмент лога моего эксперимента:

Oct 25 10:12:53 sw01 daemon.info swd[561]: New board SM-01 in slot 16
Oct 25 10:12:54 sw01 daemon.info swd[561]: New board FS-08 in slot 11
Oct 25 10:13:12 sw01 daemon.info swd[561]: admin from [192.168.0.75]: writing variable(s) to slot 16
Oct 25 10:13:13 sw01 daemon.info swd[561]: admin from [192.168.0.75]: writing variable(s) to slot 16
Oct 25 10:13:14 sw01 daemon.info swd[561]: slot 16: board SM-01 lost in space
Oct 25 10:13:35 sw01 daemon.info swd[561]: New board SM-01 in slot 16
Oct 25 10:13:40 sw01 daemon.info swd[561]: slot 16: start alarm E1: LOS (нет входного сигнала)
Oct 25 10:13:40 sw01 daemon.info swd[561]: slot 16: start alarm DSLA: LOS (нет входного сигнала)
Oct 25 10:13:40 sw01 daemon.info swd[561]: slot 16: start alarm DSLB: LOS (нет входного сигнала)
Oct 25 10:13:42 sw01 daemon.info swd[561]: slot 16: start alarm ALARM (Общая авария платы)

А вот фрагмент лога, зафиксировавшего перезапуск по WDT:

Oct 23 12:04:19 sw01 daemon.info swd[1483]: starting swd-r1607
Oct 23 12:04:19 sw01 daemon.info swd[1483]: current storage database version is 1
Oct 23 12:04:19 sw01 daemon.info swd[1483]: zabbix-agent.cpp:735: Zabbix agent started
Oct 23 12:04:19 sw01 daemon.info swd[1483]: Current FPGA revision is 9
Oct 23 12:04:19 sw01 daemon.info swd[1483]: current logins database version is 2
Oct 23 12:04:19 sw01 daemon.info swd[1483]: my address is 9
Oct 23 12:04:19 sw01 daemon.info swd[1483]: HTTP daemon started
Oct 23 12:04:19 sw01 daemon.info swd[1483]: HTTP IPv6 daemon started
Oct 23 12:04:19 sw01 daemon.err swd[1483]: cannot start HTTPS IPv4 daemon
Oct 23 12:04:19 sw01 daemon.err swd[1483]: cannot start HTTPS IPv6 daemon
Oct 23 12:04:19 sw01 daemon.info swd[1483]: New board SW-01 in slot 9
Oct 23 12:04:19 sw01 daemon.info swd[1483]: slot 03: switching to CRC32 mode
Oct 23 12:04:20 sw01 daemon.info swd[1483]: New board VE-01 in slot 3
Oct 23 12:04:21 sw01 daemon.info swd[1483]: New board PS-220D in slot 18
Oct 23 12:04:21 sw01 daemon.info swd[1483]: New board TE-01 in slot 15
Oct 23 12:04:21 sw01 daemon.info swd[1483]: New board SM-01 in slot 16
Oct 23 12:04:21 sw01 daemon.info swd[1483]: slot 16: start alarm ALARM (Общая авария платы)
Oct 23 12:04:21 sw01 daemon.info swd[1483]: New board PD-04 in slot 2
Oct 23 12:04:21 sw01 daemon.info swd[1483]: New board PE-04 in slot 1
Oct 23 12:04:23 sw01 daemon.warn swd[1483]: --> timer callback scheduled from board_SW.cpp:227 executed 163 ms
Oct 23 12:04:23 sw01 daemon.warn swd[1483]: --> timer callback scheduled from board_SW.cpp:227 executed 133 ms
Oct 23 12:04:23 sw01 daemon.warn swd[1483]: --> timer callback scheduled from board_SW.cpp:227 executed 102 ms
Oct 23 12:04:23 sw01 daemon.warn swd[1483]: --> timer callback scheduled from board_SW.cpp:227 executed 132 ms
Oct 23 12:04:23 sw01 daemon.warn swd[1483]: --> timer callback scheduled from board_SW.cpp:227 executed 145 ms
Oct 23 12:04:23 sw01 daemon.warn swd[1483]: --> timer callback scheduled from board_SW.cpp:227 executed 130 ms
Oct 23 12:04:24 sw01 daemon.warn swd[1483]: --> timer callback scheduled from board_SW.cpp:227 executed 164 ms
Oct 23 12:04:24 sw01 daemon.warn swd[1483]: --> timer callback scheduled from board_SW.cpp:227 executed 171 ms
Oct 23 12:04:27 sw01 daemon.warn swd[1483]: --> timer callback scheduled from board_SW.cpp:227 executed 139 ms
Oct 23 12:04:27 sw01 daemon.warn swd[1483]: --> timer callback scheduled from board_SW.cpp:227 executed 128 ms
Oct 23 12:04:27 sw01 daemon.warn swd[1483]: --> timer callback scheduled from board_SW.cpp:227 executed 129 ms
Oct 23 12:04:28 sw01 daemon.warn swd[1483]: --> timer callback scheduled from board_SW.cpp:227 executed 110 ms
Oct 23 12:04:28 sw01 daemon.warn swd[1483]: --> timer callback scheduled from board_SW.cpp:227 executed 104 ms
Oct 23 12:04:52 sw01 daemon.info swd[1483]: slot 16: start alarm DSLB: LOS (нет входного сигнала)
Oct 23 12:04:53 sw01 daemon.info swd[1483]: slot 16: start alarm DSLA: LOS (нет входного сигнала)
Oct 23 12:05:57 sw01 syslog.info syslogd started: BusyBox v1.18.5

Странно, но в логе нет записи о записи в плату SM-01! Это, мне кажется, противоречит пункту 2 описания тикета...

[alx]

Ага, нашел в логе запись в плату SM-01:

Oct 23 12:07:16 sw01 daemon.info swd[254]: admin from [192.168.1.237]: writing variable(s) to slot 16
Oct 23 12:07:21 sw01 daemon.info swd[254]: admin from [192.168.1.237]: writing variable(s) to slot 16
Oct 23 12:07:22 sw01 daemon.info swd[254]: slot 16: board SM-01 lost in space
Oct 23 12:07:42 sw01 daemon.info swd[254]: New board SM-01 in slot 16
Oct 23 12:07:48 sw01 daemon.info swd[254]: slot 16: start alarm DSLA: LOS (нет входного сигнала)
Oct 23 12:07:48 sw01 daemon.info swd[254]: slot 16: start alarm DSLB: LOS (нет входного сигнала)
Oct 23 12:07:49 sw01 daemon.info swd[254]: slot 16: start alarm ALARM (Общая авария платы)
Oct 23 12:08:05 sw01 daemon.info swd[254]: slot 16: end alarm DSLA: LOS (нет входного сигнала) (duration 17 s)
Oct 23 12:08:05 sw01 daemon.info swd[254]: slot 16: start alarm DSLA: RemA (авария удаленной стороны)
Oct 23 12:08:07 sw01 daemon.info swd[254]: slot 16: end alarm DSLB: LOS (нет входного сигнала) (duration 19 s)
Oct 23 12:08:07 sw01 daemon.info swd[254]: slot 16: start alarm DSLB: RemA (авария удаленной стороны)
Oct 23 12:08:15 sw01 daemon.info swd[254]: admin from [192.168.1.237]: sound disabled
Oct 23 12:08:22 sw01 daemon.info swd[254]: slot 16: end alarm DSLA: RemA (авария удаленной стороны) (duration 17 s)
Oct 23 12:08:24 sw01 daemon.info swd[254]: slot 16: end alarm DSLB: RemA (авария удаленной стороны) (duration 17 s)
Oct 23 12:08:25 sw01 daemon.info swd[254]: slot 16: end alarm ALARM (Общая авария платы) (duration 36 s)

На этом лог закончился. Вывод: судя по логу, запись конфигурации в плату SM-01 и ее последующий рестарт к перезагрузке платы SW-01 не приводили.

[alx]

В другом логе (192.168.1.251) я вижу, что, действительно, за записью в плату SM-01 последовал рестарт SW-01 по WDT.

[san]

Теперь я сомневаюсь.
Судя по логу 1.102 и правда записи в SM-01 не было...

[alx]

Из лога 192.168.1.251 видно, что после рестарта SM-01 плата появилась, заработала (начала выдавать аварии), и после этого прошло больше 4 минут прежде чем SW-01 ушла в перезагрузку. Так что я сомневаюсь в том, что рестарт SM-01 мог быть непосредственной причиной.

С другой стороны, рассматривая другие логи, я уже замечал, что перезагрузке SW-01 по WDT часто предшествует появление сообщения об аварии в плате SM-01, а точнее, не аварии, а извещения об аварии удаленной стороны (DSLA: RemA). В данном случае в блоке (192.168.1.251) они есть, хотя к моменту перезагрузки они успели закончиться...

[san]

Сделал в веб-морде перезапуск swd, в результате получил WD reset.
27.11.2017 - 11:34
r1636
логи: xchange\alx\SW-01_test_and_bugs\перезапуск_WD\на_столе\WDreset_вместо перезапуска_192.168.1.251.tar.gz

[san]

Расширил описание тикета и повысил приоритет

[alx]

Replying to san:

Расширил описание тикета и повысил приоритет

Саша, по какой причине ты установил этому тикету высокий приоритет? Я как раз хотел сделать обратное - понизить его... Соображения мои следующие:

• самопроизвольная перезагрузка по WD происходит с довольно низкой вероятностью.
• даже если самопроизвольная перезагрузка происходит, она не приводит к нарушению ("коммерческой") связи, происходит всего лишь 20-секундный перерыв в работе веб-интерфейса.

Поэтому лично я не вижу причин считать эту проблему достаточно серьезной...

С предложением не заводить новый тикет по каждому случаю перезагрузки по WD я, конечно, согласен.

[san]

она не приводит к нарушению ("коммерческой") связи

Дело в том что после перезапуска происходит запись конфига в платы, а некоторые платы изменяют состояние своих входов/выходов в момент записи, например E1-08, переводит порты сначала в блокированное состояние, а затем записывает в них конфиг и разблокирует порты, в результате таких манипуляций возможны нарушения связи.
В связи с этими особенностями перезапуска, пользователи уделяют повышенное внимание к этой проблеме...

[san]

В том-же блоке что и comment:7 попробовал ещё раз перезапустить swd, всё прошло штатно, затем в ходе своих экспериментов сделал перезагрузку блока и снова получил WD reset
27.11.2017 - 11:57
attachment:messages_1.251​​

[alx]

Replying to san:

Дело в том что после перезапуска происходит запись конфига в платы, а некоторые платы изменяют состояние своих входов/выходов в момент записи, например E1-08, переводит порты сначала в блокированное состояние, а затем записывает в них конфиг и разблокирует порты, в результате таких манипуляций возможны нарушения связи.

Так это ИМХО баг платы E1-08, а не SW-01! Логика подсказывает, что если плате дают конфигурацию, которая в ней уже есть, то ничего в ее работе измениться не должно, и уж тем более, не должно ничего при этом ломаться! В данном примере "переводит порты сначала в блокированное состояние" - это баг, так как в конфигурации, которую передали плате, блокировка портов отключена. Создал тикеты ​mc-04:#175 и ​mc-04:#176.

В связи с этими особенностями перезапуска, пользователи уделяют повышенное внимание к этой проблеме...

Я думаю, не менее "повышенное" внимание они вынуждены уделять любой записи конфигурации в платы GE-xx, так как, например, включение/выключение порта 4 неминуемо ведет к кратковременному пропаданию линка портов 1, 2 и 3, которые находятся в работе под коммерческой нагрузкой, и конфигурацию которых никто не менял... Причем возникает это, в отличие от WD reset'а, со 100% вероятностью. А конфигурация-то платы случается почаще чем обновление прошивки блока... Так что не надо валить с большой головы на здоровую... :)

[alx]

Replying to san:

Сделал в веб-морде перезапуск swd, в результате получил WD reset.
27.11.2017 - 11:34
r1636

Replying to san:

В том-же блоке что и comment:7... сделал перезагрузку блока и снова получил WD reset

По сомптомам, это были случаи тикета #287. Если так, то это уже исправлено. Если хочешь поэкспериментировать, то можно обновить sw из ​http://192.168.0.62/ipk

[san]

конфигурация-то платы случается почаще

Вообще довольно редкое событие, да и, по крайней мере, предсказуемое - переконфигурация блоков обычно делается в специально отведённое время, с предупреждением служб пользующихся каналом связи, на фоне этого проблемы любой конфигурации не видны.

В остальном согласен. По поводу приоритета, давай обсудим отдельно оффлайн.

[alx]

Replying to san:

переконфигурация блоков обычно делается в специально отведённое время, с предупреждением служб пользующихся каналом связи

В том-то и дело, что пользующихся каналом связи! Представь, что ты - оператор, сдающий в аренду потоки E1. У тебя в блоке стоит плата E1-08, потоками которой пользуются твои клиенты. И вот тебе требуется изменить режим работы восьмого потока. Понятное дело, что своего клиента, арендующего этот поток, ты предупредишь. Но кому придет в голову обзванивать и предупреждать семь других клиентов, арендующих семь других потоков? И разве нормально, что вообще требуется обзванивать семь других арендаторов и предупреждать их о том, что у них будет нарушение связи из-за того что ты выделяешь восьмой поток для восьмого арендатора? По-моему нет...

[san]

И разве нормально... ? По-моему нет...

Согласен.

Одну из плат, которые периодически перезапускались и перезапуску предшествовало завершение аварии TE-01, обновили до r1636, после этого был ещё один случай перезапуска, вот свежий лог: attachment:messages.20.67​​

[alx]

Replying to san:

вот свежий лог: attachment:messages.20.67​​

К сожалению, не вижу в нем ничего, что могло бы помочь...
В 05:36 возникла авария платы TE-01, и через 80 секунд - перезагрузка... По крайней мере мы можем исключить проблему с основным рабочим потоком - если бы он остановил работу, другой поток вывел бы в лог соответствующее сообщение...

Похоже что проблема развивалась очень быстро, и программа не успела обнаружить никаких тревожных симптомов, предшествующих ресету. Может swd просто упал по какому-то сигналу, типа SIGSEGV?..

Кстати, уже после перезагрузки, в 06:37 есть странное сообщение: timer callback scheduled from transport.cpp:1368 executed 984 ms. В указанном callback'е всего-то три существенные строчки:

void Transport::free_id(void *context)
{
    TransportId *tid = (TransportId *)context;
    Transport *transport = tid->first;
    {
        MUTEX_AUTO_LOCK(&transport->wmutex);
        transport->wmap.erase( tid->second );
    }
    delete tid;
}

wmutex нигде не может захватываться на длительное время, там все операции короткие. wmap - это хэш размером не более 256... Нечему тут выполняться почти секунду. Косвенно это может свидетельствовать о том, что общая загруженность системы в этот момент была очень высокой, поэтому основной тред swd, выполнявший free_id(), получал мало процессорного времени, и выполнение растянулось почти на секунду...

[alx]

Замечено, что если в блоке мониторится много параметров, то парсинг и обработка их списка занимает много времени. Так, на "Нижнем Самурае" сейчас мониторится ~3300 параметров, и после получения их списка от сервера парсинг и обработка списка длятся почти 4 секунды. В это время захвачен mutex, и если в момент начала опроса в блоке возникнет или пропадет авария, основной рабочий поток будет ждать освобождения mutex'а чтобы передать агенту сообщение.

4 секунды - это, конечно, недостаточно чтобы сработал WDT (для этого надо блокировать рабочий поток более чем на 15 секунд), а блок, в котором мониторятся десятки тысяч параметров представить себе трудно, тем не менее, я решил изменить алгоритм работы с данными агента Zabbix: он будет быстро копировать все нужные данные себе во временный объект, потом работать с временным объектом, и в конце работы быстро копировать данные обратно. Mutex будет захватываться только на время копирования.

[alx]

Сделано в r1653.

[san]

Ещё один случай от Вити r1667​

[alx]

Replying to san:

Ещё один случай от Вити r1667​

Интересный случай... Здесь сегодня в 08:03 admin с адреса 10.6.51.111 что-то записывал в плату GE-12. Тремя минутами позже в логе появились многочисленные записи планировщика о том, что запланированные callback'и выполняются подозрительно долго. Больше всего (около секунды) выполняются колбэки, запланированные в prestera.cpp:883. Это обработчик RSTP/LACP, где выполняется прием и обработка PDU. В норме этот обработчик вызывается каждые 100 мс (а выполняется, наверное, менее 1 мс). То, что он выполнялся на 3 порядка дольше, говорит о том, что либо внезапно резко возрос входящий трафик (стало приходить так много PDU, что требовалось много времени чтобы все это разгрести), либо общая загрузка системы (CPU) по каким-то причинам настолько возросла, что обработка пары пакетов стала длиться секунду...

Тот факт, что выполнялись какие-то манипуляции с GE-12, наводит на мысль, что проблема связана именно с сетью - то есть первое мое предположение мне кажется более вероятным. Что с этими выводами нам делать - я не знаю...

[san]

Насколько я понял, настройка блока происходила "на столе", т.е. не в "живой" сети, так-что внезапное возрастание входящего трафика мне кажется маловероятным...

[alx]

Replying to san:

Насколько я понял, настройка блока происходила "на столе", т.е. не в "живой" сети, так-что внезапное возрастание входящего трафика мне кажется маловероятным...

То, что настройка происходила "на столе", еще не означает, что блок не был подключен к сети. Настраивали-то с помощью веб-браузера, значит персональный компьютер был к нему подключен. И мне кажется маловероятным, что для рутинной настройки кто-то будет организовывать выделенную изолированную сеть. Скорее всего блок просто подключили к уже существующей "живой" сети, в которой находится компьютер...

Хотя, конечно, все это - не более чем гадания...

[san]

проблема связана именно с сетью - то есть первое мое предположение мне кажется более вероятным

Уточнил, во время настройки блок был в оптическом кольце, проблемы с сетью(шторм) вполне возможны в этом случае.

[alx]

Провел эксперимент: превратил плату SW-01 в слоте 16 в генератор MC/BC трафика (сделал кольцо, соединив порты eth1 и eth2), трафик из этой платы направил в CPU главной платы SW-01.

В результате, как только я снял ограничение трафика в CPU, я получил очень похожие симптомы. Вот что стало падать в системный лог:

Feb  1 08:37:55 sw01 daemon.warn swd[8057]: --> timer callback scheduled from prestera.cpp:883 executed 167 ms
Feb  1 08:38:20 sw01 daemon.warn swd[8057]: --> timer callback scheduled from transport.cpp:1038 executed 116 ms
Feb  1 08:38:42 sw01 daemon.warn swd[8057]: --> timer callback scheduled from prestera.cpp:883 executed 119 ms
Feb  1 08:39:07 sw01 daemon.warn swd[8057]: --> timer callback scheduled from prestera.cpp:883 executed 202 ms
Feb  1 08:39:26 sw01 daemon.warn swd[8057]: --> timer callback scheduled from prestera.cpp:883 executed 118 ms
Feb  1 08:40:12 sw01 daemon.warn swd[8057]: --> timer callback scheduled from prestera.cpp:883 executed 106 ms
Feb  1 08:40:27 sw01 daemon.warn swd[8057]: --> timer callback scheduled from prestera.cpp:883 executed 258 ms
Feb  1 08:40:41 sw01 daemon.warn swd[8057]: --> timer callback scheduled from prestera.cpp:883 executed 262 ms
Feb  1 08:40:48 sw01 daemon.warn swd[8057]: --> timer callback scheduled from prestera.cpp:883 executed 120 ms
Feb  1 08:41:05 sw01 daemon.warn swd[8057]: --> timer callback scheduled from prestera.cpp:883 executed 276 ms
Feb  1 08:41:38 sw01 daemon.warn swd[8057]: --> timer callback scheduled from prestera.cpp:883 executed 202 ms
Feb  1 08:42:14 sw01 daemon.warn swd[8057]: --> timer callback scheduled from prestera.cpp:883 executed 140 ms
Feb  1 08:42:32 sw01 daemon.warn swd[8057]: --> timer callback scheduled from transport.cpp:2177 executed 116 ms
Feb  1 08:42:41 sw01 daemon.warn swd[8057]: --> timer callback scheduled from transport.cpp:2177 executed 124 ms
Feb  1 08:43:05 sw01 daemon.warn swd[8057]: --> timer callback scheduled from prestera.cpp:883 executed 114 ms
Feb  1 08:43:32 sw01 daemon.warn swd[8057]: --> timer callback scheduled from prestera.cpp:883 executed 101 ms
Feb  1 08:43:42 sw01 daemon.warn swd[8057]: --> timer callback scheduled from prestera.cpp:883 executed 130 ms
Feb  1 08:43:56 sw01 daemon.info swd[8057]: admin from [192.168.0.75]: ethernet port 63 configuration changed
Feb  1 08:44:18 sw01 daemon.warn swd[8057]: --> timer callback scheduled from transport.cpp:2177 executed 121 ms
Feb  1 08:44:44 sw01 daemon.warn swd[8057]: --> timer callback scheduled from prestera.cpp:883 executed 173 ms
Feb  1 08:44:50 sw01 daemon.warn swd[8057]: --> timer callback scheduled from prestera.cpp:883 executed 108 ms

Что интересно, загрузка CPU при этом повысилась незначительно - до 1.6. И более 50% idle. Подозреваю, что у Вити ситуация усугублялась тем, что в кольцо был пойман BPDU и/или LACPDU, что вызывало их обработку в userspace.

[alx]

На производстве обнаружен метод более-менее стабильного воспроизведения зависания. Замечено, что оно всегда происходит при окончании аварии. Вот фрагмент лога с отладочным выводом в момент падения:

swd[1131]: slot 19: sending 8 bytes: 00 44 01 00 02 00 03 00
swd[1131]: slot 18: sending 8 bytes: 00 f0 01 00 02 00 03 00
swd[1131]: slot 18: 26 bytes received: 80 f0 01 00 00 01 1d 01 02 00 00 04 09 00 50 53 2d 32 32 30 44 03 00 00 00 02
swd[1131]: slot 18: start alarm ALARM (Общая авария платы)
swd[1131]: slot 20: sending 8 bytes: 00 ef 01 00 02 00 03 00
swd[1131]: slot 20: 26 bytes received: 80 ef 01 00 00 01 1d 01 02 00 00 04 09 00 50 53 2d 32 32 30 44 03 00 00 00 00
swd[1131]: slot 20: end alarm ALARM (Общая авария платы) (duration 750 s)
terminate called after throwing an instance of 'std::length_error'
  what():  basic_string::_S_create

Здесь видно, что был получен ответ на запрос переменных .1.0, .2.0 и .3.0, зафиксировано окончание общей аварии платы, после чего swd упал с непойманным исключением std::length_error.

[alx]

Обнаружена ошибка, приводившая к исключению: итератор списка аварий платы использовался после удаления указываемого им элемента! Ошибка могла проявляться только при условии, что на момент получения ответа на запрос переменной .3.0 со значением 0 (нет аварий) в списке аварий имелись аварии, которые не были очищены получением соответствующих TRAP'ов.

[alx]

In 1677/sw:

Исправлена ошибка, которая могла приводить к перезагрузке платы
SW-01 по watchdog, если на момент получения безаварийного статуса
(переменная .3.0 равна нулю) от какой-либо платы в списке аварий
этой платы были неочищенные аварии. See #297.