Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Deadlock with multiple readers and quick reads #220

Closed
Skill3t opened this issue Dec 11, 2024 · 33 comments
Closed

Deadlock with multiple readers and quick reads #220

Skill3t opened this issue Dec 11, 2024 · 33 comments
Assignees

Comments

@Skill3t
Copy link

Skill3t commented Dec 11, 2024

Your system information

  • Operating system used: Ubuntu
  • pyscard version: 2.2.0
  • Python version: 3.10

Please describe your issue in as much detail as possible:

Describe what you expected should happen.
I have a setup where I have 2 Readers (call them a and b). If I hold on / off a card really quickly for about 40 times to reader a. the CardObserver miss one removedcards.
When I hold on any card to the other reader (b), no card will be detected on this reader.
To heal this state, I need to hold a card to reader a (this will not be detected throw the observer as well) and remove the card (will be detected). Then both reader works as intended. Sometimes holding a card to reader b will call update with one card add and one removed (his did not trigger the deadlock).
I could not reproduce this with pcscd in debug mode.

Here is ne minimum script to reproduce.

import time
from smartcard.CardMonitoring import CardMonitor, CardObserver
from smartcard.util import toHexString

class NFCObserver(CardObserver):

    def update(self, observable, actions):
        # callback method from observer
        addedcards, removedcards = actions
        print("------ update %s", actions)
        try:
            for card in addedcards:
                print("Add Card from reader %s- Add card: %s", card.reader, toHexString(card.atr))
                connection = card.createConnection()
                connection.connect()
                connection.disconnect()
            for card in removedcards:
                print("Removed Card from reader %s- Removed card: %s", card.reader, toHexString(card.atr))

        except Exception as e:
            print("Unexpected %s during NFCObserver callback: %s action=%s", e.__class__.__name__, e, actions)

def main():
    card_observer = NFCObserver()
    card_monitor = CardMonitor()
    card_monitor.addObserver(card_observer)
    while True:
        time.sleep(1)
    card_monitor.deleteObserver(card_observer)

if __name__ == "__main__":
    main()

Describe what did happen.

Steps for reproducing this issue:

  1. Start the Programm with pcscd started and 2 readers connected
  2. Hold a Card quickly to reader a for 40 times
  3. Remove the Card quickly and check if the remove was detected from the CardObserver
  4. If not hold a card to reader b (This schould not trigger update from the CardObserver)

It is sometiimes a bit tricky to reproduce it. Just try for a few times.
If you need further information please let me know.
Thank you in advance

@LudovicRousseau
Copy link
Owner

By "hold on / off" you mean insert and remove?

If I hold on / off a card really quickly for about 40 times to reader a. the CardObserver miss one removedcards.

You mean the card is no more inserted in the reader but PySCard has not generated a removedcards event?

Can you also run pcsc_scan to see what status is reported (card inserted or removed) when the problem occurs?

@LudovicRousseau LudovicRousseau self-assigned this Dec 11, 2024
@Skill3t
Copy link
Author

Skill3t commented Dec 11, 2024

I use NFC Reader. So i only hold on a Desfire Card and Remote the Card ready quick.

@Skill3t
Copy link
Author

Skill3t commented Dec 11, 2024

"You mean the card is no more inserted in the reader but PySCard has not generated a removedcards event?"
Yes exactly this.

@LudovicRousseau
Copy link
Owner

Running pcsc_scan at the same time would really help to know if the wrong status (card reported inserted when no card is present) comes from PySCard or pcsc-lite.

@Skill3t
Copy link
Author

Skill3t commented Dec 12, 2024

so you are write the pcsc_scan did not detect the "Card removed" (from reader a) in the attached picture the card was already removed. But the pcsc_scan could detect new cards on reader b. Witch where not shown with a update call from the observer.
image

And after a few minutes reader a is set to "Status unavailable"

image
my setup ist:
"NXP PN7462AU CCID (1.00) 00 00" -> reader a
"NXP PN7462AU CCID (1.00) 01 00" -> reader b

So it seems to be a missing remove from pcscd and then the observer is not working correctly.

@LudovicRousseau
Copy link
Owner

Tell me if I am. correct in my understanding:

  1. after some time you remove the card from reader a but pcsc_scan still reports a card present in reader a. Exact?
  2. when this happens you can insert/remove a card on reader b. The events are reported by pcsc_scan but NOT by PySCard. Exact?
  3. what did you do to get "status unavailable" for reader b (not a as you wrote)?

