SCardTransmit silent failure

[jonahkagan]

Your system information

• Operating system used: macOS 11.6.4
• pyscard version: 2.0.2
• Python version: 3.7.12

Please describe your issue in as much detail as possible:

Describe what you expected should happen. I have a script that does some reads and writes to a smartcard to test whether a given card reader is functioning correctly. I expect that the reads and writes all succeed (they usually do).

Describe what did happen. In some cases, an initial read command silently fails (using CardConnection.transmit) and (I think) the thread just dies. My script continues executing, I think because the transmit call is happening in a separate thread created by a CardObserver.

I've traced the execution down to the _scard.SCardTransmit command executed in scard.py on L833. This line is reached, but does not return.

Steps for reproducing this issue:

Unfortunately I haven't been able to create a minimal set of steps to repro, but I can tell you exactly what I've been doing. Here is my script: https://github.com/votingworks/vxsuite/blob/main/services/smartcards/testCardReader.py.

1. Ensure no card reader is connected.
2. Run pipenv run python testCardReader.py
3. Connect a card reader when prompted
4. Insert a card when prompted
5. At this point, the behavior will occur sometimes and the script will fail

Logs

I was reading through some other issues and saw it might be helpful to capture the pcscd logs, so I'm attaching those here as well log.txt

[LudovicRousseau]

pcscd is not available on macOS 11.6.4. Are you sure you are using macOS?

[jonahkagan]

Oh whoops my bad! I forgot I was running this all in a VM. OS: Ubuntu 20.04.2

[LudovicRousseau]

What is the module smartcards.core? Do you have a sample code using only PySCard and standard modules?

[jonahkagan]

smartcards.core is this module: https://github.com/votingworks/vxsuite/blob/main/services/smartcards/smartcards/core.py. The only relevant part here is that it exports CardInterface, which is just a redefinition of VxCardObserver (defined here: https://github.com/votingworks/vxsuite/blob/main/services/smartcards/smartcards/card.py).

I know it's not fun to wade through other people's code though so I'll also work on creating a more minimal example.

[jonahkagan]

Ok I tried to trim down the code into a simpler script a bit: https://gist.github.com/jonahkagan/bc7cb0ba618cbf687393a7c599c82547. Let me know if this is helpful.

Again, steps to reproduce are:

1. Ensure no card reader is connected
2. Run the script
3. When prompted, plug in a card reader (with no card inserted)
4. When prompted, insert a card
5. The assertion at the end of the script should pass, but fails

Note that for me, if I run the script with a card reader already inserted or a card in the reader, the failure does not occur.

Let me know if there's any more info I can provide. I really appreciate your help!

[LudovicRousseau]

I used your sample. But I have no problem (I think).

$ ./bug.py 
Connect reader
Insert card
read_chunk about to transmit: [255, 48, 0, 5, 9, 1, 0, 0, 0, 32, 0, 0, 0, 64]
read_chunk result: []

Maybe that is because my card does understand the APDU the program is sending? Can you provide an even simpler test code?

I also note that I can't find any problem in the pcscd trace you sent.

[LudovicRousseau]

You can run pcsc_scan in another terminal to check if you get card events when you have the problem? https://ludovicrousseau.blogspot.com/2014/03/level-1-smart-card-support-on-gnulinux.html

[jonahkagan]

Thanks for trying it out @LudovicRousseau. Too bad it didn't fail for you! Sometimes it takes me quite a few tries to produce a failure. One thing I have noticed is that when I use a card with some of our data written onto it already, it seems to fail more often than when I use a fresh card from a pack.

I tried running pcsc_scan but it didn't show any interesting card events - it just showed when the card connected/disconnected normally.

Here are two new pcsd log files from the more minimal script I sent you last time. I used a fresh card and recorded one log when the script passes and one when the script fails. Maybe you can identify some interesting discrepancy. failure.txt success.txt

I will see if I can create a more minimal failing script in the meantime.

[jonahkagan]

Also I'm noticing that for me, when I use a fresh card and the script succeeds, this is the output:

read_chunk result: [255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255]

I'm curious why it would return that, while in your case it returned read_chunk result: [].

[LudovicRousseau]

I can't find any problem in your log failure.txt In my case I gey an empty result because the card I used does not understand the command [255, 48, 0, 5, 9, 1, 0, 0, 0, 32, 0, 0, 0, 64] your program is sending.

You do not get any error from a PySCard method. I guess the problem is in your code.

[jonahkagan]

I figured out the issue. Due to the fact that CardMonitor creates a separate thread under the hood, the execution of the code in the VXCardObserver.update method can be interleaved with the main thread. So my main thread thought it was waiting for the execution of the initial read to complete when checking if VxCardObserver.card was non-null, but really it VxCardObserver.card could be set to the card and then the main thread could regain control and start executing before the read completed.

[LudovicRousseau]

I am happy you found the problem.