HACK: Solve weird problem with lost OUT transfer on ping-pong endpoint

This adds an unconditional endpoint reset procedure to every SET_FEATURE(UnHalt).

It doesn't really make sense that this is required, *particularly* as
we *MUST NOT* set bEndpoint->bank to 0 here.

Without this patch, I'm observing the following problem:

Every first OUT transfer after a SET_INTERFACE + UNHALT on a bulk endpoint
is lost. "lost" means that it completes successfully on the host, can
be seen completing successfully with an ACK on a USB bus analyzer,
but still doesn't show up in the firmware.  No Endpoint Interrupt
is generated.

This can be reproduced by calling libusb_set_interface_alt_setting()
from the host and then submitting a single OUT transfer.

Change-Id: I18ed530e617baddf76e8f9829512443ce2a76e0d

contrib/simtrace.lua

@@ -1,3 +1,12 @@
+-- wireshark LUA dissector for the SIMtrace USB protocol
+-- (C) 2021 by sysmocom - s.f.m.c. GmbH, Author: Eric Wild
+-- SPDX-License-Identifier: GPL-2.0+
+--
+-- Usage: Move this file to your "personal lua plugins" folder that
+-- can be found in the Wireshark Help->About Wireshark->Folders tab
+-- Windows: %APPDATA%\Wireshark\plugins.
+-- Unix-like systems: ~/.local/lib/wireshark/plugins.
+
 usb_simtrace_protocol = Proto("USB_simtrace",  "USB simtrace protocol")
 
 
@@ -7,42 +16,55 @@ local control_commands = {
 [0x0001] = "SIMTRACE_CMD_BD_BOARD_INFO",
 
 -- /* SIMTRACE_MSGC_CARDEM */
-[0x0101] = "SIMTRACE_MSGT_DT_CEMU_TX_DATA",
-[0x0102] = "SIMTRACE_MSGT_DT_CEMU_SET_ATR",
-[0x0103] = "SIMTRACE_MSGT_BD_CEMU_STATS",
-[0x0104] = "SIMTRACE_MSGT_BD_CEMU_STATUS",
-[0x0105] = "SIMTRACE_MSGT_DT_CEMU_CARDINSERT",
-[0x0106] = "SIMTRACE_MSGT_DO_CEMU_RX_DATA",
-[0x0107] = "SIMTRACE_MSGT_DO_CEMU_PTS",
-[0x0108] = "SIMTRACE_MSGT_BD_CEMU_CONFIG",
+[0x0101] = "DT_CEMU_TX_DATA",
+[0x0102] = "DT_CEMU_SET_ATR",
+[0x0103] = "BD_CEMU_STATS",
+[0x0104] = "BD_CEMU_STATUS",
+[0x0105] = "DT_CEMU_CARDINSERT",
+[0x0106] = "DO_CEMU_RX_DATA",
+[0x0107] = "DO_CEMU_PTS",
+[0x0108] = "BD_CEMU_CONFIG",
 
 -- /* SIMTRACE_MSGC_MODEM */
-[0x0201] = "SIMTRACE_MSGT_DT_MODEM_RESET",
-[0x0202] = "SIMTRACE_MSGT_DT_MODEM_SIM_SELECT",
-[0x0203] = "SIMTRACE_MSGT_BD_MODEM_STATUS",
+[0x0201] = "DT_MODEM_RESET",
+[0x0202] = "DT_MODEM_SIM_SELECT",
+[0x0203] = "BD_MODEM_STATUS",
 
 -- /* SIMTRACE_MSGC_SNIFF */
-[0x0300] = "SIMTRACE_MSGT_SNIFF_CHANGE",
-[0x0301] = "SIMTRACE_MSGT_SNIFF_FIDI",
-[0x0302] = "SIMTRACE_MSGT_SNIFF_ATR",
-[0x0304] = "SIMTRACE_MSGT_SNIFF_TPDU",
-[0x0303] = "SIMTRACE_MSGT_SNIFF_PPS"
+[0x0300] = "SNIFF_CHANGE",
+[0x0301] = "SNIFF_FIDI",
+[0x0302] = "SNIFF_ATR",
+[0x0304] = "SNIFF_TPDU",
+[0x0303] = "SNIFF_PPS"
 }
 
 local msgtype  = ProtoField.uint16("usb_simtrace.msgtype", "Message Type", base.HEX_DEC, control_commands)
-local seqnr  = ProtoField.uint8("usb_simtrace.seqnr", "Sequence Number", base.HEX_DEC)
-local slotnr  = ProtoField.uint8("usb_simtrace.slotnr", "Slot Number", base.HEX_DEC)
+local seqnr  = ProtoField.uint8("usb_simtrace.seqnr", "Sequence Number", base.DEC)
+local slotnr  = ProtoField.uint8("usb_simtrace.slotnr", "Slot Number", base.DEC)
 local reserved  = ProtoField.uint16("usb_simtrace.reserved", "reserved", base.HEX_DEC)
-local payloadlen  = ProtoField.uint16("usb_simtrace.length", "length", base.HEX_DEC)
+local payloadlen  = ProtoField.uint16("usb_simtrace.length", "length", base.DEC)
 local payload  = ProtoField.bytes("usb_simtrace.payload", "Data")
 
 local pb_and_rx  = ProtoField.uint32("usb_simtrace.pb_and_rx", "pb_and_rx", base.HEX_DEC, NULL, 0x8)
 local pb_and_tx  = ProtoField.uint32("usb_simtrace.pb_and_tx", "pb_and_tx", base.HEX_DEC, NULL, 0x4)
 local final  = ProtoField.uint32("usb_simtrace.final", "final", base.HEX_DEC, NULL, 0x2)
 local tpdu_hdr  = ProtoField.uint32("usb_simtrace.tpdu_hdr", "tpdu_hdr", base.HEX_DEC, NULL, 0x1)