@Skill3t
Copy link
Author

Skill3t commented Dec 12, 2024

  1. yes exactly.
  2. yes exactly.
  3. Status unavailable is from reader a not reader b. So I just wait around 2-4 minutes, then pcsc_scan seems to detect that the removed card is not present anymore.

Thanks a lot for your quick response. If I could provide you any further information, let me know

@LudovicRousseau
Copy link
Owner

About point 3, from your second screen capture the "status unavailable" is for reader "NXP PN7462AU CCID (1.00) 01 00". Is that reader a or reader b?

@Skill3t
Copy link
Author

Skill3t commented Dec 12, 2024

Sorry for the confusion
"NXP PN7462AU CCID (1.00) 00 00" -> reader b
"NXP PN7462AU CCID (1.00) 01 00" -> reader a
So ist is the reader who not detect the "Card removed"
I try to reproduce it again. Hold a card short to reader a and remove it direktly. Now I got a "Card removed" after 3,5 minutes.
image

@Skill3t
Copy link
Author

Skill3t commented Dec 12, 2024

Here is a nother example without a "status unavailable" but you can see on the left that the last "Card removed" is not present in the pyscard
image

and a nother example with "Status unavailable,"
image

@LudovicRousseau
Copy link
Owner

We have 2 issues:

  1. PySCard is missing events
  2. pcsc-lite fails to report events (card removed)

For 1 I will have a look.

For 2 the problem is not in PySCard.
It may be in:

  1. the reader firmware
  2. the CCID driver
  3. pcsc-lite

Are you able to reproduce issue 1 or 2 with only one reader?

@Skill3t
Copy link
Author

Skill3t commented Dec 12, 2024

Hey, i total agree that there are 2 issues.
The main Problem is issue 1. If I miss an event, this is not a big deal. Users normal represent the Card again. The main Problem is that the second reader did not get any further events. At my Laptop I have 4 reader 2 USB reader (reader a and b called) and 2 Internal readers of the Laptop itself.
But in the example attached, you can see that only one reader is involved, "NXP PN7462AU CCID (1.00) 01 00". I but on the card at "Thu Dec 12 11:37:22 2024" with event number "1768" and removed it directly. Lets say at Thu Dec 12 11:37:23 2024 (1 second later). This was not detected but after 3,5 minutes i get "Status unavailable" with Eventnumer 0 which is kind of crazy. Then I get additional 10 minutes later a "Card removed" with a correct Event numer "1769"

image

@LudovicRousseau
Copy link
Owner

From pcsc-lite source code, SCARD_STATE_UNAVAILABLE is used when the reader is in state SCARD_UNKNOWN. And that happens if the call to IFDStatusICC() fails. i.e. a problem has been reported by the driver.

To continue the investigation I will need pcscd logs as described in https://ccid.apdu.fr/#support

@Skill3t
Copy link
Author

Skill3t commented Dec 12, 2024

image
log.txt
Here you can find a example with the logfile. Thanks a lot for your help.

@LudovicRousseau
Copy link
Owner

From your logs:

00000007 [129921473054272] -> 000001 63 00 00 00 00 00 9D 00 00 00 
00041001 [129921642923584] winscard_svc.c:361:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 15
00000027 [129921642923584] winscard_svc.c:840:MSGSendReaderStates() Send reader states: 15
00146423 [129921684866624] ccid_usb.c:1519:InterruptRead() after (1) (0)
00000017 [129921684866624] NotifySlotChange: 50 02 
99999999 [129921473054272] ccid_usb.c:993:ReadUSB() read failed (3/9): LIBUSB_ERROR_TIMEOUT
00000038 [129921473054272] ifdhandler.c:1235:IFDHPowerICC() PowerDown failed

The driver sends a PC_to_RDR_IccPowerOff command (63h)
But at the "same" time the card is removed. The reader sends a NotifySlotChange to indicate that.
But the PC_to_RDR_IccPowerOff command never completes. The driver gets a LIBUSB_ERROR_TIMEOUT.
The driver should get a "card absent error" instead.

After that the reader is "confused" and refuses to work correctly:

