LINUX.ORG.RU
Форум — Admin  

Костыль не работает! [systemd/rsyslog/script]

 , , ,


0

1

Добрый день!

Предыстория: есть некая железка, которая периодически пинает электричеством USB-порт, там срабатывает защита, после чего девайс переподключается и работает. Но не работает сервисная программа, которая запускается из-под юзера посредством systemd и затыкается. Сервисную программу нужно перезапустить через systemctl --user ....

Т.к. железку заменить невозможно, для решения проблемы был написан дополнительный юнит костыльного типа, который тоже запускается из-под юзера. Юнит запускает следующий скрипт:

#!/bin/bash

echo EMI handling monitor is on

tail -f /var/log/syslog | fgrep --line-buffered 'disabled by hub (EMI?)' | while read -r line; do 
   echo "EMI trigger detected"
   systemctl --user is-active --quiet user_service_program.service && systemctl --user restart user_service_program.service 
   /opt/some_id/bin/emi-alert.sh
done

Так вот: этот скрипт срабатывает… не всегда, когда сообщение приходит от ядра, но всегда во время тестов:

  • Если сделать logger 'TEST disabled by hub (EMI?), срабатывает всегда.
  • Если поменять строчку на другую, которая есть в логе, например, на Product: CP2102 USB to UART Bridge Controller, то на EMI все равно срабатывает спорадически, а на ручное втыкание — всегда.

Резюмируя: любой «ручной» способ отрабатывает всегда корректно. А когда происходит реальная ситуация, раз через три. Происходит это не очень часто, но каждый раз, когда не срабатывает, об этом знают все, т.к. при этом разливается куча воды… В общем, все на нервах, а я в шоке и что делать с этой недетерминированностью, не представляю.

Буду очень благодарен за помощь.

Примеры, когда сработало (2) и не сработало (1,3):

