Вот такая картина 10 часов.
Wiren Board 6.9.1 (s/n A6YXEPXP), release wb-2207 (as wb-2207)
wb-utils 3.7.0-wb4
А происходит такое, когда подключаешься к ppp по gsm а потом при активном соединении делаешь reboot.
Если перезагружать по питанию, такой беды не происходит.
приветствую!
взяли в работу; кое-что починили; просим попробовать у себя!
вероятная причина проблемы - неаккуратная работа wb-gsm с занятыми (например, ppp) портами
Обновил. Теперь не зависает. В логе видим следующее:
Контроллер перезагружал. По питанию не выключал.
в ppp работаю c /dev/ttyUSB2
tail -n 50 -f /var/log/messages | grep -e chat -e ppp -e sim
Nov 18 15:37:22 wirenboard-A6YXEPXP chat[16049]: ERROR
Nov 18 15:37:22 wirenboard-A6YXEPXP chat[16049]: -- failed
Nov 18 15:37:22 wirenboard-A6YXEPXP chat[16049]: Failed (ERROR)
Nov 18 15:37:22 wirenboard-A6YXEPXP pppd[12967]: Connect script failed
Nov 18 15:37:39 wirenboard-A6YXEPXP chat[16363]: timeout set to 2 seconds
Nov 18 15:37:39 wirenboard-A6YXEPXP chat[16363]: abort on (ERROR)
Nov 18 15:37:39 wirenboard-A6YXEPXP chat[16363]: abort on (BUSY)
Nov 18 15:37:39 wirenboard-A6YXEPXP chat[16363]: send (AT^M)
Nov 18 15:37:39 wirenboard-A6YXEPXP chat[16363]: expect (OK)
Nov 18 15:37:39 wirenboard-A6YXEPXP chat[16363]: AT
Nov 18 15:37:39 wirenboard-A6YXEPXP chat[16363]:
Nov 18 15:37:39 wirenboard-A6YXEPXP chat[16363]:
Nov 18 15:37:39 wirenboard-A6YXEPXP chat[16363]: OK
Nov 18 15:37:39 wirenboard-A6YXEPXP chat[16363]: -- got it
Nov 18 15:37:39 wirenboard-A6YXEPXP chat[16363]: send (^M)
Nov 18 15:37:39 wirenboard-A6YXEPXP simcard_watchdog.sh[618]: <2022-11-18 15:37:39,852//opt/simcard_watchdog/simcard_switcher.py:60/INFO>- got exception in serial port write: UnicodeDecodeError('utf-8', b'\x14\x00\x00\x00\x00\x00\x00\x02+\x001G7>i\x00\r\x00\xc8\x00', 18, 19, 'invalid continuation byte')
Nov 18 15:37:39 wirenboard-A6YXEPXP simcard_watchdog.sh[618]: <2022-11-18 15:37:39,883//opt/simcard_watchdog/watchdog.py:200/INFO>- bad rssi_index AT answer:
Nov 18 15:37:39 wirenboard-A6YXEPXP simcard_watchdog.sh[618]: <2022-11-18 15:37:39,888//opt/simcard_watchdog/watchdog.py:236/INFO>- fail in signal_sender_loop, e:KeyError('bad AT answer'), skip_single_error: False
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16407]: timeout set to 5 seconds
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16407]: abort on (ERROR)
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16407]: abort on (BUSY)
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16407]: send (AT^M)
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16407]: expect (OK)
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16407]: AT
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16407]:
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16407]:
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16407]: OK
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16407]: -- got it
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16407]: send (^M)
Nov 18 15:37:40 wirenboard-A6YXEPXP pppd[12967]: Serial port initialized.
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16412]: abort on (BUSY)
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16412]: abort on (NO ANSWER)
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16412]: abort on (NO CARRIER)
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16412]: abort on (ERROR)
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16412]: timeout set to 5 seconds
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16412]: send (ATZ^M)
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16412]: expect (OK)
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16412]: ATZ^M^M
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16412]: ERROR
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16412]: -- failed
Nov 18 15:37:40 wirenboard-A6YXEPXP chat[16412]: Failed (ERROR)
Nov 18 15:37:40 wirenboard-A6YXEPXP pppd[12967]: Connect script failed
root@wirenboard-A6YXEPXP:~# wb-gsm off
root@wirenboard-A6YXEPXP:~#
root@wirenboard-A6YXEPXP:~#
root@wirenboard-A6YXEPXP:~# ls -l /dev| grep -e ACM -e GSM -e USB
root@wirenboard-A6YXEPXP:~# DEBUG=true wb-gsm restart_if_broken
DEBUG: main: Called from pid 28609 (bash)
DEBUG: guess_of_node: Got of_gsm_node: /soc/bus@2100000/usb@2184200/usb-hub@1/wbc-modem@2
DEBUG: restart_if_broken: Modem switched off, switch it on instead of testing the connection
DEBUG: ensure_on: switching on GSM modem using POWER FET
DEBUG: toggle: toggle GSM modem state using PWRKEY
DEBUG: ensure_on: Waiting for modem to start
DEBUG: init_usb_connection: Will wait up to 30s untill usb port becomes available
DEBUG: probe_usb_ports: Probing all modem's usb ports
DEBUG: test_connection: (port:/dev/ttyUSB0; timeout:2) => 137
DEBUG: test_connection: (port:/dev/ttyUSB1; timeout:2) => 137
DEBUG: test_connection: /dev/ttyUSB2 is not free
DEBUG: test_connection: (port:/dev/ttyUSB2; timeout:2) => 1
DEBUG: probe_usb_ports: Modem's usb ports: ttyUSB0 ttyUSB1 ttyUSB2
DEBUG: probe_usb_ports: Answered to 'AT':
Turning OFF modem's POWER FET
DEBUG: of_get_prop_gpio: /soc/bus@2100000/usb@2184200/usb-hub@1/wbc-modem@2 power-gpios
DEBUG: of_get_prop_gpio: gpio 33 4 0
DEBUG: of_gpio_to_num: Unpacked gpio 128:4:0 -> 128+4
Force exit: no valid usb-AT connection after 30s
1: /usr/lib/wb-utils/wb-gsm-common.sh:518 init_usb_connection(...)
2: /usr/lib/wb-utils/wb-gsm-common.sh:554 ensure_on(...)
3: /usr/bin/wb-gsm:29 restart_if_broken(...)
Error in /usr/lib/wb-utils/wb-gsm-common.sh:71. '[[ -n $unlinked_ports ]]' exited with status 0
Call tree:
1: /usr/lib/wb-utils/wb-gsm-common.sh:1 force_exit_handler(...)
2: /usr/lib/wb-utils/wb-gsm-common.sh:184 force_exit(...)
3: /usr/lib/wb-utils/wb-gsm-common.sh:518 init_usb_connection(...)
4: /usr/lib/wb-utils/wb-gsm-common.sh:554 ensure_on(...)
5: /usr/bin/wb-gsm:29 restart_if_broken(...)
Exiting with status 1
предполагаю, ошибка - потому, что вообще все порты модема заняты (предполагаю, watchdog-скриптом); кажется, wb-gsm именно так и ругнулся
кстати, хотелось бы взглянуть на скрипт вочдога, если можно:)
(в частности, интересует: ходит ли он в тот же порт, что и pppd; как часто ходит; проверяет ли занятость порта; …)
если интересует уровень связи - можно ходить через второй порт модема (не занятый pppd)
в общем случае - поведение вида “после включения не работало-не работало; через 5 минут всё заработало” выглядит примерно так: pppd, видя непорядок, периодически дёргает wb-gsm; в какой-то момент времени скрипт вочдога отпускает порты, и всё запускается
Давайте упростим. Дисейблю этот вочдог и убирпем его из нашего уравнения.
Пытаемся обеспечить автостарт ppp штатными способами из wiki. (не автостартует)
Что имеем:
Что мы имеем после перезапуска по reboot контроллера.
Вуаля!
Но почему не поднимается модем при перезапуске контроллера автоматом? Что-то не так в последовательности инициализаций служб и устройств? Я даже не понимаю как лог собрать.
Да, похоже на гонку в момент запуска.
В логах есть от chat записи?
Ну и если первый pre-up sleep 10
увеличить, до 20 для проверки гипотезы - при запуске поднимается?
еще раз перезагрузил с 30 сек.
но теперь по кругу гоняет вот такой лог: У вас нет понимания почему такое происходить может?
Nov 22 14:13:41 wirenboard-A6YXEPXP chat[13025]: -- got it
Nov 22 14:13:41 wirenboard-A6YXEPXP chat[13025]: send (^M)
Nov 22 14:13:41 wirenboard-A6YXEPXP pppd[7826]: Serial port initialized.
Nov 22 14:13:41 wirenboard-A6YXEPXP chat[13030]: abort on (BUSY)
Nov 22 14:13:41 wirenboard-A6YXEPXP chat[13030]: abort on (NO ANSWER)
Nov 22 14:13:41 wirenboard-A6YXEPXP chat[13030]: abort on (NO CARRIER)
Nov 22 14:13:41 wirenboard-A6YXEPXP chat[13030]: abort on (ERROR)
Nov 22 14:13:41 wirenboard-A6YXEPXP chat[13030]: timeout set to 5 seconds
Nov 22 14:13:41 wirenboard-A6YXEPXP chat[13030]: send (ATZ^M)
Nov 22 14:13:41 wirenboard-A6YXEPXP chat[13030]: expect (OK)
Nov 22 14:13:41 wirenboard-A6YXEPXP chat[13030]: ATZ^M^M
Nov 22 14:13:41 wirenboard-A6YXEPXP chat[13030]: OK
Nov 22 14:13:41 wirenboard-A6YXEPXP chat[13030]: -- got it
Nov 22 14:13:41 wirenboard-A6YXEPXP chat[13030]: send (AT+CGDCONT=1,"IP","internet"^M)
Nov 22 14:13:41 wirenboard-A6YXEPXP chat[13030]: expect (OK)
Nov 22 14:13:41 wirenboard-A6YXEPXP chat[13030]: ^M
Nov 22 14:13:42 wirenboard-A6YXEPXP chat[13030]: AT+CGDCONT=1,"IP","internet"^M^M
Nov 22 14:13:42 wirenboard-A6YXEPXP chat[13030]: OK
Nov 22 14:13:42 wirenboard-A6YXEPXP chat[13030]: -- got it
Nov 22 14:13:42 wirenboard-A6YXEPXP chat[13030]: send (ATD*99***1#^M)
Nov 22 14:13:42 wirenboard-A6YXEPXP chat[13030]: expect (CONNECT)
Nov 22 14:13:42 wirenboard-A6YXEPXP chat[13030]: ^M
Nov 22 14:13:42 wirenboard-A6YXEPXP chat[13030]: ATD*99***1#^M^M
Nov 22 14:13:42 wirenboard-A6YXEPXP chat[13030]: CONNECT
Nov 22 14:13:42 wirenboard-A6YXEPXP chat[13030]: -- got it
Nov 22 14:13:42 wirenboard-A6YXEPXP pppd[7826]: Serial connection established.
Nov 22 14:13:42 wirenboard-A6YXEPXP pppd[7826]: Using interface ppp0
Nov 22 14:13:42 wirenboard-A6YXEPXP pppd[7826]: Connect: ppp0 <--> /dev/ttyUSB2
Nov 22 14:13:43 wirenboard-A6YXEPXP pppd[7826]: PAP authentication succeeded
Nov 22 14:13:43 wirenboard-A6YXEPXP pppd[7826]: kernel does not support PPP filtering
Nov 22 14:13:43 wirenboard-A6YXEPXP pppd[7826]: LCP terminated by peer
Nov 22 14:13:46 wirenboard-A6YXEPXP pppd[7826]: Connection terminated.
Nov 22 14:13:46 wirenboard-A6YXEPXP avahi-daemon[544]: Withdrawing workstation service for ppp0.
Nov 22 14:13:47 wirenboard-A6YXEPXP pppd[7826]: Modem hangup
слипы, конечно, вариант плохой; постараемся от них избавиться
есть проблема: у нас не получается воспроизвести такое же поведение (с wb-utils_3.7.0-wb107~exp-1)
что мы делаем:
Берем чистый контроллер (wb6.7+); вставляем туда wbc-4g (рабочая sim-карта в sim1; антенна - прикручена); накатываем factoryreset с wb-2207 (вот этот, например)
apt update; apt upgrade -y
выставляем модем в webui
настраиваем ppp, как в этой секции вики (прописываем в /etc/network/interfaces)
прописываем /dev/ttyUSB2 в чат-скрипте (в нашем случае, мтс); кстати, настоятельно не рекомендуем так делать: с wb-utils_3.7.0-wb107~exp-1, wb-gsm сам симлинкает нужный для ppp порт на /dev/ttyGSM
всё работает (и при перезагрузке, и при ifup/ifdown ppp0)
отличаются ли как-то действия на Вашей стороне? (например, запущены свои systemd-сервисы)
если есть возможность проделать то же самое на чистом контроллере - было бы здорово! (назовём это “Эксперимент 1”)
глядя в логи, пока что есть только одна гипотеза - гонка сетей и wb-hwconf-manager.service
посему - попрошу Вас (на контроллере с wb-utils_3.7.0-wb107~exp-1) (Эксперимент 2) :
прислать картинку systemd-analyze plot > bootup_ppp.svg, когда ppp не поднялся после перезагрузки
если после п.2 проблема так и осталась - предлагаю мне подключится к Вашему контроллеру (например, по anydesk; в удобное Вам время (по МСК; рабочие дни); хочется minicom и ssh на wb)
p.s. хочется информацию по версии модуля модема (наклеечка вида “v1.2.3A”; а еще лучше - прям фотографии модемного модуля с наклеечками и imei, если есть возможность)
