Периодически wb-mqtt-serial.service: Main process exited, code=killed, status=4/ILL

Программное обеспечение
1

image
image946×286 9.98 KB

Вот что-то нехорошее наблюдаю в логах.
Обновления пакетов сделал 30 минут назад. Так что они сегодняшние.

Dec 18 12:45:12 wirenboard-AN4RTE7N systemd[1]: wb-mqtt-serial.service: Main process exited, code=killed, status=4/ILL
Dec 18 12:45:12 wirenboard-AN4RTE7N systemd[1]: wb-mqtt-serial.service: Failed with result 'signal'.
Dec 18 12:45:12 wirenboard-AN4RTE7N systemd[1]: wb-mqtt-serial.service: Consumed 27.559s CPU time.
Dec 18 12:45:13 wirenboard-AN4RTE7N systemd[1]: wb-mqtt-serial.service: Scheduled restart job, restart counter is at 12.
Dec 18 12:45:13 wirenboard-AN4RTE7N systemd[1]: Stopped MQTT Driver for serial devices.
Dec 18 12:45:13 wirenboard-AN4RTE7N systemd[1]: wb-mqtt-serial.service: Consumed 27.559s CPU time.
Dec 18 12:45:13 wirenboard-AN4RTE7N systemd[1]: Started MQTT Driver for serial devices.
Dec 18 12:45:15 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] Default host and port detected, checking if UNIX socket exists on /var/run/mosquitto/mosquitto.sock
Dec 18 12:45:15 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] UNIX socket exists, using it for connection
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] connection estabilished with code "0" <success>
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 1)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 2)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 14)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 21)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 28)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 29)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 30)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 94)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 95)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 108)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 115)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 122)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 129)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 136)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 143)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 150)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 151)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 164)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 219)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 226)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 233)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 240)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 247)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 254)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 261)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 268)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 275)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 282)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 289)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 296)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 339)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 346)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 353)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 360)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 367)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 374)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 411)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 412)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 416)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [mqtt] subscription succeeded (message id 418)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Continuous read enabled [slave_id is 1]
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: Baud rate: setup register <modbus:1:holding: 110> <-- 1152 (0x480)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: Maximum value: setup register <modbus:1:holding: 5130> <-- 10000 (0x2710)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: Minimum value: setup register <modbus:1:holding: 5128> <-- -10000 (0xd8f0)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: Mode: setup register <modbus:1:holding: 5120> <-- 5376 (0x1500)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: Maximum value: setup register <modbus:1:holding: 9226> <-- 10000 (0x2710)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: Minimum value: setup register <modbus:1:holding: 9224> <-- -10000 (0xd8f0)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: Mode: setup register <modbus:1:holding: 9216> <-- 5376 (0x1500)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: Mode: setup register <modbus:1:holding: 13313> <-- 0 (0x0)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: Mode: setup register <modbus:1:holding: 13312> <-- 0 (0x0)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: Mode: setup register <modbus:1:holding: 17409> <-- 0 (0x0)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: Mode: setup register <modbus:1:holding: 17408> <-- 1 (0x1)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: Mode: setup register <modbus:1:holding: 21505> <-- 0 (0x0)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: Mode: setup register <modbus:1:holding: 21504> <-- 0 (0x0)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: Mode: setup register <modbus:1:holding: 25601> <-- 0 (0x0)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: Mode: setup register <modbus:1:holding: 25600> <-- 0 (0x0)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [serial device] device modbus:1 is connected
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: WARNING: [modbus] Continuous read is not enabled [slave_id is 11]
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: Baud rate: setup register <modbus:11:holding: 110> <-- 1152 (0x480)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: Outputs State After Power On: setup register <modbus:11:holding: 6> <-- 0 (0x0)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [modbus] Init: disable legacy input mode control: setup register <modbus:11:holding: 5> <-- 0 (0x0)
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [serial device] device modbus:11 is connected
Dec 18 12:45:16 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [serial device] device modbus:12 is connected
Dec 18 12:45:17 wirenboard-AN4RTE7N wb-mqtt-serial[5144]: INFO: [serial device] device modbus:13 is connected
Dec 18 12:45:55 wirenboard-AN4RTE7N kernel: i2c i2c-2: mv64xxx: I2C bus locked, block: 1, time_left: 0
Dec 18 12:45:57 wirenboard-AN4RTE7N kernel: i2c i2c-2: mv64xxx: I2C bus locked, block: 1, time_left: 0
Dec 18 12:45:59 wirenboard-AN4RTE7N kernel: i2c i2c-2: mv64xxx: I2C bus locked, block: 1, time_left: 0
Dec 18 12:46:34 wirenboard-AN4RTE7N kernel: i2c i2c-2: mv64xxx: I2C bus locked, block: 1, time_left: 0
Dec 18 12:46:36 wirenboard-AN4RTE7N kernel: i2c i2c-2: mv64xxx: I2C bus locked, block: 1, time_left: 0
Dec 18 12:46:38 wirenboard-AN4RTE7N kernel: i2c i2c-2: mv64xxx: I2C bus locked, block: 1, time_left: 0
Dec 18 12:47:37 wirenboard-AN4RTE7N kernel: i2c i2c-2: mv64xxx: I2C bus locked, block: 1, time_left: 0
Dec 18 12:47:39 wirenboard-AN4RTE7N kernel: i2c i2c-2: mv64xxx: I2C bus locked, block: 1, time_left: 0
Dec 18 12:47:41 wirenboard-AN4RTE7N kernel: i2c i2c-2: mv64xxx: I2C bus locked, block: 1, time_left: 0
Dec 18 12:47:48 wirenboard-AN4RTE7N systemd[1]: wb-mqtt-db.service: Main process exited, code=killed, status=4/ILL
Dec 18 12:47:48 wirenboard-AN4RTE7N systemd[1]: wb-mqtt-db.service: Failed with result 'signal'.
Dec 18 12:47:48 wirenboard-AN4RTE7N systemd[1]: wb-mqtt-db.service: Consumed 4.578s CPU time.
Dec 18 12:47:49 wirenboard-AN4RTE7N systemd[1]: wb-mqtt-db.service: Scheduled restart job, restart counter is at 18.
Dec 18 12:47:49 wirenboard-AN4RTE7N systemd[1]: Stopped Wiren Board database logger.
Dec 18 12:47:49 wirenboard-AN4RTE7N systemd[1]: wb-mqtt-db.service: Consumed 4.578s CPU time.
Dec 18 12:47:49 wirenboard-AN4RTE7N systemd[1]: Started Wiren Board database logger.
Dec 18 12:47:49 wirenboard-AN4RTE7N wb-mqtt-db[6388]: MQTT broker localhost:1883
Dec 18 12:47:49 wirenboard-AN4RTE7N wb-mqtt-db[6388]: Config file /etc/wb-mqtt-db.conf
Dec 18 12:47:49 wirenboard-AN4RTE7N wb-mqtt-db[6388]: INFO: [mqtt] Default host and port detected, checking if UNIX socket exists on /var/run/mosquitto/mosquitto.sock
Dec 18 12:47:49 wirenboard-AN4RTE7N wb-mqtt-db[6388]: INFO: [mqtt] UNIX socket exists, using it for connection
Dec 18 12:47:49 wirenboard-AN4RTE7N wb-mqtt-db[6388]: INFO: [sqlite] Creating tables if necessary
Dec 18 12:47:49 wirenboard-AN4RTE7N wb-mqtt-db[6388]: INFO: [sqlite] Create indices if necessary
Dec 18 12:47:49 wirenboard-AN4RTE7N wb-mqtt-db[6388]: INFO: [sqlite] Analyzing data table
Dec 18 12:47:49 wirenboard-AN4RTE7N wb-mqtt-db[6388]: INFO: [sqlite] DB initialization is done
Dec 18 12:47:50 wirenboard-AN4RTE7N wb-mqtt-db[6388]: INFO: DB logger started, go to main loop
Dec 18 12:47:50 wirenboard-AN4RTE7N wb-mqtt-db[6388]: INFO: [mqtt] connection estabilished with code "0" <success>
Dec 18 12:47:50 wirenboard-AN4RTE7N wb-mqtt-db[6388]: INFO: [mqtt] subscription succeeded (message id 1)
Dec 18 12:47:50 wirenboard-AN4RTE7N wb-mqtt-db[6388]: INFO: [mqtt] subscription succeeded (message id 2)
Dec 18 12:47:50 wirenboard-AN4RTE7N wb-mqtt-db[6388]: INFO: [mqtt] subscription succeeded (message id 5)
Dec 18 12:47:50 wirenboard-AN4RTE7N wb-mqtt-db[6388]: INFO: [mqtt] subscription succeeded (message id 6)
Dec 18 12:47:50 wirenboard-AN4RTE7N wb-mqtt-db[6388]: INFO: [mqtt] subscription succeeded (message id 7)
3