-local rxtxdatalen  = ProtoField.uint16("usb_simtrace.rxtxdatalen", "rx/tx data length", base.HEX_DEC)
+local rxtxdatalen  = ProtoField.uint16("usb_simtrace.rxtxdatalen", "rx/tx data length", base.DEC)
 local rxtxdata  = ProtoField.bytes("usb_simtrace.rxtxdata", "rx/tx (data)")
 
+local hf_pts_len = ProtoField.uint8("usb_simtrace.pts_len", "PTS length", base.DEC)
+local hf_pts_req = ProtoField.bytes("usb_simtrace.pts_req", "PTS request")
+local hf_pts_resp = ProtoField.bytes("usb_simtrace.pts_resp", "PTS response")
+
+local hf_cemu_cfg_features = ProtoField.uint32("usb_simtrace.cemu_cfg.features.status_irq", "CardEm Features", base.HEX)
+local hf_cemu_cfg_slot_mux_nr = ProtoField.uint32("usb_simtrace.cemu_cfg.features.slot_mux_nr", "CardEm Slot Mux Nr", base.DEC)
+
+local card_insert_types = {
+    [0x00] = "not inserted",
+    [0x01] = "inserted",
+}
+local hf_cemu_cardinsert = ProtoField.uint8("usb_simtrace.cardinsert", "Card Insert", base.DEC, card_insert_types, 0xff)
+
 local CEMU_STATUS_F_VCC_PRESENT  = ProtoField.uint32("usb_simtrace.CEMU_STATUS.F_VCC_PRESENT", "VCC_PRESENT", base.HEX_DEC, NULL, 0x00000001)
 local CEMU_STATUS_F_CLK_ACTIVE  = ProtoField.uint32("usb_simtrace.CEMU_STATUS.F_CLK_ACTIVE", "CLK_ACTIVE", base.HEX_DEC, NULL, 0x00000002)
 local CEMU_STATUS_F_RCEMU_ACTIVE  = ProtoField.uint32("usb_simtrace.CEMU_STATUS.F_RCEMU_ACTIVE", "CEMU_ACTIVE", base.HEX_DEC, NULL, 0x00000004)
