Opened 5 years ago
Closed 4 years ago
#35 closed баг (fixed)
Модуль SIM включается в работу только после многократных перевключений питания
| Reported by: | san | Owned by: | |
|---|---|---|---|
| Priority: | major | Milestone: | 1 очередь |
| Keywords: | Cc: | andrei |
Description (last modified by )
Пользователи выслали нам логи работы устройств, в логе одного из устройств(назовём его клиент2) я вижу что контроллер дёргает питанием сима 8 раз подряд прежде чем Sim выйдет в рабочий режим.
В логах других устройств подобных сценариев пока не обнаружил, а в логах клиент2 такое поведение встречается не раз. Думаю что это, как минимум, странно и нужно попытаться понять причины.
Все логи можно увидеть в xchange\alx\Test_and_bugs\Рамис, там логи от трёх разных устройств, в том числе и клиент2.
Вот фрагмент лога(r140) с описанным поведением:
Jul 4 17:52:16 3gd[17863]: sim5320.cpp:164: powering off SIM5320... Jul 4 17:52:16 kernel: option1 ttyUSB2: GSM modem (1-port) converter now disconnected from ttyUSB2 Jul 4 17:52:16 kernel: option 1-2:1.2: device disconnected Jul 4 17:52:16 pppd[22895]: Hangup (SIGHUP) Jul 4 17:52:16 pppd[22895]: Modem hangup Jul 4 17:52:16 pppd[22895]: Connect time 20.5 minutes. Jul 4 17:52:16 pppd[22895]: Sent 3441244 bytes, received 2145184 bytes. Jul 4 17:52:16 pppd[22895]: Script /etc/ppp/ip-down started (pid 23002) Jul 4 17:52:16 pppd[22895]: Connection terminated. Jul 4 17:52:16 kernel: option1 ttyUSB3: GSM modem (1-port) converter now disconnected from ttyUSB3 Jul 4 17:52:16 kernel: option 1-2:1.3: device disconnected Jul 4 17:52:16 kernel: option1 ttyUSB4: GSM modem (1-port) converter now disconnected from ttyUSB4 Jul 4 17:52:16 kernel: option 1-2:1.4: device disconnected Jul 4 17:52:16 pppd[22895]: Script /etc/ppp/ip-down finished (pid 23002), status = 0x0 Jul 4 17:52:18 ntpd[253]: Deleting interface #78 ppp0, 46.23.190.112#123, interface stats: received=47, sent=51, dropped=0, active_time=1230 secs Jul 4 17:52:18 ntpd[253]: 91.189.94.4 local addr 46.23.190.112 -> <null> Jul 4 17:52:18 ntpd[253]: 91.189.91.157 local addr 46.23.190.112 -> <null> Jul 4 17:52:18 ntpd[253]: 91.189.89.199 local addr 46.23.190.112 -> <null> Jul 4 17:52:18 ntpd[253]: 91.189.89.198 local addr 46.23.190.112 -> <null> Jul 4 17:52:21 3gd[17863]: sim5320.cpp:139: powering on SIM5320... Jul 4 17:52:36 3gd[17863]: sim5320.cpp:190: cannot open /dev/ttyUSB2: No such file or directory Jul 4 17:52:36 3gd[17863]: sim5320.cpp:164: powering off SIM5320... Jul 4 17:52:41 3gd[17863]: sim5320.cpp:139: powering on SIM5320... Jul 4 17:52:46 pppd[22895]: Failed to open /dev/modem: No such file or directory Jul 4 17:52:56 3gd[17863]: sim5320.cpp:190: cannot open /dev/ttyUSB2: No such file or directory Jul 4 17:52:56 3gd[17863]: sim5320.cpp:164: powering off SIM5320... Jul 4 17:53:01 3gd[17863]: sim5320.cpp:139: powering on SIM5320... Jul 4 17:53:14 ntpd[253]: error resolving pool ntp.ubuntu.com: Temporary failure in name resolution (-3) Jul 4 17:53:16 3gd[17863]: tcp_tty.cpp:355: TCP inactivity timeout Jul 4 17:53:16 3gd[17863]: link.cpp:192: --> Link::error(): connection closed (16) Jul 4 17:53:16 pppd[22895]: Failed to open /dev/modem: No such file or directory Jul 4 17:53:16 3gd[17863]: sim5320.cpp:190: cannot open /dev/ttyUSB2: No such file or directory Jul 4 17:53:16 3gd[17863]: sim5320.cpp:164: powering off SIM5320... Jul 4 17:53:21 3gd[17863]: sim5320.cpp:139: powering on SIM5320... Jul 4 17:53:37 3gd[17863]: sim5320.cpp:190: cannot open /dev/ttyUSB2: No such file or directory Jul 4 17:53:37 3gd[17863]: sim5320.cpp:164: powering off SIM5320... Jul 4 17:53:42 3gd[17863]: sim5320.cpp:139: powering on SIM5320... Jul 4 17:53:46 3gd[17863]: tcp_tty.cpp:181: connecting to 46.23.184.150 port 1001 (fd 16)... Jul 4 17:53:46 3gd[17863]: tcp_tty.cpp:197: cannot connect: Network is unreachable Jul 4 17:53:46 3gd[17863]: link.cpp:192: --> Link::error(): connection closed (-1) Jul 4 17:53:46 pppd[22895]: Failed to open /dev/modem: No such file or directory Jul 4 17:53:57 3gd[17863]: sim5320.cpp:190: cannot open /dev/ttyUSB2: No such file or directory Jul 4 17:53:57 3gd[17863]: sim5320.cpp:164: powering off SIM5320... Jul 4 17:54:02 3gd[17863]: sim5320.cpp:139: powering on SIM5320... Jul 4 17:54:16 3gd[17863]: tcp_tty.cpp:181: connecting to 46.23.184.150 port 1001 (fd 16)... Jul 4 17:54:16 3gd[17863]: tcp_tty.cpp:197: cannot connect: Network is unreachable Jul 4 17:54:16 3gd[17863]: link.cpp:192: --> Link::error(): connection closed (-1) Jul 4 17:54:16 pppd[22895]: Failed to open /dev/modem: No such file or directory Jul 4 17:54:17 3gd[17863]: sim5320.cpp:190: cannot open /dev/ttyUSB2: No such file or directory Jul 4 17:54:17 3gd[17863]: sim5320.cpp:164: powering off SIM5320... Jul 4 17:54:20 ntpd[253]: error resolving pool ntp.ubuntu.com: Temporary failure in name resolution (-3) Jul 4 17:54:22 3gd[17863]: sim5320.cpp:139: powering on SIM5320... Jul 4 17:54:37 3gd[17863]: sim5320.cpp:190: cannot open /dev/ttyUSB2: No such file or directory Jul 4 17:54:37 3gd[17863]: sim5320.cpp:164: powering off SIM5320... Jul 4 17:54:42 3gd[17863]: sim5320.cpp:139: powering on SIM5320... Jul 4 17:54:43 kernel: usb 1-2: new high-speed USB device number 39 using atmel-ehci Jul 4 17:54:43 kernel: usb 1-2: New USB device found, idVendor=1e0e, idProduct=9001 Jul 4 17:54:43 kernel: usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3 Jul 4 17:54:43 kernel: usb 1-2: Product: SimTech, Incorporated Jul 4 17:54:43 kernel: usb 1-2: Manufacturer: SimTech, Incorporated Jul 4 17:54:43 kernel: usb 1-2: SerialNumber: 0123456789ABCDEF Jul 4 17:54:43 kernel: option 1-2:1.0: GSM modem (1-port) converter detected Jul 4 17:54:43 kernel: usb 1-2: GSM modem (1-port) converter now attached to ttyUSB0 Jul 4 17:54:43 kernel: option 1-2:1.1: GSM modem (1-port) converter det ... ...
p.s. В логах от других устройств так-же замечены случаи когда сим стартует только после многократного перезапуска.
Change History (21)
comment:1 by , 5 years ago
| Description: | modified (diff) |
|---|
comment:2 by , 5 years ago
follow-up: 6 comment:4 by , 5 years ago
Может сим не всегда стартует при подаче питания? (на практике, например, были случаи когда дефектные преобразователи DC/DC не запускались)
comment:5 by , 5 years ago
Replying to san:
А почему его нет?
Понятия не имею.
может надо ещё подождать?
Насколько я помню, согласно документации, через 10 секунд после включения питания все уже должно работать. Мы ждем 15 секунд. Не вижу резона ждать дольше.
comment:6 by , 5 years ago
Replying to san:
Может сим не всегда стартует при подаче питания?
Не могу исключить такую возможность. Именно из этих соображений в случае отсутствия /dev/ttyUSB2 и выполняется выключение и повторное включение питания модуля. И, как мы могли убедиться, это помогает.
comment:7 by , 5 years ago
| Owner: | changed from to |
|---|---|
| Status: | new → assigned |
comment:8 by , 5 years ago
| Owner: | removed |
|---|
comment:11 by , 5 years ago
Replying to san:
Jul 4 08:47:14 3gd[17863]: sim5320.cpp:164: powering off SIM5320...Насколько я понял, тут говорится что в процессе работы внезапно пропала связь с модулем SIM.
Не так уж и внезапно. Судя по логу, питание модуля было выключено. Поэтому хост и перестал видеть его на шине USB.
follow-up: 13 comment:12 by , 5 years ago
Погоди, всё же совсем наоборот, выключение питания - это действие контролера по причине дисконекта USB, другой причины для выключения питания я не вижу, вот лог выше:
Jul 4 08:30:00 ntpd[253]: Soliciting pool server 2001:67c:1560:8003::c7 Jul 4 08:31:06 ntpd[253]: Soliciting pool server 2001:67c:1560:8003::c8 Jul 4 08:32:11 ntpd[253]: Soliciting pool server 2001:67c:1560:8003::c8 Jul 4 08:33:15 ntpd[253]: Soliciting pool server 2001:67c:1560:8003::c7 Jul 4 08:34:20 ntpd[253]: Soliciting pool server 2001:67c:1560:8003::c8 Jul 4 08:35:27 ntpd[253]: Soliciting pool server 2001:67c:1560:8003::c7 Jul 4 08:36:33 ntpd[253]: Soliciting pool server 2001:67c:1560:8003::c7 Jul 4 08:37:40 ntpd[253]: Soliciting pool server 2001:67c:1560:8003::c8 Jul 4 08:38:47 ntpd[253]: Soliciting pool server 2001:67c:1560:8003::c7 Jul 4 08:39:53 ntpd[253]: Soliciting pool server 2001:67c:1560:8003::c8 Jul 4 08:40:58 ntpd[253]: Soliciting pool server 2001:67c:1560:8003::c8 Jul 4 08:42:02 ntpd[253]: Soliciting pool server 2001:67c:1560:8003::c7 Jul 4 08:42:59 dropbear[18773]: Child connection from 185.232.67.53:46690 Jul 4 08:43:07 ntpd[253]: Soliciting pool server 2001:67c:1560:8003::c7 Jul 4 08:43:17 dropbear[18773]: Login attempt for nonexistent user from 185.232.67.53:46690 Jul 4 08:43:20 dropbear[18773]: Client trying multiple usernames from 185.232.67.53:46690 Jul 4 08:43:20 dropbear[18773]: Login attempt for nonexistent user from 185.232.67.53:46690 Jul 4 08:43:28 dropbear[18773]: Client trying multiple usernames from 185.232.67.53:46690 Jul 4 08:43:28 dropbear[18773]: Login attempt for nonexistent user from 185.232.67.53:46690 Jul 4 08:43:33 dropbear[18778]: Child connection from 185.232.67.53:42378 Jul 4 08:43:33 dropbear[18773]: Exit before auth: Exited normally Jul 4 08:43:46 dropbear[18778]: Bad password attempt for 'root' from 185.232.67.53:42378 Jul 4 08:43:48 dropbear[18778]: Client trying multiple usernames from 185.232.67.53:42378 Jul 4 08:43:48 dropbear[18778]: Login attempt for nonexistent user from 185.232.67.53:42378 Jul 4 08:43:50 dropbear[18778]: Login attempt for nonexistent user from 185.232.67.53:42378 Jul 4 08:43:52 dropbear[18778]: Exit before auth: Exited normally Jul 4 08:43:52 dropbear[18779]: Child connection from 185.232.67.53:45110 Jul 4 08:44:01 dropbear[18779]: Login attempt for nonexistent user from 185.232.67.53:45110 Jul 4 08:44:03 dropbear[18779]: Client trying multiple usernames from 185.232.67.53:45110 Jul 4 08:44:03 dropbear[18779]: Login attempt for nonexistent user from 185.232.67.53:45110 Jul 4 08:44:05 dropbear[18779]: Client trying multiple usernames from 185.232.67.53:45110 Jul 4 08:44:05 dropbear[18779]: Login attempt for nonexistent user from 185.232.67.53:45110 Jul 4 08:44:07 dropbear[18779]: Exit before auth: Exited normally Jul 4 08:44:08 dropbear[18780]: Child connection from 185.232.67.53:36009 Jul 4 08:44:12 ntpd[253]: Soliciting pool server 2001:67c:1560:8003::c8 Jul 4 08:44:17 dropbear[18780]: Login attempt for nonexistent user from 185.232.67.53:36009 Jul 4 08:44:18 dropbear[18780]: Client trying multiple usernames from 185.232.67.53:36009 Jul 4 08:44:18 dropbear[18780]: Login attempt for nonexistent user from 185.232.67.53:36009 Jul 4 08:44:21 dropbear[18780]: Client trying multiple usernames from 185.232.67.53:36009 Jul 4 08:44:21 dropbear[18780]: Login attempt for nonexistent user from 185.232.67.53:36009 Jul 4 08:44:23 dropbear[18785]: Child connection from 185.232.67.53:54994 Jul 4 08:44:23 dropbear[18780]: Exit before auth: Exited normally Jul 4 08:44:34 dropbear[18785]: Login attempt for nonexistent user from 185.232.67.53:54994 Jul 4 08:44:38 dropbear[18785]: Login attempt for nonexistent user from 185.232.67.53:54994 Jul 4 08:44:41 dropbear[18785]: Client trying multiple usernames from 185.232.67.53:54994 Jul 4 08:44:41 dropbear[18785]: Login attempt for nonexistent user from 185.232.67.53:54994 Jul 4 08:44:44 dropbear[18786]: Child connection from 185.232.67.53:36467 Jul 4 08:44:44 dropbear[18785]: Exit before auth: Exited normally Jul 4 08:45:02 dropbear[18786]: Login attempt for nonexistent user from 185.232.67.53:36467 Jul 4 08:45:08 dropbear[18786]: Client trying multiple usernames from 185.232.67.53:36467 Jul 4 08:45:08 dropbear[18786]: Bad password attempt for 'root' from 185.232.67.53:36467 Jul 4 08:45:12 dropbear[18786]: Client trying multiple usernames from 185.232.67.53:36467 Jul 4 08:45:12 dropbear[18786]: Login attempt for nonexistent user from 185.232.67.53:36467 Jul 4 08:45:17 dropbear[18786]: Exit before auth: Exited normally Jul 4 08:45:17 dropbear[18791]: Child connection from 185.232.67.53:41125 Jul 4 08:45:19 ntpd[253]: Soliciting pool server 2001:67c:1560:8003::c7 Jul 4 08:45:28 dropbear[18791]: Login attempt for nonexistent user from 185.232.67.53:41125 Jul 4 08:45:31 dropbear[18791]: Client trying multiple usernames from 185.232.67.53:41125 Jul 4 08:45:31 dropbear[18791]: Login attempt for nonexistent user from 185.232.67.53:41125 Jul 4 08:45:33 dropbear[18791]: Client trying multiple usernames from 185.232.67.53:41125 Jul 4 08:45:33 dropbear[18791]: Login attempt for nonexistent user from 185.232.67.53:41125 Jul 4 08:45:38 dropbear[18791]: Exit before auth: Exited normally Jul 4 08:45:38 dropbear[18792]: Child connection from 185.232.67.53:50434 Jul 4 08:45:47 dropbear[18792]: Login attempt for nonexistent user from 185.232.67.53:50434 Jul 4 08:45:49 dropbear[18792]: Client trying multiple usernames from 185.232.67.53:50434 Jul 4 08:45:49 dropbear[18792]: Login attempt for nonexistent user from 185.232.67.53:50434 Jul 4 08:45:53 dropbear[18792]: Client trying multiple usernames from 185.232.67.53:50434 Jul 4 08:45:53 dropbear[18792]: Login attempt for nonexistent user from 185.232.67.53:50434 Jul 4 08:45:58 dropbear[18792]: Exit before auth: Exited normally Jul 4 08:45:58 dropbear[18793]: Child connection from 185.232.67.53:37539 Jul 4 08:46:24 ntpd[253]: Soliciting pool server 2001:67c:1560:8003::c8 Jul 4 08:46:46 dropbear[18793]: Login attempt for nonexistent user from 185.232.67.53:37539 Jul 4 08:46:49 dropbear[18793]: Client trying multiple usernames from 185.232.67.53:37539 Jul 4 08:46:49 dropbear[18793]: Bad password attempt for 'root' from 185.232.67.53:37539 Jul 4 08:46:50 dropbear[18793]: Client trying multiple usernames from 185.232.67.53:37539 Jul 4 08:46:50 dropbear[18793]: Login attempt for nonexistent user from 185.232.67.53:37539 Jul 4 08:46:51 dropbear[18798]: Child connection from 185.232.67.53:51815 Jul 4 08:46:51 dropbear[18793]: Exit before auth: Exited normally Jul 4 08:46:56 dropbear[18798]: Login attempt for nonexistent user from 185.232.67.53:51815 Jul 4 08:46:57 dropbear[18798]: Login attempt for nonexistent user from 185.232.67.53:51815 Jul 4 08:46:58 dropbear[18798]: Login attempt for nonexistent user from 185.232.67.53:51815 Jul 4 08:46:59 dropbear[18798]: Exit before auth: Exited normally Jul 4 08:46:59 dropbear[18799]: Child connection from 185.232.67.53:34450 Jul 4 08:47:07 dropbear[18799]: Login attempt for nonexistent user from 185.232.67.53:34450 Jul 4 08:47:10 dropbear[18799]: Client trying multiple usernames from 185.232.67.53:34450 Jul 4 08:47:10 dropbear[18799]: Login attempt for nonexistent user from 185.232.67.53:34450 Jul 4 08:47:14 kernel: usb 1-2: USB disconnect, device number 6 Jul 4 08:47:14 kernel: option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0 Jul 4 08:47:14 kernel: option 1-2:1.0: device disconnected Jul 4 08:47:14 kernel: option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1 Jul 4 08:47:14 kernel: option 1-2:1.1: device disconnected Jul 4 08:47:14 3gd[17863]: sim5320.cpp:164: powering off SIM5320... Jul 4 08:47:14 kernel: option1 ttyUSB2: GSM modem (1-port) converter now disconnected from ttyUSB2 Jul 4 08:47:14 kernel: option 1-2:1.2: device disconnected
follow-up: 18 comment:13 by , 5 years ago
Replying to san:
Погоди, всё же совсем наоборот, выключение питания - это действие контролера по причине дисконекта USB
Насколько я помню, такой функции (выключать питание модуля при отключении устройства с шины USB) в устройстве нет. По крайней мене, не помню, чтобы я ее реализовывал. Да и сама эта функция бессмысленна - если плата SAM-3G установлена, то модуль SIM заведомо подключен к шине.
follow-up: 16 comment:14 by , 5 years ago
Хм.. тогда по какой причине может происходить отключение?
Jul 4 08:47:14 3gd[17863]: sim5320.cpp:164: powering off SIM5320...
я в логе не замечаю подсказки о возможных причинах...
comment:15 by , 5 years ago
| Description: | modified (diff) |
|---|
comment:16 by , 5 years ago
follow-up: 19 comment:17 by , 5 years ago
по-моему уже ответил на этот вопрос
Кажется я запутал тебя. Создал для последнего вопроса #38, отсюда лишние комменты уберу.
comment:18 by , 5 years ago
Replying to alx:
Насколько я помню, такой функции (выключать питание модуля при отключении устройства с шины USB) в устройстве нет. По крайней мене, не помню, чтобы я ее реализовывал.
Уточню сам себя. Специально такую функцию я, действительно, не реализовывал. Но, похоже, такая функция получилась случайно. :) Дело в том, что в процессе работы 3gd все время поллит файл /dev/ttyUSB2 на предмет поступления каких-либо данных от модуля SIM. И, как я написал в ticket:38#comment:1, пропадание устройства с шины, видимо, приводит к завершению вызова poll() с ошибкой, реакцией на которую является выключение питания (с последующим включением) модуля SIM.
То есть в данном случае в случае тикета #38 сообщение "powering off SIM5320...", действительно, является следствием пропадания устройства с шины USB, а не его причиной. Возможно, причиной является самопроизвольное выключение питания на плате SAM-3G. Однако в случае, описанном в данном тикете, имеет место не пропадание /dev/ttyUSB2 в процессе нормальной работы, а непоявление его после подачи команды включения модуля SIM. Другое дело, что причина обоих случаем может быть одна и таже - например плохая (на физическом уровне) работа шины USB...
comment:19 by , 5 years ago
comment:20 by , 5 years ago
Replying to san:
контроллер дёргает питанием сима 8 раз подряд прежде чем Sim выйдет в рабочий режим.
Обнаружено, что в отличие от SIM5320, SIM7600 требует более длительного импульса включения питания (не менее 100 мс), в то время как до сегодняшнего дня у нас длительность импульса включения была 65 мс. Это может объяснить поведение модуля - он просто не включался в большинстве случаев.
В r141 длительность импульса включения была увеличена, имеет смысл проверить - возможно, проблема этим устранена.
comment:21 by , 4 years ago
| Resolution: | → fixed |
|---|---|
| Status: | assigned → closed |
В логах последних экспериментов(r160) вижу что SIM включается с первого раза. Ну и по лампочкам тоже давно не наблюдал каких либо странностей при включении.
Replying to san:
Причина ясна - отсутствие /dev/ttyUSB2 после включения модуля.