Opened 7 years ago

Closed 6 years ago

#297 closed баг (готово)

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

Reported by: san Owned by: alx
Priority: высокий Milestone: 1 очередь
Component: sw Keywords:
Cc: andrey, vlad

Description (last modified by 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\на_столе\

Attachments (3)

messages_1.251​ (57.2 KB ) - added by san 6 years ago.
messages.20.67​ (45.5 KB ) - added by san 6 years ago.
31_01_vitya.txt​ (75.9 KB ) - added by san 6 years ago.

Download all attachments as: .zip

Change History (32)

comment:1 by alx, 7 years ago

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

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

comment:2 by alx, 7 years ago

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

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 описания тикета...

comment:3 by alx, 7 years ago

Ага, нашел в логе запись в плату 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 не приводили.

comment:4 by alx, 7 years ago

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

comment:5 by san, 7 years ago

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

comment:6 by alx, 7 years ago

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

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

comment:7 by san, 6 years ago

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

Last edited 6 years ago by san (previous) (diff)

comment:8 by san, 6 years ago

Cc: vlad added
Description: modified (diff)
Priority: средний → высокий

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

in reply to:  8 comment:9 by alx, 6 years ago

Replying to san:

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

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

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

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

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

comment:10 by san, 6 years ago

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

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

by san, 6 years ago

Attachment: messages_1.251​ added

comment:11 by san, 6 years ago

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

in reply to:  10 comment:12 by alx, 6 years ago

Replying to san:

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

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

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

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

in reply to:  7 comment:13 by alx, 6 years ago

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

comment:14 by san, 6 years ago

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

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

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

in reply to:  14 comment:15 by alx, 6 years ago

Replying to san:

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

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

by san, 6 years ago

Attachment: messages.20.67​ added

comment:16 by san, 6 years ago

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

Согласен.

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

in reply to:  16 comment:17 by alx, 6 years ago

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(), получал мало процессорного времени, и выполнение растянулось почти на секунду...

comment:18 by alx, 6 years ago

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

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

comment:19 by alx, 6 years ago

Сделано в r1653.

comment:20 by san, 6 years ago

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

Jan 31 07:54:03 sw01 daemon.info swd[254]: admin from [10.6.51.111]: reboot initiated
Jan 31 07:54:03 sw01 daemon.info swd[254]: slot 04: board EM-04 lost in space
Jan 31 07:54:03 sw01 daemon.info swd[254]: slot 03: board EM-04 lost in space
Jan 31 07:54:03 sw01 daemon.info swd[254]: slot 20: board PS-48D lost in space
Jan 31 07:54:03 sw01 daemon.info swd[254]: slot 20: end alarm Отсутствует входное напряжение (duration 7717 s)
Jan 31 07:54:03 sw01 daemon.info swd[254]: slot 20: end alarm Отсутствует напряжение 12 В (duration 7717 s)
Jan 31 07:54:03 sw01 daemon.info swd[254]: slot 20: end alarm ALARM (Общая авария платы) (duration 7716 s)
Jan 31 07:54:03 sw01 daemon.info swd[254]: slot 21: board PS-48D lost in space
Jan 31 07:54:04 sw01 daemon.info swd[254]: New board EM-04 in slot 4
Jan 31 07:54:04 sw01 daemon.info swd[254]: New board PS-48D in slot 20
Jan 31 07:54:04 sw01 daemon.info swd[254]: New board EM-04 in slot 3
Jan 31 07:54:04 sw01 daemon.info swd[254]: New board PS-48D in slot 21
Jan 31 07:54:04 sw01 daemon.info swd[254]: slot 20: start alarm Отсутствует входное напряжение
Jan 31 07:54:04 sw01 daemon.info swd[254]: slot 20: start alarm Отсутствует напряжение 12 В
Jan 31 07:54:05 sw01 daemon.info swd[254]: slot 20: start alarm ALARM (Общая авария платы)
Jan 31 07:54:06 sw01 user.notice shutdown[1214]: shutting down for system reboot
Jan 31 07:54:06 sw01 daemon.info init: Switching to runlevel: 6
Jan 31 07:54:06 sw01 authpriv.info dropbear[241]: Early exit: Terminated by signal
Jan 31 07:54:06 sw01 daemon.notice ntpd[247]: ntpd exiting on signal 15
Jan 31 07:54:06 sw01 daemon.info snmpd[251]: Received TERM or STOP signal...  shutting down...
Jan 31 07:54:06 sw01 daemon.err swd[254]: got signal 15
Jan 31 07:54:06 sw01 daemon.info swd[254]: shutting down...
Jan 31 07:54:06 sw01 daemon.err swd[254]: accept connection error: Interrupted system call
Jan 31 07:54:06 sw01 daemon.crit swd[254]: queue.cpp:122: Queue is null!
Jan 31 07:54:06 sw01 daemon.info swd[254]: slot 02: board FS-08 lost in space
Jan 31 07:54:06 sw01 daemon.info swd[254]: slot 03: board EM-04 lost in space
Jan 31 07:54:06 sw01 daemon.info swd[254]: slot 04: board EM-04 lost in space
Jan 31 07:54:06 sw01 daemon.info swd[254]: slot 08: board E1-08 lost in space
Jan 31 07:54:06 sw01 daemon.info swd[254]: slot 09: board SW-01 lost in space
Jan 31 07:54:06 sw01 daemon.info swd[254]: slot 14: board GE-12 lost in space
Jan 31 07:54:06 sw01 daemon.info swd[254]: slot 20: board PS-48D lost in space
Jan 31 07:54:06 sw01 daemon.info swd[254]: slot 20: end alarm Отсутствует входное напряжение (duration 2 s)
Jan 31 07:54:06 sw01 daemon.info swd[254]: slot 20: end alarm Отсутствует напряжение 12 В (duration 2 s)
Jan 31 07:54:06 sw01 daemon.info swd[254]: slot 20: end alarm ALARM (Общая авария платы) (duration 1 s)
Jan 31 07:54:06 sw01 daemon.info swd[254]: slot 21: board PS-48D lost in space
Jan 31 07:54:06 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1199 executed 118 ms
Jan 31 07:54:07 sw01 daemon.info swd[254]: zabbix-agent.cpp:1379: Zabbix agent stopped
Jan 31 07:54:07 sw01 daemon.info swd[254]: exiting swd
Jan 31 07:54:07 sw01 daemon.crit swd[254]: scheduler.cpp:333: sched is null!
Jan 31 07:54:07 sw01 syslog.info syslogd exiting
Jan 31 07:54:34 sw01 syslog.info syslogd started: BusyBox v1.18.5
Jan 31 07:54:34 sw01 user.notice kernel: klogd started: BusyBox v1.18.5 (2015-09-18 17:21:03 YEKT)
Jan 31 07:54:34 sw01 user.info kernel: Booting Linux on physical CPU 0
Jan 31 07:54:34 sw01 user.notice kernel: Linux version 3.6.9 (alx@ubuntu) (gcc version 4.5.3 20110311 (prerelease) (GCC) ) #1 Mon Aug 28 15:29:11 +05 2017
Jan 31 07:54:34 sw01 user.warn kernel: CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=00053177
Jan 31 07:54:34 sw01 user.warn kernel: CPU: VIVT data cache, VIVT instruction cache
Jan 31 07:54:34 sw01 user.warn kernel: Machine: Atmel AT91SAM9G20-EK
Jan 31 07:54:34 sw01 user.warn kernel: Memory policy: ECC disabled, Data cache writeback
Jan 31 07:54:34 sw01 user.info kernel: AT91: Detected soc type: at91sam9g20
Jan 31 07:54:34 sw01 user.info kernel: AT91: Detected soc subtype: Unknown
Jan 31 07:54:34 sw01 user.info kernel: AT91: sram at 0x2fc000 of 0x8000 mapped at 0xfef70000
Jan 31 07:54:34 sw01 user.debug kernel: On node 0 totalpages: 16384
Jan 31 07:54:34 sw01 user.debug kernel: free_area_init_node: node 0, pgdat c03d39a8, node_mem_map c03e7000
Jan 31 07:54:34 sw01 user.debug kernel:   Normal zone: 128 pages used for memmap
Jan 31 07:54:34 sw01 user.debug kernel:   Normal zone: 0 pages reserved
Jan 31 07:54:34 sw01 user.debug kernel:   Normal zone: 16256 pages, LIFO batch:3
Jan 31 07:54:34 sw01 user.warn kernel: Clocks: CPU 396 MHz, master 132 MHz, main 18.432 MHz
Jan 31 07:54:34 sw01 user.debug kernel: pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
Jan 31 07:54:34 sw01 user.debug kernel: pcpu-alloc: [0] 0 
Jan 31 07:54:34 sw01 user.warn kernel: Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 16256
Jan 31 07:54:34 sw01 user.notice kernel: Kernel command line: console=ttyS0,115200 root=/dev/mtdblock5 mtdparts=atmel_nand:128k(bootstrap)ro,256k(uboot)ro,128k(env1)ro,128k(env2)ro,3M(linux),-(root) rw rootfstype=jffs2
Jan 31 07:54:34 sw01 user.info kernel: PID hash table entries: 256 (order: -2, 1024 bytes)
Jan 31 07:54:34 sw01 user.info kernel: Dentry cache hash table entries: 8192 (order: 3, 32768 bytes)
Jan 31 07:54:34 sw01 user.info kernel: Inode-cache hash table entries: 4096 (order: 2, 16384 bytes)
Jan 31 07:54:34 sw01 user.info kernel: Memory: 64MB = 64MB total
Jan 31 07:54:34 sw01 user.notice kernel: Memory: 60932k/60932k available, 4604k reserved, 0K highmem
Jan 31 07:54:34 sw01 user.notice kernel: Virtual kernel memory layout:
Jan 31 07:54:34 sw01 user.notice kernel:     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
Jan 31 07:54:34 sw01 user.notice kernel:     fixmap  : 0xfff00000 - 0xfffe0000   ( 896 kB)
Jan 31 07:54:34 sw01 user.notice kernel:     vmalloc : 0xc4800000 - 0xff000000   ( 936 MB)
Jan 31 07:54:34 sw01 user.notice kernel:     lowmem  : 0xc0000000 - 0xc4000000   (  64 MB)
Jan 31 07:54:34 sw01 user.notice kernel:     modules : 0xbf000000 - 0xc0000000   (  16 MB)
Jan 31 07:54:34 sw01 user.notice kernel:       .text : 0xc0008000 - 0xc038b134   (3597 kB)
Jan 31 07:54:34 sw01 user.notice kernel:       .init : 0xc038c000 - 0xc03abcdc   ( 128 kB)
Jan 31 07:54:34 sw01 user.notice kernel:       .data : 0xc03ac000 - 0xc03d4200   ( 161 kB)
Jan 31 07:54:34 sw01 user.notice kernel:        .bss : 0xc03d4224 - 0xc03e6cd8   (  75 kB)
Jan 31 07:54:34 sw01 user.info kernel: NR_IRQS:16 nr_irqs:16 16
Jan 31 07:54:34 sw01 user.info kernel: AT91: 96 gpio irqs in 3 banks
Jan 31 07:54:34 sw01 user.info kernel: sched_clock: 32 bits at 1kHz, resolution 1000000ns, wraps every 4294967295ms
Jan 31 07:54:34 sw01 user.info kernel: Console: colour dummy device 80x30
Jan 31 07:54:34 sw01 user.info kernel: Calibrating delay loop... 196.35 BogoMIPS (lpj=98176)
Jan 31 07:54:34 sw01 user.info kernel: pid_max: default: 32768 minimum: 301
Jan 31 07:54:34 sw01 user.info kernel: Mount-cache hash table entries: 512
Jan 31 07:54:34 sw01 user.info kernel: CPU: Testing write buffer coherency: ok
Jan 31 07:54:34 sw01 user.info kernel: Setting up static identity map for 0x202aed60 - 0x202aedb8
Jan 31 07:54:34 sw01 user.info kernel: devtmpfs: initialized
Jan 31 07:54:34 sw01 user.info kernel: NET: Registered protocol family 16
Jan 31 07:54:34 sw01 user.info kernel: DMA: preallocated 256 KiB pool for atomic coherent allocations
Jan 31 07:54:34 sw01 user.info kernel: AT91: Power Management
Jan 31 07:54:34 sw01 user.info kernel: AT91: Starting after software reset
Jan 31 07:54:34 sw01 user.debug kernel: tcb_clksrc: tc0 at 16.012 MHz
Jan 31 07:54:34 sw01 user.info kernel: bio: create slab <bio-0> at 0
Jan 31 07:54:34 sw01 user.notice kernel: SCSI subsystem initialized
Jan 31 07:54:34 sw01 user.info kernel: usbcore: registered new interface driver usbfs
Jan 31 07:54:34 sw01 user.info kernel: usbcore: registered new interface driver hub
Jan 31 07:54:34 sw01 user.info kernel: usbcore: registered new device driver usb
Jan 31 07:54:34 sw01 user.info kernel: i2c-gpio i2c-gpio.0: using pins 23 (SDA) and 24 (SCL)
Jan 31 07:54:34 sw01 user.info kernel: i2c-gpio i2c-gpio.1: using pins 65 (SDA) and 64 (SCL)
Jan 31 07:54:34 sw01 user.info kernel: cfg80211: Calling CRDA to update world regulatory domain
Jan 31 07:54:34 sw01 user.info kernel: Switching to clocksource tcb_clksrc
Jan 31 07:54:34 sw01 user.info kernel: NET: Registered protocol family 2
Jan 31 07:54:34 sw01 user.info kernel: TCP established hash table entries: 2048 (order: 2, 16384 bytes)
Jan 31 07:54:34 sw01 user.info kernel: TCP bind hash table entries: 2048 (order: 1, 8192 bytes)
Jan 31 07:54:34 sw01 user.info kernel: TCP: Hash tables configured (established 2048 bind 2048)
Jan 31 07:54:34 sw01 user.info kernel: TCP: reno registered
Jan 31 07:54:34 sw01 user.info kernel: UDP hash table entries: 256 (order: 0, 4096 bytes)
Jan 31 07:54:34 sw01 user.info kernel: UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
Jan 31 07:54:34 sw01 user.info kernel: NET: Registered protocol family 1
Jan 31 07:54:34 sw01 user.info kernel: RPC: Registered named UNIX socket transport module.
Jan 31 07:54:34 sw01 user.info kernel: RPC: Registered udp transport module.
Jan 31 07:54:34 sw01 user.info kernel: RPC: Registered tcp transport module.
Jan 31 07:54:34 sw01 user.info kernel: RPC: Registered tcp NFSv4.1 backchannel transport module.
Jan 31 07:54:34 sw01 user.info kernel: jffs2: version 2.2. (NAND) (SUMMARY)  © 2001-2006 Red Hat, Inc.
Jan 31 07:54:34 sw01 user.info kernel: msgmni has been set to 119
Jan 31 07:54:34 sw01 user.info kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
Jan 31 07:54:34 sw01 user.info kernel: io scheduler noop registered (default)
Jan 31 07:54:34 sw01 user.info kernel: atmel_usart.0: ttyS0 at MMIO 0xfffff200 (irq = 17) is a ATMEL_SERIAL
Jan 31 07:54:34 sw01 user.info kernel: console [ttyS0] enabled
Jan 31 07:54:34 sw01 user.info kernel: atmel_usart.1: ttyS1 at MMIO 0xfffb0000 (irq = 22) is a ATMEL_SERIAL
Jan 31 07:54:34 sw01 user.info kernel: brd: module loaded
Jan 31 07:54:34 sw01 user.info kernel: loop: module loaded
Jan 31 07:54:34 sw01 user.info kernel: atmel_nand: Use On Flash BBT
Jan 31 07:54:34 sw01 user.info kernel: atmel_nand atmel_nand: No DMA support for NAND access.
Jan 31 07:54:34 sw01 user.info kernel: ONFI param page 0 valid
Jan 31 07:54:34 sw01 user.info kernel: ONFI flash detected
Jan 31 07:54:34 sw01 user.info kernel: NAND device: Manufacturer ID: 0x2c, Chip ID: 0xda (Micron MT29F2G08ABAEAWP), page size: 2048, OOB size: 64
Jan 31 07:54:34 sw01 user.info kernel: Bad block table found at page 131008, version 0x01
Jan 31 07:54:34 sw01 user.info kernel: Bad block table found at page 130944, version 0x01
Jan 31 07:54:34 sw01 user.notice kernel: 6 cmdlinepart partitions found on MTD device atmel_nand
Jan 31 07:54:34 sw01 user.notice kernel: Creating 6 MTD partitions on "atmel_nand":
Jan 31 07:54:34 sw01 user.notice kernel: 0x000000000000-0x000000020000 : "bootstrap"
Jan 31 07:54:34 sw01 user.notice kernel: 0x000000020000-0x000000060000 : "uboot"
Jan 31 07:54:34 sw01 user.notice kernel: 0x000000060000-0x000000080000 : "env1"
Jan 31 07:54:34 sw01 user.notice kernel: 0x000000080000-0x0000000a0000 : "env2"
Jan 31 07:54:34 sw01 user.notice kernel: 0x0000000a0000-0x0000003a0000 : "linux"
Jan 31 07:54:34 sw01 user.notice kernel: 0x0000003a0000-0x000010000000 : "root"
Jan 31 07:54:34 sw01 user.info kernel: atmel_spi atmel_spi.0: Atmel SPI Controller at 0xfffc8000 (irq 28)
Jan 31 07:54:34 sw01 user.info kernel: atmel_spi atmel_spi.0: master is unqueued, this is deprecated
Jan 31 07:54:34 sw01 user.info kernel: atmel_spi atmel_spi.1: Atmel SPI Controller at 0xfffcc000 (irq 29)
Jan 31 07:54:34 sw01 user.info kernel: atmel_spi atmel_spi.1: master is unqueued, this is deprecated
Jan 31 07:54:34 sw01 user.info kernel: libphy: MACB_mii_bus: probed
Jan 31 07:54:34 sw01 user.info kernel: macb macb: eth0: Cadence MACB at 0xfffc4000 irq 37 (02:ad:c2:00:03:16)
Jan 31 07:54:34 sw01 user.info kernel: macb macb: eth0: attached PHY driver [Marvell DX107 PHY] (mii_bus:phy_addr=macb-ffffffff:00, irq=-1)
Jan 31 07:54:34 sw01 user.info kernel: PPP generic driver version 2.4.2
Jan 31 07:54:34 sw01 user.info kernel: ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
Jan 31 07:54:34 sw01 user.info kernel: at91_ohci at91_ohci: AT91 OHCI
Jan 31 07:54:34 sw01 user.info kernel: at91_ohci at91_ohci: new USB bus registered, assigned bus number 1
Jan 31 07:54:34 sw01 user.info kernel: at91_ohci at91_ohci: irq 36, io mem 0x00500000
Jan 31 07:54:34 sw01 user.info kernel: hub 1-0:1.0: USB hub found
Jan 31 07:54:34 sw01 user.info kernel: hub 1-0:1.0: 2 ports detected
Jan 31 07:54:34 sw01 user.info kernel: Initializing USB Mass Storage driver...
Jan 31 07:54:34 sw01 user.info kernel: usbcore: registered new interface driver usb-storage
Jan 31 07:54:34 sw01 user.info kernel: USB Mass Storage support registered.
Jan 31 07:54:34 sw01 user.info kernel: udc: at91_udc version 3 May 2006
Jan 31 07:54:34 sw01 user.info kernel: mousedev: PS/2 mouse device common for all mice
Jan 31 07:54:34 sw01 user.info kernel: rtc-m41t80 0-0068: chip found, driver version 0.05
Jan 31 07:54:34 sw01 user.info kernel: rtc-m41t80 0-0068: rtc core: registered m41t80 as rtc0
Jan 31 07:54:34 sw01 user.info kernel: i2c /dev entries driver
Jan 31 07:54:34 sw01 user.info kernel: at91sam9_wdt: enabled (heartbeat=15 sec, nowayout=0)
Jan 31 07:54:34 sw01 user.debug kernel: Registered led device: alr
Jan 31 07:54:34 sw01 user.debug kernel: Registered led device: mem
Jan 31 07:54:34 sw01 user.debug kernel: Registered led device: ok
Jan 31 07:54:34 sw01 user.debug kernel: Registered led device: link9
Jan 31 07:54:34 sw01 user.debug kernel: Registered led device: buzzer
Jan 31 07:54:34 sw01 user.info kernel: TCP: cubic registered
Jan 31 07:54:34 sw01 user.info kernel: NET: Registered protocol family 10
Jan 31 07:54:34 sw01 user.info kernel: sit: IPv6 over IPv4 tunneling driver
Jan 31 07:54:34 sw01 user.info kernel: NET: Registered protocol family 17
Jan 31 07:54:34 sw01 user.info kernel: lib80211: common routines for IEEE802.11 drivers
Jan 31 07:54:34 sw01 user.debug kernel: lib80211_crypt: registered algorithm 'NULL'
Jan 31 07:54:34 sw01 user.info kernel: input: gpio-keys as /devices/platform/gpio-keys/input/input0
Jan 31 07:54:34 sw01 user.info kernel: rtc-m41t80 0-0068: setting system clock to 2018-01-31 07:54:22 UTC (1517385262)
Jan 31 07:54:34 sw01 user.info kernel: VFS: Mounted root (jffs2 filesystem) on device 31:5.
Jan 31 07:54:34 sw01 user.info kernel: devtmpfs: mounted
Jan 31 07:54:34 sw01 user.info kernel: Freeing init memory: 124K
Jan 31 07:54:34 sw01 user.info kernel:  gadget: Gadget Serial v2.4
Jan 31 07:54:34 sw01 user.info kernel:  gadget: g_serial ready
Jan 31 07:54:34 sw01 user.info kernel: IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Jan 31 07:54:34 sw01 user.info kernel: macb macb: eth0: link up (100/Full)
Jan 31 07:54:34 sw01 user.info kernel: IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Jan 31 07:54:36 sw01 daemon.info swd[254]: starting swd-r1667
Jan 31 07:54:36 sw01 daemon.info swd[254]: current storage database version is 1
Jan 31 07:54:36 sw01 daemon.info swd[254]: current logins database version is 2
Jan 31 07:54:36 sw01 daemon.info swd[254]: HTTP daemon started
Jan 31 07:54:36 sw01 daemon.info swd[254]: HTTP IPv6 daemon started
Jan 31 07:54:36 sw01 daemon.err swd[254]: cannot start HTTPS IPv4 daemon
Jan 31 07:54:36 sw01 daemon.err swd[254]: cannot start HTTPS IPv6 daemon
Jan 31 07:54:36 sw01 daemon.info swd[254]: Current FPGA revision is 9
Jan 31 07:54:36 sw01 daemon.info swd[254]: my address is 9
Jan 31 07:54:36 sw01 daemon.info swd[254]: New board SW-01 in slot 9
Jan 31 07:54:38 sw01 daemon.info swd[254]: New board PS-48D in slot 21
Jan 31 07:54:38 sw01 daemon.info swd[254]: New board EM-04 in slot 3
Jan 31 07:54:38 sw01 daemon.info swd[254]: New board PS-48D in slot 20
Jan 31 07:54:38 sw01 daemon.info swd[254]: slot 20: start alarm ALARM (Общая авария платы)
Jan 31 07:54:38 sw01 daemon.info swd[254]: New board FS-08 in slot 2
Jan 31 07:54:38 sw01 daemon.info swd[254]: New board EM-04 in slot 4
Jan 31 07:54:38 sw01 daemon.warn swd[254]: --> timer callback scheduled from board_SW.cpp:227 executed 105 ms
Jan 31 07:54:43 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 130 ms
Jan 31 07:54:45 sw01 daemon.info swd[254]: zabbix-agent.cpp:944: Zabbix agent started
Jan 31 07:54:50 sw01 daemon.info swd[254]: New board E1-08 in slot 8
Jan 31 07:54:50 sw01 daemon.info swd[254]: New board GE-12 in slot 14
Jan 31 07:54:54 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 1: LOF
Jan 31 07:54:54 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 2: LOF
Jan 31 07:54:54 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 1: LOF (duration 0 s)
Jan 31 07:54:54 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 2: LOF (duration 0 s)
Jan 31 07:54:55 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 1: LOF
Jan 31 07:54:55 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 2: LOF
Jan 31 07:54:55 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 1: LOF (duration 0 s)
Jan 31 07:54:55 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 2: LOF (duration 0 s)
Jan 31 07:54:55 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 3: LOF
Jan 31 07:54:55 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 4: LOF
Jan 31 07:54:55 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 5: LOF
Jan 31 07:54:55 sw01 daemon.info swd[254]: slot 14: start alarm ALARM (Общая авария платы)
Jan 31 07:54:56 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 3: LOF (duration 1 s)
Jan 31 07:54:56 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 4: LOF (duration 1 s)
Jan 31 07:54:56 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 5: LOF (duration 1 s)
Jan 31 07:54:56 sw01 daemon.info swd[254]: slot 14: end alarm ALARM (Общая авария платы) (duration 1 s)
Jan 31 07:55:02 sw01 authpriv.info dropbear[295]: Child connection from 10.6.51.111:52283
Jan 31 07:55:02 sw01 authpriv.info dropbear[295]: Exit before auth: Exited normally
Jan 31 07:55:31 sw01 authpriv.info dropbear[297]: Child connection from 10.6.51.111:52335
Jan 31 07:55:31 sw01 authpriv.info dropbear[297]: Exit before auth: Exited normally
Jan 31 07:56:01 sw01 authpriv.info dropbear[302]: Child connection from 10.6.51.111:52384
Jan 31 07:56:01 sw01 authpriv.info dropbear[302]: Exit before auth: Exited normally
Jan 31 07:56:32 sw01 authpriv.info dropbear[304]: Child connection from 10.6.51.111:52431
Jan 31 07:56:32 sw01 authpriv.info dropbear[304]: Exit before auth: Exited normally
Jan 31 07:57:01 sw01 authpriv.info dropbear[309]: Child connection from 10.6.51.111:52485
Jan 31 07:57:01 sw01 authpriv.info dropbear[309]: Exit before auth: Exited normally
Jan 31 07:57:31 sw01 authpriv.info dropbear[310]: Child connection from 10.6.51.111:52537
Jan 31 07:57:31 sw01 authpriv.info dropbear[310]: Exit before auth: Exited normally
Jan 31 07:57:44 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 1: LOF
Jan 31 07:57:44 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 2: LOF
Jan 31 07:57:45 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 1: LOF (duration 1 s)
Jan 31 07:57:45 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 2: LOF (duration 1 s)
Jan 31 07:57:45 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 1: LOF
Jan 31 07:57:45 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 2: LOF
Jan 31 07:57:45 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 1: LOF (duration 0 s)
Jan 31 07:57:45 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 2: LOF (duration 0 s)
Jan 31 07:57:45 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 5: LOF
Jan 31 07:57:46 sw01 daemon.info swd[254]: slot 14: start alarm ALARM (Общая авария платы)
Jan 31 07:57:46 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 5: LOF (duration 1 s)
Jan 31 07:57:47 sw01 daemon.info swd[254]: slot 14: end alarm ALARM (Общая авария платы) (duration 1 s)
Jan 31 07:58:01 sw01 authpriv.info dropbear[316]: Child connection from 10.6.51.111:52565
Jan 31 07:58:01 sw01 authpriv.info dropbear[316]: Exit before auth: Exited normally
Jan 31 07:58:26 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 1: LOF
Jan 31 07:58:26 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 2: LOF
Jan 31 07:58:26 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 1: LOF (duration 0 s)
Jan 31 07:58:26 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 2: LOF (duration 0 s)
Jan 31 07:58:27 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 5: LOF
Jan 31 07:58:27 sw01 daemon.info swd[254]: slot 14: start alarm ALARM (Общая авария платы)
Jan 31 07:58:28 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 5: LOF (duration 1 s)
Jan 31 07:58:31 sw01 authpriv.info dropbear[318]: Child connection from 10.6.51.111:52587
Jan 31 07:58:31 sw01 authpriv.info dropbear[318]: Exit before auth: Exited normally
Jan 31 07:58:39 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 1: LOF
Jan 31 07:58:40 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 1: LOF (duration 1 s)
Jan 31 07:58:40 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 5: LOF
Jan 31 07:58:41 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 5: LOF (duration 1 s)
Jan 31 07:58:54 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 1: LOF
Jan 31 07:58:55 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 1: LOF (duration 1 s)
Jan 31 07:58:55 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 5: LOF
Jan 31 07:58:56 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 5: LOF (duration 1 s)
Jan 31 07:59:01 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 1: LOF
Jan 31 07:59:01 sw01 authpriv.info dropbear[323]: Child connection from 10.6.51.111:52633
Jan 31 07:59:01 sw01 authpriv.info dropbear[323]: Exit before auth: Exited normally
Jan 31 07:59:02 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 1: LOF (duration 1 s)
Jan 31 07:59:02 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 5: LOF
Jan 31 07:59:03 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 5: LOF (duration 1 s)
Jan 31 07:59:31 sw01 authpriv.info dropbear[325]: Child connection from 10.6.51.111:52687
Jan 31 07:59:31 sw01 authpriv.info dropbear[325]: Exit before auth: Exited normally
Jan 31 08:00:01 sw01 authpriv.info dropbear[330]: Child connection from 10.6.51.111:52737
Jan 31 08:00:01 sw01 authpriv.info dropbear[330]: Exit before auth: Exited normally
Jan 31 08:00:31 sw01 authpriv.info dropbear[333]: Child connection from 10.6.51.111:52789
Jan 31 08:00:31 sw01 authpriv.info dropbear[333]: Exit before auth: Exited normally
Jan 31 08:01:01 sw01 authpriv.info dropbear[338]: Child connection from 10.6.51.111:52838
Jan 31 08:01:01 sw01 authpriv.info dropbear[338]: Exit before auth: Exited normally
Jan 31 08:01:15 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 4: LOF
Jan 31 08:01:16 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 4: LOF (duration 1 s)
Jan 31 08:01:30 sw01 daemon.info swd[254]: slot 14: start alarm Порт E1 4: LOF
Jan 31 08:01:31 sw01 daemon.info swd[254]: slot 14: end alarm Порт E1 4: LOF (duration 1 s)
Jan 31 08:01:31 sw01 authpriv.info dropbear[339]: Child connection from 10.6.51.111:52885
Jan 31 08:01:31 sw01 authpriv.info dropbear[339]: Exit before auth: Exited normally
Jan 31 08:01:56 sw01 daemon.info swd[254]: admin from [10.6.51.111]: TDM mapper table changed
Jan 31 08:02:01 sw01 authpriv.info dropbear[346]: Child connection from 10.6.51.111:52931
Jan 31 08:02:01 sw01 authpriv.info dropbear[346]: Exit before auth: Exited normally
Jan 31 08:02:31 sw01 authpriv.info dropbear[351]: Child connection from 10.6.51.111:52978
Jan 31 08:02:31 sw01 authpriv.info dropbear[351]: Exit before auth: Exited normally
Jan 31 08:02:52 sw01 daemon.info swd[254]: admin from [10.6.51.111]: writing variable(s) to slot 14
Jan 31 08:02:52 sw01 daemon.info swd[254]: admin from [10.6.51.111]: writing variable(s) to slot 14
Jan 31 08:02:52 sw01 daemon.info swd[254]: admin from [10.6.51.111]: writing variable(s) to slot 14
Jan 31 08:02:53 sw01 daemon.info swd[254]: admin from [10.6.51.111]: writing variable(s) to slot 14
Jan 31 08:02:53 sw01 daemon.info swd[254]: admin from [10.6.51.111]: writing variable(s) to slot 14
Jan 31 08:02:53 sw01 daemon.info swd[254]: admin from [10.6.51.111]: writing variable(s) to slot 14
Jan 31 08:03:01 sw01 daemon.info swd[254]: admin from [10.6.51.111]: writing variable(s) to slot 14
Jan 31 08:03:01 sw01 authpriv.info dropbear[356]: Child connection from 10.6.51.111:53030
Jan 31 08:03:01 sw01 authpriv.info dropbear[356]: Exit before auth: Exited normally
Jan 31 08:03:02 sw01 daemon.info swd[254]: admin from [10.6.51.111]: writing variable(s) to slot 14
Jan 31 08:03:02 sw01 daemon.info swd[254]: admin from [10.6.51.111]: writing variable(s) to slot 14
Jan 31 08:03:02 sw01 daemon.info swd[254]: admin from [10.6.51.111]: writing variable(s) to slot 14
Jan 31 08:03:03 sw01 daemon.info swd[254]: admin from [10.6.51.111]: writing variable(s) to slot 14
Jan 31 08:03:03 sw01 daemon.info swd[254]: admin from [10.6.51.111]: writing variable(s) to slot 14
Jan 31 08:03:31 sw01 authpriv.info dropbear[358]: Child connection from 10.6.51.111:53082
Jan 31 08:03:31 sw01 authpriv.info dropbear[358]: Exit before auth: Exited normally
Jan 31 08:04:01 sw01 authpriv.info dropbear[363]: Child connection from 10.6.51.111:53129
Jan 31 08:04:01 sw01 authpriv.info dropbear[363]: Exit before auth: Exited normally
Jan 31 08:04:31 sw01 authpriv.info dropbear[367]: Child connection from 10.6.51.111:53176
Jan 31 08:04:31 sw01 authpriv.info dropbear[367]: Exit before auth: Exited normally
Jan 31 08:05:01 sw01 authpriv.info dropbear[372]: Child connection from 10.6.51.111:53224
Jan 31 08:05:02 sw01 authpriv.info dropbear[372]: Exit before auth: Exited normally
Jan 31 08:05:32 sw01 authpriv.info dropbear[375]: Child connection from 10.6.51.111:53277
Jan 31 08:05:32 sw01 authpriv.info dropbear[375]: Exit before auth: Exited normally
Jan 31 08:06:01 sw01 authpriv.info dropbear[380]: Child connection from 10.6.51.111:53329
Jan 31 08:06:02 sw01 authpriv.info dropbear[380]: Exit before auth: Exited normally
Jan 31 08:06:03 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1368 executed 122 ms
Jan 31 08:06:03 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 334 ms
Jan 31 08:06:03 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1019 executed 216 ms
Jan 31 08:06:04 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 766 ms
Jan 31 08:06:04 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 153 ms
Jan 31 08:06:04 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 122 ms
Jan 31 08:06:05 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 183 ms
Jan 31 08:06:05 sw01 daemon.warn swd[254]: transport thread isn't alive for more than 2 sec
Jan 31 08:06:05 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 554 ms
Jan 31 08:06:05 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 153 ms
Jan 31 08:06:06 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 123 ms
Jan 31 08:06:06 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 551 ms
Jan 31 08:06:06 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 213 ms
Jan 31 08:06:06 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 183 ms
Jan 31 08:06:07 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 214 ms
Jan 31 08:06:07 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 121 ms
Jan 31 08:06:08 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 1041 ms
Jan 31 08:06:08 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 125 ms
Jan 31 08:06:08 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 307 ms
Jan 31 08:06:08 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 153 ms
Jan 31 08:06:09 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 152 ms
Jan 31 08:06:09 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 765 ms
Jan 31 08:06:10 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1368 executed 153 ms
Jan 31 08:06:10 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 212 ms
Jan 31 08:06:10 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 124 ms
Jan 31 08:06:11 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 978 ms
Jan 31 08:06:12 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1368 executed 121 ms
Jan 31 08:06:12 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 1215 ms
Jan 31 08:06:12 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1368 executed 121 ms
Jan 31 08:06:13 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 641 ms
Jan 31 08:06:13 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1368 executed 184 ms
Jan 31 08:06:13 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 184 ms
Jan 31 08:06:14 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 215 ms
Jan 31 08:06:15 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 1200 ms
Jan 31 08:06:15 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 155 ms
Jan 31 08:06:15 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 123 ms
Jan 31 08:06:16 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 433 ms
Jan 31 08:06:17 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 1167 ms
Jan 31 08:06:17 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:2177 executed 462 ms
Jan 31 08:06:18 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1019 executed 247 ms
Jan 31 08:06:18 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1019 executed 339 ms
Jan 31 08:06:18 sw01 user.crit kernel: at91sam9_wdt: I will reset your machine !
Jan 31 08:06:19 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:2177 executed 436 ms
Jan 31 08:06:19 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 1102 ms
Jan 31 08:06:20 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 153 ms
Jan 31 08:06:21 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 1136 ms
Jan 31 08:06:21 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 215 ms
Jan 31 08:06:21 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 122 ms
Jan 31 08:06:21 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:2177 executed 183 ms
Jan 31 08:06:22 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 802 ms
Jan 31 08:06:22 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1019 executed 337 ms
Jan 31 08:06:23 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 369 ms
Jan 31 08:06:23 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 152 ms
Jan 31 08:06:25 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 2187 ms
Jan 31 08:06:25 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 280 ms
Jan 31 08:06:26 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 445 ms
Jan 31 08:06:26 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1019 executed 252 ms
Jan 31 08:06:27 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 1453 ms
Jan 31 08:06:28 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 246 ms
Jan 31 08:06:28 sw01 daemon.warn swd[254]: --> timer callback scheduled from transport.cpp:1038 executed 123 ms
Jan 31 08:06:28 sw01 daemon.warn swd[254]: --> timer callback scheduled from prestera.cpp:883 executed 524 ms
Jan 31 08:06:29 sw01 daemon.info swd[254]: slot 14: board GE-12 lost in space
Jan 31 08:06:29 sw01 daemon.info swd[254]: slot 14: end alarm ALARM (Общая авария платы) (duration 482 s)
Jan 31 08:06:53 sw01 syslog.info syslogd started: BusyBox v1.18.5
Jan 31 08:06:53 sw01 user.notice kernel: klogd started: BusyBox v1.18.5 (2015-09-18 17:21:03 YEKT)
Jan 31 08:06:53 sw01 user.info kernel: Booting Linux on physical CPU 0
Jan 31 08:06:53 sw01 user.notice kernel: Linux version 3.6.9 (alx@ubuntu) (gcc version 4.5.3 20110311 (prerelease) (GCC) ) #1 Mon Aug 28 15:29:11 +05 2017
Jan 31 08:06:53 sw01 user.warn kernel: CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=00053177
Jan 31 08:06:53 sw01 user.warn kernel: CPU: VIVT data cache, VIVT instruction cache
Jan 31 08:06:53 sw01 user.warn kernel: Machine: Atmel AT91SAM9G20-EK
Jan 31 08:06:53 sw01 user.warn kernel: Memory policy: ECC disabled, Data cache writeback
Jan 31 08:06:53 sw01 user.info kernel: AT91: Detected soc type: at91sam9g20
Jan 31 08:06:53 sw01 user.info kernel: AT91: Detected soc subtype: Unknown
Jan 31 08:06:53 sw01 user.info kernel: AT91: sram at 0x2fc000 of 0x8000 mapped at 0xfef70000
Jan 31 08:06:53 sw01 user.debug kernel: On node 0 totalpages: 16384
Jan 31 08:06:53 sw01 user.debug kernel: free_area_init_node: node 0, pgdat c03d39a8, node_mem_map c03e7000
Jan 31 08:06:53 sw01 user.debug kernel:   Normal zone: 128 pages used for memmap
Jan 31 08:06:53 sw01 user.debug kernel:   Normal zone: 0 pages reserved
Jan 31 08:06:53 sw01 user.debug kernel:   Normal zone: 16256 pages, LIFO batch:3
Jan 31 08:06:53 sw01 user.warn kernel: Clocks: CPU 396 MHz, master 132 MHz, main 18.432 MHz
Jan 31 08:06:53 sw01 user.debug kernel: pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
Jan 31 08:06:53 sw01 user.debug kernel: pcpu-alloc: [0] 0 
Jan 31 08:06:53 sw01 user.warn kernel: Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 16256
Jan 31 08:06:53 sw01 user.notice kernel: Kernel command line: console=ttyS0,115200 root=/dev/mtdblock5 mtdparts=atmel_nand:128k(bootstrap)ro,256k(uboot)ro,128k(env1)ro,128k(env2)ro,3M(linux),-(root) rw rootfstype=jffs2
Jan 31 08:06:53 sw01 user.info kernel: PID hash table entries: 256 (order: -2, 1024 bytes)
Jan 31 08:06:53 sw01 user.info kernel: Dentry cache hash table entries: 8192 (order: 3, 32768 bytes)
Jan 31 08:06:53 sw01 user.info kernel: Inode-cache hash table entries: 4096 (order: 2, 16384 bytes)
Jan 31 08:06:53 sw01 user.info kernel: Memory: 64MB = 64MB total
Jan 31 08:06:53 sw01 user.notice kernel: Memory: 60932k/60932k available, 4604k reserved, 0K highmem
Jan 31 08:06:53 sw01 user.notice kernel: Virtual kernel memory layout:
Jan 31 08:06:53 sw01 user.notice kernel:     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
Jan 31 08:06:53 sw01 user.notice kernel:     fixmap  : 0xfff00000 - 0xfffe0000   ( 896 kB)
Jan 31 08:06:53 sw01 user.notice kernel:     vmalloc : 0xc4800000 - 0xff000000   ( 936 MB)
Jan 31 08:06:53 sw01 user.notice kernel:     lowmem  : 0xc0000000 - 0xc4000000   (  64 MB)
Jan 31 08:06:53 sw01 user.notice kernel:     modules : 0xbf000000 - 0xc0000000   (  16 MB)
Jan 31 08:06:53 sw01 user.notice kernel:       .text : 0xc0008000 - 0xc038b134   (3597 kB)
Jan 31 08:06:53 sw01 user.notice kernel:       .init : 0xc038c000 - 0xc03abcdc   ( 128 kB)
Jan 31 08:06:53 sw01 user.notice kernel:       .data : 0xc03ac000 - 0xc03d4200   ( 161 kB)
Jan 31 08:06:53 sw01 user.notice kernel:        .bss : 0xc03d4224 - 0xc03e6cd8   (  75 kB)
Jan 31 08:06:53 sw01 user.info kernel: NR_IRQS:16 nr_irqs:16 16
Jan 31 08:06:53 sw01 user.info kernel: AT91: 96 gpio irqs in 3 banks
Jan 31 08:06:53 sw01 user.info kernel: sched_clock: 32 bits at 1kHz, resolution 1000000ns, wraps every 4294967295ms
Jan 31 08:06:53 sw01 user.info kernel: Console: colour dummy device 80x30
Jan 31 08:06:53 sw01 user.info kernel: Calibrating delay loop... 196.35 BogoMIPS (lpj=98176)
Jan 31 08:06:53 sw01 user.info kernel: pid_max: default: 32768 minimum: 301
Jan 31 08:06:53 sw01 user.info kernel: Mount-cache hash table entries: 512
Jan 31 08:06:53 sw01 user.info kernel: CPU: Testing write buffer coherency: ok
Jan 31 08:06:53 sw01 user.info kernel: Setting up static identity map for 0x202aed60 - 0x202aedb8
Jan 31 08:06:53 sw01 user.info kernel: devtmpfs: initialized
Jan 31 08:06:53 sw01 user.info kernel: NET: Registered protocol family 16
Jan 31 08:06:53 sw01 user.info kernel: DMA: preallocated 256 KiB pool for atomic coherent allocations
Jan 31 08:06:53 sw01 user.info kernel: AT91: Power Management
Jan 31 08:06:53 sw01 user.info kernel: AT91: Starting after watchdog reset
Version 1, edited 6 years ago by san (previous) (next) (diff)

by san, 6 years ago

Attachment: 31_01_vitya.txt​ added

in reply to:  20 comment:21 by alx, 6 years ago

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, наводит на мысль, что проблема связана именно с сетью - то есть первое мое предположение мне кажется более вероятным. Что с этими выводами нам делать - я не знаю...

comment:22 by san, 6 years ago

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

in reply to:  22 comment:23 by alx, 6 years ago

Replying to san:

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

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

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

comment:24 by san, 6 years ago

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

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

comment:25 by alx, 6 years ago

Провел эксперимент: превратил плату 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.

comment:26 by alx, 6 years ago

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

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.

comment:27 by alx, 6 years ago

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

comment:28 by alx, 6 years ago

In 1677/sw:

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

comment:29 by san, 6 years ago

Resolution: → готово
Status: new → closed
Note: See TracTickets for help on using tickets.