syslog.1:Mar 14 16:40:08 some_id kernel: [293630.870396] usb usb2-port2: disabled by hub (EMI?), re-enabling...
syslog.1-Mar 14 16:40:08 some_id kernel: [293630.870409] usb 2-2: USB disconnect, device number 3
syslog.1-Mar 14 16:40:08 some_id kernel: [293630.871148] cp210x ttyUSB5: failed set request 0x7 status: -19
syslog.1-Mar 14 16:40:08 some_id kernel: [293630.871162] cp210x ttyUSB5: failed set request 0x12 status: -19
syslog.1-Mar 14 16:40:08 some_id kernel: [293630.871170] cp210x ttyUSB5: failed set request 0x0 status: -19
syslog.1-Mar 14 16:40:08 some_id kernel: [293630.871472] cp210x ttyUSB5: cp210x converter now disconnected from ttyUSB5
syslog.1-Mar 14 16:40:08 some_id kernel: [293630.871545] cp210x 2-2:1.0: device disconnected
syslog.1-Mar 14 16:40:08 some_id kernel: [293631.146323] usb 2-2: new full-speed USB device number 4 using uhci_hcd
syslog.1-Mar 14 16:40:08 some_id kernel: [293631.367108] usb 2-2: New USB device found, idVendor=10c4, idProduct=ea60, bcdDevice= 1.00
syslog.1-Mar 14 16:40:08 some_id kernel: [293631.367114] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
syslog.1-Mar 14 16:40:08 some_id kernel: [293631.367118] usb 2-2: Product: CP2102 USB to UART Bridge Controller
syslog.1-Mar 14 16:40:08 some_id kernel: [293631.367122] usb 2-2: Manufacturer: Silicon Labs
syslog.1-Mar 14 16:40:08 some_id kernel: [293631.367125] usb 2-2: SerialNumber: 0001
syslog.1-Mar 14 16:40:08 some_id kernel: [293631.380262] cp210x 2-2:1.0: cp210x converter detected
syslog.1-Mar 14 16:40:08 some_id kernel: [293631.385298] usb 2-2: cp210x converter now attached to ttyUSB0
syslog.1-Mar 14 16:40:08 some_id mtp-probe: checking bus 2, device 4: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-2"
syslog.1-Mar 14 16:40:08 some_id mtp-probe: bus: 2, device: 4 was not an MTP device
syslog.1-Mar 14 16:40:08 some_id mtp-probe: checking bus 2, device 4: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-2"
syslog.1-Mar 14 16:40:08 some_id mtp-probe: bus: 2, device: 4 was not an MTP device
syslog.1-Mar 14 16:40:11 some_id ModemManager[943]: <info>  Couldn't check support for device '/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-2': not supported by any plugin
syslog.1-Mar 14 16:40:30 some_id systemd[1]: Started Check network for actual connectivity.
--
syslog.4:Mar 11 19:48:28 some_id kernel: [45736.461730] usb usb2-port2: disabled by hub (EMI?), re-enabling...
syslog.4-Mar 11 19:48:28 some_id kernel: [45736.461743] usb 2-2: USB disconnect, device number 2
syslog.4-Mar 11 19:48:28 some_id kernel: [45736.462915] cp210x ttyUSB0: failed set request 0x7 status: -19
syslog.4-Mar 11 19:48:28 some_id kernel: [45736.462925] cp210x ttyUSB0: failed set request 0x12 status: -19
syslog.4-Mar 11 19:48:28 some_id kernel: [45736.462931] cp210x ttyUSB0: failed set request 0x0 status: -19
syslog.4-Mar 11 19:48:28 some_id kernel: [45736.463203] cp210x ttyUSB0: cp210x converter now disconnected from ttyUSB0
syslog.4-Mar 11 19:48:28 some_id kernel: [45736.463267] cp210x 2-2:1.0: device disconnected
syslog.4-Mar 11 19:48:28 some_id kernel: [45736.737642] usb 2-2: new full-speed USB device number 3 using uhci_hcd
syslog.4-Mar 11 19:48:28 some_id kernel: [45736.953898] usb 2-2: New USB device found, idVendor=10c4, idProduct=ea60, bcdDevice= 1.00
syslog.4-Mar 11 19:48:28 some_id kernel: [45736.953904] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
syslog.4-Mar 11 19:48:28 some_id kernel: [45736.953908] usb 2-2: Product: CP2102 USB to UART Bridge Controller
syslog.4-Mar 11 19:48:28 some_id kernel: [45736.953911] usb 2-2: Manufacturer: Silicon Labs
syslog.4-Mar 11 19:48:28 some_id kernel: [45736.953914] usb 2-2: SerialNumber: 0001
syslog.4-Mar 11 19:48:28 some_id emi-monitor.sh[1159]: EMI trigger detected
syslog.4-Mar 11 19:48:28 some_id kernel: [45736.967084] cp210x 2-2:1.0: cp210x converter detected
syslog.4-Mar 11 19:48:28 some_id kernel: [45736.978122] usb 2-2: cp210x converter now attached to ttyUSB5
syslog.4-Mar 11 19:48:28 some_id systemd[1101]: Stopping Operate user_service_program software...
syslog.4-Mar 11 19:48:28 some_id mtp-probe: checking bus 2, device 3: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-2"
syslog.4-Mar 11 19:48:28 some_id mtp-probe: bus: 2, device: 3 was not an MTP device
syslog.4-Mar 11 19:48:28 some_id mtp-probe: checking bus 2, device 3: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-2"
syslog.4-Mar 11 19:48:28 some_id mtp-probe: bus: 2, device: 3 was not an MTP device
syslog.4-Mar 11 19:48:29 some_id user_service_program_rpc.py[133121]: True
syslog.4-Mar 11 19:48:29 some_id dhclient[811]: DHCPREQUEST for 10.100.252.40 on wlan0 to 192.168.68.248 port 67 (xid=0x7391afc3)
syslog.4-Mar 11 19:48:30 some_id systemd[1101]: user_service_program.service: Succeeded.
syslog.4-Mar 11 19:48:30 some_id systemd[1101]: Stopped Operate user_service_program software.
syslog.4-Mar 11 19:48:30 some_id systemd[1101]: Started Operate user_service_program software.
syslog.4-Mar 11 19:48:30 some_id emi-monitor.sh[133135]: EMI restart detected
syslog.4-Mar 11 19:48:31 some_id ModemManager[943]: <info>  Couldn't check support for device '/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-2': not supported by any plugin
--
syslog.5:Mar 10 15:29:01 some_id kernel: [995309.299430] usb usb2-port2: disabled by hub (EMI?), re-enabling...
syslog.5-Mar 10 15:29:01 some_id kernel: [995309.299443] usb 2-2: USB disconnect, device number 11
syslog.5-Mar 10 15:29:01 some_id kernel: [995309.300017] cp210x ttyUSB5: failed set request 0x7 status: -19
syslog.5-Mar 10 15:29:01 some_id kernel: [995309.300028] cp210x ttyUSB5: failed set request 0x12 status: -19
syslog.5-Mar 10 15:29:01 some_id kernel: [995309.300037] cp210x ttyUSB5: failed set request 0x0 status: -19
syslog.5-Mar 10 15:29:01 some_id kernel: [995309.300314] cp210x ttyUSB5: cp210x converter now disconnected from ttyUSB5
syslog.5-Mar 10 15:29:01 some_id kernel: [995309.300361] cp210x 2-2:1.0: device disconnected
syslog.5-Mar 10 15:29:01 some_id kernel: [995309.575389] usb 2-2: new full-speed USB device number 12 using uhci_hcd
syslog.5-Mar 10 15:29:01 some_id kernel: [995309.788021] usb 2-2: New USB device found, idVendor=10c4, idProduct=ea60, bcdDevice= 1.00
syslog.5-Mar 10 15:29:01 some_id kernel: [995309.788031] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
syslog.5-Mar 10 15:29:01 some_id kernel: [995309.788037] usb 2-2: Product: CP2102 USB to UART Bridge Controller
syslog.5-Mar 10 15:29:01 some_id kernel: [995309.788043] usb 2-2: Manufacturer: Silicon Labs
syslog.5-Mar 10 15:29:01 some_id kernel: [995309.788048] usb 2-2: SerialNumber: 0001
syslog.5-Mar 10 15:29:01 some_id kernel: [995309.800152] cp210x 2-2:1.0: cp210x converter detected
syslog.5-Mar 10 15:29:01 some_id kernel: [995309.805278] usb 2-2: cp210x converter now attached to ttyUSB0
syslog.5-Mar 10 15:29:01 some_id mtp-probe: checking bus 2, device 12: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-2"
syslog.5-Mar 10 15:29:01 some_id mtp-probe: bus: 2, device: 12 was not an MTP device
syslog.5-Mar 10 15:29:01 some_id mtp-probe: checking bus 2, device 12: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-2"
syslog.5-Mar 10 15:29:01 some_id mtp-probe: bus: 2, device: 12 was not an MTP device
syslog.5-Mar 10 15:29:04 some_id ModemManager[938]: <info>  Couldn't check support for device '/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-2': not supported by any plugin
syslog.5-Mar 10 15:30:01 some_id CRON[2483393]: (root) CMD ([ -x /etc/init.d/anacron ] && if [ ! -d /run/systemd/system ]; then /usr/sbin/invoke-rc.d anacron start >/dev/null; fi)
syslog.5-Mar 10 15:33:41 some_id systemd[1]: Started Run anacron jobs.
syslog.5-Mar 10 15:33:41 some_id anacron[2483696]: Anacron 2.3 started on 2021-03-10
syslog.5-Mar 10 15:33:41 some_id anacron[2483696]: Normal exit (0 jobs run)
syslog.5-Mar 10 15:33:41 some_id systemd[1]: anacron.service: Succeeded.
syslog.5-Mar 10 15:43:15 some_id dhclient[802]: DHCPREQUEST for 10.100.252.40 on wlan0 to 192.168.68.248 port 67 (xid=0xd7d2b2d)
syslog.5-Mar 10 15:43:15 some_id dhclient[802]: send_packet: Network is unreachable
syslog.5-Mar 10 15:43:15 some_id dhclient[802]: send_packet: please consult README file regarding broadcast address.
syslog.5-Mar 10 15:43:15 some_id dhclient[802]: dhclient.c:2887: Failed to send 300 byte long packet over fallback interface.
★★