@@ -57,11 +79,20 @@ local modem_reset_types = {
 local modem_reset_status = ProtoField.uint8("usb_simtrace.modem.reset_type", "modem reset type", base.HEX, modem_reset_types, 0xf)
 local modem_reset_len = ProtoField.uint8("usb_simtrace.modem.reset_len", "modem reset length (ms)", base.DEC)
 
+local modem_sim_select_types = {
+    [0x00] = "local",
+    [0x01] = "remote",
+}
+local hf_modem_sim_select = ProtoField.uint8("usb_simtrace.modem.sim_select", "SIM card selection", base.DEC, modem_sim_select_types, 0xff)
+
 usb_simtrace_protocol.fields = {
   msgtype, seqnr, slotnr, reserved, payloadlen, payload,
   pb_and_rx, pb_and_tx, final, tpdu_hdr, rxtxdatalen, rxtxdata,
   CEMU_STATUS_F_VCC_PRESENT, CEMU_STATUS_F_CLK_ACTIVE, CEMU_STATUS_F_RCEMU_ACTIVE, CEMU_STATUS_F_CARD_INSERT, CEMU_STATUS_F_RESET_ACTIVE,
-  modem_reset_status, modem_reset_len
+  modem_reset_status, modem_reset_len,
+  hf_pts_len, hf_pts_req, hf_pts_resp,
+  hf_cemu_cfg_features, hf_cemu_cfg_slot_mux_nr,
+  hf_cemu_cardinsert, hf_modem_sim_select,
 }
 
 local is_hdr = Field.new("usb_simtrace.tpdu_hdr")
@@ -83,6 +114,30 @@ function dissect_rxtx(payload_data,pinfo,tree)
   headerSubtree:add(rxtxdatalen, len)
   headerSubtree:add_le(rxtxdata, payload_data(6,len))
 
+  local flagstr = " "
+  if is_pbrx().value == 1 then
+    flagstr = flagstr .. "R"
+  else
+    flagstr = flagstr .. "."
+  end
+  if is_pbtx().value == 1 then
+    flagstr = flagstr .. "T"
+  else
+    flagstr = flagstr .. "."
+  end
+  if is_final().value == 1 then
+    flagstr = flagstr .. "F"
+  else
+    flagstr = flagstr .. "."
+  end
+  if is_hdr().value == 1 then
+    flagstr = flagstr .. "H"
+  else
+    flagstr = flagstr .. "."
+  end
+  flagstr = flagstr .. " "
+  pinfo.cols.info:append(flagstr .. payload_data(6,len))
+
   -- ghetto dissection does not work due to mixed in procedure bytes
   --if pinfo.visited == false then
   -- Dissector.get("iso7816"):call(payload_data(6):tvb(), pinfo, tree)
@@ -142,6 +197,44 @@ function dissect_modem_reset(payload_data,pinfo,tree)
 
 end
 
+function dissect_pts(payload_data, pinfo, tree)
+  local subtree = tree:add(usb_simtrace_protocol, payload_data, "PTS")
+  local pts_len = payload_data(0,1):le_uint()
+  local pts_req = payload_data(1, pts_len);
+  local pts_resp = payload_data(7, pts_len);
+
+  subtree:add(hf_pts_len, pts_len);
+  subtree:add(hf_pts_req, pts_req);
+  subtree:add(hf_pts_resp, pts_resp);
+
+  pinfo.cols.info:append(" Req: " .. pts_req .. ", Resp: " .. pts_resp);
+end
+
+function dissect_cemu_config(payload_data, pinfo, tree)
+  local subtree = tree:add(usb_simtrace_protocol, payload_data, "Card Emu Config")
+
+  subtree:add(hf_cemu_cfg_features, payload_data(0,4));
+  subtree:add(hf_cemu_cfg_slot_mux_nr, payload_data(4,1));
+end
+
+function dissect_modem_sim_sel(payload_data, pinfo, tree)
+  local subtree = tree:add(usb_simtrace_protocol, payload_data, "Modem SIM Select")
+  local sim_select = payload_data(0,1):le_uint();
+
+  subtree:add(hf_modem_sim_select, sim_select);
+  pinfo.cols.info:append(" " .. modem_sim_select_types[sim_select]);
+end
+
+function dissect_cemu_cardinsert(payload_data, pinfo, tree)
+  local subtree = tree:add(usb_simtrace_protocol, payload_data, "Card Insert")
+  local cins_type = payload_data(0,1):le_uint()
+
+  subtree:add(hf_cemu_cardinsert, cins_type);
+  pinfo.cols.info:append(" " .. card_insert_types[cins_type]);
+end
+
+
+
 function usb_simtrace_protocol.dissector(buffer, pinfo, tree)
   length = buffer:len()
   if length == 0 then return end
@@ -160,11 +253,19 @@ function usb_simtrace_protocol.dissector(buffer, pinfo, tree)
   if(command == 0x0101 or command == 0x0106) then
     return dissect_rxtx(payload_data(),pinfo,subtree)
   elseif(command == 0x0104) then
-	return dissect_status(payload_data(),pinfo,subtree)
+    return dissect_status(payload_data(),pinfo,subtree)
   elseif(command == 0x0102) then
-	return dissect_atr(payload_data(),pinfo,subtree)
+    return dissect_atr(payload_data(),pinfo,subtree)
+  elseif(command == 0x0105) then
+    return dissect_cemu_cardinsert(payload_data(),pinfo,subtree)
+  elseif(command == 0x0107) then
+    return dissect_pts(payload_data(),pinfo,subtree)
+  elseif(command == 0x0108) then
+    return dissect_cemu_config(payload_data(),pinfo,subtree)
   elseif(command == 0x0201) then
-	return dissect_modem_reset(payload_data(),pinfo,subtree)
+    return dissect_modem_reset(payload_data(),pinfo,subtree)
+  elseif(command == 0x0202) then
+    return dissect_modem_sim_sel(payload_data(),pinfo,subtree)
   else
     subtree:add(payload, payload_data)
   end
@@ -173,10 +274,13 @@ end
 
 
 function usb_simtrace_protocol.init()
-local usb_product_dissectors = DissectorTable.get("usb.product")
-usb_product_dissectors:add(0x1d50616d, usb_simtrace_protocol)
-usb_product_dissectors:add(0x1d50616e, usb_simtrace_protocol)
-DissectorTable.get("usb.bulk"):add(0xffff, usb_simtrace_protocol)
-DissectorTable.get("usb.interrupt"):add(0xffff, usb_simtrace_protocol)
---concatss =  ByteArray.new()
+  local usb_product_dissectors = DissectorTable.get("usb.product")
+  usb_product_dissectors:add(0x1d50616d, usb_simtrace_protocol) -- OCTSIMTEST
+  usb_product_dissectors:add(0x1d50616e, usb_simtrace_protocol) -- NGFF_CARDEM
+  usb_product_dissectors:add(0x1d5060e3, usb_simtrace_protocol) -- SIMTRACE2
+  usb_product_dissectors:add(0x1d504004, usb_simtrace_protocol) -- QMOD
+  usb_product_dissectors:add(0x1d504001, usb_simtrace_protocol) -- OWHW
+  DissectorTable.get("usb.device"):add_for_decode_as(usb_simtrace_protocol)
+  DissectorTable.get("usb.bulk"):add(0xffff, usb_simtrace_protocol)
+  DissectorTable.get("usb.interrupt"):add(0xffff, usb_simtrace_protocol)
 end

firmware/apps/cardem/main.c

@@ -137,6 +137,12 @@ static void check_exec_dbg_cmd(void)
 	board_exec_dbg_cmd(ch);
 }
 
+#include <osmocom/core/panic.h>
+void WDT_IrqHandler(void)
+{
+	osmo_panic("WDT");
+}
+
 /*------------------------------------------------------------------------------
  *        Main
  *------------------------------------------------------------------------------*/
@@ -152,10 +158,11 @@ extern int main(void)
 	led_blink(LED_GREEN, BLINK_ALWAYS_ON);
 
 	/* Enable watchdog for 2000ms, with no window */
-	WDT_Enable(WDT, WDT_MR_WDRSTEN | WDT_MR_WDDBGHLT | WDT_MR_WDIDLEHLT |
-		   (WDT_GetPeriod(2000) << 16) | WDT_GetPeriod(2000));
+	WDT_Enable(WDT, WDT_MR_WDFIEN | WDT_MR_WDDBGHLT | WDT_MR_WDIDLEHLT |
+		   (WDT_GetPeriod(1000) << 16) | WDT_GetPeriod(1000));
+	NVIC_EnableIRQ(WDT_IRQn);
 
-	PIO_InitializeInterrupts(0);
+	PIO_InitializeInterrupts(10);
 
 	print_banner();
 	board_main_top();

firmware/atmel_softpack_libraries/libchip_sam3s/source/USBD_HAL.c

@@ -1672,6 +1672,10 @@ uint8_t USBD_HAL_Halt(uint8_t bEndpoint, uint8_t ctl)
             UDP->UDP_RST_EP |= 1 << bEndpoint;
             UDP->UDP_RST_EP &= ~(1 << bEndpoint);
         }
+
+        /* This fixes a weird bug with regard to ping-pong OUT endpoints */
+        UDP->UDP_RST_EP |= 1 << bEndpoint;
+        UDP->UDP_RST_EP &= ~(1 << bEndpoint);
     }
 
     /* Return Halt status */

