Project

General

Profile

Actions
Copy link

Bug #5578

open

osmo-remsim-client-st2 hangs after usb-reset without power loss on qmod

Added by roh 9 months ago. Updated about 2 months ago.

Status:
Stalled
Priority:
Low
Assignee:
laforge
Category:
firmware
Target version:
-
Start date:
06/15/2022
Due date:
% Done:

30%

Spec Reference:

Description

in case of a osmo-remsim-client-st2 session which gets restarted after being stopped by a usb-disconnect
(terminates with "DST2 FATAL user_simtrace2.c:221 USB IN transfer failed, status=1" as expected)

osmo-remsim-client-st2 gets stuck and then terminates after some time:

root@raspberrypi:~# /usr/bin/osmo-remsim-client-st2 -i 10.15.1.135 -V 1d50 -P 4004 -C 1 -I 0 -H 1-1.3.1 -c 1 -n 0
DRSPRO INFO ../rspro_client_fsm.c:307 RSPRO_CLIENT(server){REESTABLISH}: Creating TCP connection to server at 10.15.1.135:9998
DLINP NOTICE simtrace2_api.c:267 [0] <= osmo_st2_cardem_request_config(features=00000001)
DLINP NOTICE input/ipa.c:128 10.15.1.135:9998 connection done
DRSPRO NOTICE ../rspro_client_fsm.c:125 RSPRO_CLIENT(server){REESTABLISH}: RSPRO link to 10.15.1.135:9998 UP
DRSPRO INFO ../rspro_client_fsm.c:307 RSPRO_CLIENT(bankd){REESTABLISH}: Creating TCP connection to server at 10.15.1.135:9999
DLINP NOTICE input/ipa.c:128 10.15.1.135:9999 connection done
DRSPRO NOTICE ../rspro_client_fsm.c:125 RSPRO_CLIENT(bankd){REESTABLISH}: RSPRO link to 10.15.1.135:9999 UP
DLINP NOTICE simtrace2_api.c:168 [0] <= osmo_st2_cardem_request_card_insert(inserted=1)
DLINP NOTICE simtrace2_api.c:317 [0] <= _modem_sim_select(remote_sim=1)
DLINP NOTICE simtrace2_api.c:250 [0] <= osmo_st2_cardem_request_set_atr(3b 00 )
DLINP NOTICE simtrace2_api.c:285 [0] <= _modem_reset(asserted=2, pulse_ms=300)
DLINP NOTICE simtrace2_api.c:250 [0] <= osmo_st2_cardem_request_set_atr(3b 9f 96 80 1f 87 80 31 e0 73 fe 21 1b 67 4a 4c 75 30 34 05 4b a9 )
DST2 INFO user_simtrace2.c:65 SIMtrace => PTS req: ff 10 96 79 00 00 
...
<modem starts, usb enumeration of serials/wwlan>
...
USB OUT transfer failed, status=2

later restarts remain the same in behaviour but a bit different in output:

root@raspberrypi:~# /usr/bin/osmo-remsim-client-st2 -i 10.15.1.135 -V 1d50 -P 4004 -C 1 -I 0 -H 1-1.3.1 -c 1 -n 0
DRSPRO INFO ../rspro_client_fsm.c:307 RSPRO_CLIENT(server){REESTABLISH}: Creating TCP connection to server at 10.15.1.135:9998
DLINP NOTICE simtrace2_api.c:267 [0] <= osmo_st2_cardem_request_config(features=00000001)
DLINP NOTICE input/ipa.c:128 10.15.1.135:9998 connection done
DRSPRO NOTICE ../rspro_client_fsm.c:125 RSPRO_CLIENT(server){REESTABLISH}: RSPRO link to 10.15.1.135:9998 UP
DRSPRO INFO ../rspro_client_fsm.c:307 RSPRO_CLIENT(bankd){REESTABLISH}: Creating TCP connection to server at 10.15.1.135:9999
DLINP NOTICE input/ipa.c:128 10.15.1.135:9999 connection done
DRSPRO NOTICE ../rspro_client_fsm.c:125 RSPRO_CLIENT(bankd){REESTABLISH}: RSPRO link to 10.15.1.135:9999 UP
DLINP NOTICE simtrace2_api.c:168 [0] <= osmo_st2_cardem_request_card_insert(inserted=1)
DLINP NOTICE simtrace2_api.c:317 [0] <= _modem_sim_select(remote_sim=1)
DLINP NOTICE simtrace2_api.c:250 [0] <= osmo_st2_cardem_request_set_atr(3b 00 )
DLINP NOTICE simtrace2_api.c:285 [0] <= _modem_reset(asserted=2, pulse_ms=300)
DLINP NOTICE simtrace2_api.c:250 [0] <= osmo_st2_cardem_request_set_atr(3b 9f 96 80 1f 87 80 31 e0 73 fe 21 1b 67 4a 4c 75 30 34 05 4b a9 )
USB OUT transfer failed, status=2

