Opened 5 years ago

Closed 5 years ago

#38 closed баг (fixed)

USB disconnect

Reported by: san Owned by: andrei
Priority: critical Milestone: 1 очередь
Keywords: Cc: andrei, AlexLir

Description

В логах устройства клиент2 довольно часто встречаются такие записи:
Jul 4 08:47:14 kernel: usb 1-2: USB disconnect, device number 6
...
Jul 4 09:30:41 kernel: usb 1-2: USB disconnect, device number 7
...
Jul 4 09:56:34 kernel: usb 1-2: USB disconnect, device number 8
...
Jul 4 10:16:28 kernel: usb 1-2: USB disconnect, device number 9
...
Jul 4 10:33:11 kernel: usb 1-2: USB disconnect, device number 10
...
Рядом с этими записями присутствует 3gd[17863]: sim5320.cpp:164: powering off SIM5320...

Сначала я думал что внезапно произошёл USB disconnect и контроллер по причине того что USB отвалился перезапускает SIM, но Алексей сообщил:

Насколько я помню, такой функции (выключать питание модуля при отключении устройства с шины USB) в устройстве нет. По крайней мене, не помню, чтобы я ее реализовывал. Да и сама эта функция бессмысленна - если плата SAM-3G установлена, то модуль SIM заведомо подключен к шине.

В таком случае возникает вопрос почему контроллер выключает SIM, без видимой причины?

Вот кусок лога вблизи одного из происшествий:

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

r140

Attachments (1)

disconnectUSB.txt​ (13.4 KB ) - added by AlexLir 5 years ago.

Download all attachments as: .zip

Change History (23)

comment:1 by alx, 5 years ago

Owner: changed from alx to andrei
Status: new → assigned

В представленном фрагменте лога перед записью "powering off SIM5320..." не выведено никаких сообщений, уточняющих причину. Я посмотрел код - в нем есть единственное место, где выполняется выключение модуля без предварительного вывода дополнительного сообщения - когда поллинг /dev/ttyUSB2 вернул ошибку. Таким образом, я предполагаю, что в данном случае сначала по каким-то причинам устройство "пропало" с шины USB (хотя физически модуль оставался подключенным), в результате этого вызов poll() завершился с ошибкой.

Насколько я понимаю, ложное "пропадание" устройства с шины - аппаратная проблема. Предполагаю, что имеет место проблема с напряжением питания модуля SIM на плате SAM-3G. Также нельзя исключить проблемы с самой шиной USB (лишние конденсаторы, дефектная защита и т.п.), что приводит к неустойчивой видимости устройства хостом.

by AlexLir, 5 years ago

Attachment: disconnectUSB.txt​ added

comment:2 by AlexLir, 5 years ago

Подобное поведение проявляется на разных устройствах. Лог одного происшествия приложил выше.
Кажется что SIM-ы, которые отваливаются, греются сильнее...

comment:3 by san, 5 years ago

Саша выяснил что SIM стабильно отключается при активной передаче данных, если же активно охлаждать его в процессе, то отключения не происходит.

comment:4 by san, 5 years ago

При тестировании модуля SAM-4G отдельно от устройства выяснилось, что при некоторых условиях SIM может "поддормаживать" несколько секунд, при этом он вообще не отвечает на команды в UART. Затем SIM продолжает работать как ни в чём не бывало.
При подобных условиях в устройстве и наблюдается проблема описанная в тикете.

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

Предполагаю что причиной пропадания устройства с шины могло быть это самое "подтормаживание".
Алексей, скажи пожалуйста, если poll() завершился с ошибкой, то контроллер сразу выключает модуль?

comment:5 by san, 5 years ago

Priority: major → critical

in reply to:  4 comment:6 by alx, 5 years ago

Replying to san:

Алексей, скажи пожалуйста, если poll() завершился с ошибкой, то контроллер сразу выключает модуль?

Да.

comment:7 by san, 5 years ago

Алексей, можешь реализовать такое?:

  1. если poll() завершился с ошибкой выдать в лог сообщение.
  2. Выключать SIM не после первой ошибки, а допустим, секунд через 5 (при этом продолжать поллить и надеяться что сим жив)

Думаю, что это поможет в тестировании.

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

in reply to:  7 comment:8 by alx, 5 years ago

Replying to san:

Алексей, можешь реализовать такое?:

  1. если poll() завершился с ошибкой выдать в лог сообщение.

Могу. Без проблем.

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

Нет, не могу. Точнее, могу частично: выключать SIM не сразу - могу, но вот продолжать поллить в эти 5 секунд - не могу (невозможно поллить то, чего нет).

comment:9 by san, 5 years ago

Нет, не могу

переформулирую:
Есть подозрения что через пару секунд после неудачного poll СИМ оживёт и хочется чтобы контроллер в таком случае продолжил с ним работать не выключая его. А если через 5 секунд не оживёт- тогда уже перезапустить.
Вот так сможешь сделать?

in reply to:  9 comment:10 by alx, 5 years ago

Replying to san:

Вот так сможешь сделать?

Да, так можно - через 5 секунд проверить, не появилось ли устройство само, и только если само не появилось, дергать питание.

comment:11 by san, 5 years ago

Да так подойдёт, сделай пожалуйста.

comment:12 by alx, 5 years ago

In 159/smartCrypto:

При ошибке поллинга /dev/ttyUSB2 (предположительно вызванной пропаданием
модуля SIM с шины USB) выполняется проверка наличия файла /dev/ttyUSB2
и (при его наличии) попытка чтения для выявления ошибки, после чего
файл закрывается, и через 10 секунд ожидания выполняется попытка переподключения
без выключения модуля SIM. И только если попытка переподключения заканчивается
неудачей, выполняется выключение питания модуля SIM. See #38.

in reply to:  11 comment:13 by alx, 5 years ago

Replying to san:

Да так подойдёт, сделай пожалуйста.

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

Пакет выложен в репозиторий, можно обновиться.

comment:14 by san, 5 years ago

Удалось выяснить корень проблемы, он оказался совсем в другом месте:
Входной сигнал RESET модуля SIM, через тразистор(инвертер) подключен к PORTB.22 контроллера, в контроллере этот пин подтянут к 1, а на модуле SIM этот сигнал подтянут к 0, получается делитель и на базе транзистора в итоге оказывается напряжение около 0.5 В..(а открывается транзистор при 0.6 В).
В итоге: транзистор закрыт, SIM работает, но при нагреве транзистора(теплом которое выделяет SIM при передаче данных) транзистор открывается и на SIM поступает сигнал reset и он выключается, что приводит к отпаданию USB и так далее.

Алексей, нужно для PORTB.22 включить подтяжку к 0.

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

Replying to san:

Алексей, нужно для PORTB.22 включить подтяжку к 0.

Это решение мне кажется немного странным... Если ты пишешь, что на модуле RESET - это вход, то почему ты предлагаешь на плате SAM5 тоже оставить его входом? Не будет ли логичнее перевести его в режим выхода и установить низкий уровень?

comment:16 by san, 5 years ago

Ну насколько я понял, ты его не используешь, поэтому главное чтобы подтяжки к 1 не было.

Не будет ли логичнее перевести его в режим выхода и установить низкий уровень?

Можно и так.

comment:17 by alx, 5 years ago

In 160/smartCrypto:

При старте линия PB22 контроллера (вход RESET модуля SIM) переводится
в режим выхода, и на ней устанавливается низкий уровень. See #38.

comment:18 by alx, 5 years ago

В репозитории 3gd-1.0-r160.

comment:19 by alx, 5 years ago

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

comment:20 by san, 5 years ago

Есть подозрения что через пару секунд после неудачного poll СИМ оживёт и хочется чтобы контроллер в таком случае продолжил с ним работать не выключая его. А если через 5 секунд не оживёт- тогда уже перезапустить.

При резете от транзистора сим, насколько мы видели выключался, совсем и не оживал.

при некоторых условиях SIM может "поддормаживать" несколько секунд

На модуле в составе устройства, ничего похожего не воспроизводилось пока, только на "голом" модуле наблюдали, но довольно редко (всего раза три, за пару десятков экспериментов)

Version 1, edited 5 years ago by san (previous) (next) (diff)

comment:21 by san, 5 years ago

Cc: AlexLir added

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

AlexLir, ответственный за схемотехнику модуля, говорит "вроде бы нет".

comment:22 by san, 5 years ago

Resolution: → fixed
Status: assigned → closed

После установки низкого уровня сигнала reset(r160) проблема не воспроизводится.

Note: See TracTickets for help on using tickets.