firmware/libboard/common/source/uart_console.c

@@ -100,6 +100,7 @@ extern void UART_Configure( uint32_t baudrate, uint32_t masterClock)
 
 	/* Enable TX interrupts */
 	pUart->UART_IER = UART_IER_TXRDY;
+	NVIC_SetPriority(CONSOLE_IRQ, 15); /* lowest priority */
 	NVIC_EnableIRQ(CONSOLE_IRQ);
 	
 	/* Enable receiver and transmitter */

firmware/libboard/qmod/include/board.h

@@ -89,8 +89,8 @@
 #define PINS_WWAN_IN		{ PIN_WWAN1, PIN_WWAN2 }
 
 /* outputs controlling RESET input of modems */
-#define PIN_PERST1		{PIO_PA25, PIOA, ID_PIOA, PIO_OUTPUT_0, PIO_PULLUP}
-#define PIN_PERST2		{PIO_PA26, PIOA, ID_PIOA, PIO_OUTPUT_0, PIO_PULLUP}
+#define PIN_PERST1		{PIO_PA25, PIOA, ID_PIOA, PIO_OUTPUT_1, PIO_PULLUP}
+#define PIN_PERST2		{PIO_PA26, PIOA, ID_PIOA, PIO_OUTPUT_1, PIO_PULLUP}
 #define PINS_PERST		{ PIN_PERST1, PIN_PERST2 }
 
 #define PIN_VERSION_DET		{PIO_PA19, PIOA, ID_PIOA, PIO_PERIPH_D, PIO_DEFAULT}

firmware/libboard/simtrace/include/board.h

@@ -155,3 +155,7 @@
 #endif
 /* SIMtrace board supports man-in-the-middle mode */
 //#define HAVE_MITM
+
+#define DETECT_VCC_BY_ADC
+#define VCC_UV_THRESH_1V8	(1500000/2)	/* 10k/10k resistive divider halves voltage */
+#define VCC_UV_THRESH_3V	(2500000/2)	/* 10k/10k resistive divider halves voltage */

firmware/libcommon/include/card_emu.h

@@ -69,6 +69,8 @@ void card_emu_uart_enable(uint8_t uart_chan, uint8_t rxtx);
 void card_emu_uart_wait_tx_idle(uint8_t uart_chan);
 void card_emu_uart_interrupt(uint8_t uart_chan);
 
+int card_emu_get_vcc(uint8_t uart_chan);
+
 struct cardemu_usb_msg_config;
 int card_emu_set_config(struct card_handle *ch, const struct cardemu_usb_msg_config *scfg,
 			unsigned int scfg_len);

firmware/libcommon/source/card_emu.c

@@ -1058,7 +1058,10 @@ void card_emu_report_status(struct card_handle *ch, bool report_on_irq)
 		sts->flags |= CEMU_STATUS_F_CLK_ACTIVE;
 	if (ch->in_reset)
 		sts->flags |= CEMU_STATUS_F_RESET_ACTIVE;
-	/* FIXME: voltage + card insert */
+#ifdef DETECT_VCC_BY_ADC
+	sts->voltage_mv = card_emu_get_vcc(ch->num);
+#endif
+	/* FIXME: card insert */
 	sts->F_index = ch->F_index;
 	sts->D_index = ch->D_index;
 	sts->wi = ch->wi;
@@ -1102,7 +1105,12 @@ void card_emu_io_statechg(struct card_handle *ch, enum card_io io, int active)
 			card_set_state(ch, ISO_S_WAIT_POWER);
 			chg_mask |= CEMU_STATUS_F_VCC_PRESENT;
 		} else if (active == 1 && ch->vcc_active == 0) {
+#ifdef DETECT_VCC_BY_ADC
+			TRACE_INFO("%u: VCC activated (%d mV)\r\n", ch->num,
+				   card_emu_get_vcc(ch->num));
+#else
 			TRACE_INFO("%u: VCC activated\r\n", ch->num);
+#endif
 			card_set_state(ch, ISO_S_WAIT_CLK);
 			chg_mask |= CEMU_STATUS_F_VCC_PRESENT;
 		}

firmware/libcommon/source/mode_cardemu.c

@@ -168,6 +168,16 @@ static void card_emu_uart_set_direction(uint8_t uart_chan, bool tx)
 #endif
 }
 