please note that the modem does not seem to reboot on later restarts of osmo-remsim-client-st2, which is odd.

osmo-remsim-client version 1.0.0.18-f5f5
qmod firmware 0.8.1.33-9088

osmo-remsim-bankd version 1.0.0.18-f5f5
osmo-resmim-server version 1.0.0.18-f5f5

maybe this is a rerun of #4409

for this test the server/bankd were on x86_64 and the client was on armv7l (rpi) but i don't think it matters.
i have also tried a older qmod firmware (0.7.0.57-f46d) for comparison but i can see no difference in behavior.

please note that i could not reproduce this issue with a modem on st34, only on st12. i suspect it has to do with st12 staying powered all the time and not reset/rebooted on usb-connect properly somehow.

this may as well be a firmware issue on the qmod.

Related issues

Related to SIMtrace 2 - Bug #5921: simtrace2 cardem vs. Linux kernel USB autosuspendIn Progresslaforge02/23/2023

Actions
Actions
Copy link
 #1

Updated by roh 9 months ago

further details:
  • testmodem is a ec20 in slot1 of 4 on the qmod which is powered externally with 12V 2A (enough for one modem)
  • mapping of osmo-remsim-server is slot 0 of bank1 to slot0 on client1
  • ccid reader is sysmooctsim with a card in slot0 - but i don't think this matters
  • packages from -nightly feeds
  • platform does not matter (arm/x86)
  • distribution does not matter (all 3 services can run on the same host)
  • only both slots of st12 show this behavior, st34 is not affected - i have tested all 4 slots individually
Actions
Copy link
 #2

Updated by laforge 9 months ago

  • Category set to remsim-client
  • Assignee set to laforge

do we have the serial console output during the time this behavior is observed? I think it's more likely to be a simtrace2/cardem firmware problem, than a osmo-remsim issue...

Actions
Copy link
 #3

Updated by roh 9 months ago

just tried to redo the test with a serial cable connected to provide a log, but for some reason i can not replicate the behavior anymore. tried again without the serial cable and its still stable.

i also suspect the issue to be in the firmware, due to the differences in what gets reset when, but i need to get it to show again, first.

Actions
Copy link
 #4

Updated by laforge 8 months ago

  • Status changed from New to In Progress
I've now tried to reproduce this:
  • osmo-remsim-client-st2 from nightly on raspi3
  • sysmoQMOD attached via USB
    • cardem firmware 0.8.1.35-fdfb; dfu loader also upgraded via blupdate
    • powered from 12V PSU
  • fully establish osmo-remsim mapping between remote bankd(octsim) and modem 1 on ST12
  • un-plug the USB between QMOD and raspi and re-plug it again

remsim-client-st2 log