00000020 [129921684866624] -> 000001 65 00 00 00 00 00 9E 00 00 00 
00000551 [129921684866624] <- 000001 65 00 00 00 00 00 9E 40 E0 00 
00000019 [129921684866624] commands.c:1282:CmdGetSlotStatus Slot busy

It is not a problem in PySCard or pcsc-lite or the CCID driver.
You should report the issue to the reader manufacturer.

@Skill3t
Copy link
Author

Skill3t commented Dec 13, 2024

Thanks a lot for this deep analysis. I will provide this information to the Vendor. So this is Issue 2. Do you see a chance that pyscard can get the events in the scenario on other readers (Issue 1)? This would help a lot.

@LudovicRousseau
Copy link
Owner

Maybe the firmware of your NXP reader is old.
Please follow https://ccid.apdu.fr/#CCID_compliant

@LudovicRousseau
Copy link
Owner

An easy way to reproduce the missing event problem is to use this patch:

diff --git a/src/smartcard/CardMonitoring.py b/src/smartcard/CardMonitoring.py
index bb7f3f7..d9bad74 100644
--- a/src/smartcard/CardMonitoring.py
+++ b/src/smartcard/CardMonitoring.py
@@ -177,6 +177,8 @@ class CardMonitoringThread:
                         self.observable.setChanged()
                         self.observable.notifyObservers((addedcards, removedcards))
 
+                    sleep(5)
+
                 except CardRequestTimeoutException:
                     pass

I know what need to be fixed.

LudovicRousseau added a commit to LudovicRousseau/pyscard-devel that referenced this issue Dec 15, 2024
We now use the states returned by the previous SCardGetStatusChange()
call as initial state for the next call.
Since pcsc-lite includes and use the number of card events in the high
word of dwEventState the function SCardGetStatusChange() returns if an
event was missed.

Thanks to Lars Lengersdorf for the bug report
" Deadlock with multiple readers and quick reads #220 "
LudovicRousseau/pyscard#220
@LudovicRousseau
Copy link
Owner

The missing event problem should be fixed in https://github.com/LudovicRousseau/pyscard-devel
Please try again using the "pyscard-devel" repo and tell me if that is OK for you.

@Skill3t
Copy link
Author

Skill3t commented Dec 19, 2024

Hey Sorry for the late response, do i need to compile it in a way? In the installed pyscard i have smartcard/scard/scard.py file witch is missing in https://github.com/LudovicRousseau/pyscard-devel/tree/master/src/smartcard/scard. So i try to copy the last 2 commit in my installed pyscard but the bug ist not fixed then.

@LudovicRousseau
Copy link
Owner

The easiest way to test is to download the file PCSCCardRequest.py and replace the one from your local installation.

You should add something like:

print("hello world")

at the beginning of the method waitforcardevent() (line 302) just to be sure the new file is really used. If you do not see the text "hello world" when you run your test code then you are not using the new version of the file.

The only Ubuntu version that provides python3-pyscard version 2.2.0 is plucky (the not yet released Ubuntu 25.04) https://packages.ubuntu.com/search?keywords=python3-pyscard
Do you really use this version of Ubuntu?
If not how have you installed pyscard version 2.2.0?

@Skill3t
Copy link
Author

Skill3t commented Dec 20, 2024

I use Ubuntu 22.04.5 LTS with Python 3.10 and poetry to manage my dependencys. So i hade the error with pyscard 2.0.10 and then i update to pyscard version 2.2.0 and still have the problmen.
Now i exchange PCSCCardRequest.py and add (print("-----Test waitforcardevent----")) to inle 302. But i still have the problem that the second reader did not get
image
the event in case the first reader missed the card remove. pcsc_scan see the events on the second reader.

@LudovicRousseau
Copy link
Owner

Here is a fixed version of your sample code.

import time
from smartcard.CardMonitoring import CardMonitor, CardObserver
from smartcard.util import toHexString

class NFCObserver(CardObserver):

    def update(self, observable, actions):
        # callback method from observer
        addedcards, removedcards = actions
        print("------ update", actions)
        try:
            for card in addedcards:
                print(f"Add Card from reader {card.reader}- ATR: {toHexString(card.atr)}")
                connection = card.createConnection()
                connection.connect()
                connection.disconnect()
            for card in removedcards:
                print("Removed Card from reader %s- Removed card: %s" % (card.reader, toHexString(card.atr)))

        except Exception as e:
            print(e.__class__.__name__, e, actions)
            print("Unexpected %s during NFCObserver callback: %s action=%s" % (e.__class__.__name__, e, actions))