+int card_emu_get_vcc(uint8_t uart_chan)
+{
+	struct cardem_inst *ci = &cardem_inst[uart_chan];
+#ifdef DETECT_VCC_BY_ADC
+	return ci->vcc_uv / 1000;
+#else
+	return -1;
+#endif
+}
+
 /* call-back from card_emu.c to enable/disable transmit and/or receive */
 void card_emu_uart_enable(uint8_t uart_chan, uint8_t rxtx)
 {
@@ -400,10 +410,9 @@ void card_emu_uart_reset_wt(uint8_t uart_chan)
 /* call-back from card_emu.c to force a USART interrupt */
 void card_emu_uart_interrupt(uint8_t uart_chan)
 {
+	OSMO_ASSERT(uart_chan < ARRAY_SIZE(cardem_inst));
 	Usart *usart = get_usart_by_chan(uart_chan);
-	if (!usart) {
-		return;
-	}
+
 	if (USART0 == usart) {
 		NVIC_SetPendingIRQ(USART0_IRQn);
 	} else if (USART1 == usart) {
@@ -461,6 +470,7 @@ static int card_vcc_adc_init(void)
 	ADC->ADC_CHER |= ADC_CHER_CH6;
 	ADC->ADC_IER |= ADC_IER_EOC6;
 #endif
+	NVIC_SetPriority(ADC_IRQn, 13);
 	NVIC_EnableIRQ(ADC_IRQn);
 	ADC->ADC_CR |= ADC_CR_START;
 
@@ -557,6 +567,35 @@ void mode_cardemu_configure(void)
 	TRACE_ENTRY();
 }
 
+struct relevant_irq {
+	uint32_t irq;
+	uint32_t prio;
+	const char *name;
+};
+static const struct relevant_irq relevant_irqs[] = {
+	{ UDP_IRQn, 		14, "USB" },
+	{ CONSOLE_IRQ,		15, "CONSOLE" },
+	{ FIRST_USART_IRQ,	 0, "7816_0" },
+#ifdef CARDEMU_SECOND_UART
+	{ USART0_IRQn,	 	 0, "7816_1" },
+#endif
+#ifdef DETECT_VCC_BY_ADC
+	{ ADC_IRQn,		13, "ADC" },
+#endif
+	{ PIOA_IRQn,		10, "PIOA" },
+	{ PIOB_IRQn,		10, "PIOB" },
+	{ PIOC_IRQn,		10, "PIOC" },
+};
+void dump_irq_prios(void)
+{
+	printf("Interrupt Enable Mask (ISER): %08x%08x\n\r", NVIC->ISER[1], NVIC->ISER[0]);
+	for (unsigned int i = 0; i < ARRAY_SIZE(relevant_irqs); i++) {
+		const struct relevant_irq *ri = &relevant_irqs[i];
+		printf("IRQ prio %02u (%s): current=%u, expected=%u\r\n", ri->irq, ri->name,
+			NVIC_GetPriority(ri->irq), ri->prio);
+	}
+}
+
 /* called if config is activated */
 void mode_cardemu_init(void)
 {
@@ -564,6 +603,8 @@ void mode_cardemu_init(void)
 
 	TRACE_ENTRY();
 
+	NVIC_SetPriority(UDP_IRQn, 14);
+
 #ifdef PINS_CARDSIM
 	PIO_Configure(pins_cardsim, PIO_LISTSIZE(pins_cardsim));
 #endif
@@ -577,6 +618,7 @@ void mode_cardemu_init(void)
 
 	/* configure USART as ISO-7816 slave (e.g. card) */
 	ISO7816_Init(&cardem_inst[0].usart_info, CLK_SLAVE);
+	NVIC_SetPriority(FIRST_USART_IRQ, 0);
 	NVIC_EnableIRQ(FIRST_USART_IRQ);
 	PIO_ConfigureIt(&pin_usim1_rst, usim1_rst_irqhandler);
 	PIO_EnableIt(&pin_usim1_rst);
@@ -604,6 +646,7 @@ void mode_cardemu_init(void)
 	PIO_Configure(pins_usim2, PIO_LISTSIZE(pins_usim2));
 	ISO7816_Init(&cardem_inst[1].usart_info, CLK_SLAVE);
 	/* TODO enable timeout */
+	NVIC_SetPriority(USART0_IRQn, 0);
 	NVIC_EnableIRQ(USART0_IRQn);
 	PIO_ConfigureIt(&pin_usim2_rst, usim2_rst_irqhandler);
 	PIO_EnableIt(&pin_usim2_rst);
@@ -622,6 +665,9 @@ void mode_cardemu_init(void)
 	sim_switch_use_physical(1, 1);
 	/* TODO check RST and VCC */
 #endif /* CARDEMU_SECOND_UART */
+
+	dump_irq_prios();
+
 }
 
 /* called if config is deactivated */

firmware/libcommon/source/usb.c

@@ -206,7 +206,7 @@ static const SIMTraceDriverConfigurationDescriptorSniffer
 						SIMTRACE_USB_EP_CARD_INT),
 		.bmAttributes		= USBEndpointDescriptor_INTERRUPT,
 		.wMaxPacketSize	= USBEndpointDescriptor_MAXINTERRUPTSIZE_FS,
-		.bInterval = 0x10,
+		.bInterval = 1,
 	},
 	DFURT_IF_DESCRIPTOR(1, 0),
 };
@@ -382,7 +382,7 @@ static const SIMTraceDriverConfigurationDescriptorPhone
 						SIMTRACE_CARDEM_USB_EP_USIM1_INT),
 		.bmAttributes		= USBEndpointDescriptor_INTERRUPT,
 		.wMaxPacketSize		= USBEndpointDescriptor_MAXINTERRUPTSIZE_FS,
-		.bInterval		= 0x10
+		.bInterval		= 1
 	},
 #ifdef CARDEMU_SECOND_UART
 	/* Communication class interface standard descriptor */
@@ -429,7 +429,7 @@ static const SIMTraceDriverConfigurationDescriptorPhone
 						SIMTRACE_CARDEM_USB_EP_USIM2_INT),
 		.bmAttributes		= USBEndpointDescriptor_INTERRUPT,
 		.wMaxPacketSize		= USBEndpointDescriptor_MAXINTERRUPTSIZE_FS,
-		.bInterval		= 0x10,
+		.bInterval		= 1,
 	},
 	DFURT_IF_DESCRIPTOR(2, 0),
 #else
@@ -547,7 +547,7 @@ static const SIMTraceDriverConfigurationDescriptorMITM
 						      CCID_EPT_NOTIFICATION),
 		.bmAttributes		= USBEndpointDescriptor_INTERRUPT,
 		.wMaxPacketSize = USBEndpointDescriptor_MAXINTERRUPTSIZE_FS,
-		.bInterval = 0x10,
+		.bInterval = 1,
 	},
 
 	/* Communication class interface standard descriptor */
@@ -593,7 +593,7 @@ static const SIMTraceDriverConfigurationDescriptorMITM
 						SIMTRACE_USB_EP_PHONE_INT),
 		.bmAttributes		= USBEndpointDescriptor_INTERRUPT,
 		.wMaxPacketSize		= USBEndpointDescriptor_MAXINTERRUPTSIZE_FS,
-		.bInterval		= 0x10
+		.bInterval		= 1
 	},
 	DFURT_IF_DESCRIPTOR(2, 0),
 };

