From dde112e71c5a977a61813885c02a4220560417a5 Mon Sep 17 00:00:00 2001 From: Harald Welte Date: Sun, 20 Mar 2016 16:42:11 +0100 Subject: [PATCH] print instance/channel number in all trace messages When debugging issues related to two concurrent SIM card emulations, it is vital to know to which USART a message relates. --- firmware/src_simtrace/card_emu.c | 70 ++++++++++++++++------------ firmware/src_simtrace/mode_cardemu.c | 20 +++++--- 2 files changed, 55 insertions(+), 35 deletions(-) diff --git a/firmware/src_simtrace/card_emu.c b/firmware/src_simtrace/card_emu.c index e458f1ce..e7a9c2d8 100644 --- a/firmware/src_simtrace/card_emu.c +++ b/firmware/src_simtrace/card_emu.c @@ -96,6 +96,8 @@ enum tpdu_state { #define _P3 4 struct card_handle { + uint32_t num; + enum iso7816_3_card_state state; /* signal levels */ @@ -245,14 +247,15 @@ static void emu_update_fidi(struct card_handle *ch) rc = compute_fidi_ratio(ch->fi, ch->di); if (rc > 0 && rc < 0x400) { - TRACE_INFO("computed Fi(%u) Di(%u) ratio: %d\r\n", - ch->fi, ch->di, rc); + TRACE_INFO("%u: computed Fi(%u) Di(%u) ratio: %d\r\n", + ch->num, ch->fi, ch->di, rc); /* make sure UART uses new F/D ratio */ card_emu_uart_update_fidi(ch->uart_chan, rc); /* notify ETU timer about this */ tc_etu_set_etu(ch->tc_chan, rc); } 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 */ @@ -262,7 +265,8 @@ static void card_set_state(struct card_handle *ch, if (ch->state == new_state) 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; switch (new_state) { @@ -314,7 +318,8 @@ static void card_set_state(struct card_handle *ch, /* Update the ATR sub-state */ 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; } @@ -384,7 +389,8 @@ process_byte_pts(struct card_handle *ch, uint8_t byte) case PTS_S_WAIT_REQ_PCK: ch->pts.req[_PCK] = byte; 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 */ set_pts_state(ch, PTS_S_WAIT_REQ_PTSS); 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)); break; default: - TRACE_ERROR("process_byte_pts() in invalid state %u\r\n", - ch->pts.state); + TRACE_ERROR("%u: process_byte_pts() in invalid state %u\r\n", + ch->num, ch->pts.state); break; } /* calculate the next state and set it */ @@ -431,7 +437,8 @@ static int tx_byte_pts(struct card_handle *ch) /* This must be TA1 */ ch->fi = byte >> 4; 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; case PTS_S_WAIT_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]; break; default: - TRACE_ERROR("get_byte_pts() in invalid state %u\r\n", - ch->pts.state); + TRACE_ERROR("%u: get_byte_pts() in invalid state %u\r\n", + ch->num, ch->pts.state); return 0; } @@ -502,7 +509,8 @@ static void add_tpdu_byte(struct card_handle *ch, uint8_t byte) if (!ch->uart_rx_ctx) { rctx = ch->uart_rx_ctx = req_ctx_find_get(0, RCTX_S_FREE, RCTX_S_UART_RX_BUSY); 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; } 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) 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; @@ -583,24 +592,25 @@ static void send_tpdu_header(struct card_handle *ch) struct req_ctx *rctx; 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[2], ch->tpdu.hdr[3], ch->tpdu.hdr[4]); /* if we already/still have a context, send it off */ 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) { - TRACE_DEBUG("flushing old buffer\r\n"); + TRACE_DEBUG("%u: flushing old buffer\r\n", ch->num); flush_rx_buffer(ch); } } else { - TRACE_DEBUG("allocating new buffer\r\n"); + TRACE_DEBUG("%u: allocating new buffer\r\n", ch->num); /* ensure we have a new buffer */ ch->uart_rx_ctx = req_ctx_find_get(0, RCTX_S_FREE, RCTX_S_UART_RX_BUSY); if (!ch->uart_rx_ctx) { - TRACE_ERROR("%s: ENOMEM\r\n", __func__); + TRACE_ERROR("%u: %s: ENOMEM\r\n", ch->num, __func__); return; } } @@ -652,8 +662,8 @@ process_byte_tpdu(struct card_handle *ch, uint8_t byte) add_tpdu_byte(ch, byte); break; default: - TRACE_ERROR("process_byte_tpdu() in invalid state %u\r\n", - ch->tpdu.state); + TRACE_ERROR("%u: process_byte_tpdu() in invalid state %u\r\n", + ch->num, ch->tpdu.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_RST: case ISO_S_WAIT_ATR: - TRACE_ERROR("Received UART char in invalid 7816 state %u\r\n", - ch->state); + TRACE_ERROR("%u: Received UART char in invalid 7816 state " + "%u\r\n", ch->num, ch->state); /* we shouldn't receive any data from the reader yet! */ break; 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) { case CARD_IO_VCC: 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); card_set_state(ch, ISO_S_WAIT_POWER); } 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); } ch->vcc_active = active; break; case CARD_IO_CLK: 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) card_set_state(ch, ISO_S_WAIT_RST); } 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; break; case CARD_IO_RST: 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) { /* enable the TC/ETU counter once reset has been released */ 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); } } 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); } 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 */ 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 */ @@ -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); /* initialize the card_handle with reasonabe defaults */ + ch->num = slot_num; ch->state = ISO_S_WAIT_POWER; ch->vcc_active = 0; ch->in_reset = 1; diff --git a/firmware/src_simtrace/mode_cardemu.c b/firmware/src_simtrace/mode_cardemu.c index 4c8fec34..d53d60bf 100644 --- a/firmware/src_simtrace/mode_cardemu.c +++ b/firmware/src_simtrace/mode_cardemu.c @@ -27,6 +27,7 @@ static const Pin pin_usim2_vcc = PIN_USIM2_VCC; #endif struct cardem_inst { + uint32_t num; struct card_handle *ch; struct llist_head usb_out_queue; struct ringbuf rb; @@ -42,6 +43,7 @@ struct cardem_inst { static struct cardem_inst cardem_inst[] = { { + .num = 0, .usart_info = { .base = USART1, .id = ID_USART1, @@ -54,6 +56,7 @@ static struct cardem_inst cardem_inst[] = { }, #ifdef CARDEMU_SECOND_UART { + .num = 1, .usart_info = { .base = USART0, .id = ID_USART0, @@ -148,8 +151,9 @@ int card_emu_uart_tx(uint8_t uart_chan, uint8_t byte) int i = 1; while ((usart->US_CSR & (US_CSR_TXRDY)) == 0) { if (!(i%1000000)) { - TRACE_ERROR("s: %x %02X\r\n", - usart->US_CSR, usart->US_RHR & 0xFF); + TRACE_ERROR("%u: s: %x %02X\r\n", + uart_chan, usart->US_CSR, + usart->US_RHR & 0xFF); usart->US_CR = US_CR_RSTTX; 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| US_CSR_TIMEOUT|US_CSR_NACK|(1<<10))) { 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; case CEMU_USB_MSGT_DT_CARDINSERT: 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) PIO_Set(&ci->pin_insert); 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)) { segm = req_ctx_find_get(0, RCTX_S_FREE, RCTX_S_MAIN_PROCESSING); if (!segm) { - TRACE_ERROR("ENOMEM during rctx segmentation\r\n"); + TRACE_ERROR("%u: ENOMEM during rctx segmentation\r\n", + ci->num); break; } segm->idx = 0; @@ -546,13 +553,14 @@ void mode_cardemu_run(void) uint8_t byte = rbuf_read(&ci->rb); __enable_irq(); 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); int usb_pending = llist_count(queue); 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; } usb_refill_to_host(queue, ci->ep_in);