catarrh/simtrace2
1
0
Fork 0
mirror of https://gitea.osmocom.org/sim-card/simtrace2.git synced 2026-03-23 00:38:33 +03:00
Code Issues Packages Projects Releases Wiki Activity

print instance/channel number in all trace messages

Browse Source 
When debugging issues related to two concurrent SIM card emulations,
it is vital to know to which USART a message relates.
This commit is contained in:
Harald Welte
2016-03-20 16:42:11 +01:00
parent 8ee15dbc2a
commit dde112e71c
2 changed files with 55 additions and 35 deletions
Download Patch File Download Diff File Expand all files Collapse all files

70
firmware/src_simtrace/card_emu.c
View File

@@ -96,6 +96,8 @@ enum tpdu_state {
#define _P3 4 #define _P3 4
struct card_handle { struct card_handle {
uint32_t num;
enum iso7816_3_card_state state; enum iso7816_3_card_state state;
/* signal levels */ /* signal levels */
@@ -245,14 +247,15 @@ static void emu_update_fidi(struct card_handle *ch)
rc = compute_fidi_ratio(ch->fi, ch->di); rc = compute_fidi_ratio(ch->fi, ch->di);
if (rc > 0 && rc < 0x400) { if (rc > 0 && rc < 0x400) {
TRACE_INFO("computed Fi(%u) Di(%u) ratio: %d\r\n", TRACE_INFO("%u: computed Fi(%u) Di(%u) ratio: %d\r\n",
ch->fi, ch->di, rc); ch->num, ch->fi, ch->di, rc);
/* make sure UART uses new F/D ratio */ /* make sure UART uses new F/D ratio */
card_emu_uart_update_fidi(ch->uart_chan, rc); card_emu_uart_update_fidi(ch->uart_chan, rc);
/* notify ETU timer about this */ /* notify ETU timer about this */
tc_etu_set_etu(ch->tc_chan, rc); tc_etu_set_etu(ch->tc_chan, rc);
} else } else
TRACE_INFO("computed FiDi ration %d unsupported\r\n", rc); TRACE_INFO("%u: computed FiDi ration %d unsupported\r\n",
ch->num, rc);
} }
/* Update the ISO 7816-3 TPDU receiver state */ /* Update the ISO 7816-3 TPDU receiver state */
@@ -262,7 +265,8 @@ static void card_set_state(struct card_handle *ch,
if (ch->state == new_state) if (ch->state == new_state)
return; return;
TRACE_DEBUG("7816 card state %u -> %u\r\n", ch->state, new_state); TRACE_DEBUG("%u: 7816 card state %u -> %u\r\n", ch->num,
ch->state, new_state);
ch->state = new_state; ch->state = new_state;
switch (new_state) { switch (new_state) {
@@ -314,7 +318,8 @@ static void card_set_state(struct card_handle *ch,
/* Update the ATR sub-state */ /* Update the ATR sub-state */
static void set_pts_state(struct card_handle *ch, enum pts_state new_ptss) static void set_pts_state(struct card_handle *ch, enum pts_state new_ptss)
{ {
TRACE_DEBUG("7816 PTS state %u -> %u\r\n", ch->pts.state, new_ptss); TRACE_DEBUG("%u: 7816 PTS state %u -> %u\r\n",
ch->num, ch->pts.state, new_ptss);
ch->pts.state = new_ptss; ch->pts.state = new_ptss;
} }
@@ -384,7 +389,8 @@ process_byte_pts(struct card_handle *ch, uint8_t byte)
case PTS_S_WAIT_REQ_PCK: case PTS_S_WAIT_REQ_PCK:
ch->pts.req[_PCK] = byte; ch->pts.req[_PCK] = byte;
if (ch->pts.req[_PCK] != csum_pts(ch->pts.req)) { if (ch->pts.req[_PCK] != csum_pts(ch->pts.req)) {
TRACE_ERROR("Error in PTS Checksum!\r\n"); TRACE_ERROR("%u: Error in PTS Checksum!\r\n",
ch->num);
/* Wait for the next TPDU */ /* Wait for the next TPDU */
set_pts_state(ch, PTS_S_WAIT_REQ_PTSS); set_pts_state(ch, PTS_S_WAIT_REQ_PTSS);
return ISO_S_WAIT_TPDU; return ISO_S_WAIT_TPDU;
@@ -393,8 +399,8 @@ process_byte_pts(struct card_handle *ch, uint8_t byte)
memcpy(ch->pts.resp, ch->pts.req, sizeof(ch->pts.resp)); memcpy(ch->pts.resp, ch->pts.req, sizeof(ch->pts.resp));
break; break;
default: default:
TRACE_ERROR("process_byte_pts() in invalid state %u\r\n", TRACE_ERROR("%u: process_byte_pts() in invalid state %u\r\n",
ch->pts.state); ch->num, ch->pts.state);
break; break;
} }
/* calculate the next state and set it */ /* calculate the next state and set it */
@@ -431,7 +437,8 @@ static int tx_byte_pts(struct card_handle *ch)
/* This must be TA1 */ /* This must be TA1 */
ch->fi = byte >> 4; ch->fi = byte >> 4;
ch->di = byte & 0xf; ch->di = byte & 0xf;
TRACE_DEBUG("found Fi=%u Di=%u\r\n", ch->fi, ch->di); TRACE_DEBUG("%u: found Fi=%u Di=%u\r\n", ch->num,
ch->fi, ch->di);
break; break;
case PTS_S_WAIT_RESP_PTS2: case PTS_S_WAIT_RESP_PTS2:
byte = ch->pts.resp[_PTS2]; byte = ch->pts.resp[_PTS2];
@@ -443,8 +450,8 @@ static int tx_byte_pts(struct card_handle *ch)
byte = ch->pts.resp[_PCK]; byte = ch->pts.resp[_PCK];
break; break;
default: default:
TRACE_ERROR("get_byte_pts() in invalid state %u\r\n", TRACE_ERROR("%u: get_byte_pts() in invalid state %u\r\n",
ch->pts.state); ch->num, ch->pts.state);
return 0; return 0;
} }
@@ -502,7 +509,8 @@ static void add_tpdu_byte(struct card_handle *ch, uint8_t byte)
if (!ch->uart_rx_ctx) { if (!ch->uart_rx_ctx) {
rctx = ch->uart_rx_ctx = req_ctx_find_get(0, RCTX_S_FREE, RCTX_S_UART_RX_BUSY); rctx = ch->uart_rx_ctx = req_ctx_find_get(0, RCTX_S_FREE, RCTX_S_UART_RX_BUSY);
if (!ch->uart_rx_ctx) { if (!ch->uart_rx_ctx) {
TRACE_ERROR("Received UART byte but ENOMEM\r\n"); TRACE_ERROR("%u: Received UART byte but ENOMEM\r\n",
ch->num);
return; return;
} }
rd = (struct cardemu_usb_msg_rx_data *) ch->uart_rx_ctx->data; rd = (struct cardemu_usb_msg_rx_data *) ch->uart_rx_ctx->data;
@@ -532,7 +540,8 @@ static void set_tpdu_state(struct card_handle *ch, enum tpdu_state new_ts)
if (ch->tpdu.state == new_ts) if (ch->tpdu.state == new_ts)
return; return;
TRACE_DEBUG("7816 TPDU state %u -> %u\r\n", ch->tpdu.state, new_ts); TRACE_DEBUG("%u: 7816 TPDU state %u -> %u\r\n", ch->num,
ch->tpdu.state, new_ts);
ch->tpdu.state = new_ts; ch->tpdu.state = new_ts;
@@ -583,24 +592,25 @@ static void send_tpdu_header(struct card_handle *ch)
struct req_ctx *rctx; struct req_ctx *rctx;
struct cardemu_usb_msg_rx_data *rd; struct cardemu_usb_msg_rx_data *rd;
TRACE_INFO("%s: %02x %02x %02x %02x %02x\r\n", __func__, TRACE_INFO("%u: %s: %02x %02x %02x %02x %02x\r\n",
ch->num, __func__,
ch->tpdu.hdr[0], ch->tpdu.hdr[1], ch->tpdu.hdr[0], ch->tpdu.hdr[1],
ch->tpdu.hdr[2], ch->tpdu.hdr[3], ch->tpdu.hdr[2], ch->tpdu.hdr[3],
ch->tpdu.hdr[4]); ch->tpdu.hdr[4]);
/* if we already/still have a context, send it off */ /* if we already/still have a context, send it off */
if (ch->uart_rx_ctx) { if (ch->uart_rx_ctx) {
TRACE_DEBUG("have old buffer\r\n"); TRACE_DEBUG("%u: have old buffer\r\n", ch->num);
if (ch->uart_rx_ctx->idx) { if (ch->uart_rx_ctx->idx) {
TRACE_DEBUG("flushing old buffer\r\n"); TRACE_DEBUG("%u: flushing old buffer\r\n", ch->num);
flush_rx_buffer(ch); flush_rx_buffer(ch);
} }
} else { } else {
TRACE_DEBUG("allocating new buffer\r\n"); TRACE_DEBUG("%u: allocating new buffer\r\n", ch->num);
/* ensure we have a new buffer */ /* ensure we have a new buffer */
ch->uart_rx_ctx = req_ctx_find_get(0, RCTX_S_FREE, RCTX_S_UART_RX_BUSY); ch->uart_rx_ctx = req_ctx_find_get(0, RCTX_S_FREE, RCTX_S_UART_RX_BUSY);
if (!ch->uart_rx_ctx) { if (!ch->uart_rx_ctx) {
TRACE_ERROR("%s: ENOMEM\r\n", __func__); TRACE_ERROR("%u: %s: ENOMEM\r\n", ch->num, __func__);
return; return;
} }
} }
@@ -652,8 +662,8 @@ process_byte_tpdu(struct card_handle *ch, uint8_t byte)
add_tpdu_byte(ch, byte); add_tpdu_byte(ch, byte);
break; break;
default: default:
TRACE_ERROR("process_byte_tpdu() in invalid state %u\r\n", TRACE_ERROR("%u: process_byte_tpdu() in invalid state %u\r\n",
ch->tpdu.state); ch->num, ch->tpdu.state);
} }
/* ensure we stay in TPDU ISO state */ /* ensure we stay in TPDU ISO state */
@@ -745,8 +755,8 @@ void card_emu_process_rx_byte(struct card_handle *ch, uint8_t byte)
case ISO_S_WAIT_CLK: case ISO_S_WAIT_CLK:
case ISO_S_WAIT_RST: case ISO_S_WAIT_RST:
case ISO_S_WAIT_ATR: case ISO_S_WAIT_ATR:
TRACE_ERROR("Received UART char in invalid 7816 state %u\r\n", TRACE_ERROR("%u: Received UART char in invalid 7816 state "
ch->state); "%u\r\n", ch->num, ch->state);
/* we shouldn't receive any data from the reader yet! */ /* we shouldn't receive any data from the reader yet! */
break; break;
case ISO_S_WAIT_TPDU: case ISO_S_WAIT_TPDU:
@@ -859,28 +869,28 @@ void card_emu_io_statechg(struct card_handle *ch, enum card_io io, int active)
switch (io) { switch (io) {
case CARD_IO_VCC: case CARD_IO_VCC:
if (active == 0 && ch->vcc_active == 1) { if (active == 0 && ch->vcc_active == 1) {
TRACE_INFO("VCC deactivated\r\n"); TRACE_INFO("%u: VCC deactivated\r\n", ch->num);
tc_etu_disable(ch->tc_chan); tc_etu_disable(ch->tc_chan);
card_set_state(ch, ISO_S_WAIT_POWER); card_set_state(ch, ISO_S_WAIT_POWER);
} else if (active == 1 && ch->vcc_active == 0) { } else if (active == 1 && ch->vcc_active == 0) {
TRACE_INFO("VCC activated\r\n"); TRACE_INFO("%u: VCC activated\r\n", ch->num);
card_set_state(ch, ISO_S_WAIT_CLK); card_set_state(ch, ISO_S_WAIT_CLK);
} }
ch->vcc_active = active; ch->vcc_active = active;
break; break;
case CARD_IO_CLK: case CARD_IO_CLK:
if (active == 1 && ch->clocked == 0) { if (active == 1 && ch->clocked == 0) {
TRACE_INFO("CLK activated\r\n"); TRACE_INFO("%u: CLK activated\r\n", ch->num);
if (ch->state == ISO_S_WAIT_CLK) if (ch->state == ISO_S_WAIT_CLK)
card_set_state(ch, ISO_S_WAIT_RST); card_set_state(ch, ISO_S_WAIT_RST);
} else if (active == 0 && ch->clocked == 1) { } else if (active == 0 && ch->clocked == 1) {
TRACE_INFO("CLK deactivated\r\n"); TRACE_INFO("%u: CLK deactivated\r\n", ch->num);
} }
ch->clocked = active; ch->clocked = active;
break; break;
case CARD_IO_RST: case CARD_IO_RST:
if (active == 0 && ch->in_reset) { if (active == 0 && ch->in_reset) {
TRACE_INFO("RST released\r\n"); TRACE_INFO("%u: RST released\r\n", ch->num);
if (ch->vcc_active && ch->clocked) { if (ch->vcc_active && ch->clocked) {
/* enable the TC/ETU counter once reset has been released */ /* enable the TC/ETU counter once reset has been released */
tc_etu_enable(ch->tc_chan); tc_etu_enable(ch->tc_chan);
@@ -889,7 +899,7 @@ void card_emu_io_statechg(struct card_handle *ch, enum card_io io, int active)
card_set_state(ch, ISO_S_IN_ATR); card_set_state(ch, ISO_S_IN_ATR);
} }
} else if (active && !ch->in_reset) { } else if (active && !ch->in_reset) {
TRACE_INFO("RST asserted\r\n"); TRACE_INFO("%u: RST asserted\r\n", ch->num);
tc_etu_disable(ch->tc_chan); tc_etu_disable(ch->tc_chan);
} }
ch->in_reset = active; ch->in_reset = active;
@@ -937,7 +947,8 @@ void tc_etu_wtime_half_expired(void *handle)
/* hardware driver informs us that one (more) ETU has expired */ /* hardware driver informs us that one (more) ETU has expired */
void tc_etu_wtime_expired(void *handle) void tc_etu_wtime_expired(void *handle)
{ {
TRACE_ERROR("wtime_exp\r\n"); struct card_handle *ch = handle;
TRACE_ERROR("%u: wtime_exp\r\n", ch->num);
} }
/* shortest ATR found in smartcard_list.txt */ /* shortest ATR found in smartcard_list.txt */
@@ -960,6 +971,7 @@ struct card_handle *card_emu_init(uint8_t slot_num, uint8_t tc_chan, uint8_t uar
INIT_LLIST_HEAD(&ch->uart_tx_queue); INIT_LLIST_HEAD(&ch->uart_tx_queue);
/* initialize the card_handle with reasonabe defaults */ /* initialize the card_handle with reasonabe defaults */
ch->num = slot_num;
ch->state = ISO_S_WAIT_POWER; ch->state = ISO_S_WAIT_POWER;
ch->vcc_active = 0; ch->vcc_active = 0;
ch->in_reset = 1; ch->in_reset = 1;

20
firmware/src_simtrace/mode_cardemu.c
View File

@@ -27,6 +27,7 @@ static const Pin pin_usim2_vcc = PIN_USIM2_VCC;
#endif #endif
struct cardem_inst { struct cardem_inst {
uint32_t num;
struct card_handle *ch; struct card_handle *ch;
struct llist_head usb_out_queue; struct llist_head usb_out_queue;
struct ringbuf rb; struct ringbuf rb;
@@ -42,6 +43,7 @@ struct cardem_inst {
static struct cardem_inst cardem_inst[] = { static struct cardem_inst cardem_inst[] = {
{ {
.num = 0,
.usart_info = { .usart_info = {
.base = USART1, .base = USART1,
.id = ID_USART1, .id = ID_USART1,
@@ -54,6 +56,7 @@ static struct cardem_inst cardem_inst[] = {
}, },
#ifdef CARDEMU_SECOND_UART #ifdef CARDEMU_SECOND_UART
{ {
.num = 1,
.usart_info = { .usart_info = {
.base = USART0, .base = USART0,
.id = ID_USART0, .id = ID_USART0,
@@ -148,8 +151,9 @@ int card_emu_uart_tx(uint8_t uart_chan, uint8_t byte)
int i = 1; int i = 1;
while ((usart->US_CSR & (US_CSR_TXRDY)) == 0) { while ((usart->US_CSR & (US_CSR_TXRDY)) == 0) {
if (!(i%1000000)) { if (!(i%1000000)) {
TRACE_ERROR("s: %x %02X\r\n", TRACE_ERROR("%u: s: %x %02X\r\n",
usart->US_CSR, usart->US_RHR & 0xFF); uart_chan, usart->US_CSR,
usart->US_RHR & 0xFF);
usart->US_CR = US_CR_RSTTX; usart->US_CR = US_CR_RSTTX;
usart->US_CR = US_CR_RSTRX; usart->US_CR = US_CR_RSTRX;
} }
@@ -189,7 +193,7 @@ void usart_irq_rx(uint8_t uart)
if (csr & (US_CSR_OVRE|US_CSR_FRAME|US_CSR_PARE| if (csr & (US_CSR_OVRE|US_CSR_FRAME|US_CSR_PARE|
US_CSR_TIMEOUT|US_CSR_NACK|(1<<10))) { US_CSR_TIMEOUT|US_CSR_NACK|(1<<10))) {
usart->US_CR = US_CR_RSTSTA | US_CR_RSTIT | US_CR_RSTNACK; usart->US_CR = US_CR_RSTSTA | US_CR_RSTIT | US_CR_RSTNACK;
TRACE_ERROR("e 0x%x st: 0x%x\n", byte, csr); TRACE_ERROR("%u e 0x%x st: 0x%x\n", ci->num, byte, csr);
} }
} }
@@ -451,6 +455,8 @@ static void dispatch_usb_command(struct req_ctx *rctx, struct cardem_inst *ci)
break; break;
case CEMU_USB_MSGT_DT_CARDINSERT: case CEMU_USB_MSGT_DT_CARDINSERT:
cardins = (struct cardemu_usb_msg_cardinsert *) hdr; cardins = (struct cardemu_usb_msg_cardinsert *) hdr;
TRACE_INFO("%u: set card_insert to %s\r\n", ci->num,
cardins->card_insert ? "INSERTED" : "REMOVED");
if (cardins->card_insert) if (cardins->card_insert)
PIO_Set(&ci->pin_insert); PIO_Set(&ci->pin_insert);
else else
@@ -491,7 +497,8 @@ static void dispatch_received_rctx(struct req_ctx *rctx, struct cardem_inst *ci)
mh = (struct cardemu_usb_msg_hdr * ) ((uint8_t *)mh + mh->msg_len)) { mh = (struct cardemu_usb_msg_hdr * ) ((uint8_t *)mh + mh->msg_len)) {
segm = req_ctx_find_get(0, RCTX_S_FREE, RCTX_S_MAIN_PROCESSING); segm = req_ctx_find_get(0, RCTX_S_FREE, RCTX_S_MAIN_PROCESSING);
if (!segm) { if (!segm) {
TRACE_ERROR("ENOMEM during rctx segmentation\r\n"); TRACE_ERROR("%u: ENOMEM during rctx segmentation\r\n",
ci->num);
break; break;
} }
segm->idx = 0; segm->idx = 0;
@@ -546,13 +553,14 @@ void mode_cardemu_run(void)
uint8_t byte = rbuf_read(&ci->rb); uint8_t byte = rbuf_read(&ci->rb);
__enable_irq(); __enable_irq();
card_emu_process_rx_byte(ci->ch, byte); card_emu_process_rx_byte(ci->ch, byte);
//TRACE_ERROR("Rx%02x\r\n", byte); //TRACE_ERROR("%uRx%02x\r\n", i, byte);
} }
queue = card_emu_get_usb_tx_queue(ci->ch); queue = card_emu_get_usb_tx_queue(ci->ch);
int usb_pending = llist_count(queue); int usb_pending = llist_count(queue);
if (usb_pending != ci->usb_pending_old) { if (usb_pending != ci->usb_pending_old) {
TRACE_DEBUG("usb_pending=%d\r\n", usb_pending); TRACE_DEBUG("%u usb_pending=%d\r\n",
i, usb_pending);
ci->usb_pending_old = usb_pending; ci->usb_pending_old = usb_pending;
} }
usb_refill_to_host(queue, ci->ep_in); usb_refill_to_host(queue, ci->ep_in);