host/src/simtrace2-cardem-pcsc.c

@@ -1,7 +1,7 @@
 /* simtrace2-cardem-pcsc - main program for the host PC to provide a remote SIM
  * using the SIMtrace 2 firmware in card emulation mode
  *
- * (C) 2016-2021 by Harald Welte <hwelte@hmw-consulting.de>
+ * (C) 2016-2022 by Harald Welte <hwelte@hmw-consulting.de>
  * (C) 2018, sysmocom -s.f.m.c. GmbH, Author: Kevin Redon <kredon@sysmocom.de>
  *
  * This program is free software; you can redistribute it and/or
@@ -49,7 +49,7 @@
 #include <osmocom/sim/class_tables.h>
 #include <osmocom/sim/sim.h>
 
-#define LOGCI(ci, lvl, fmt, args ...) printf(fmt, ## args)
+#define LOGCI(ci, lvl, fmt, args ...) LOGP(DLGLOBAL, lvl,  fmt, ## args)
 
 static void atr_update_csum(uint8_t *atr, unsigned int atr_len)
 {
@@ -62,7 +62,7 @@ static void atr_update_csum(uint8_t *atr, unsigned int atr_len)
 	atr[atr_len-1] = csum;
 }
 
-static void cemu_flags2str(char *out, unsigned int out_len, uint32_t flags)
+static void cemu_status_flags2str(char *out, unsigned int out_len, uint32_t flags)
 {
 	snprintf(out, out_len, "%s%s%s%s%s",
 		 flags & CEMU_STATUS_F_RESET_ACTIVE ? "RESET " : "",
@@ -72,25 +72,54 @@ static void cemu_flags2str(char *out, unsigned int out_len, uint32_t flags)
 		 flags & CEMU_STATUS_F_RCEMU_ACTIVE ? "RCEMU " : "");
 }
 
-static uint32_t last_flags = 0;
+static uint32_t last_status_flags = 0;
 
-static void update_flags(struct osmo_st2_cardem_inst *ci, uint32_t flags)
+#define NO_RESET 0
+#define COLD_RESET 1
+#define WARM_RESET 2
+
+static void update_status_flags(struct osmo_st2_cardem_inst *ci, uint32_t flags)
 {
 	struct osim_card_hdl *card = ci->chan->card;
+	int reset = NO_RESET;
 
+	/* check if card is _now_ operational: VCC+CLK present, RST absent */
 	if ((flags & CEMU_STATUS_F_VCC_PRESENT) && (flags & CEMU_STATUS_F_CLK_ACTIVE) &&
 	    !(flags & CEMU_STATUS_F_RESET_ACTIVE)) {
-		if (last_flags & CEMU_STATUS_F_RESET_ACTIVE) {
+		if (last_status_flags & CEMU_STATUS_F_RESET_ACTIVE) {
 			/* a reset has just ended, forward it to the real card */
-			bool cold_reset = true;
-			if (last_flags & CEMU_STATUS_F_VCC_PRESENT)
-				cold_reset = false;
-			LOGCI(ci, LOGL_NOTICE, "%s Resetting card in reader...\n",
-				cold_reset ? "Cold" : "Warm");
-			osim_card_reset(card, cold_reset);
+			if (last_status_flags & CEMU_STATUS_F_VCC_PRESENT)
+				reset = WARM_RESET;
+			else
+				reset = COLD_RESET;
+		} else if (!(last_status_flags & CEMU_STATUS_F_VCC_PRESENT)) {
+			/* power-up has just happened, perform cold reset */
+			reset = COLD_RESET;
 		}
+	} else if (flags == CEMU_STATUS_F_VCC_PRESENT &&
+		   !(last_status_flags & CEMU_STATUS_F_VCC_PRESENT)) {
+		/* improper power-up: Only power enabled, but no reset active. */
+		reset = COLD_RESET;
 	}
-	last_flags = flags;
+
+	if (reset) {
+		LOGCI(ci, LOGL_NOTICE, "%s Resetting card in reader...\n",
+			reset == COLD_RESET ? "Cold" : "Warm");
+		osim_card_reset(card, reset == COLD_RESET ? true : false);
+	}
+
+	last_status_flags = flags;
+}
+
+static const char *cemu_data_flags2str(uint32_t flags)
+{
+	static char out[64];
+	snprintf(out, sizeof(out), "%s%s%s%s",
+		 flags & CEMU_DATA_F_TPDU_HDR ? "HDR " : "",
+		 flags & CEMU_DATA_F_FINAL ? "FINAL " : "",
+		 flags & CEMU_DATA_F_PB_AND_TX ? "PB_AND_TX " : "",
+		 flags & CEMU_DATA_F_PB_AND_RX ? "PB_AND_RX" : "");
+	return out;
 }
 
 /***********************************************************************
@@ -103,12 +132,12 @@ static int process_do_status(struct osmo_st2_cardem_inst *ci, uint8_t *buf, int
 	struct cardemu_usb_msg_status *status = (struct cardemu_usb_msg_status *) buf;
 	char fbuf[80];
 
-	cemu_flags2str(fbuf, sizeof(fbuf), status->flags);
-	printf("=> STATUS: flags=0x%x, fi=%u, di=%u, wi=%u wtime=%u (%s)\n",
+	cemu_status_flags2str(fbuf, sizeof(fbuf), status->flags);
+	LOGCI(ci, LOGL_NOTICE, "=> STATUS: flags=0x%x, fi=%u, di=%u, wi=%u wtime=%u (%s)\n",
 		status->flags, status->fi, status->di, status->wi,
 		status->waiting_time, fbuf);
 
-	update_flags(ci, status->flags);
+	update_status_flags(ci, status->flags);
 
 	return 0;
 }
@@ -119,7 +148,7 @@ static int process_do_pts(struct osmo_st2_cardem_inst *ci, uint8_t *buf, int len
 	struct cardemu_usb_msg_pts_info *pts;
 	pts = (struct cardemu_usb_msg_pts_info *) buf;
 
-	printf("=> PTS req: %s\n", osmo_hexdump(pts->req, sizeof(pts->req)));
+	LOGCI(ci, LOGL_NOTICE, "=> PTS req: %s\n", osmo_hexdump(pts->req, pts->pts_len));
 
 	return 0;
 }
@@ -133,8 +162,8 @@ static int process_do_rx_da(struct osmo_st2_cardem_inst *ci, uint8_t *buf, int l
 
 	data = (struct cardemu_usb_msg_rx_data *) buf;
 
-	printf("=> DATA: flags=%x, %s: ", data->flags,
-		osmo_hexdump(data->data, data->data_len));
+	LOGCI(ci, LOGL_INFO, "=> DATA: flags=0x%02x (%s), %s\n ", data->flags,
+	      cemu_data_flags2str(data->flags), osmo_hexdump(data->data, data->data_len));
 
 	rc = osmo_apdu_segment_in(&ac, data->data, data->data_len,
 				  data->flags & CEMU_DATA_F_TPDU_HDR);
@@ -163,7 +192,6 @@ static int process_do_rx_da(struct osmo_st2_cardem_inst *ci, uint8_t *buf, int l
 		msgb_apdu_sw(tmsg) = msgb_get_u16(tmsg);
 		ac.sw[0] = msgb_apdu_sw(tmsg) >> 8;
 		ac.sw[1] = msgb_apdu_sw(tmsg) & 0xff;
-		printf("SW=0x%04x, len_rx=%d\n", msgb_apdu_sw(tmsg), msgb_l3len(tmsg));
 		if (msgb_l3len(tmsg))
 			osmo_st2_cardem_request_pb_and_tx(ci, ac.hdr.ins, tmsg->l3h, msgb_l3len(tmsg));
 		osmo_st2_cardem_request_sw_tx(ci, ac.sw);
@@ -179,8 +207,6 @@ static int process_usb_msg(struct osmo_st2_cardem_inst *ci, uint8_t *buf, int le
 	struct simtrace_msg_hdr *sh = (struct simtrace_msg_hdr *)buf;
 	int rc;
 
-	printf("-> %s\n", osmo_hexdump(buf, len));
-
 	buf += sizeof(*sh);
 
 	switch (sh->msg_type) {
@@ -212,12 +238,12 @@ static int process_irq_status(struct osmo_st2_cardem_inst *ci, const uint8_t *bu
 	const struct cardemu_usb_msg_status *status = (struct cardemu_usb_msg_status *) buf;
 	char fbuf[80];
 
-	cemu_flags2str(fbuf, sizeof(fbuf), status->flags);
-	LOGCI(ci, LOGL_INFO, "SIMtrace IRQ STATUS: flags=0x%x, fi=%u, di=%u, wi=%u wtime=%u (%s)\n",
+	cemu_status_flags2str(fbuf, sizeof(fbuf), status->flags);
+	LOGCI(ci, LOGL_NOTICE, "=> IRQ STATUS: flags=0x%x, fi=%u, di=%u, wi=%u wtime=%u (%s)\n",
 		status->flags, status->fi, status->di, status->wi,
 		status->waiting_time, fbuf);
 
-	update_flags(ci, status->flags);
+	update_status_flags(ci, status->flags);
 
 	return 0;
 }
@@ -227,8 +253,6 @@ static int process_usb_msg_irq(struct osmo_st2_cardem_inst *ci, const uint8_t *b
 	struct simtrace_msg_hdr *sh = (struct simtrace_msg_hdr *)buf;
 	int rc;
 
-	LOGCI(ci, LOGL_INFO, "SIMtrace IRQ %s\n", osmo_hexdump(buf, len));
-
 	buf += sizeof(*sh);
 
 	switch (sh->msg_type) {
@@ -254,6 +278,10 @@ static void usb_in_xfer_cb(struct libusb_transfer *xfer)
 		/* hand the message up the stack */
 		process_usb_msg(ci, xfer->buffer, xfer->actual_length);
 		break;