def main():
    card_observer = NFCObserver()
    card_monitor = CardMonitor()
    card_monitor.addObserver(card_observer)
    while True:
        time.sleep(10)
    card_monitor.deleteObserver(card_observer)

if __name__ == "__main__":
    main()

Use print("%s %s" % (a, b)) instead of print("%s %s", a, b) or use f"{a}" strings

Questions:

  • From your screen capture I understand that you add/remove the card only on the reader named "NXP PN7462AU CCID (1.00) 01 00". Exact?
  • If you use 1 reader only do you also get the missing event problem?

Since you have a firmware issue (reader reports "CmdGetSlotStatus Slot busy") I don't think it is a good idea to continue your tests with these readers. You will always get problems. Do you have readers from another manufacturer?

@LudovicRousseau
Copy link
Owner

I don't understand why a problem on one reader would create problems on the second reader.

I propose you to generate debug traces so I can analyze in detail what is happening.
I would need:

Start the 2 logs capture and reproduce the problem.

@Skill3t
Copy link
Author

Skill3t commented Jan 6, 2025

Sorry for the late response, Chrismath and end of year hits in, but now I am back in Focus with Smartcards.

From your screen capture, I understand that you add/remove the card only on the reader named "NXP PN7462AU CCID (1.00) 01 00". Exact? --> Yes

If you use 1 reader only, do you also get the missing event problem? -> Yes, but only one missing remove Card. When I hold the card again to this reader, everything works fine. This is due to the fact that the reader did not fully comply (guess from your analysis)

I don't understand why a problem on one reader would create problems on the second reader.
So I can reproduce this also with only one of my readers and a second one (internal reader of my Dell Laptop).
I do not think I can reproduce this without any of my readers. I will provide you the needed logfiels Tomorrow.

@LudovicRousseau
Copy link
Owner

A missing event is a card event reported by pcsc_scan but not by PySCard. If the problem is the firmware issue then the reader will fail to report a card removed but pcsc_scan and PySCard will have the same status.

So when you use only 1 reader do you see a event that is reported by pcsc_scan but not by PySCard (with my patch applied)?

Can you detail what you can reproduce exactly when you use a NXP reader and your internal laptop reader?
What do you do and what happens?

@Skill3t
Copy link
Author

Skill3t commented Jan 7, 2025

first on ubuntu 22.04 the latest pcsc-lite version is 1.9.5 and install_spy.sh is available in 1.9.8
So I upgraded to 24.04 now my pcsc-lite version is 2.0.3

So when you use only 1 reader do you see an event that is reported by pcsc_scan but not by PySCard (with my patch applied)?
--> When I only use one Reader with your patch the event (remove card) is missing in pcsc_scan but after around 3,5 minute
pcsc_scan gets a "Status unavailable" and shortly after a "Card removed" event witch is mapped to a single card_removed in pyscard
witch is totally fine for me.

Can you detail what you can reproduce exactly when you use a NXP reader and your internal laptop reader?
What do you do and what happens?
So on the NXP reader (NFC reader) I present a DesfireTag and remove ist quickly for around 50 times until I did not get the remove event (I get it but 3,5 Minutes later).
When I insert a card (just a Plastic Card sorry do not habe a real one here) In the waiting time of this 3,5 Minutes into my Laptop reader (Broadcom Corp 58200)
I see the events in pcsc_scan but dit not get them in pyscard.

Here you find the pcsc-spy log of pcsc_scan and the pcscd log.

Some Times pcsc-spy crashed

Traceback (most recent call last):
  File "/usr/bin/pcsc-spy", line 1014, in <module>
    main(logfile, color=color, diffable=diffable)
  File "/usr/bin/pcsc-spy", line 968, in main
    spy.loop()
  File "/usr/bin/pcsc-spy", line 902, in loop
    (thread, tail) = line.split('@')
    ^^^^^^^^^^^^^^

log_pcscd_multi_nxp_and_internal.txt
log_pcsc-spy.txt

I Relay hope this will help you. If you need any further information, do not hesitate to ask.
Thanks a lot!

@LudovicRousseau
Copy link
Owner

Thanks.
I would also need the pscs-spy logs from your Python program.
Can you try again and generate:

  • pcscd logs
  • pcsc-spy logs for pcsc_scan
  • pcsc-spy logs for the Python program