и wb-mqtt-serial с неприятной периодичностью так падает.

4

Добрый день.
Без диагностического архива сказать что-то определенное, к сожалению нельзя. Но по симптомам - мало RAM.
Посмотрите в тему Зависает WB7.3.2 и выложите архив.

5

приложен диагностический архив, доступен только сотрудникам поддержки
(150,5 КБ)
Вот все что пока есть по контроллеру.

7

А Debug для wb-mqtt-serial включен - зачем? из-за него данные в логе только за последний день…

8

Включили посмотреть что там писать будет.
Но что-то там опять умерло. OpenVPN лег, доступ к контроллеру пока потеряли. Хотя интернет на узле есть…

9

А контроллер с других узлов в этой же сети не пингуется?

10

Не… Неоткуда там пинговать.
Завтра обещали ребутнуть.

11

приложен диагностический архив, доступен только сотрудникам поддержки
(291,7 КБ)

Вот более свежий и надеюсь более нужный архив.

13

На всякий случай более свежий дебаг, пока контроллер онлайн.

приложен диагностический архив, доступен только сотрудникам поддержки
(318,9 КБ)

15

сейчас два сервиса-кандидата на срабатывание oom. Это wb-rules, занимающий треть RAM и NR с десятой долей.
За три дня их объем используемой памяти не изменился?