DST2 FATAL user_simtrace2.c:272 USB IN transfer failed, status=1
osmo-remsim-client@0.service: Main process exited, code=exited, status=1/FAILURE
osmo-remsim-client@0.service: Failed with result 'exit-code'.
osmo-remsim-client@0.service: Service RestartSec=2s expired, scheduling restart.
osmo-remsim-client@0.service: Scheduled restart job, restart counter is at 101.
Stopped Osmocom Remote SIM Client 0.
Started Osmocom Remote SIM Client 0.
DRSPRO INFO ../rspro_client_fsm.c:307 RSPRO_CLIENT(server){REESTABLISH}: Creating TCP connection to server at 10.34.2.99:9998
No USB device with matching VID/PID: Resource temporarily unavailable
DMAIN ERROR user_simtrace2.c:426 can't open USB device
osmo-remsim-client@0.service: Succeeded.
osmo-remsim-client@0.service: Service RestartSec=2s expired, scheduling restart.
osmo-remsim-client@0.service: Scheduled restart job, restart counter is at 102.
Stopped Osmocom Remote SIM Client 0.
Started Osmocom Remote SIM Client 0.
DRSPRO INFO ../rspro_client_fsm.c:307 RSPRO_CLIENT(server){REESTABLISH}: Creating TCP connection to server at 10.34.2.99:9998
DLINP NOTICE simtrace2_api.c:267 [0] <= osmo_st2_cardem_request_config(features=00000001)
DLINP NOTICE input/ipa.c:128 10.34.2.99:9998 connection done
DRSPRO NOTICE ../rspro_client_fsm.c:125 RSPRO_CLIENT(server){REESTABLISH}: RSPRO link to 10.34.2.99:9998 UP
DMAIN INFO main_fsm.c:249 CLIENT_MAIN(main){UNCONFIGURED}: Rx configClientBankReq(10.34.2.245:9999 / B1:2)
DRSPRO INFO ../rspro_client_fsm.c:307 RSPRO_CLIENT(bankd){REESTABLISH}: Creating TCP connection to server at 10.34.2.245:9999
DLINP NOTICE input/ipa.c:128 10.34.2.245:9999 connection done
DRSPRO NOTICE ../rspro_client_fsm.c:125 RSPRO_CLIENT(bankd){REESTABLISH}: RSPRO link to 10.34.2.245:9999 UP
DLINP NOTICE simtrace2_api.c:168 [0] <= osmo_st2_cardem_request_card_insert(inserted=1)
DLINP NOTICE simtrace2_api.c:317 [0] <= _modem_sim_select(remote_sim=1)
DLINP NOTICE simtrace2_api.c:250 [0] <= osmo_st2_cardem_request_set_atr(3b 00 )
DLINP NOTICE simtrace2_api.c:285 [0] <= _modem_reset(asserted=2, pulse_ms=300)
DLINP NOTICE simtrace2_api.c:250 [0] <= osmo_st2_cardem_request_set_atr(3b 9f 96 80 1f 87 80 31 e0 73 fe 21 1b 67 4a 4c 75 30 34 05 4b a9 )
DST2 INFO user_simtrace2.c:65 SIMtrace => PTS req: ff 10 96 79 00 00
USB OUT transfer failed, status=2
osmo-remsim-client@0.service: Main process exited, code=exited, status=1/FAILURE
osmo-remsim-client@0.service: Failed with result 'exit-code'.

remsim-bankd log

