USB debug console prevents gpg mode from working

[osresearch]

I've built the firmware from source and verified that gpg mode works in the stock build (flashing over SWD):

./configure --vidpid=20a0:4211 --target=NITROKEY_START

[790047.231169] usb 1-3: new full-speed USB device number 27 using xhci_hcd
[790047.380856] usb 1-3: New USB device found, idVendor=20a0, idProduct=4211, bcdDevice= 2.00
[790047.380863] usb 1-3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[790047.380867] usb 1-3: Product: Nitrokey Start
[790047.380870] usb 1-3: Manufacturer: Nitrokey
[790047.380873] usb 1-3: SerialNumber: FSIJ-1.2.15-43115544

% gpg2 --card-status
Reader ...........: 20A0:4211:FSIJ-1.2.15-43115544:0
Application ID ...: D276000124010200FFFE431155440000
Version ..........: 2.0
Manufacturer .....: unmanaged S/N range
Serial number ....: 43115544
Name of cardholder: [not set]
Language prefs ...: [not set]
Sex ..............: unspecified
URL of public key : [not set]
Login data .......: [not set]
Signature PIN ....: forced
Key attributes ...: rsa2048 rsa2048 rsa2048
Max. PIN lengths .: 127 127 127
PIN retry counter : 3 3 3
Signature counter : 0
Signature key ....: [none]
Encryption key....: [none]
Authentication key: [none]
General key info..: [none]

However when I enable the debug console there is both nothing printed on the uart and the device doesn't respond to gpg --card-status commands. The USB enumeration looks right -- there are both the CCID and CDC endpoints.

[790104.186428] usb 1-3: new full-speed USB device number 28 using xhci_hcd
[790104.340240] usb 1-3: New USB device found, idVendor=20a0, idProduct=4211, bcdDevice= 2.00
[790104.340247] usb 1-3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[790104.340250] usb 1-3: Product: Nitrokey Start
[790104.340253] usb 1-3: Manufacturer: Nitrokey
[790104.340256] usb 1-3: SerialNumber: FSIJ-1.2.15-43115544
[790104.344389] cdc_acm 1-3:1.1: ttyACM1: USB ACM device

lsusb.txt

Running gpg2 --card-status hangs. Attempting to open the serial port produces a warning on the dmesg (but no output ever appears on the console):

[790249.857875] cdc_acm 1-3:1.1: failed to set dtr/rts

It's not clear with gdb where the card is; everytime I single step it is in chx_idle().

[osresearch]

When _write() is modified to early return, the gpg2 --card-status works, which makes me think something is getting clogged in the mutex. The first write appears to go into the mutex cond wait since the stdout.connected is not yet set, and it never comes out.

Using the swd interface, gdb can log what the writes would have been:

Breakpoint 5, _write (s=s@entry=0x8017060 "Rx ready\r\n", len=10) at usb-ccid.c:1978
1978	{
(gdb) 
Continuing.
Breakpoint 5, _write (s=s@entry=0x8017530 "GPG!: ", len=6) at usb-ccid.c:1978
1978	{
(gdb) 
Continuing.
Breakpoint 5, _write (s=s@entry=0x80173d7 " - select 0x2f02 EF\r\n", len=21) at usb-ccid.c:1978
1978	{
(gdb) 
Continuing.
Breakpoint 5, _write (s=s@entry=0x8017307 "DATA\r\n", len=6) at usb-ccid.c:1978
1978	{
[....]

Adding a breakpoint at usb_tx_done() seems to indicate that it is not called when the serial write has finished, so no further writes happen. I'm trying to track down why that is, since the other endpoints seem to work.

[osresearch]

If I comment out the cond wait in _write() it works with the debug port enabled:

      chopstx_mutex_lock (&stdout.m_dev);
#ifdef GNU_LINUX_EMULATION
      usb_lld_tx_enable_buf (ENDP3, s, packet_len);
#else
      usb_lld_write (ENDP3, s, packet_len);
#endif
      //chopstx_cond_wait (&stdout.cond_dev, &stdout.m_dev);
      chopstx_mutex_unlock (&stdout.m_dev);

(and by "work", I mean that interacting with the card works. the debug console has lots of messed up messages as a result of not waiting for the tx to complete)

[osresearch]

I'm not positive how usb_tx_done() is supposed to be called. It looks to me that ccid_thread() is responsible for periodically checking the USB interrupt:

  while (1)
    { /* ... */
      if (usb_intr.ready)
        {
          if (usb_event_handle (&dev) == 0)

Except that DEBUG_INFO() will call _write(), which will go to sleep until the USB events have been processed, while won't happen until back in the main loop of the thread. Am I missing something in the architecture that allows progress to continue when the thread is asleep?

[osresearch]

txfifo.txt

This hack of a patch uses a tx fifo instead of the cond variables and it allows the debug console to work again. I'm really confused how it worked in the past since it appears to self-deadlock based on the way the condition variables are used and the single thread handling both the _write() and the USB hardware.