version 1.6 causes hangs in pcsc, opensc, gpg

[al-heisner]

Working with both 1.4 and 1.6: lsusb shows device: Bus 008 Device 037: ID 234b:0000 Free Software Initiative of Japan Gnuk Token pcscd logs device: 00000104 [140218338324992] readerfactory.c:1387:RFCleanupReaders() Stopping reader: Free Software Initiative of Japan Gnuk [Pico HSM Interface] (E6609103C3395D24) 00 00 opensc-tool -l lists device:

Detected readers (pcsc)

Nr. Card Features Name 0 Yes Free Software Initiative of Japan Gnuk [Pico HSM Interface] (E6609103C3395D24) 00 00 opensc-tool -a lists atr bytes

Works in 1.4 but hangs in 1.6 opensc-tool --serial opensc-tool -l -v opensc-tool -n gpg --card-edit

versions: pcscd: pcsc-lite version 1.9.5 opensc-tool: 0.22.0-1ubuntu2 gpg: 0.22.0-1ubuntu2

[polhenarejos]

It should be fixed in v1.8 https://github.com/polhenarejos/pico-openpgp/releases/tag/v1.8 check it and reopen if it happens again.

[al-heisner]

Same issue with 1.8

[polhenarejos]

Did you compile or patch it?

[al-heisner]

I used the vid:pid patch script on release 1.8. I'm able to compile it also to test prior to new release.

[al-heisner]

I did some debugging on this one. Issue 1 was I saw bMessageType == 0x63 come in twice from pcsc (during opensc-tool -l, for example). It looks like this caused one to shut down the card thread, and the other remain in queue. The one in queue would immediately shut down the card thread when it was spun back up. I got past this problem in my setup by commenting out the original card_exit() in ccid.c and adding "if (ccid_status == 0) card_exit();" just before "ccid_status = 1;". This seems to prevent placing the extra shutdown on the card thread queue.

Issue 2: I'm not sure what the problem is, as attempting to observe it changed the outcome. Compiling with debug and additional printf in usb_write_offest() and usb_write_flush() in usb.c made it not reproducible. Maybe a timing issue?

[polhenarejos]

I cannot reproduce it in a Debian machine. I am using pcscd 1.8.24-1, libccid 1.4.30 and opensc 0.19.0.

• Does it blink regularly?
• Can you stop pcscd service, and execute it in foreground? pcscd --foreground --debug
• Is lsusb -vvv detecting correctly?
• Try with OPENSC_DEBUG=9 opensc-tool -an to see if it is a bug with the CCID or USB interface.

[al-heisner]

I'm using Linux Mint 21, it's Debian/Ubuntu based but seems to have slightly newer package versions. lsusb does show device. I've been running pcscd in forground with debug, it is properly reporting the pico, eg: Stopping reader: Free Software Initiative of Japan Gnuk [Pico HSM Interface] (E6609103C3395D24) 00 00

For issue 1 with card thread, I added some debug printf's to show it from the pico's serial connection. From pico serial port during start of pcscd: driver_process_usb_packet(): dwLength=0 rx_read-10=0 bMessageType=65 usb_write_offset(): length=10 driver_process_usb_packet(): dwLength=0 rx_read-10=0 bMessageType=65 usb_write_offset(): length=10 driver_process_usb_packet(): dwLength=0 rx_read-10=0 bMessageType=65 usb_write_offset(): length=10 driver_process_usb_packet(): dwLength=0 rx_read-10=0 bMessageType=65 usb_write_offset(): length=10 driver_process_usb_packet(): dwLength=0 rx_read-10=0 bMessageType=65 usb_write_offset(): length=10 driver_process_usb_packet(): dwLength=0 rx_read-10=0 bMessageType=62 card_start(): called card_thread(): start usb_write_offset(): length=31 driver_process_usb_packet(): dwLength=0 rx_read-10=0 bMessageType=65 usb_write_offset(): length=10 driver_process_usb_packet(): dwLength=0 rx_read-10=0 bMessageType=65 usb_write_offset(): length=10 driver_process_usb_packet(): dwLength=0 rx_read-10=0 bMessageType=63 card_exit(): called card_thread(): EXIT usb_write_offset(): length=10 driver_process_usb_packet(): dwLength=0 rx_read-10=0 bMessageType=63 card_exit(): called usb_write_offset(): length=10 driver_process_usb_packet(): dwLength=0 rx_read-10=0 bMessageType=65 usb_write_offset(): length=10 driver_process_usb_packet(): dwLength=0 rx_read-10=0 bMessageType=65 usb_write_offset(): length=10 driver_process_usb_packet(): dwLength=0 rx_read-10=0 bMessageType=65 usb_write_offset(): length=10 driver_process_usb_packet(): dwLength=0 rx_read-10=0 bMessageType=65 usb_write_offset(): length=10 driver_process_usb_packet(): dwLength=0 rx_read-10=0 bMessageType=63 card_exit(): called usb_write_offset(): length=10