520 DBANKDW INFO bankd_main.c:982 [004 B1:2 CONN_CLIENT_MAPPED_CARD] Error -2 occurred: Cleaning up state
520 DBANKDW INFO bankd_main.c:456 [004 B1:2 CONN_CLIENT_MAPPED_CARD] Changing state to ACCEPTING
520 DBANKDW INFO bankd_main.c:970 [001 B65535:65535 ACCEPTING] Accepted connection from 10.34.2.161:33641
520 DBANKDW INFO bankd_main.c:456 [001 B65535:65535 ACCEPTING] Changing state to CONN_WAIT_ID
520 DBANKDW INFO bankd_main.c:670 [001 B65535:65535 CONN_WAIT_ID] Rx RSPRO connectClientReq(T=0, N='remsim-client', SW='remsim-client', VER='1.0.0.25-6cfc')
520 DBANKDW INFO bankd_main.c:456 [001 B65535:65535 CONN_WAIT_ID] Changing state to CONN_CLIENT
520 DBANKDW INFO bankd_main.c:641 [001 B65535:65535 CONN_CLIENT] slotmap found: C(0:0) -> B(1:2)
520 DBANKDW INFO bankd_main.c:465 [001 B1:2 CONN_CLIENT] Changing state to CONN_CLIENT_MAPPED (timeout=10)
520 DBANKDW INFO bankd_pcsc.c:267 [001 B1:2 CONN_CLIENT_MAPPED] Attempting to open PC/SC context
520 DBANKDW INFO bankd_pcsc.c:270 [001 B1:2 CONN_CLIENT_MAPPED] SCardEstablishContext: OK
520 DBANKDW INFO bankd_pcsc.c:215 [001 B1:2 CONN_CLIENT_MAPPED] Attempting to find card/slot using regex 'ACS ACR33 ICC Reader 00 02'
520 DBANKDW INFO bankd_pcsc.c:234 [001 B1:2 CONN_CLIENT_MAPPED] Attempting to open card/slot 'ACS ACR33 ICC Reader 00 02'
520 DBANKDW INFO bankd_pcsc.c:198 [001 B1:2 CONN_CLIENT_MAPPED] SCardStatus: OK
520 DBANKDW INFO bankd_pcsc.c:200 [001 B1:2 CONN_CLIENT_MAPPED] Card ATR: 3b9f96801f878031e073fe211b674a4c753034054ba9
520 DBANKDW INFO bankd_main.c:456 [001 B1:2 CONN_CLIENT_MAPPED] Changing state to CONN_CLIENT_MAPPED_CARD
520 DBANKDW INFO bankd_main.c:795 [001 B1:2 CONN_CLIENT_MAPPED_CARD] Rx RSPRO setAtrRes
... minutes later (no output)....
520 DBANKDW INFO bankd_main.c:982 [001 B1:2 CONN_CLIENT_MAPPED_CARD] Error -2 occurred: Cleaning up state
520 DBANKDW INFO bankd_main.c:456 [001 B1:2 CONN_CLIENT_MAPPED_CARD] Changing state to ACCEPTING

serial console output

-I- 0: WWAN LED 0
-I- 0: VCC deactivated
-I- 0: CLK deactivated
-I- 0: RST asserted
-I- 1: WWAN LED 0
-I- USB is now configured
SetAddr(71) -W- Sta 0x888A8 [0] -W- _ -W- Sta 0x888A8 [0] -W- _ -W- Sta 0x888A8 [0] -W- _ SetCfg(1) cfgChanged1 -I- USB is now configured
-W- Sta 0x88828 [0] -W- _ -I- 0: RST released
-I- 0: RST asserted
-I- EP06: dropping first queue element (qlen=3)
-I- 0: VCC activated (2958 mV)
-I- EP06: dropping first queue element (qlen=3)
-I- 0: CLK activated
-I- EP06: dropping first queue element (qlen=3)
-I- 0: RST released
-I- 0: computed F(1)/D(1) ratio: 372
-I- EP06: dropping first queue element (qlen=3)
-I- 0: computed F(9)/D(6) ratio: 16
-I- 0: send_tpdu_header: 00 a4 00 04 02
-I- 0: flush_rx_buffer (5)
NNNNNNNNNNNN-I- 0: WWAN LED 1
NNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN-I- 1: WWAN LED 1
NNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN

This then cycles, every few minutes the same cycle repeats, and while that cycle happens

NNNNNN-W- Sta 0x88828 [0] -W- _ NNNNNNNNN

occurs on the console

Actions
Copy link
 #5

Updated by laforge 8 months ago

Trying now various ways to recover to get an idea about where things might go wrong

de-authorize/re-authorize

echo 0 > /sys/bus/usb/devices/1-1.3.1/authorized
echo 1 > /sys/bus/usb/devices/1-1.3.1/authorized

This generates the following output on the console:

SetCfg(0) cfgChanged0 -I- USB config chg 1 -> 0
SetCfg(0) cfgChanged0 SetCfg(0) cfgChanged0 SetCfg(0) cfgChanged0 SetCfg(0) cfgChanged0 SetCfg(1) cfgChanged1 -I- USB is now configured
-I- USB config chg 0 -> 1
-I- Enabling Rev.A ADC Errata work-around
-I- Modem 0: physical SIM
-I- 0: Use local/physical SIM
-I- Modem 1: physical SIM
-I- 1: Use local/physical SIM
-I- 0: RST released
-W- Sta 0x88828 [0] -W- _

so it seems to primarily use USB SET CONFIGURATION to switch to cfg0 and then to cfg1, but not perform a bus reset. It also doesn't recover:

DRSPRO NOTICE ../rspro_client_fsm.c:125 RSPRO_CLIENT(server){REESTABLISH}: RSPRO link to 10.34.2.99:9998 UP
DMAIN INFO main_fsm.c:249 CLIENT_MAIN(main){UNCONFIGURED}: Rx configClientBankReq(10.34.2.245:9999 / B1:2)
DRSPRO INFO ../rspro_client_fsm.c:307 RSPRO_CLIENT(bankd){REESTABLISH}: Creating TCP connection to server at 10.34.2.245:9999
DLINP NOTICE input/ipa.c:128 10.34.2.245:9999 connection done
DRSPRO NOTICE ../rspro_client_fsm.c:125 RSPRO_CLIENT(bankd){REESTABLISH}: RSPRO link to 10.34.2.245:9999 UP
DLINP NOTICE simtrace2_api.c:168 [0] <= osmo_st2_cardem_request_card_insert(inserted=1)
DLINP NOTICE simtrace2_api.c:317 [0] <= _modem_sim_select(remote_sim=1)
DLINP NOTICE simtrace2_api.c:250 [0] <= osmo_st2_cardem_request_set_atr(3b 00 )
DLINP NOTICE simtrace2_api.c:285 [0] <= _modem_reset(asserted=2, pulse_ms=300)
DLINP NOTICE simtrace2_api.c:250 [0] <= osmo_st2_cardem_request_set_atr(3b 9f 96 80 1f 87 80 31 e0 73 fe 21 1b 67 4a 4c 75 30 34 05 4b a9 )
USB OUT transfer failed, status=2
osmo-remsim-client@0.service: Main process exited, code=exited, status=1/FAILURE
osmo-remsim-client@0.service: Failed with result 'exit-code'.

Interestingly the NNNNNNNNNNNNNN were gone now, so the SetCfg(0) must have stopped some internal state machine on the 7816 side. However, the USB communication to the host still is stuck. You also cannot use simtrace2-tool to talk to the device anymore

root@remsim-client:/etc/apt/preferences.d# simtrace2-tool -H 1-1.3.1 -V 1d50 -P 4004 -C 1 modem reset cycle
simtrace2-tool
(C) 2019 Harald Welte <laforge@gnumonks.org>
Pulsing Modem RESET (1s)
<0002> simtrace2_api.c:285 [0] <= _modem_reset(asserted=2, pulse_ms=1000)
.... minutes of delay ...
Error executing command: -7

Console output is -W- Sta 0x88828 [0] -W- _ -W- Sta 0x88828 [0] -W- _ at that point.

Actions
Copy link
 #6

Updated by laforge 8 months ago

so rather than trying to debug what exactly is getting stuck, I think it makes sense to turn the 'main' of the firmware into a proper finite state machine.

Right now there are a number of things we only execute the first time we reach USBD_STATE_CONFIGURED, but not at any subsequent such event.

It's also rather clear that this doesn't really show in simtrace2 as it is bus-powered. And it doesn't show on OWHW as we don't have any USB unplug situations of the USB between the on-board traces of USB host and SAM3S.

A cheap and dirty fix would probably be to simply reset the entire uC every time a USB unplug happens.

Actions
Copy link
 #7

Updated by laforge 8 months ago

  • % Done changed from 0 to 30

laforge wrote in #note-6:

A cheap and dirty fix would probably be to simply reset the entire uC every time a USB unplug happens.

implemented and tested locally. Now the end-to-end osmo-remsim setup recovers nicely on any usb disconnect/reconnect without power cycle: https://gerrit.osmocom.org/c/simtrace2/+/28795

Actions
Copy link
 #8

Updated by laforge 8 months ago

  • Project changed from osmo-remsim to SIMtrace 2
  • Category changed from remsim-client to firmware
Actions
Copy link
 #9

Updated by laforge 4 months ago

  • Status changed from In Progress to Stalled
Actions
Copy link
 #10

Updated by laforge about 2 months ago

  • Priority changed from Normal to Low
Actions
Copy link
 #11

Updated by laforge 28 days ago

  • Related to Bug #5921: simtrace2 cardem vs. Linux kernel USB autosuspend added
Actions
Copy link

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)