+	case LIBUSB_TRANSFER_ERROR:
+	case LIBUSB_TRANSFER_STALL:
+		LOGCI(ci, LOGL_FATAL, "USB IN transfer error, trying resubmit\n");
+		break;
 	case LIBUSB_TRANSFER_NO_DEVICE:
 		LOGCI(ci, LOGL_FATAL, "USB device disappeared\n");
 		exit(1);
@@ -305,12 +333,16 @@ static void usb_irq_xfer_cb(struct libusb_transfer *xfer)
 	case LIBUSB_TRANSFER_COMPLETED:
 		process_usb_msg_irq(ci, xfer->buffer, xfer->actual_length);
 		break;
+	case LIBUSB_TRANSFER_ERROR:
+	case LIBUSB_TRANSFER_STALL:
+		LOGCI(ci, LOGL_FATAL, "USB INT transfer error, trying resubmit\n");
+		break;
 	case LIBUSB_TRANSFER_NO_DEVICE:
 		LOGCI(ci, LOGL_FATAL, "USB device disappeared\n");
 		exit(1);
 		break;
 	default:
-		LOGCI(ci, LOGL_FATAL, "USB IN transfer failed, status=%u\n", xfer->status);
+		LOGCI(ci, LOGL_FATAL, "USB INT transfer failed, status=%u\n", xfer->status);
 		exit(1);
 		break;
 	}
@@ -351,7 +383,7 @@ static void allocate_and_submit_irq(struct osmo_st2_cardem_inst *ci)
 static void print_welcome(void)
 {
 	printf("simtrace2-cardem-pcsc - Using PC/SC reader as SIM\n"
-	       "(C) 2010-2020, Harald Welte <laforge@gnumonks.org>\n"
+	       "(C) 2010-2022, Harald Welte <laforge@gnumonks.org>\n"
 	       "(C) 2018, sysmocom -s.f.m.c. GmbH, Author: Kevin Redon <kredon@sysmocom.de>\n\n");
 }
 