From the above output, I see that bMessageType=63 is sent several times just from starting pcscd. Then when I attempt opensc-tool -n, the card thread starts and exits immediate since "queue_try_add(&usb_to_card_q, &flag);" in card_exit() has placed extra exit messages on the usb_to_card_q queue. From pico serial port when trying "opensc-tool -n": driver_process_usb_packet(): dwLength=0 rx_read-10=0 bMessageType=62 card_start(): called card_thread(): start usb_write_offset(): length=31 card_thread(): EXIT driver_process_usb_packet(): dwLength=12 rx_read-10=12 bMessageType=6f usb_write_offset(): length=10

The following in ccid.c seems to work to prevent the extra exit messages from being placed on usb_to_card_q by checking ccid_status before calling card_exit():

            else if (ccid_header->bMessageType == 0x63) {
                if (ccid_status == 0) card_exit();
                ccid_status = 1;
                ccid_response->bMessageType = CCID_SLOT_STATUS_RET;
                ccid_response->dwLength = 0;
                ccid_response->bSlot = 0;
                ccid_response->bSeq = ccid_header->bSeq;
                ccid_response->abRFU0 = ccid_status;
                ccid_response->abRFU1 = 0;
                //card_exit();
                ccid_write(0);
            }

[al-heisner]

After I've put the workaround in for card_exit, I then get hangs during communication with the pico. pcscd shows libusb timeout:

00000020 [140706369947200] APDU: 00 CA 00 6E 00 20 00 
00000020 [140706369947200] ifdhandler.c:1368:IFDHTransmitToICC() usb:234b/0000:libudev:0:/dev/bus/usb/008/060 (lun: 0)
14467008 [140706369947200] ccid_usb.c:993:ReadUSB() read failed (8/60): LIBUSB_ERROR_TIMEOUT
00000052 [140706369947200] SW: 
00000010 [140706369947200] ifdwrapper.c:543:IFDTransmit() Card not transacted: 612
00000021 [140706369947200] winscard.c:1618:SCardTransmit() Card not transacted: 0x80100016

This second issue seems to be timing related. With the workaround for the first issue in place, the pico appears to hang with any attempt to retrieve data from it. When I added a printf to the function usb_write_flush, it made this issue disappear. Swapping the printf out with busy_wait_us(10) also worked.

uint32_t usb_write_flush() {
    if (w_len > 0) {
        busy_wait_us(10);
        driver_write(tx_buffer+tx_r_offset, MIN(w_len, 64));
        //printf("usb_write_flush(): length=%i\r\n",MIN(w_len, 64));
        tx_r_offset += MIN(w_len, 64);
        w_len -= MIN(w_len, 64);
    }
    return w_len;
}

[polhenarejos]

Sounds interesting.

I made some changes in usb_write_flush weeks ago on streamline of pico-hsm-sdk. Could you cd pico-hsm-sdk && git checkout - and recompile with the latest version of the HSM SDK? I also added a bugfix for multiple cardPowerOff (0x63).

[al-heisner]

With the bugfix for cardPowerOff and latest HSM SDK it appears to work. I'm able to use opensc-tool without hang, and I was able to use gpg --card-edit to generate keys on the virtual gpg card

[al-heisner]

perhaps the cardPowerOff bug is this one too? https://github.com/polhenarejos/pico-hsm/issues/9

[polhenarejos]

Could be. I could not reproduce it, hope it will help fixing it. BTW, it is fixed in openpgp.