Что именно не срабатывает, перезапуск юнита или нет сообщения «EMI trigger detected»?

ИМХО, неправильно, что скрипт не пишет время своего срабатывания.

Для ротируемых лог-файлов советуют опцию -F (-f - -retry).

mky ★★★★★
()
Последнее исправление: mky (всего исправлений: 2)
Ответ на: комментарий от mky

Ох, чувствую, что в точку!

Гениально! Думаю, именно в том и проблема, что он ротируется! Огромное-преогромное спасибо!

fAX ★★
() автор топика

systemctl --user is-active --quiet user_service_program.service && systemctl --user restart user_service_program.service

systemctl --user try-restart user_service_program.service

eternal_sorrow ★★★★★
()
Ответ на: комментарий от intelfx

Я не понял, как правильно (семантически) из udev пробрасывать события в юзерский systemd. Притом событие на старте системы обязательно нужно фильтровать.

Может, есть ссылка на почитать? Спасибо!

fAX ★★
() автор топика
Последнее исправление: fAX (всего исправлений: 1)
Ответ на: комментарий от fAX

Ну, с юзерским действительно сложнее. Тебе точно нужен именно юзерский, PID 1 с User= в сервис-файле не подойдёт?

А так можно попробовать сделать совсем по-другому: выкинуть в принципе весь костыль с рестартом сервиса, удавом добавить к железке TAG+="uaccess" и добавить свой сервис в двусторонние зависимости к .device-юниту.

intelfx ★★★★★
()
Последнее исправление: intelfx (всего исправлений: 1)
Вы не можете добавлять комментарии в эту тему. Тема перемещена в архив.
Admin