@@ -447,13 +479,21 @@ int main(int argc, char **argv)
 
 	print_welcome();
 
+	osmo_init_logging2(NULL, &log_info);
+
 	rc = osmo_libusb_init(NULL);
 	if (rc < 0) {
 		fprintf(stderr, "libusb initialization failed\n");
 		return rc;
 	}
 
-	osmo_init_logging2(NULL, &log_info);
+	log_set_print_category_hex(osmo_stderr_target, false);
+	log_set_print_category(osmo_stderr_target, true);
+	log_set_print_level(osmo_stderr_target, true);
+	log_set_print_filename_pos(osmo_stderr_target, LOG_FILENAME_POS_LINE_END);
+	log_set_print_filename2(osmo_stderr_target, LOG_FILENAME_NONE);
+	log_set_category_filter(osmo_stderr_target, DLINP, 1, LOGL_DEBUG);
+	log_set_category_filter(osmo_stderr_target, DLGLOBAL, 1, LOGL_DEBUG);
 
 	while (1) {
 		int option_index = 0;
@@ -549,19 +589,21 @@ int main(int argc, char **argv)
 
 	do {
 		struct usb_interface_match _ifm, *ifm = &_ifm;
+		memset(ifm, 0, sizeof(*ifm));
 		ifm->vendor = vendor_id;
 		ifm->product = product_id;
 		ifm->configuration = config_id;
 		ifm->interface = if_num;
 		ifm->altsetting = altsetting;
-		ifm->addr = addr;
+		if (addr > 0 && addr < 256)
+			ifm->addr = addr;
 		if (path)
 			osmo_strlcpy(ifm->path, path, sizeof(ifm->path));
 		transp->udp_fd = -1;
 		transp->usb_async = true;
 		transp->usb_devh = osmo_libusb_open_claim_interface(NULL, NULL, ifm);
 		if (!transp->usb_devh) {
-			fprintf(stderr, "can't open USB device\n");
+			fprintf(stderr, "can't open USB device: %s\n", strerror(errno));
 			goto close;
 		}
 

host/src/simtrace2-sniff.c

@@ -442,9 +442,9 @@ int main(int argc, char **argv)
 	}
 	struct usb_interface_match ifm_selected = ifm_filtered[0];
 	printf("Using USB device %04x:%04x Addr=%u, Path=%s, Cfg=%u, Intf=%u, Alt=%u: %d/%d/%d ",
-	ifm_selected.vendor, ifm_selected.product, ifm_selected.addr, ifm_selected.path,
-	ifm_selected.configuration, ifm_selected.interface, ifm_selected.altsetting,
-	ifm_selected.class, ifm_selected.sub_class, ifm_selected.protocol);
+		ifm_selected.vendor, ifm_selected.product, ifm_selected.addr, ifm_selected.path,
+		ifm_selected.configuration, ifm_selected.interface, ifm_selected.altsetting,
+		ifm_selected.class, ifm_selected.sub_class, ifm_selected.protocol);
 	libusb_device_handle *dev_handle;
 	rc = libusb_open(ifm_selected.usb_dev, &dev_handle);
 	if (rc < 0) {
@@ -472,7 +472,7 @@ int main(int argc, char **argv)
 	do {
 		_transp.usb_devh = osmo_libusb_open_claim_interface(NULL, NULL, &ifm_selected);
 		if (!_transp.usb_devh) {
-			fprintf(stderr, "can't open USB device\n");
+			fprintf(stderr, "can't open USB device: %s\n", strerror(errno));
 			goto close_exit;
 		}
 

host/src/simtrace2-tool.c

@@ -290,6 +290,8 @@ int main(int argc, char **argv)
 
 	transp->udp_fd = -1;
 
+	print_welcome();
+
 	osmo_init_logging2(NULL, &log_info);
 
 	rc = osmo_libusb_init(NULL);
@@ -298,22 +300,22 @@ int main(int argc, char **argv)
 		goto do_exit;
 	}
 
-	print_welcome();
-
 	do {
 		if (transp->udp_fd < 0) {
 			struct usb_interface_match _ifm, *ifm = &_ifm;
+			memset(ifm, 0, sizeof(*ifm));
 			ifm->vendor = vendor_id;
 			ifm->product = product_id;
 			ifm->configuration = config_id;
 			ifm->interface = if_num;
 			ifm->altsetting = altsetting;
-			ifm->addr = addr;
+			if (addr > 0 && addr < 256)
+				ifm->addr = addr;
 			if (path)
 				osmo_strlcpy(ifm->path, path, sizeof(ifm->path));
 			transp->usb_devh = osmo_libusb_open_claim_interface(NULL, NULL, ifm);
 			if (!transp->usb_devh) {
-				fprintf(stderr, "can't open USB device\n");
+				fprintf(stderr, "can't open USB device: %s\n", strerror(errno));
 				goto close_exit;
 			}
 

host/src/simtrace2_usb.c

@@ -18,6 +18,8 @@
 #include <errno.h>
 
 #include <osmocom/core/utils.h>
+#include <osmocom/core/logging.h>
+#include <osmocom/core/application.h>
 
 #include <osmocom/usb/libusb.h>
 #include <osmocom/simtrace2/simtrace_usb.h>
@@ -71,8 +73,11 @@ static int find_devices(void)
 	return num_interfaces;
 }
 
+static struct log_info log_info = {};
+
 int main(int argc, char **argv)
 {
+	osmo_init_logging2(NULL, &log_info);
 	osmo_libusb_init(NULL);
 	find_devices();
 	return 0;