16

Да кто же его знает… Я палочкой тыкал в контроллер в праздники, перезагружал его.
Что интересно, у нас есть аналогичный контроллер, на нем в 2 раза больше рулесов запущенно таких же. Там все как-то норм.
Вот еще дебаг. Пока больше не буду перезагружать контроллер. И что-то там трогать лишний раз. Но у наз из-за перезагрузки serial система не работает. Она уходит в ошибку каждый раз и простаивает. А так как ошибка раз в 20-30 минут происходит, то мы ее и запустить не можем в продакшн.

приложен диагностический архив, доступен только сотрудникам поддержки
(170,7 КБ)

18

В целом память вроде есть свободная если верить скриншоту:
Правда не знаю кто его 2 часа назад перезагрузил. Я его уже больше суток не трогал. Чудны дела.

image
image949×366 12.8 KB

19

Так. Смотрю в логи.
Вижу

Jan 09 11:10:23 wirenboard-AN4RTE7N systemd[1]: wb-mqtt-serial.service: Main process exited, code=killed, status=4/ILL

Выполняю у себя kiil процесса, получаю:

Jan 09 08:59:41 wirenboard-AWI3MCGC systemd[1]: wb-mqtt-serial.service: Main process exited, code=killed, status=4/ILL
Jan 09 08:59:41 wirenboard-AWI3MCGC systemd[1]: wb-mqtt-serial.service: Failed with result 'signal'.
Jan 09 08:59:41 wirenboard-AWI3MCGC systemd[1]: wb-mqtt-serial.service: Consumed 7.152s CPU time.

При этом в логе нет срабатывания OOM.
Точно нигде не программно не убивается процесс?

20

Мы такой цели не преследовали. Убивать mqtt-serial. Так что точно нет. Может какой-нибудь взлом? У меня других идей нет. Как бы проверить системные файлы на целостность?

Там еще с mqtt-db такая же ерунда. Тоже вышибает его чуть ли не чаще сериала.

21

У меня, кстати, аналогичная мысль возникла.

Да, причем в то же время точно что и serial/
Оптимально сделать бэкап конфигов и factory reset - чтоб убедиться что именно аппаратно (на 99% в этом и так уверен) все хорошо.

22

прогнал rkhunter --check. На первый взгляд все чисто. Я слабо верю что там кто-то что-то крутое мог подсадить на контроллер.
iptraf на первый взгляд паразитный трафик тоже не показывает. все соединения более менее понятно откуда и куда.

А как-то можно посмотреть кто сигнал kill процессу посылает?

rkhunter.log (126,9 КБ)

23

И вот что нам советует ИИ: Попробую.

Чтобы выяснить, какой процесс отправляет сигнал SIGKILL (или любой другой сигнал) вашему процессу в Linux, вы можете использовать системный вызов auditd, который предназначен для аудита системных событий. Убедитесь, что auditd установлен и запущен на вашей системе. Вот как вы можете настроить аудит для отслеживания сигналов, отправляемых процессам:

Установите auditd, если он еще не установлен:

sudo apt-get install auditd

Включите аудит для сигналов, настроив правила аудита. Например, создайте файл правил /etc/audit/rules.d/audit.rules и добавьте туда следующие строки:

-a always,exit -F arch=b64 -S kill -F a0=9 -k audit_kill
-a always,exit -F arch=b32 -S kill -F a0=9 -k audit_kill

Здесь -F a0=9 означает, что вы отслеживаете сигнал SIGKILL, который имеет номер 9. -k audit_kill — это ключевая метка для поиска соответствующих записей в логах.

Перезапустите auditd, чтобы применить новые правила:

sudo systemctl restart auditd

Проверьте логи, чтобы увидеть, какие события были зафиксированы:

sudo ausearch -k audit_kill

Это даст вам вывод с деталями о каждом событии kill, включая ID процесса (pid), который отправил сигнал, и целевой процесс. Обратите внимание, что SIGKILL не может быть обработан или проигнорирован самим процессом, поэтому его сложнее отслеживать напрямую внутри самого процесса.
24

И нет, фактори ресет сделать не могу. Контроллер стоит далеко, и самое не приятное, что он сам поднимает openvpn для связи с наружей. Так что при любом ресет я потеряю к контроллеру доступ. Везти его через пол страны в офис - это последнее, что я буду делать.

25

Не прокатит. auditd не поддерживается ядром.

image
image1215×470 18 KB