The pcsc-spy crash trace is not complete. I guess Python reported an exception name. But it is not present in what you provide.

@Skill3t
Copy link
Author

Skill3t commented Jan 9, 2025

How do I log pcsc_scan an python with pcsc_spy in multiple Files?
Try To Start pcsc_spy first then pscsc_scan then a nother pcsc_spy and then python this results in the followwing logfiles.

Screenshot from 2025-01-09 07-26-49

log_multi_nxp_and_internal.txt
pcsc-spy.log

@LudovicRousseau
Copy link
Owner

Ah yes, you can't (easily) spy 2 applications at the same time.
The pcsc-spy.log file is corrupted.

I see you have in fact 2 Broadcom readers (or interfaces) and 4 readers in total:

  • "NXP PN7462AU CCID (1.00) 00 00" on /dev/bus/usb/003/008
  • "NXP PN7462AU CCID (1.00) 01 00" on /dev/bus/usb/003/009
  • "Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 02 00" on /dev/bus/usb/003/003
  • "Broadcom Corp 58200 [Contactless SmartCard] (0123456789ABCD) 03 00" on /dev/bus/usb/003/003

One question: are you able to see card events on each reader with your Python program (when you do not try to generate a problem)?

@LudovicRousseau
Copy link
Owner

I think I found the problem thanks to the pcscd logs.
You code is doing:

                print(f"Add Card from reader {card.reader}- ATR: {toHexString(card.atr)}")
                connection = card.createConnection()
                connection.connect()
                connection.disconnect()

The .connect() to the card and .disconnect() takes time.
And since the NXP reader is confused by the rapid card insertion/removal the driver is blocked waiting after the reader for a long time (few minutes).
During that time, of course, all the card events are lost and NOT reported by the PySCard observer. The observer is waiting for the update() method to return.

If you do not want to lose card events, your update() method should be very quick.

The problem is NOT in PySCard.

@LudovicRousseau
Copy link
Owner

My patch is now included in a released version
https://blog.apdu.fr/posts/2025/01/new-version-of-pyscard-221/

Closing this issue.

@Skill3t
Copy link
Author

Skill3t commented Jan 13, 2025

Yes, you are totally right. This is exactly the Problem. So just for everyone running in this Problem. The wrapt_timeout_decorator can handle multithreading timeouts. So when the problem occurs, the print("------ After connection") is missing in the output. But after 10 seconds the update method return throw the except TimeoutError and the update method is 'free' to get trigger by new events again. As an example, this can look like this:

import datetime
import time

from smartcard.CardMonitoring import CardMonitor, CardObserver
from smartcard.scard import (
    SCardEstablishContext,
    SCardListReaders,
    SCARD_SCOPE_USER,
)
from smartcard.util import toHexString
from wrapt_timeout_decorator import timeout


class NFCObserver(CardObserver):

    def update(self, observable, actions):
        # callback method from observer
        print("------ update", actions, datetime.datetime.now().isoformat())
        try:
            self.long_function_call(actions)
        except TimeoutError as e:
            print("Timed out!")

    @timeout(10, use_signals=False, timeout_exception=TimeoutError, dec_poll_subprocess=1)
    def long_function_call(self, actions):
        addedcards, removedcards = actions
        try:
            for card in addedcards:
                print(f"ADD Card from reader {card.reader}- ATR: {toHexString(card.atr)}")
                connection = card.createConnection()
                connection.connect()
                connection.disconnect()
                print("------ After connection")
            for card in removedcards:
                print("REMOVED Card from reader %s- Removed card: %s" % (card.reader, toHexString(card.atr)))

        except Exception as e:
            print(e.__class__.__name__, e, actions)
            print("Unexpected %s during NFCObserver callback: %s action=%s" % (e.__class__.__name__, e, actions))


def main():
    hresult, hcontext = SCardEstablishContext(SCARD_SCOPE_USER)
    hresult, readers = SCardListReaders(hcontext, [])
    print(readers)
    card_observer = NFCObserver()
    card_monitor = CardMonitor()
    card_monitor.addObserver(card_observer)
    while True:
        time.sleep(10)
    card_monitor.deleteObserver(card_observer)


if __name__ == "__main__":
    main()

Thank you so much for your Support, the really quick response time and the fix.
A good start to the week

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants