Do you have some debug logs from opensc? What opensc version is used? What NSS version is used? What smart card type and reader are used?

Created attachment 1834254 [details]
Debug logs for OpenSC/Firefox

OPENSC_DEBUG=9 firefox

> What opensc version is used?

opensc-0.20.0-4.el8.x86_64

> What NSS version is used?

nss-3.67.0-6.el8_4.x86_64

> What smart card type and reader are used?

Common Access Card (CAC)
Broadcom Corp 58200 (built-in to laptop)

--

$ opensc-tool --list-readers
# Detected readers (pcsc)
Nr.  Card  Features  Name
0    Yes             Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00
$ opensc-tool --list-drivers 
Configured card drivers:
  cac              Common Access Card (CAC)
  PIV-II           Personal Identity Verification Card

Assuming the hang happens in the end of the log, its in the CCID.

The Broadcom 58200 is whole bunch of readers with different descriptors and limitations. Can you get us the "lsusb -v" output for the reader?

The reader itself should work probably https://ccid.apdu.fr/ccid/shouldwork.html#0x0A5C0x5842

Can you try with different, external reader that is know to work to rule out the problem in the rest of the system?

> Can you try with different, external reader that is know to work to rule out the problem in the rest of the system?

Of course. I have tried the following readers:

Bus 001 Device 016: ID 413c:2101 Dell Computer Corp. SK-3205 SmartCard Reader Keyboard
Bus 001 Device 017: ID 04e6:5116 SCM Microsystems, Inc. SCR331-LC1 / SCR3310 SmartCard Reader

The issue still occurs when using either one. This wasn't an issue with Firefox 68 or 78.

> Can you get us the "lsusb -v" output for the reader?

Bus 001 Device 007: ID 0a5c:5842 Broadcom Corp. 
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               2.00
  bDeviceClass            0 
  bDeviceSubClass         0 
  bDeviceProtocol         0 
  bMaxPacketSize0        64
  idVendor           0x0a5c Broadcom Corp.
  idProduct          0x5842 
  bcdDevice            1.01
  iManufacturer           1 Broadcom Corp
  iProduct                2 58200
  iSerial                 3 0123456789ABCD
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength       0x008b
    bNumInterfaces          2
    bConfigurationValue     1
    iConfiguration          0 
    bmAttributes         0xe0
      Self Powered
      Remote Wakeup
    MaxPower              100mA
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           3
      bInterfaceClass       254 Application Specific Interface
      bInterfaceSubClass      0 
      bInterfaceProtocol      0 
      iInterface              4 Broadcom ControlVault 3
      ** UNRECOGNIZED:  10 25 00 00 00 00 00 00 00 00 00 00 00 00 00 00
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x81  EP 1 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x01  EP 1 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x85  EP 5 IN
        bmAttributes            3
          Transfer Type            Interrupt
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0400  1x 1024 bytes
        bInterval               1
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        1
      bAlternateSetting       0
      bNumEndpoints           3
      bInterfaceClass        11 Chip/SmartCard
      bInterfaceSubClass      0 
      bInterfaceProtocol      0 
      iInterface              5 Contacted SmartCard
      ChipCard Interface Descriptor:
        bLength                54
        bDescriptorType        33
        bcdCCID              1.00
        nMaxSlotIndex           0
        bVoltageSupport         7  5.0V 3.0V 1.8V 
        dwProtocols             3  T=0 T=1
        dwDefaultClock       4000
        dwMaxiumumClock      4000
        bNumClockSupported      0
        dwDataRate           9600 bps
        dwMaxDataRate      250000 bps
        bNumDataRatesSupp.      0
        dwMaxIFSD             247
        dwSyncProtocols  00000000 
        dwMechanical     00000000 
        dwFeatures       000102BA
          Auto configuration based on ATR
          Auto voltage selection
          Auto clock change
          Auto baud rate change
          Auto PPS made by CCID
          NAD value other than 0x00 accepted
          TPDU level exchange
        dwMaxCCIDMsgLen       271
        bClassGetResponse      00
        bClassEnvelope         00
        wlcdLayout           none
        bPINSupport             0 
        bMaxCCIDBusySlots       1
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x82  EP 2 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x02  EP 2 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x86  EP 6 IN
        bmAttributes            3
          Transfer Type            Interrupt
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0400  1x 1024 bytes
        bInterval               1
Device Qualifier (for other device speed):
  bLength                10
  bDescriptorType         6
  bcdUSB               2.00
  bDeviceClass            0 
  bDeviceSubClass         0 
  bDeviceProtocol         0 
  bMaxPacketSize0        64
  bNumConfigurations      1
Device Status:     0x0000
  (Bus Powered)

The SCM reader should work, but we had some issues with the Dell keyboard too.

If you use the SCM reader, does it hang on the same place (when it tries to talk to the broadcom reader)? If so, could disabling the internal reader (for example using usbguard) solve the issue?

The SCM reader is a reliable device. We use it where a Dell Keyboard is not available.

Blocked the 0a5c:5842 Broadcom Corp. reader on the laptop with usbguard. The issue still occurs with only the SCM reader attached. The activity light remained solid, no activity once firefox stopped responding. openscl-tool, pcsc_scan do not return until the firefox process was terminated.

# usbguard list-devices --blocked
31: block id 0a5c:5842 serial "0123456789ABCD" name "58200" hash "****" parent-hash "****" via-port "1-8" with-interface { fe:00:00 0b:00:00 } with-connect-type "hardwired"
# opensc-tool --list-readers
# Detected readers (pcsc)
Nr.  Card  Features  Name
0    Yes             SCM Microsystems Inc. SCR 3310 [CCID Interface] 02 00

The same behavior was observed with only the SK-3205 attached.

I am wondering if also pcsc_scan or similar tool would get stuck if running long enough.

The logs look like something is opening too many connections to the pcscd, which can not be handled by the internal select. Jan, could that be some change in firefox that it would open the smart card connection from more processes than before through NSS? I am not familiar how this works inside of firefox.

Complete debug log from pcscd could bring some light into this. But it might get quite long. You can collect it with the following commands:

  sudo systemctl stop pcscd.socket pcscd.service; sudo LIBCCID_ifdLogLevel=0x000F pcscd --foreground --debug --apdu --color | tee log.txt

Created attachment 1839768 [details]
sudo LIBCCID_ifdLogLevel=0x000F pcscd --foreground --debug --apdu --color | tee log.txt

The moment when Firefox and other services requiring a smartcard stopped responding:

00000008 winscard_svc.c:818:MSGSignalClient() SIGNAL rv=0x0 for client 22
00000024 winscard_svc.c:815:MSGSignalClient() Signal client: 22
00000009 winscard_svc.c:818:MSGSignalClient() SIGNAL rv=0x0 for client 22
00000023 winscard_svc.c:815:MSGSignalClient() Signal client: 22
00000009 winscard_svc.c:818:MSGSignalClient() SIGNAL rv=0x0 for client 22
00446398 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 14
00000266 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 14
00000179 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 14
00000141 winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 14
00357317 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 17
00000180 winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 17

Issued opensc-tool --list-readers shortly afterwards (returned after firefox was killed):

99999999 winscard_msg_srv.c:255:ProcessEventsServer() Common channel packet arrival
00000174 winscard_msg_srv.c:267:ProcessEventsServer() ProcessCommonChannelRequest detects: 26
00000015 pcscdaemon.c:133:SVCServiceRunLoop() A new context thread creation is requested: 26
00176033 winscard_svc.c:340:ContextThread() Authorized PC/SC client
00000020 winscard_svc.c:344:ContextThread() Thread is started: dwClientID=26, threadContext @0x5600dd92c510
00000028 winscard_svc.c:362:ContextThread() Received command: CMD_VERSION from client 26
00000017 winscard_svc.c:374:ContextThread() Client is protocol version 4:3
00000008 winscard_svc.c:394:ContextThread() CMD_VERSION rv=0x0 for client 26
00000118 winscard_svc.c:362:ContextThread() Received command: ESTABLISH_CONTEXT from client 26
00000021 winscard.c:215:SCardEstablishContext() Establishing Context: 0x4301248
00000005 winscard_svc.c:458:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 26
00000122 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 26
00000138 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 26
00000116 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 26
00000115 winscard_svc.c:362:ContextThread() Received command: CONNECT from client 26
00013404 winscard_svc.c:496:ContextThread() Authorized client for 'Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00'
00000019 winscard.c:259:SCardConnect() Attempting Connect to Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00 using protocol: 3
00000007 readerfactory.c:821:RFReaderInfo() RefReader() count was: 1
00000006 winscard.c:352:SCardConnect() powerState: POWER_STATE_INUSE
00000005 winscard.c:431:SCardConnect() Active Protocol: T=0
00000009 winscard.c:456:SCardConnect() hCard Identity: 65c20e62
00000006 winscard.c:518:SCardConnect() UnrefReader() count was: 2
00000007 winscard_svc.c:510:ContextThread() CONNECT rv=0x0 for client 26
00000196 winscard_svc.c:362:ContextThread() Received command: CONTROL from client 26
00000034 readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000012 ifdhandler.c:1424:IFDHControl() ControlCode: 0x42000D48, usb:0a5c/5842:libudev:1:/dev/bus/usb/001/007 (lun: 0)
00000006 Control TxBuffer: 
00000010 Control RxBuffer: 12 04 42 33 00 12 
00000008 winscard.c:1359:SCardControl() UnrefReader() count was: 2
00000008 winscard_svc.c:732:ContextThread() CONTROL rv=0x0 for client 26
00000105 winscard_svc.c:362:ContextThread() Received command: CONTROL from client 26
00000024 readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000009 ifdhandler.c:1424:IFDHControl() ControlCode: 0x42330012, usb:0a5c/5842:libudev:1:/dev/bus/usb/001/007 (lun: 0)
00000005 Control TxBuffer: 
00000016 Control RxBuffer: 01 02 00 00 03 01 00 09 01 00 0B 02 5C 0A 0C 02 42 58 0A 04 00 00 01 00 
00000008 winscard.c:1359:SCardControl() UnrefReader() count was: 2
00000007 winscard_svc.c:732:ContextThread() CONTROL rv=0x0 for client 26
00000072 winscard_svc.c:362:ContextThread() Received command: CONTROL from client 26
00000023 readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000008 ifdhandler.c:1424:IFDHControl() ControlCode: 0x42330012, usb:0a5c/5842:libudev:1:/dev/bus/usb/001/007 (lun: 0)
00000005 Control TxBuffer: 
00000015 Control RxBuffer: 01 02 00 00 03 01 00 09 01 00 0B 02 5C 0A 0C 02 42 58 0A 04 00 00 01 00 
00000007 winscard.c:1359:SCardControl() UnrefReader() count was: 2
00000007 winscard_svc.c:732:ContextThread() CONTROL rv=0x0 for client 26
00000155 winscard_svc.c:362:ContextThread() Received command: GET_ATTRIB from client 26
00000026 readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000010 ifdhandler.c:381:IFDHGetCapabilities() tag: 0x10100, usb:0a5c/5842:libudev:1:/dev/bus/usb/001/007 (lun: 0)
00000009 winscard.c:1434:SCardGetAttrib() UnrefReader() count was: 2
00000007 winscard_svc.c:761:ContextThread() GET_ATTRIB rv=0x0 for client 26
00000130 winscard_svc.c:362:ContextThread() Received command: GET_ATTRIB from client 26
00000025 readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000008 ifdhandler.c:381:IFDHGetCapabilities() tag: 0x10102, usb:0a5c/5842:libudev:1:/dev/bus/usb/001/007 (lun: 0)
00000007 winscard.c:1434:SCardGetAttrib() UnrefReader() count was: 2
00000007 winscard_svc.c:761:ContextThread() GET_ATTRIB rv=0x0 for client 26
00000063 winscard_svc.c:362:ContextThread() Received command: DISCONNECT from client 26
00000022 readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000007 winscard.c:878:SCardDisconnect() Active Contexts: 8
00000007 winscard.c:879:SCardDisconnect() dwDisposition: 0
00000007 winscard.c:1040:SCardDisconnect() UnrefReader() count was: 2
00000007 winscard_svc.c:547:ContextThread() DISCONNECT rv=0x0 for client 26
00000118 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 26
00000089 winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 26

When firefox was terminated:

32646738 winscard_svc.c:354:ContextThread() Client die: 19
00002198 winscard_svc.c:354:ContextThread() Client die: 25
00025687 winscard_svc.c:354:ContextThread() Client die: 20
00050555 winscard_svc.c:354:ContextThread() Client die: 24
00001732 winscard_svc.c:354:ContextThread() Client die: 23
00028809 winscard_svc.c:354:ContextThread() Client die: 21
00013224 winscard_svc.c:354:ContextThread() Client die: 22

I am wondering why firefox uses so many threads/processes to check for smart card status. If I see right, you got 7 terminated "clients" by killing firefox.

That sounds like some race condition was hit inside of pcscd. Could you install debuginfo for pcsc-lite and pcsc-lite-ccid and attach the gdb to the pcscd to see where and why it hangs?

I too have been seeing firefox 91.3.0-1.el8_4 freeze in RHEL 8.4 x86-64, seems to be related to smartcard use in my case, for example, the freezes are co-located with these errors in `pcscd`
```

winscard_msg.c:429:MessageSend() select returns with failure: Bad file descriptor
```

Hopefully this is what you wanted. Attached back-trace when firefox became unresponsive.

$ sudo gdb
(gdb) attach 1079979
Attaching to process 1079979
[New LWP 1079983]
[New LWP 1079988]
[New LWP 1079989]
[New LWP 1079990]
[New LWP 1079991]
[New LWP 1079992]
[New LWP 1079993]
[New LWP 1128606]
[New LWP 1282732]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
bt0x00007f4d9394e3bf in select () from /lib64/libc.so.6
Missing separate debuginfos, use: yum debuginfo-install glibc-2.28-167.el8.x86_64 gmp-6.1.2-10.el8.x86_64 gnutls-3.6.16-4.el8.x86_64 libblkid-2.32.1-28.el8.x86_64 libcap-2.26-5.el8.x86_64 libffi-3.1-22.el8.x86_64 libgcc-8.5.0-3.el8.x86_64 libgcrypt-1.8.5-6.el8.x86_64 libgpg-error-1.31-1.el8.x86_64 libidn2-2.2.0-1.el8.x86_64 libmount-2.32.1-28.el8.x86_64 libselinux-2.9-5.el8.x86_64 libtasn1-4.13-3.el8.x86_64 libunistring-0.9.9-3.el8.x86_64 libusbx-1.0.23-4.el8.x86_64 libuuid-2.32.1-28.el8.x86_64 lz4-libs-1.8.3-3.el8_4.x86_64 p11-kit-0.23.22-1.el8.x86_64 pcre2-10.32-2.el8.x86_64 polkit-libs-0.115-12.el8.x86_64 systemd-libs-239-51.el8.x86_64 xz-libs-5.2.4-3.el8.x86_64 zlib-1.2.11-17.el8.x86_64
(gdb) c
Continuing.
[New Thread 0x7f4d7ffff700 (LWP 1561809)]
[New Thread 0x7f4d7f7fe700 (LWP 1561969)]
[New Thread 0x7f4d7dffb700 (LWP 1561970)]
[Thread 0x7f4d7dffb700 (LWP 1561970) exited]
[New Thread 0x7f4d7dffb700 (LWP 1562268)]
[New Thread 0x7f4d7e7fc700 (LWP 1562448)]
[New Thread 0x7f4d7d7fa700 (LWP 1563178)]
[New Thread 0x7f4d5bfff700 (LWP 1564854)]
[Thread 0x7f4d7d7fa700 (LWP 1563178) exited]
[New Thread 0x7f4d7d7fa700 (LWP 1565662)]
^C
Thread 1 "pcscd" received signal SIGINT, Interrupt.
0x00007f4d9394e3bf in select () from /lib64/libc.so.6
(gdb) bt
#0  0x00007f4d9394e3bf in select () from /lib64/libc.so.6
#1  0x00005596b3469db0 in ProcessEventsServer (pdwClientID=0x7ffe85992254) at winscard_msg_srv.c:227
#2  0x00005596b345b57d in SVCServiceRunLoop () at pcscdaemon.c:129
#3  main (argc=3, argv=<optimized out>) at pcscdaemon.c:777

$ OPENSC_DEBUG=9 firefox
[... snip ...]
P:1562426; T:0x139883607107456 17:40:01.045 [opensc-pkcs11] reader-pcsc.c:298:pcsc_transmit: 
Outgoing APDU (5 bytes):
00 20 00 00 00 . ...
P:1562426; T:0x139883607107456 17:40:01.045 [opensc-pkcs11] reader-pcsc.c:216:pcsc_internal_transmit: called
P:1562426; T:0x139883607107456 17:40:01.062 [opensc-pkcs11] reader-pcsc.c:307:pcsc_transmit: 
Incoming APDU (2 bytes):
90 00 ..
P:1562426; T:0x139883607107456 17:40:01.062 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:1562426; T:0x139883607107456 17:40:01.062 [opensc-pkcs11] apdu.c:535:sc_transmit: returning with: 0 (Success)
P:1562426; T:0x139883607107456 17:40:01.063 [opensc-pkcs11] card.c:523:sc_unlock: called
P:1562426; T:0x139883607107456 17:40:01.063 [opensc-pkcs11] sec.c:247:sc_pin_cmd: returning with: 0 (Success)
P:1562426; T:0x139883607107456 17:40:01.063 [opensc-pkcs11] card.c:523:sc_unlock: called
P:1562426; T:0x139883607107456 17:40:01.063 [opensc-pkcs11] reader-pcsc.c:709:pcsc_unlock: called
P:1562426; T:0x139883607107456 17:40:01.070 [opensc-pkcs11] pkcs15-pin.c:723:sc_pkcs15_get_pin_info: returning with: 0 (Success)
P:1562426; T:0x139883607107456 17:40:01.072 [opensc-pkcs11] pkcs11-session.c:238:C_GetSessionInfo: C_GetSessionInfo(0x7f3906457c10) = CKR_OK
P:1561595; T:0x139942152128256 17:40:02.861 [opensc-pkcs11] pkcs11-global.c:582:C_GetSlotInfo: C_GetSlotInfo(0x0)
P:1561595; T:0x139942152128256 17:40:02.862 [opensc-pkcs11] slot.c:393:card_detect_all: Detect all cards
P:1561595; T:0x139942152128256 17:40:02.862 [opensc-pkcs11] slot.c:219:card_detect: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: Detecting smart card
P:1561595; T:0x139942152128256 17:40:02.862 [opensc-pkcs11] sc.c:315:sc_detect_card_presence: called
P:1561595; T:0x139942152128256 17:40:02.863 [opensc-pkcs11] reader-pcsc.c:445:pcsc_detect_card_presence: called
P:1561595; T:0x139942152128256 17:40:02.863 [opensc-pkcs11] reader-pcsc.c:333:refresh_attributes: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00 check
Exiting due to channel error.
Exiting due to channel error.
Exiting due to channel error.
Exiting due to channel error.
Exiting due to channel error.
Exiting due to channel error.
Exiting due to channel error.
Killed

Installed the missing symbols -- needed to find an https source as http is filtered -- Here is the complete output until firefox became unresponsive. All I did was open up 6 different tabs for various things, and let them run in the background, then wait 10 to 20 minutes.

(gdb) attach 1079979
Attaching to process 1079979
[New LWP 1079983]
[New LWP 1079988]
[New LWP 1079989]
[New LWP 1079990]
[New LWP 1079991]
[New LWP 1079992]
[New LWP 1079993]
[New LWP 1128606]
[New LWP 1282732]
[New LWP 1908420]
[New LWP 1908547]
[New LWP 1908618]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
0x00007f4d9394e3bf in __GI___select (nfds=4, 
    readfds=readfds@entry=0x7ffe85992190, writefds=writefds@entry=0x0, 
    exceptfds=exceptfds@entry=0x0, timeout=timeout@entry=0x0)
    at ../sysdeps/unix/sysv/linux/select.c:41
41	  return SYSCALL_CANCEL (select, nfds, readfds, writefds, exceptfds,
(gdb) c
Continuing.
[New Thread 0x7f4d7ffff700 (LWP 1911547)]
[New Thread 0x7f4d7dffb700 (LWP 1911626)]
[New Thread 0x7f4d5bfff700 (LWP 1911729)]
[New Thread 0x7f4d5b7fe700 (LWP 1911811)]
^C
Thread 1 "pcscd" received signal SIGINT, Interrupt.
0x00007f4d9394e3bf in __GI___select (nfds=4, 
    readfds=readfds@entry=0x7ffe85992190, writefds=writefds@entry=0x0, 
    exceptfds=exceptfds@entry=0x0, timeout=timeout@entry=0x0)
    at ../sysdeps/unix/sysv/linux/select.c:41
41	  return SYSCALL_CANCEL (select, nfds, readfds, writefds, exceptfds,
(gdb) bt
#0  0x00007f4d9394e3bf in __GI___select (nfds=4, 
    readfds=readfds@entry=0x7ffe85992190, writefds=writefds@entry=0x0, 
    exceptfds=exceptfds@entry=0x0, timeout=timeout@entry=0x0)
    at ../sysdeps/unix/sysv/linux/select.c:41
#1  0x00005596b3469db0 in ProcessEventsServer (pdwClientID=0x7ffe85992254)
    at winscard_msg_srv.c:227
#2  0x00005596b345b57d in SVCServiceRunLoop () at pcscdaemon.c:129
#3  main (argc=3, argv=<optimized out>) at pcscdaemon.c:777

Upgraded to RHEL 8.5, Firefox 91.3.0esr is still freezing with the following errors in the logs of pcscd (SC in use):

winscard_msg.c:429:MessageSend() select returns with failure: Bad file descriptor
...
winscard_msg.c:429:MessageSend() select returns with failure: Bad file descriptor

Another data point, re-imaged to a fresh copy of x86-64 RHEL 8.5 and applied all updates as of 11/16.  I was unable to unlock my workstation after returning with firefox running in the background.  Fortunately, I was able to get some info while it was occurring.

pcscd showed the following warnings:  `readerfactory.c:1195:RFAddReaderHandle() Too many handles opened, exceeding configured max (200)`

So I did a `ps -ef | grep firefox | wc -l` and it showed ~120K.  I killed the firefox process and I was immediately able to login using MFA.  I launched the same websites in firefox and reran the command, which showed only about a dozen lines.

(In reply to Jakub Jelen from comment #9)

> The logs look like something is opening too many connections to the pcscd,
> which can not be handled by the internal select. Jan, could that be some
> change in firefox that it would open the smart card connection from more
> processes than before through NSS? I am not familiar how this works inside
> of firefox.

FWIW, I have rebuilt the pcsc-lite package with a patch [1] to replace select() with poll() in winscard_msg.c. Then I applied the same technique to winscard_msg_srv.c. No improvement when Firefox is open. It either lasts 10 minutes or 2 hours. Depends on how many tabs I have open and what's going on in the background. If I forget that Firefox is open and the screen locks, GDM could block until the firefox process is terminated (similar to comment #17). Depends if Firefox is frozen or not.

[1] https://salsa.debian.org/rousseau/PCSC/-/commit/20385efba2075d4c13acfea43d0abc8c38d8c106

Note: If I bypass smartcard login with a password, all kinds of weirdness happens. Even if I terminate firefox after unlocking, it will not gracefully recover. It behaves as-if it's still at the GDM login screen. Nothing works. Unable to click on anything. The top and bottom bars as gray in Gnome Classic (same GDM background, hard to tell?). The screen blanks out after 15 seconds of idle (in my case 45 as I've rebuild gnome-settings-daemon with an extended timeout specifically for smart cards [yes, it's that slow]).

Jan, do you have idea why firefox would be opening too many handles to query smart cards status or open too many NSS dbs? Was there some recent change in the threading? Or is it something that should be checked by NSS developers?

Backtraces from firefox when blocked might be also useful. Do you have some information when it worked last time? Does it work in fresh RHEL 8.4 or 83.? Does downgrade of Firefox, NSS or something else helps (we did not update pcsc-lite for some time)?

(In reply to Jakub Jelen from comment #19)
> Backtraces from firefox when blocked might be also useful. Do you have some
> information when it worked last time? Does it work in fresh RHEL 8.4 or 83.?
> Does downgrade of Firefox, NSS or something else helps (we did not update
> pcsc-lite for some time)?

Worked fine in firefox-78.14.0. Downgrading firefox resolves the issue.

Yes, it worked fine in RHEL/CentOS Linux 8.2, 8.3, 8.4, and CentOS Stream 8 prior to update.

(gdb) attach 175263
Attaching to process 175263
[New LWP 175269]
[New LWP 175270]
[New LWP 175285]
[New LWP 175531]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
0x00007f36ab318b61 in __GI___poll (fds=0x7f36aa7a1070, nfds=2, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
29	  return SYSCALL_CANCEL (poll, fds, nfds, timeout);
(gdb) bt
#0  0x00007f36ab318b61 in __GI___poll (fds=0x7f36aa7a1070, nfds=2, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007f369968d49c in PollWrapper (ufds=ufds@entry=0x7f36aa7a1070, nfsd=nfsd@entry=2, timeout_=timeout_@entry=-1) at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/widget/gtk/nsAppShell.cpp:58
#2  0x00007f36a6020c86 in g_main_context_poll (priority=<optimized out>, n_fds=2, fds=0x7f36aa7a1070, timeout=<optimized out>, context=0x7f36aa7c99d0) at gmain.c:4247
#3  g_main_context_iterate (context=context@entry=0x7f36aa7c99d0, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at gmain.c:3941
#4  0x00007f36a6020db0 in g_main_context_iteration (context=0x7f36aa7c99d0, context@entry=0x0, may_block=1) at gmain.c:4007
#5  0x00007f369968c700 in nsAppShell::ProcessNextNativeEvent (this=<optimized out>, mayWait=<optimized out>) at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/widget/gtk/nsAppShell.cpp:247
#6  0x00007f3699623f86 in nsBaseAppShell::DoProcessNextNativeEvent (this=this@entry=0x7f3694d31520, mayWait=<optimized out>) at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/widget/nsBaseAppShell.cpp:120
#7  0x00007f369962411e in nsBaseAppShell::OnProcessNextEvent (this=0x7f3694d31520, thr=0x7f36aa7152e0, mayWait=<optimized out>)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/widget/nsBaseAppShell.cpp:259
#8  0x00007f3696fff980 in nsThread::ProcessNextEvent (this=0x7f36aa7152e0, aMayWait=<optimized out>, aResult=0x7ffdb408e8f7)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/xpcom/threads/nsThread.cpp:1068
#9  0x00007f3696fed72c in NS_ProcessNextEvent (aThread=<optimized out>, aThread@entry=0x7f36aa7152e0, aMayWait=aMayWait@entry=true)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/xpcom/threads/nsThreadUtils.cpp:466
#10 0x00007f36975648c0 in mozilla::ipc::MessagePump::Run (this=0x7f36aa7bf4c0, aDelegate=0x7ffdb408eaa0) at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/ipc/glue/MessagePump.cpp:107
#11 0x00007f36975202f9 in MessageLoop::RunInternal (this=<optimized out>) at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/objdir/dist/include/mozilla/RefPtr.h:313
#12 MessageLoop::RunHandler (this=<optimized out>) at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/ipc/chromium/src/base/message_loop.cc:324
#13 MessageLoop::Run (this=<optimized out>) at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/ipc/chromium/src/base/message_loop.cc:306
#14 0x00007f369961ef8c in nsBaseAppShell::Run (this=0x7f3694d31520) at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/widget/nsBaseAppShell.cpp:137
#15 0x00007f369a7cf5bb in XRE_RunAppShell () at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/toolkit/xre/nsEmbedFunctions.cpp:923
#16 0x00007f36975202f9 in MessageLoop::RunInternal (this=0x7ffdb408eaa0) at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/objdir/dist/include/mozilla/RefPtr.h:313
#17 MessageLoop::RunHandler (this=0x7ffdb408eaa0) at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/ipc/chromium/src/base/message_loop.cc:324
#18 MessageLoop::Run (this=this@entry=0x7ffdb408eaa0) at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/ipc/chromium/src/base/message_loop.cc:306
#19 0x00007f369a7cfacf in XRE_InitChildProcess (aArgc=10, aArgv=0x7ffdb408ee28, aChildData=<optimized out>) at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/toolkit/xre/nsEmbedFunctions.cpp:755
#20 0x00005650ec08305a in content_process_main (bootstrap=0x7f36aa7266c0, argc=11, argv=argv@entry=0x7ffdb408ee28)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/browser/app/../../ipc/contentproc/plugin-container.cpp:57
#21 0x00005650ec08278a in main (argc=<optimized out>, argv=<optimized out>, envp=0x7ffdb408ee90) at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/objdir/dist/include/mozilla/UniquePtr.h:290

The above backtrace is not much helpful unfortunately. 
As part of the Firefox 91 esr rebase we rebased also nss/nspr, which calls the C_GetSessionInfo and C_GetSlotList.

@Jakub do you have any hints how to reproduce it without actual hardware?

@Bob: do you have any idea what could be wrong there? Any additional logging suggestions?

@Jonathan Sattelberger: Could you please try the upstream version of Firefox from https://www.mozilla.org/firefox/enterprise/ and check if it accepts the smartcards and working fine?

> Worked fine in firefox-78.14.0. Downgrading firefox resolves the issue.

When you downgraded firefox, did you also downgrade NSS? If not, the triggering issue is some change in firefox, but the real issue could still be a race in pcsc-lite, ccid, and/or NSS. But at least we could identify the proximate cause here.

I don't know of any NSS changes that would trigger more C_GetSessionInfo/C_GetSlotList calls. NSS actually has code the caches the responses from these for about 1 second, so if you are bombarded with PK11_IsSlotPresent calls (which NSS calls liberally), then the token only sees one per second or so.

Hmm I wonder if firefox is running in multiple processes per tab rather then multiple threads. Each process would have it's own cache state (actually it's own login state) for the smart cards.

jakub is correct about some of those readers (broadcom and Dell), but the SCM reader shouldn't have any issues.

(In reply to Bob Relyea from comment #22)
> When you downgraded firefox, did you also downgrade NSS? If not, the
> triggering issue is some change in firefox, but the real issue could still
> be a race in pcsc-lite, ccid, and/or NSS. But at least we could identify the
> proximate cause here.

No, NSS was not downgraded as part of the process. Last update to NSS was sometime back in August.

> 2021-08-11T18:29:15-0400 SUBDEBUG Upgrade: nss-util-3.67.0-6.el8_4.x86_64
> 2021-08-11T18:29:56-0400 SUBDEBUG Upgrade: nss-softokn-freebl-3.67.0-6.el8_4.x86_64
> 2021-08-11T18:29:56-0400 SUBDEBUG Upgrade: nss-softokn-3.67.0-6.el8_4.x86_64
> 2021-08-11T18:33:48-0400 SUBDEBUG Upgrade: nss-sysinit-3.67.0-6.el8_4.x86_64
> 2021-08-11T18:33:48-0400 SUBDEBUG Upgrade: nss-3.67.0-6.el8_4.x86_64
> 2021-08-11T18:33:48-0400 SUBDEBUG Upgrade: nss-tools-3.67.0-6.el8_4.x86_64

(In reply to Jan Horak from comment #21)
> @Jonathan Sattelberger: Could you please try the upstream version of Firefox
> from https://www.mozilla.org/firefox/enterprise/ and check if it accepts the
> smartcards and working fine?

Of course! Smart card support is not enabled by default, but fairly easy to add p11-kit-proxy to the temporary profile. The only noticeable difference is the immediate prompt for a PIN upon launch. The RPM package doesn't prompt until something requests it. Copied over the site-policies as well.

I've been using the Mozilla ESR release on and off for a few hours each day. It seems fine. Similar result with the default profile.

I can not reproduce this with Red Hat Enterprise Linux release 8.6 Beta (Ootpa):
firefox-91.3.0-1.el8.x86_64
pcsc-lite-1.8.23-4.1.el8_4.x86_64
p11-kit-0.23.22-1.el8.x86_64
polkit-0.115-12.el8.x86_64

I launch firefox with security device smartcard  ACS ACR 38U-CCID logged in.
Performed various tasks with Firefox instance for ~3 hours.

No crash nor freeze.

I have the same issue with Firefox 91.3.0-1.el8_4 in RHEL 8.5. It crashes frequently while using a Common Access Card (CAC).  If I don't introduce the CAC, the browser is stable.

(In reply to Jan Horak from comment #21)
> The above backtrace is not much helpful unfortunately. 

Didn't think so. Is this one more helpful? Taken from thread 7 (out of 117) of the parent process:

(gdb) thr 7
[Switching to thread 7 (Thread 0x7f891ebbd700 (LWP 219188))]
#0  0x00007f891da803bf in __GI___select (nfds=nfds@entry=111, readfds=readfds@entry=0x7f891ebbbcd0, writefds=writefds@entry=0x0, 
    exceptfds=exceptfds@entry=0x0, timeout=timeout@entry=0x0) at ../sysdeps/unix/sysv/linux/select.c:41
41	  return SYSCALL_CANCEL (select, nfds, readfds, writefds, exceptfds,
(gdb) bt
#0  0x00007f891da803bf in __GI___select (nfds=nfds@entry=111, readfds=readfds@entry=0x7f891ebbbcd0, writefds=writefds@entry=0x0, 
    exceptfds=exceptfds@entry=0x0, timeout=timeout@entry=0x0) at ../sysdeps/unix/sysv/linux/select.c:41
#1  0x00007f88ce181605 in MessageReceive (buffer_void=buffer_void@entry=0x7f891ebbbe18, buffer_size=buffer_size@entry=8, 
    filedes=filedes@entry=110) at winscard_msg.c:472
#2  0x00007f88ce17de27 in SCardGetStatusChange (hContext=<optimized out>, dwTimeout=<optimized out>, rgReaderStates=<optimized out>, 
    cReaders=<optimized out>) at winscard_clnt.c:2100
#3  0x00007f88ce8c5260 in refresh_attributes (reader=0x7f88d5be21f0) at reader-pcsc.c:346
#4  0x00007f88ce8c56cc in pcsc_detect_card_presence (reader=0x7f88d5be21f0) at reader-pcsc.c:447
#5  0x00007f88ce89085c in sc_detect_card_presence (reader=<optimized out>) at sc.c:319
#6  0x00007f88cec77cc0 in card_detect (reader=0x7f88d5be21f0) at slot.c:242
#7  0x00007f88cec7882d in card_detect_all () at slot.c:409
#8  0x00007f88cec71fed in C_GetSlotInfo (pInfo=0x7f891ebbc0e0, slotID=0) at pkcs11-global.c:590
#9  C_GetSlotInfo (slotID=0, pInfo=0x7f891ebbc0e0) at pkcs11-global.c:569
#10 0x00007f8913f5557c in proxy_C_GetSlotInfo (self=<optimized out>, id=<optimized out>, info=0x7f891ebbc0e0) at ../p11-kit/proxy.c:556
#11 0x00007f890813d00c in nssSlot_IsTokenPresent (slot=0x7f88db567030) at devslot.c:173
#12 nssSlot_IsTokenPresent (slot=0x7f88db567030) at devslot.c:121
#13 0x00007f890813f42d in nssToken_IsPresent (token=<optimized out>) at devtoken.c:1427
#14 0x00007f8908122a45 in pk11_IsPresentCertLoad (slot=0x7f88cfa06c00, loadCerts=1) at pk11slot.c:1602
#15 0x00007f89081232f1 in PK11_GetAllTokens (type=16426, needRW=needRW@entry=0, loadCerts=loadCerts@entry=1, wincx=wincx@entry=0x0)
    at pk11slot.c:2222
#16 0x00007f89081237ad in PK11_GetBestSlotMultipleWithAttributes (type=type@entry=0x7f891ebbc328, 
    mechanismInfoFlags=mechanismInfoFlags@entry=0x0, keySize=keySize@entry=0x0, mech_count=mech_count@entry=1, wincx=wincx@entry=0x0)
    at pk11slot.c:2344
#17 0x00007f8908123853 in PK11_GetBestSlot (type=<optimized out>, type@entry=16426, wincx=wincx@entry=0x0) at pk11slot.c:2429
#18 0x00007f8908663e10 in tls13_HkdfExtract (ikm1=ikm1@entry=0x0, ikm2=<optimized out>, ikm2@entry=0x0, baseHash=<optimized out>, 
    prkp=prkp@entry=0x7f88c5775898) at tls13hkdf.c:105
#19 0x00007f890865b617 in tls13_ComputeHandshakeSecret (ss=ss@entry=0x7f88c5775000) at tls13con.c:1198
#20 0x00007f890865ff47 in tls13_HandleServerHelloPart2 (ss=ss@entry=0x7f88c5775000, 
    savedMsg=savedMsg@entry=0x7f88c62d7004 "\003\003\320\345`\253\230\274%\005\240sz\230\251!\240\060F\340\067L킁7\361\225\256\253M8\257R 1Ct\374ݔ\301\326\312e\235\004}\323\315\350ò\262\232\275\027\265\006)\246+x\257r\"\213\023\002", savedLength=savedLength@entry=118)
    at tls13con.c:3114
#21 0x00007f890863e384 in ssl3_HandleServerHello (length=<optimized out>, b=<optimized out>, ss=0x7f88c5775000) at ssl3con.c:7131
#22 ssl3_HandleHandshakeMessage (ss=ss@entry=0x7f88c5775000, 
    b=b@entry=0x7f88c62d7004 "\003\003\320\345`\253\230\274%\005\240sz\230\251!\240\060F\340\067L킁7\361\225\256\253M8\257R 1Ct\374ݔ\301\326\312e\235\004}\323\315\350ò\262\232\275\027\265\006)\246+x\257r\"\213\023\002", length=118, endOfRecord=1) at ssl3con.c:12439
#23 0x00007f8908641c84 in ssl3_HandleHandshake (origBuf=0x7f88c57752c0, ss=0x7f88c5775000) at ssl3con.c:12617
#24 ssl3_HandleNonApplicationData (ss=ss@entry=0x7f88c5775000, rType=<optimized out>, epoch=<optimized out>, seqNum=<optimized out>, 
    databuf=databuf@entry=0x7f88c57752c0) at ssl3con.c:13142
#25 0x00007f8908642481 in ssl3_HandleRecord (ss=ss@entry=0x7f88c5775000, cText=cText@entry=0x7f891ebbc740) at ssl3con.c:13439
#26 0x00007f8908643880 in ssl3_GatherCompleteHandshake (flags=<optimized out>, ss=<optimized out>) at ssl3gthr.c:523
#27 ssl3_GatherCompleteHandshake (ss=ss@entry=0x7f88c5775000, flags=flags@entry=0) at ssl3gthr.c:411
#28 0x00007f890864b80d in SSL_ForceHandshake (fd=<optimized out>) at sslsecur.c:382
#29 0x00007f890cb7f9d4 in nsNSSSocketInfo::DriveHandshake (this=0x7f88c5f9ea00)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/security/manager/ssl/nsNSSIOLayer.cpp:320
#30 0x00007f89099ab1d8 in mozilla::net::nsHttpConnection::EnsureNPNComplete (this=this@entry=0x7f88c936d400, 
    aOut0RTTWriteHandshakeValue=@0x7f891ebbc8f0: nsresult::NS_OK, aOut0RTTBytesWritten=@0x7f891ebbc8f4: 0)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/objdir/dist/include/nsCOMPtr.h:869
#31 0x00007f89099abe49 in mozilla::net::nsHttpConnection::EnsureNPNComplete (aOut0RTTBytesWritten=@0x7f891ebbc8f4: 0, 
    aOut0RTTWriteHandshakeValue=@0x7f891ebbc8f0: nsresult::NS_OK, this=0x7f88c936d400)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/netwerk/protocol/http/nsHttpConnection.cpp:381
#32 mozilla::net::nsHttpConnection::OnSocketWritable (this=this@entry=0x7f88c936d400)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/netwerk/protocol/http/nsHttpConnection.cpp:1890
#33 0x00007f89099ac6f7 in mozilla::net::nsHttpConnection::OnOutputStreamReady (this=0x7f88c936d400, out=<optimized out>)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/netwerk/protocol/http/nsHttpConnection.cpp:2436
#34 0x00007f89096850fc in mozilla::net::nsSocketOutputStream::OnSocketReady (this=this@entry=0x7f88c936d2b0, 
    condition=condition@entry=nsresult::NS_OK) at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/netwerk/base/nsSocketTransport2.cpp:514
#35 0x00007f8909689f85 in mozilla::net::nsSocketTransport::OnSocketReady (this=0x7f88c936d000, fd=0x7f88c660f0a0, outFlags=<optimized out>)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/netwerk/base/nsSocketTransport2.cpp:2055
#36 0x00007f890968e291 in mozilla::net::nsSocketTransportService::DoPollIteration (this=this@entry=0x7f88f93d2190, 
    pollDuration=pollDuration@entry=0x7f891ebbca58)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/netwerk/base/nsSocketTransportService2.cpp:1353
#37 0x00007f890968e6b0 in mozilla::net::nsSocketTransportService::Run (this=0x7f88f93d2190)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/netwerk/base/nsSocketTransportService2.cpp:1127
#38 0x00007f8909587edf in nsThread::ProcessNextEvent (this=0x7f88f93d22e0, aMayWait=<optimized out>, aResult=0x7f891ebbcbb7)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/objdir/dist/include/nsCOMPtr.h:869
#39 0x00007f890957572c in NS_ProcessNextEvent (aThread=<optimized out>, aThread@entry=0x7f88f93d22e0, aMayWait=aMayWait@entry=false)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/xpcom/threads/nsThreadUtils.cpp:466
#40 0x00007f8909aeca4a in mozilla::ipc::MessagePumpForNonMainThreads::Run (this=0x7f88f939ad80, aDelegate=0x7f891ebbcc70)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/ipc/glue/MessagePump.cpp:300
--Type <RET> for more, q to quit, c to continue without paging--
#41 0x00007f8909aa82f9 in MessageLoop::RunInternal (this=0x7f891ebbcc70)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/objdir/dist/include/mozilla/RefPtr.h:313
#42 MessageLoop::RunHandler (this=0x7f891ebbcc70) at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/ipc/chromium/src/base/message_loop.cc:324
#43 MessageLoop::Run (this=this@entry=0x7f891ebbcc70)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/ipc/chromium/src/base/message_loop.cc:306
#44 0x00007f89095875b7 in nsThread::ThreadFunc (aArg=0x7f88f93d31c0)
    at /usr/src/debug/firefox-91.3.0-1.el8_4.x86_64/xpcom/threads/nsThread.cpp:392
#45 0x00007f891c6ba678 in _pt_root (arg=0x7f88f930a820) at ../../.././nspr/pr/src/pthreads/ptthread.c:201
#46 0x00007f891e88c17a in start_thread (arg=<optimized out>) at pthread_create.c:479
#47 0x00007f891da88ee3 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Hm, there's a significant more calls of the nssSlot_IsTokenPresent in the Firefox 91 compared to the Firefox 78 when loading the same page in the Socket Thread. Is the nssSlot_IsTokenPresent calls limited?

91:
     60 Thread 1 "GeckoMain" hit Breakpoint 3, 0x00007fffed5ae8d0 in nssSlot_IsTokenPresent () from /lib64/libnss3.so
     24 Thread 508 "SSL Cert #63" hit Breakpoint 3, 0x00007fffed5ae8d0 in nssSlot_IsTokenPresent () from /lib64/libnss3.so
     16 Thread 509 "SSL Cert #64" hit Breakpoint 3, 0x00007fffed5ae8d0 in nssSlot_IsTokenPresent () from /lib64/libnss3.so
    639 Thread 93 "Socket Thread" hit Breakpoint 3, 0x00007fffed5ae8d0 in nssSlot_IsTokenPresent () from /lib64/libnss3.so
      2 Thread 93 "Socket Thread" received signal SIGPIPE, Broken pipe.
    204 Thread 98 "Cache2 I/O" hit Breakpoint 3, 0x00007fffed5ae8d0 in nssSlot_IsTokenPresent () from /lib64/libnss3.so
78:
     26 Thread 1 "firefox" hit Breakpoint 2, nssSlot_IsTokenPresent (slot=0x7fffd614d830) at /home/jhorak/m/mozilla-esr78/security/nss/lib/dev/devslot.c:133
     26 Thread 1 "firefox" hit Breakpoint 2, nssSlot_IsTokenPresent (slot=0x7fffd614f030) at /home/jhorak/m/mozilla-esr78/security/nss/lib/dev/devslot.c:133
     26 Thread 1 "firefox" hit Breakpoint 2, nssSlot_IsTokenPresent (slot=0x7fffd6157030) at /home/jhorak/m/mozilla-esr78/security/nss/lib/dev/devslot.c:133
      1 Thread 1 "firefox" received signal SIGINT, Interrupt.
     35 Thread 337 "SSL Cert #80" hit Breakpoint 2, nssSlot_IsTokenPresent (slot=0x7fffd614d830) at /home/jhorak/m/mozilla-esr78/security/nss/lib/dev/devslot.c:133
     35 Thread 337 "SSL Cert #80" hit Breakpoint 2, nssSlot_IsTokenPresent (slot=0x7fffd614f030) at /home/jhorak/m/mozilla-esr78/security/nss/lib/dev/devslot.c:133
     35 Thread 337 "SSL Cert #80" hit Breakpoint 2, nssSlot_IsTokenPresent (slot=0x7fffd6157030) at /home/jhorak/m/mozilla-esr78/security/nss/lib/dev/devslot.c:133
     40 Thread 338 "SSL Cert #81" hit Breakpoint 2, nssSlot_IsTokenPresent (slot=0x7fffd614d830) at /home/jhorak/m/mozilla-esr78/security/nss/lib/dev/devslot.c:133
     40 Thread 338 "SSL Cert #81" hit Breakpoint 2, nssSlot_IsTokenPresent (slot=0x7fffd614f030) at /home/jhorak/m/mozilla-esr78/security/nss/lib/dev/devslot.c:133
     40 Thread 338 "SSL Cert #81" hit Breakpoint 2, nssSlot_IsTokenPresent (slot=0x7fffd6157030) at /home/jhorak/m/mozilla-esr78/security/nss/lib/dev/devslot.c:133
    137 Thread 50 "Socket Thread" hit Breakpoint 2, nssSlot_IsTokenPresent (slot=0x7fffd614d830) at /home/jhorak/m/mozilla-esr78/security/nss/lib/dev/devslot.c:133
    137 Thread 50 "Socket Thread" hit Breakpoint 2, nssSlot_IsTokenPresent (slot=0x7fffd614f030) at /home/jhorak/m/mozilla-esr78/security/nss/lib/dev/devslot.c:133
    137 Thread 50 "Socket Thread" hit Breakpoint 2, nssSlot_IsTokenPresent (slot=0x7fffd6157030) at /home/jhorak/m/mozilla-esr78/security/nss/lib/dev/devslot.c:133
     86 Thread 63 "Cache2 I/O" hit Breakpoint 2, nssSlot_IsTokenPresent (slot=0x7fffd614d830) at /home/jhorak/m/mozilla-esr78/security/nss/lib/dev/devslot.c:133
     86 Thread 63 "Cache2 I/O" hit Breakpoint 2, nssSlot_IsTokenPresent (slot=0x7fffd614f030) at /home/jhorak/m/mozilla-esr78/security/nss/lib/dev/devslot.c:133
     86 Thread 63 "Cache2 I/O" hit Breakpoint 2, nssSlot_IsTokenPresent (slot=0x7fffd6157030) at /home/jhorak/m/mozilla-esr78/security/nss/lib/dev/devslot.c:133

One of the threads here looks to me like the same bug, encountered in Fedora 32 with Chrome as the trigger:

http://lists.infradead.org/pipermail/pcsclite-muscle/2020-September/thread.html
https://sourceforge.net/p/opensc/mailman/opensc-devel/?viewmonth=202011

I can confirm that killing pcscd un-freezes Firefox here, too. Also, we aren't seeing this problem at all on RHEL 7.9 w/Firefox 91.2 and opensc-0.19, only on RHEL 8.

It was suggested but not confirmed on opensc-devel that opensc-0.21 may have relevant fixes for the Fedora user. RHEL 8.4/8.5 has opensc-0.20. Does RHEL 8.6 Beta have a newer opensc package?

(In reply to Ray Rocker from comment #28)
> One of the threads here looks to me like the same bug, encountered in Fedora
> 32 with Chrome as the trigger:
> 
> http://lists.infradead.org/pipermail/pcsclite-muscle/2020-September/thread.
> html
> https://sourceforge.net/p/opensc/mailman/opensc-devel/?viewmonth=202011
> 
> I can confirm that killing pcscd un-freezes Firefox here, too. Also, we
> aren't seeing this problem at all on RHEL 7.9 w/Firefox 91.2 and
> opensc-0.19, only on RHEL 8.
> 
> It was suggested but not confirmed on opensc-devel that opensc-0.21 may have
> relevant fixes for the Fedora user. RHEL 8.4/8.5 has opensc-0.20. Does RHEL
> 8.6 Beta have a newer opensc package?

Jakub, this sounds promising, could you check it please? I could not find the issue on the opensc tracker.

No, the current RHEL 8 beta does not have any newer OpenSC yet. But if you can reproduce the issue reliably, I can provide you a build of newer opensc to verify that this solves your issue. I updated the following copr repository with the new OpenSC 0.22.0:

https://copr.fedorainfracloud.org/coprs/jjelen/opensc-latest/

If this build will work for you, please, change this bug to opensc and we can discuss if/when/how this can be fixed. I can not confirm if we will be able to rebase or if I will try to cherry-pick the affecting patches.

Installed the opensc package from the COPR repository. No improvement from my side. Should I merge the pkcs15 changes from opensc.conf.rpmnew?

$ diff -ur /etc/opensc.conf /etc/opensc.conf.rpmnew 
--- /etc/opensc.conf	2020-07-22 15:45:46.235013918 -0400
+++ /etc/opensc.conf.rpmnew	2021-11-24 15:27:42.000000000 -0500
@@ -2,12 +2,18 @@
 	# debug = 3;
 	# debug_file = opensc-debug.txt;
 	framework pkcs15 {
-		# use_file_caching = true;
+		use_file_caching = true;
 	}
 	reader_driver pcsc {
 		# The pinpad is disabled by default,
 		# because of many broken readers out there
 		enable_pinpad = false;
 	}
-	card_drivers = cac, PIV-II;
+}
+# the pkcs15-init is used for card initialization when the file caching
+# brings more trouble than use so disable that:
+app pkcs15-init {
+	framework pkcs15 {
+		use_file_caching = false;
+	}
 }

When the firefox freeze, attach to the firefox process and in gdb run: 

set logging on
info threads
t a a bt (to get the backtrace of all threads)

and attach created gdb.txt as attachment to the report so we can know which thread stalls in MessageReceive or somewhere in the pcsc.

From the logs I see that we're receiving the 0x8010001D [1] error from the (The Smart card resource manager is not running) in the opensc log:

P:691641; T:0x139928011450240P:691530; T:0x140536263477120 09:32:46.291 09:32:46.291 [ [opensc-pkcs11opensc-pkcs11] ] reader-pcsc.c:375:refresh_attributes: reader-pcsc.c:449:pcsc_detect_card_presence: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00:SCardGetStatusChange failed: 0x8010001d

the subsequent messages says there's no readers found:

P:691641; T:0x139928011450240 09:32:55.048 [opensc-pkcs11] reader-pcsc.c:449:pcsc_detect_card_presence: returning with: -1101 (No readers found)
P:691641; T:0x139928011450240 09:32:55.050 [opensc-pkcs11] sc.c:320:sc_detect_card_presence: returning with: -1101 (No readers found)
P:691641; T:0x139928011450240 09:32:55.052 [opensc-pkcs11] slot.c:224:card_detect: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: failed, No readers found
P:691641; T:0x139928011450240 09:32:55.053 [opensc-pkcs11] misc.c:71:sc_to_cryptoki_error_common: libopensc return value: -1101 (No readers found)

(In reply to Jonathan Sattelberger from comment #31)
> Installed the opensc package from the COPR repository. No improvement from
> my side. Should I merge the pkcs15 changes from opensc.conf.rpmnew?

Thank you for checking. The changes to the opensc.conf should be unrelated to your problem. These are just new defaults.

Created attachment 1843594 [details]
gdb.txt

(In reply to Jan Horak from comment #32)
> When the firefox freeze, attach to the firefox process and in gdb run: 
> 
> set logging on
> info threads
> t a a bt (to get the backtrace of all threads)
> 
> and attach created gdb.txt as attachment to the report so we can know which
> thread stalls in MessageReceive or somewhere in the pcsc.

Attached in comment #34.

> From the logs I see that we're receiving the 0x8010001D [1] error from the
> (The Smart card resource manager is not running) in the opensc log:
> 
> P:691641; T:0x139928011450240P:691530; T:0x140536263477120 09:32:46.291
> 09:32:46.291 [ [opensc-pkcs11opensc-pkcs11] ]
> reader-pcsc.c:375:refresh_attributes:
> reader-pcsc.c:449:pcsc_detect_card_presence: Broadcom Corp 58200 [Contacted
> SmartCard] (0123456789ABCD) 00 00:SCardGetStatusChange failed: 0x8010001d
> 
> the subsequent messages says there's no readers found:
> 
> P:691641; T:0x139928011450240 09:32:55.048 [opensc-pkcs11]
> reader-pcsc.c:449:pcsc_detect_card_presence: returning with: -1101 (No
> readers found)
> P:691641; T:0x139928011450240 09:32:55.050 [opensc-pkcs11]
> sc.c:320:sc_detect_card_presence: returning with: -1101 (No readers found)
> P:691641; T:0x139928011450240 09:32:55.052 [opensc-pkcs11]
> slot.c:224:card_detect: Broadcom Corp 58200 [Contacted SmartCard]
> (0123456789ABCD) 00 00: failed, No readers found
> P:691641; T:0x139928011450240 09:32:55.053 [opensc-pkcs11]
> misc.c:71:sc_to_cryptoki_error_common: libopensc return value: -1101 (No
> readers found)

It's fairly easy to spot, as the output from OPENSC_DEBUG turns white for large chunks. I only notice this in the RPM package. The Mozilla release did not exhibit this behavior with p11-kit-proxy added to the profile.

Created attachment 1843596 [details]
Screenshot of OPENSC_DEBUG=9 firefox

(In reply to Jonathan Sattelberger from comment #36)
> Created attachment 1843596 [details]
> Screenshot of OPENSC_DEBUG=9 firefox

You can notice that the white output is from completely different processes (the P: denotes PID) than the colorful one. I assume both of them are the processes of firefox. OpenSC detects if the stdout fd is a tty to use or not use colors.

So it might bring some light into the issue what is the difference between these two processes.

Confirmed. Processes belong to firefox.

P:49964; T:0x140312565208960 10:13:10.728 [opensc-pkcs11] slot.c:226:card_detect: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: card absent
P:49964; T:0x140312565208960 10:13:10.728 [opensc-pkcs11] slot.c:189:card_removed: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: card removed

j.satte+   49492   47789 18 09:43 pts/0    00:02:25 /usr/lib64/firefox/firefox -ProfileManager -no-remote
j.satte+   49709   49492  0 09:43 pts/0    00:00:00 /usr/lib64/firefox/firefox -contentproc -parentBuildID 20211105152524 -prefsLen 1 -prefMapSize 242624 -appdir /usr/lib64/firefox/browser 49492 socket
j.satte+   49813   49492  3 09:43 pts/0    00:00:29 /usr/lib64/firefox/firefox -contentproc -childID 2 -isForBrowser -prefsLen 320 -prefMapSize 242624 -jsInit 285716 -parentBuildID 20211105152524 -appdir /usr/lib64/firefox/browser 49492 tab
j.satte+   49844   49492  5 09:43 pts/0    00:00:43 /usr/lib64/firefox/firefox -contentproc -childID 3 -isForBrowser -prefsLen 320 -prefMapSize 242624 -jsInit 285716 -parentBuildID 20211105152524 -appdir /usr/lib64/firefox/browser 49492 tab
j.satte+   49853   49492  0 09:43 pts/0    00:00:03 /usr/lib64/firefox/firefox -contentproc -childID 4 -isForBrowser -prefsLen 320 -prefMapSize 242624 -jsInit 285716 -parentBuildID 20211105152524 -appdir /usr/lib64/firefox/browser 49492 tab
j.satte+   49897   49492  0 09:43 pts/0    00:00:01 /usr/lib64/firefox/firefox -contentproc -childID 5 -isForBrowser -prefsLen 5488 -prefMapSize 242624 -jsInit 285716 -parentBuildID 20211105152524 -appdir /usr/lib64/firefox/browser 49492 tab
j.satte+   49964   49492  5 09:43 pts/0    00:00:41 /usr/lib64/firefox/firefox -contentproc -childID 6 -isForBrowser -prefsLen 6227 -prefMapSize 242624 -jsInit 285716 -parentBuildID 20211105152524 -appdir /usr/lib64/firefox/browser 49492 tab
j.satte+   50137   49492 15 09:44 pts/0    00:01:51 /usr/lib64/firefox/firefox -contentproc -childID 7 -isForBrowser -prefsLen 6470 -prefMapSize 242624 -jsInit 285716 -parentBuildID 20211105152524 -appdir /usr/lib64/firefox/browser 49492 tab
j.satte+   50162   49492  0 09:44 pts/0    00:00:00 /usr/lib64/firefox/firefox -contentproc -parentBuildID 20211105152524 -prefsLen 6470 -prefMapSize 242624 -appdir /usr/lib64/firefox/browser 49492 rdd
j.satte+   50210   49492  0 09:44 pts/0    00:00:00 /usr/lib64/firefox/firefox -contentproc -childID 8 -isForBrowser -prefsLen 6470 -prefMapSize 242624 -jsInit 285716 -parentBuildID 20211105152524 -appdir /usr/lib64/firefox/browser 49492 tab

> Thread 7 (Thread 0x7f18f8c0c700 (LWP 1476754)):
> #0  0x00007f18f7acf3bf in __GI___select (nfds=nfds@entry=104, readfds=readfds@entry=0x7f18f8c0acd0, writefds=writefds@entry=0x0, exceptfds=exceptfds@entry=0x0, timeout=timeout@entry=0x0) at ../sysdeps/unix/sysv/linux/select.c:41
> #1  0x00007f18a7c99605 in MessageReceive (buffer_void=buffer_void@entry=0x7f18f8c0ae18, buffer_size=buffer_size@entry=8, filedes=filedes@entry=103) at winscard_msg.c:472
I'm not sure why the MessageReceive expects the server will send a response when MessageReceiveTimeout ends with timeout (ie. SCARD_E_TIMEOUT == rv):
https://github.com/LudovicRousseau/PCSC/blob/1.8.23/src/winscard_clnt.c#L2080


> #2  0x00007f18a7c95e27 in SCardGetStatusChange (hContext=<optimized out>, dwTimeout=<optimized out>, rgReaderStates=<optimized out>, cReaders=<optimized out>) at winscard_clnt.c:2100
> #3  0x00007f18a83debc6 in refresh_attributes (reader=0x7f18ab3747e0) at reader-pcsc.c:373
> #4  0x00007f18a83df01c in pcsc_detect_card_presence (reader=0x7f18ab3747e0) at reader-pcsc.c:474
> #5  0x00007f18a83a91cc in sc_detect_card_presence (reader=<optimized out>) at sc.c:339
> #6  0x00007f18a879a82f in card_detect (reader=reader@entry=0x7f18ab3747e0) at slot.c:240
> #7  0x00007f18a879b2f8 in card_detect_all () at slot.c:427
> #8  0x00007f18a8794625 in C_GetSlotInfo (slotID=0, pInfo=0x7f18f8c0b0e0) at pkcs11-global.c:611
> ...
Since I'm running out of ideas, maybe the strace output of the pcscd could help:
sudo LIBCCID_ifdLogLevel=0x000F strace -y pcscd --foreground --debug --apdu --color | tee log.txt

Created attachment 1844338 [details]
sudo LIBCCID_ifdLogLevel=0x000F strace -y pcscd --foreground --debug --apdu --color | tee log.txt

Ran until Firefox stopped responding (snippet from OPENSC_DEBUG=9 firefox ...).

P:331001; T:0x140644760266624 08:51:27.712 [opensc-pkcs11] slot.c:217:card_detect: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: Detecting smart card
P:331001; T:0x140644760266624 08:51:27.713 [opensc-pkcs11] sc.c:335:sc_detect_card_presence: called
P:331001; T:0x140644760266624 08:51:27.713 [opensc-pkcs11] reader-pcsc.c:472:pcsc_detect_card_presence: called
P:331001; T:0x140644760266624 08:51:27.713 [opensc-pkcs11] reader-pcsc.c:360:refresh_attributes: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00 check
P:331001; T:0x140644760266624 08:51:27.714 [opensc-pkcs11] reader-pcsc.c:398:refresh_attributes: returning with: 0 (Success)
P:331001; T:0x140644760266624 08:51:27.715 [opensc-pkcs11] reader-pcsc.c:477:pcsc_detect_card_presence: returning with: 0 (Success)
P:331001; T:0x140644760266624 08:51:27.715 [opensc-pkcs11] sc.c:340:sc_detect_card_presence: returning with: 0 (Success)
P:331001; T:0x140644760266624 08:51:27.715 [opensc-pkcs11] slot.c:226:card_detect: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: card absent
P:331001; T:0x140644760266624 08:51:27.716 [opensc-pkcs11] slot.c:189:card_removed: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: card removed
P:331001; T:0x140644760266624 08:51:27.716 [opensc-pkcs11] slot.c:499:slot_token_removed: slot_token_removed(0x0)
P:331001; T:0x140644760266624 08:51:27.716 [opensc-pkcs11] pkcs11-session.c:143:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x0) 0
P:331001; T:0x140644760266624 08:51:27.716 [opensc-pkcs11] slot.c:499:slot_token_removed: slot_token_removed(0x1)
P:331001; T:0x140644760266624 08:51:27.717 [opensc-pkcs11] pkcs11-session.c:143:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x1) 0
P:331001; T:0x140644760266624 08:51:27.717 [opensc-pkcs11] slot.c:499:slot_token_removed: slot_token_removed(0x2)
P:331001; T:0x140644760266624 08:51:27.718 [opensc-pkcs11] pkcs11-session.c:143:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x2) 0
P:331001; T:0x140644760266624 08:51:27.718 [opensc-pkcs11] slot.c:499:slot_token_removed: slot_token_removed(0x3)
P:331001; T:0x140644760266624 08:51:27.718 [opensc-pkcs11] pkcs11-session.c:143:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x3) 0
P:331001; T:0x140644760266624 08:51:27.719 [opensc-pkcs11] pkcs11-global.c:625:C_GetSlotInfo: C_GetSlotInfo() card detect rv 0xE0
P:331001; T:0x140644760266624 08:51:27.719 [opensc-pkcs11] pkcs11-global.c:642:C_GetSlotInfo: C_GetSlotInfo() flags 0x6
P:331001; T:0x140644760266624 08:51:27.719 [opensc-pkcs11] pkcs11-global.c:643:C_GetSlotInfo: C_GetSlotInfo(0x0) = CKR_OK
P:330552; T:0x139719363647232 08:51:31.014 [opensc-pkcs11] pkcs11-global.c:490:C_GetSlotList: C_GetSlotList(token=0, plug-n-play)
P:330552; T:0x139719363647232 08:51:31.014 [opensc-pkcs11] pkcs11-global.c:491:C_GetSlotList: VSS C_GetSlotList before ctx_detect_detect
P:330552; T:0x139719363647232 08:51:31.014 [opensc-pkcs11] reader-pcsc.c:1386:pcsc_detect_readers: called
P:330552; T:0x139719363647232 08:51:31.014 [opensc-pkcs11] reader-pcsc.c:1399:pcsc_detect_readers: Probing PC/SC readers
P:330552; T:0x139719363647232 08:51:31.015 [opensc-pkcs11] reader-pcsc.c:1568:pcsc_detect_readers: returning with: 0 (Success)
P:330552; T:0x139719363647232 08:51:31.015 [opensc-pkcs11] pkcs11-global.c:497:C_GetSlotList: VSS C_GetSlotList after ctx_detect_readers
P:330552; T:0x139719363647232 08:51:31.015 [opensc-pkcs11] slot.c:391:card_detect_all: Detect all cards
P:330552; T:0x139719363647232 08:51:31.016 [opensc-pkcs11] slot.c:217:card_detect: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: Detecting smart card
P:330552; T:0x139719363647232 08:51:31.016 [opensc-pkcs11] sc.c:335:sc_detect_card_presence: called
P:330552; T:0x139719363647232 08:51:31.016 [opensc-pkcs11] reader-pcsc.c:472:pcsc_detect_card_presence: called
P:330552; T:0x139719363647232 08:51:31.016 [opensc-pkcs11] reader-pcsc.c:360:refresh_attributes: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00 check

Created attachment 1844353 [details]
sudo LIBCCID_ifdLogLevel=0x000F strace -o strace.txt ...

Realized there was no valuable information in the last set of logs. Attaching strace output.

My mistake, the strace goes to the stderr, so you need to run:
sudo LIBCCID_ifdLogLevel=0x000F strace -y -s500 pcscd --foreground --debug --apdu &>out.log
Sorry for the confusion.

Created attachment 1844359 [details]
sudo LIBCCID_ifdLogLevel=0x000F strace -y -s500 pcscd --foreground --debug --apdu &>out.log

Around the time Firefox stopped responding:

$ OPENSC_DEBUG=9 firefox -ProfileManager -no-remote

P:398260; T:0x140158365259648 10:12:16.857 [opensc-pkcs11] sc.c:335:sc_detect_card_presence: called
P:398260; T:0x140158365259648 10:12:16.857 [opensc-pkcs11] reader-pcsc.c:472:pcsc_detect_card_presence: called
P:398260; T:0x140158365259648 10:12:16.858 [opensc-pkcs11] reader-pcsc.c:360:refresh_attributes: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00 check
P:398260; T:0x140158365259648 10:12:16.858 [opensc-pkcs11] reader-pcsc.c:398:refresh_attributes: returning with: 0 (Success)
P:398260; T:0x140158365259648 10:12:16.858 [opensc-pkcs11] reader-pcsc.c:477:pcsc_detect_card_presence: returning with: 0 (Success)
P:398260; T:0x140158365259648 10:12:16.859 [opensc-pkcs11] sc.c:340:sc_detect_card_presence: returning with: 0 (Success)
P:398260; T:0x140158365259648 10:12:16.859 [opensc-pkcs11] slot.c:226:card_detect: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: card absent
P:398260; T:0x140158365259648 10:12:16.859 [opensc-pkcs11] slot.c:189:card_removed: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: card removed
P:398260; T:0x140158365259648 10:12:16.860 [opensc-pkcs11] slot.c:499:slot_token_removed: slot_token_removed(0x0)
P:398260; T:0x140158365259648 10:12:16.860 [opensc-pkcs11] pkcs11-session.c:143:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x0) 0
P:398260; T:0x140158365259648 10:12:16.860 [opensc-pkcs11] slot.c:499:slot_token_removed: slot_token_removed(0x1)
P:398260; T:0x140158365259648 10:12:16.861 [opensc-pkcs11] pkcs11-session.c:143:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x1) 0
P:398260; T:0x140158365259648 10:12:16.861 [opensc-pkcs11] slot.c:499:slot_token_removed: slot_token_removed(0x2)
P:398260; T:0x140158365259648 10:12:16.861 [opensc-pkcs11] pkcs11-session.c:143:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x2) 0
P:398260; T:0x140158365259648 10:12:16.862 [opensc-pkcs11] slot.c:499:slot_token_removed: slot_token_removed(0x3)
P:398260; T:0x140158365259648 10:12:16.862 [opensc-pkcs11] pkcs11-session.c:143:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x3) 0
P:398260; T:0x140158365259648 10:12:16.862 [opensc-pkcs11] pkcs11-global.c:625:C_GetSlotInfo: C_GetSlotInfo() card detect rv 0xE0
P:398260; T:0x140158365259648 10:12:16.863 [opensc-pkcs11] pkcs11-global.c:642:C_GetSlotInfo: C_GetSlotInfo() flags 0x6
P:398260; T:0x140158365259648 10:12:16.863 [opensc-pkcs11] pkcs11-global.c:643:C_GetSlotInfo: C_GetSlotInfo(0x0) = CKR_OK
P:398260; T:0x140158365259648 10:12:16.864 [opensc-pkcs11] pkcs11-session.c:161:C_CloseSession: C_CloseSession(0x7f78ff257c80)
P:398260; T:0x140158365259648 10:12:16.864 [opensc-pkcs11] pkcs11-session.c:109:sc_pkcs11_close_session: real C_CloseSession(0x7f78ff257c80)
P:397513; T:0x140652169590528 10:12:17.543 [opensc-pkcs11] pkcs11-global.c:603:C_GetSlotInfo: C_GetSlotInfo(0x0)
P:397513; T:0x140652169590528 10:12:17.543 [opensc-pkcs11] slot.c:391:card_detect_all: Detect all cards
P:397513; T:0x140652169590528 10:12:17.543 [opensc-pkcs11] slot.c:217:card_detect: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: Detecting smart card
P:397513; T:0x140652169590528 10:12:17.543 [opensc-pkcs11] sc.c:335:sc_detect_card_presence: called
P:397513; T:0x140652169590528 10:12:17.543 [opensc-pkcs11] reader-pcsc.c:472:pcsc_detect_card_presence: called
P:397513; T:0x140652169590528 10:12:17.543 [opensc-pkcs11] reader-pcsc.c:360:refresh_attributes: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00 check

$ sudo LIBCCID_ifdLogLevel=0x000F strace -y -s500 pcscd --foreground --debug --apdu &>out.log

00000010 ifdhandler.c:1424:IFDHControl() ControlCode: 0x42330012, usb:0a5c/5842:libudev:1:/dev/bus/usb/001/003 (lun: 0)
00000009 Control TxBuffer: 
00000014 Control RxBuffer: 01 02 00 00 03 01 00 09 01 00 0B 02 5C 0A 0C 02 42 58 0A 04 00 00 01 00 
00000014 winscard.c:1359:SCardControl() UnrefReader() count was: 2
00000012 winscard_svc.c:732:ContextThread() CONTROL rv=0x0 for client 27
00000073 winscard_svc.c:362:ContextThread() Received command: GET_ATTRIB from client 27
00000017 readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000009 ifdhandler.c:381:IFDHGetCapabilities() tag: 0x10100, usb:0a5c/5842:libudev:1:/dev/bus/usb/001/003 (lun: 0)
00000009 winscard.c:1434:SCardGetAttrib() UnrefReader() count was: 2
00000007 winscard_svc.c:761:ContextThread() GET_ATTRIB rv=0x0 for client 27
00000057 winscard_svc.c:362:ContextThread() Received command: GET_ATTRIB from client 27
00000020 readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000008 ifdhandler.c:381:IFDHGetCapabilities() tag: 0x10102, usb:0a5c/5842:libudev:1:/dev/bus/usb/001/003 (lun: 0)
00000014 winscard.c:1434:SCardGetAttrib() UnrefReader() count was: 2
00000007 winscard_svc.c:761:ContextThread() GET_ATTRIB rv=0x0 for client 27
00000076 winscard_svc.c:362:ContextThread() Received command: DISCONNECT from client 27
00000020 readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000012 winscard.c:878:SCardDisconnect() Active Contexts: 8
00000010 winscard.c:879:SCardDisconnect() dwDisposition: 0
00000010 winscard.c:1040:SCardDisconnect() UnrefReader() count was: 2
00000008 winscard_svc.c:547:ContextThread() DISCONNECT rv=0x0 for client 27
00000073 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 27
00000062 winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 27

Sorry, the client seems to be forked so strace only works for the main thread. Could you please rerun the strace with to follow client threads:
sudo LIBCCID_ifdLogLevel=0x000F strace -y -f -s500 pcscd --foreground --debug --apdu &>out.log

and also as the Firefox freeze, do the output of pcsc also freeze? If so, please paste also end of the log to the report. It seems that you already did that for previous report. It should be more helpful with the strace output.

Created attachment 1844403 [details]
sudo LIBCCID_ifdLogLevel=0x000F strace -y -f -s500 pcscd --foreground --debug --apdu &>out.log

(In reply to Jan Horak from comment #44)
> Sorry, the client seems to be forked so strace only works for the main
> thread. Could you please rerun the strace with to follow client threads:
> sudo LIBCCID_ifdLogLevel=0x000F strace -y -f -s500 pcscd --foreground
> --debug --apdu &>out.log
> 
> and also as the Firefox freeze, do the output of pcsc also freeze? If so,
> please paste also end of the log to the report. It seems that you already
> did that for previous report. It should be more helpful with the strace
> output.

No need to be sorry.

No, pcsc output does not freeze. It'll log attempts to use the smart card, but it will not complete the requests until Firefox is closed. I encounter a similar situation using freerdp with smartcard redirection. I've never got that to successfully function under RHEL. That'll be another issue altogether.

Here is the moment Firefox froze from the perspective of pcscd:

[pid 424902] select(18, NULL, [17<socket:[3642431]>], NULL, NULL) = 1 (out [17])
[pid 424902] sendto(17<socket:[3642431]>, "Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0004\0\0\0\6\0\0\0;\371\30\0\0\0SCE7 \3\0 F\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\17\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8832, MSG_NOSIGNAL, NULL, 0) = 8832
[pid 424902] select(18, [17<socket:[3642431]>], NULL, NULL, NULL) = 1 (in [17])
[pid 424902] read(17<socket:[3642431]>, "\10\0\0\0\23\0\0\0", 8) = 8
[pid 424902] write(1</home/j.sattelberger/out.log>, "00000576 winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 17\n", 10600000576 winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 17
) = 106
[pid 424902] select(18, [17<socket:[3642431]>], NULL, NULL, NULL) = 1 (in [17])
[pid 424902] read(17<socket:[3642431]>, "\0\0\0\0\0\0\0\0", 8) = 8
[pid 424902] futex(0x55b0a5c943c0, FUTEX_WAIT_PRIVATE, 2, NULL

Followed by opensc-tool --list-readers ...

 <unfinished ...>
[pid 424288] <... select resumed>)      = 1 (in [5])
[pid 424288] write(1</home/j.sattelberger/out.log>, "88286351 winscard_msg_srv.c:255:ProcessEventsServer() Common channel packet arrival\n", 8488286351 winscard_msg_srv.c:255:ProcessEventsServer() Common channel packet arrival
) = 84
... snip ...

The output was over 31 mb, so I compressed it. Hopefully that's okay.

It seems to me that the problem lies in the pcsc-lite, where the daemon for some reason does not reply to the client after sending CMD_STOP_WAITING_READER_STATE_CHANGE request (maybe because "Too many handles opened, exceeding configured max (200)"?). It could be useful to get backtrace of the pcscd process when firefox stuck by:

gdb /usr/sbin/pcscd `pidof pcscd`
set logging on
info threads
t a a bt
and attach created gdb.txt

(you need to have the symbols for the pcscd installed, but you probably already have that).

Each child thread should correspond to connected client. After killing firefox you can observe how many threads has been finished by info threads (before and after killing ff). 

At least we could check how many connection does the Firefox open.

Hello,
I am not able to find a trace of the message "Too many handles opened, exceeding configured max (200)" in pcscd logs.
I think we should first try to fix this problem.

You get this message when the application (I guess OpenSC in our case but maybe you have another PKCS#11 library installed) calls too many SCardConnect() without calling SCardDisconnect(). This is not a normal behaviour for a PC/SC application.

It would help if I can get a pcsc-lite trace as described in https://ludovicrousseau.blogspot.com/2011/11/pcsc-api-spy-third-try.html

Created attachment 1844633 [details]
gdb.txt

(In reply to Jan Horak from comment #46)
> It seems to me that the problem lies in the pcsc-lite, where the daemon for
> some reason does not reply to the client after sending
> CMD_STOP_WAITING_READER_STATE_CHANGE request (maybe because "Too many
> handles opened, exceeding configured max (200)"?). It could be useful to get
> backtrace of the pcscd process when firefox stuck by:
> 
> gdb /usr/sbin/pcscd `pidof pcscd`
> set logging on
> info threads
> t a a bt
> and attach created gdb.txt
> 
> (you need to have the symbols for the pcscd installed, but you probably
> already have that).
> 
> Each child thread should correspond to connected client. After killing
> firefox you can observe how many threads has been finished by info threads
> (before and after killing ff). 
> 
> At least we could check how many connection does the Firefox open.

Attached gdb.txt.

Created attachment 1844723 [details]
gdb.txt - Too many context running

Dec 03 20:52:41 llt-4359731-d.ad.gfdl.noaa.gov systemd[1]: Started PC/SC Smart Card Daemon.
Dec 03 20:52:41 llt-4359731-d.ad.gfdl.noaa.gov pcscd[3706]: 00000000 ifdhandler.c:150:CreateChannelByNameOrChannel() failed
Dec 03 20:52:41 llt-4359731-d.ad.gfdl.noaa.gov pcscd[3706]: 00000068 readerfactory.c:1106:RFInitializeReader() Open Port 0x200000 Failed (usb:0a5c/5842:libudev:0:/dev/bus/usb/001/005)
Dec 03 20:52:41 llt-4359731-d.ad.gfdl.noaa.gov pcscd[3706]: 00000004 readerfactory.c:376:RFAddReader() Broadcom Corp 58200 [Broadcom ControlVault 3] (0123456789ABCD) init failed.
Dec 04 11:29:18 llt-4359731-d.ad.gfdl.noaa.gov pcscd[3706]: 99999999 winscard_svc.c:184:CreateContextThread() Too many context running: 200
Dec 04 11:29:18 llt-4359731-d.ad.gfdl.noaa.gov pcscd[3706]: 00000299 pcscdaemon.c:137:SVCServiceRunLoop() Problem during the context thread creation
Dec 04 11:29:20 llt-4359731-d.ad.gfdl.noaa.gov pcscd[3706]: 02130441 winscard_svc.c:184:CreateContextThread() Too many context running: 200
Dec 04 11:29:20 llt-4359731-d.ad.gfdl.noaa.gov pcscd[3706]: 00000165 pcscdaemon.c:137:SVCServiceRunLoop() Problem during the context thread creation

Attached gdb.txt when too many contexts are running.

Steps to reproduce:

1. Open firefox and authenticate with smart card
2. Wait until firefox freezes
3. Lock screen
4. With smart card in slot, wake the GDM screen. The prompt will gray, but never return
5. Repeat step 4 about 30 to 40 times. Each attempt spawns 2 or more threads at a time
6. Kill firefox and wait for threads to drain
7. PIN prompt will appear to unlock the screen

Note: I was unable to login when switching users. The PIN prompt appears, but it's unable to unlock the screen. PAM indicates a system error (#4). Not sure if this is a new issue with SSSD. Worked fine in the past.

/var/log/sssd/sssd_pam.log:(2021-12-04 11:52:53): [pam] [pam_reply] (0x4000): pam_reply initially called with result [4]: System error. this result might be changed during processing
/var/log/sssd/sssd_pam.log:(2021-12-04 11:52:53): [pam] [pam_reply] (0x0200): Returning [4]: System error to the client [CID #22]

Do you have the "Too many context running: 200" error at step 2? i.e. when Firefox is frozen?

(In reply to Ludovic Rousseau from comment #50)
> Do you have the "Too many context running: 200" error at step 2? i.e. when
> Firefox is frozen?

No, not at step 2. There are only a handful of pcscd threads when the issue appears. See comment 48 for an example. Once firefox is frozen, all future attempts to communicate with the card is impossible. The log messages will likely occur once more smart card capable applications are waiting for a response of some sort. The trigger in this case was the GDM login screen. Killing firefox allowed GDM (and other applications) to resume normally.

This does not appear to happen with the same ESR release from Mozilla (while including p11-kit in the profile).

Ignore the PAM/SSSD comment -- The issue is limited to our AD domain.

You are using pcsc-lite 1.8.23. I fixed some bugs (including race condition) in later versions.
Do you still reproduce the problem with a recent version of pcsc-lite?

Firefox seems fairly stable after rebuilding and installing pcsc-lite-1.8.26 (fc32). Also rebuilt pcsc-lite-1.9.1 (fc34) and pcsc-lite-1.9.4 (fc35); both seem fine. Doesn't matter if I used either opensc-0.20.0 or opensc-0.22.0 (copr). The only thing I noticed between pcsc-lite-1.8.23 and later versions was the following in the logs:

pcscd[269104]: 00026711 winscard_svc.c:383:ContextThread() Communication protocol mismatch!
pcscd[269104]: 00000050 winscard_svc.c:385:ContextThread() Client protocol is 4:3
pcscd[269104]: 00000016 winscard_svc.c:387:ContextThread() Server protocol is 4:4

Needed to restart gsd-smartcard (and a few other applications) before new smart card requests stopped processing (e.g., too many contexts ...).

The RPM version of firefox still produces the following messages from various child processes:

P:426405; T:0x140441151440768 10:40:01.088 [opensc-pkcs11] pkcs11-global.c:594:C_GetSlotInfo: C_GetSlotInfo() get slot rv CKR_OK
P:426405; T:0x140441151440768 10:40:01.088 [opensc-pkcs11] slot.c:219:card_detect: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: Detecting smart card
P:426405; T:0x140441151440768 10:40:01.089 [opensc-pkcs11] sc.c:315:sc_detect_card_presence: called
P:426405; T:0x140441151440768 10:40:01.089 [opensc-pkcs11] reader-pcsc.c:445:pcsc_detect_card_presence: called
P:426405; T:0x140441151440768 10:40:01.089 [opensc-pkcs11] reader-pcsc.c:333:refresh_attributes: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00 check
P:426405; T:0x140441151440768 10:40:01.091 [opensc-pkcs11] reader-pcsc.c:375:refresh_attributes: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00:SCardGetStatusChange failed: 0x8010001d
P:426405; T:0x140441151440768 10:40:01.091 [opensc-pkcs11] reader-pcsc.c:449:pcsc_detect_card_presence: returning with: -1101 (No readers found)
P:426405; T:0x140441151440768 10:40:01.091 [opensc-pkcs11] sc.c:320:sc_detect_card_presence: returning with: -1101 (No readers found)
P:426405; T:0x140441151440768 10:40:01.092 [opensc-pkcs11] slot.c:224:card_detect: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: failed, No readers found
P:426405; T:0x140441151440768 10:40:01.092 [opensc-pkcs11] misc.c:71:sc_to_cryptoki_error_common: libopensc return value: -1101 (No readers found)
P:426405; T:0x140441151440768 10:40:01.093 [opensc-pkcs11] pkcs11-global.c:603:C_GetSlotInfo: C_GetSlotInfo() card detect rv 0x5
P:426405; T:0x140441151440768 10:40:01.093 [opensc-pkcs11] pkcs11-global.c:620:C_GetSlotInfo: C_GetSlotInfo() flags 0x7FFDBAD34E88
P:426405; T:0x140441151440768 10:40:01.093 [opensc-pkcs11] pkcs11-global.c:621:C_GetSlotInfo: C_GetSlotInfo(0x0) = CKR_GENERAL_ERROR

Main process:

P:425952; T:0x139822266771200 10:40:01.134 [opensc-pkcs11] slot.c:219:card_detect: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: Detecting smart card
P:425952; T:0x139822266771200 10:40:01.135 [opensc-pkcs11] sc.c:315:sc_detect_card_presence: called
P:425952; T:0x139822266771200 10:40:01.135 [opensc-pkcs11] reader-pcsc.c:445:pcsc_detect_card_presence: called
P:425952; T:0x139822266771200 10:40:01.135 [opensc-pkcs11] reader-pcsc.c:333:refresh_attributes: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00 check
P:425952; T:0x139822266771200 10:40:01.137 [opensc-pkcs11] reader-pcsc.c:358:refresh_attributes: returning with: 0 (Success)
P:425952; T:0x139822266771200 10:40:01.137 [opensc-pkcs11] reader-pcsc.c:450:pcsc_detect_card_presence: returning with: 5
P:425952; T:0x139822266771200 10:40:01.138 [opensc-pkcs11] sc.c:320:sc_detect_card_presence: returning with: 5
P:425952; T:0x139822266771200 10:40:01.138 [opensc-pkcs11] slot.c:372:card_detect: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: Detection ended
P:425952; T:0x139822266771200 10:40:01.138 [opensc-pkcs11] pkcs11-global.c:603:C_GetSlotInfo: C_GetSlotInfo() card detect rv 0x0
P:425952; T:0x139822266771200 10:40:01.139 [opensc-pkcs11] pkcs11-global.c:620:C_GetSlotInfo: C_GetSlotInfo() flags 0x7
P:425952; T:0x139822266771200 10:40:01.139 [opensc-pkcs11] pkcs11-global.c:621:C_GetSlotInfo: C_GetSlotInfo(0x0) = CKR_OK
P:425952; T:0x139822266771200 10:40:01.139 [opensc-pkcs11] pkcs11-session.c:206:C_GetSessionInfo: C_GetSessionInfo(hSession:0x7f2a8a8f4040)
P:425952; T:0x139822266771200 10:40:01.140 [opensc-pkcs11] pkcs11-session.c:214:C_GetSessionInfo: C_GetSessionInfo(slot:0x0)
P:425952; T:0x139822266771200 10:40:01.140 [opensc-pkcs11] pkcs15-pin.c:695:sc_pkcs15_get_pin_info: called
P:425952; T:0x139822266771200 10:40:01.140 [opensc-pkcs11] card.c:473:sc_lock: called
P:425952; T:0x139822266771200 10:40:01.140 [opensc-pkcs11] reader-pcsc.c:657:pcsc_lock: called
P:425952; T:0x139822266771200 10:40:01.342 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:425952; T:0x139822266771200 10:40:01.342 [opensc-pkcs11] sec.c:200:sc_pin_cmd: called
P:425952; T:0x139822266771200 10:40:01.342 [opensc-pkcs11] apdu.c:546:sc_transmit_apdu: called
P:425952; T:0x139822266771200 10:40:01.342 [opensc-pkcs11] card.c:473:sc_lock: called
P:425952; T:0x139822266771200 10:40:01.343 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)

Related PIDs:

j.satte+  425952  267792 24 10:28 pts/2    00:03:18 /usr/lib64/firefox/firefox -ProfileManager -no-remote
j.satte+  426405  425952  3 10:29 pts/2    00:00:26 /usr/lib64/firefox/firefox -contentproc -childID 5 -isForBrowser -prefsLen 6171 -prefMapSize 242300 -jsInit 285716 -parentBuildID 20211105152524 -appdir /usr/lib64/firefox/browser 425952 tab

This is not observed with the ESR release from Mozilla or other smart card capable browsers. Same number of tabs and pages are loaded. Perhaps it's nothing to worry about.

You get the "Communication protocol mismatch!" error because you are using a pcscd and a libpcsclite.so from 2 different versions of pcsc-lite.
In your case the server (pcscd) is from a higher protocol version 4.4 than the client (libpcsclite.so) at 4.3

Either you have not installed all the pcsc-lite packages or the files are not installed in the correct directories and do not replace files from the previous version.

I created a epel8 builds for latest version of both pcsc-lite and pcsc-lite-ccid here:

https://copr.fedorainfracloud.org/coprs/jjelen/pcsc-lite-future/

Can you try to install the, reboot/logout (to make sure no other process keeps using the old pcsc-lite library) and retry?

Installed the following from COPR:

pcsc-lite-ccid-debuginfo-1.4.36-2.el8.x86_64
pcsc-lite-ccid-debugsource-1.4.36-2.el8.x86_64
pcsc-lite-debugsource-1.9.5-1.el8.x86_64
pcsc-lite-1.9.5-1.el8.x86_64
pcsc-lite-debuginfo-1.9.5-1.el8.x86_64
pcsc-lite-ccid-1.4.36-2.el8.x86_64
pcsc-lite-libs-debuginfo-1.9.5-1.el8.x86_64
pcsc-lite-libs-1.9.5-1.el8.x86_64

Currently on opensc-0.20.0-4. Shall I reinstall the version from COPR?

- Initial login with smart card in ok.
- VPN connection with OpenConnect and PKCS#11 URL is ok.
- Unlock existing session with smart card is ok.
- Switch user and login again (resume/unlock) with smart card is ok.
- Card removal/insert is ok.
- Firefox seems normal at the moment.
- Able to login to certificate-based authentication portals.

The parent process seems okay. The same messages still appear from various Firefox sub-processes:

P:6933; T:0x139932029773696 12:32:46.735 [opensc-pkcs11] slot.c:393:card_detect_all: Detect all cards
P:6933; T:0x139932029773696 12:32:46.736 [opensc-pkcs11] slot.c:219:card_detect: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: Detecting smart card
P:6933; T:0x139932029773696 12:32:46.736 [opensc-pkcs11] sc.c:315:sc_detect_card_presence: called
P:6933; T:0x139932029773696 12:32:46.737 [opensc-pkcs11] reader-pcsc.c:445:pcsc_detect_card_presence: called
P:6933; T:0x139932029773696 12:32:46.737 [opensc-pkcs11] reader-pcsc.c:333:refresh_attributes: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00 check
P:6933; T:0x139932029773696 12:32:46.739 [opensc-pkcs11] reader-pcsc.c:375:refresh_attributes: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00:SCardGetStatusChange failed: 0x8010001d
P:6933; T:0x139932029773696 12:32:46.739 [opensc-pkcs11] reader-pcsc.c:449:pcsc_detect_card_presence: returning with: -1101 (No readers found)
P:6933; T:0x139932029773696 12:32:46.740 [opensc-pkcs11] sc.c:320:sc_detect_card_presence: returning with: -1101 (No readers found)
P:6933; T:0x139932029773696 12:32:46.740 [opensc-pkcs11] slot.c:224:card_detect: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: failed, No readers found
P:6933; T:0x139932029773696 12:32:46.741 [opensc-pkcs11] misc.c:71:sc_to_cryptoki_error_common: libopensc return value: -1101 (No readers found)
P:6933; T:0x139932029773696 12:32:46.741 [opensc-pkcs11] slot.c:412:card_detect_all: All cards detected
P:6933; T:0x139932029773696 12:32:46.742 [opensc-pkcs11] pkcs11-global.c:594:C_GetSlotInfo: C_GetSlotInfo() get slot rv CKR_OK
P:6933; T:0x139932029773696 12:32:46.742 [opensc-pkcs11] slot.c:219:card_detect: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: Detecting smart card
P:6933; T:0x139932029773696 12:32:46.742 [opensc-pkcs11] sc.c:315:sc_detect_card_presence: called
P:6933; T:0x139932029773696 12:32:46.743 [opensc-pkcs11] reader-pcsc.c:445:pcsc_detect_card_presence: called
P:6933; T:0x139932029773696 12:32:46.743 [opensc-pkcs11] reader-pcsc.c:333:refresh_attributes: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00 check
P:6933; T:0x139932029773696 12:32:46.744 [opensc-pkcs11] reader-pcsc.c:375:refresh_attributes: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00:SCardGetStatusChange failed: 0x8010001d
P:6933; T:0x139932029773696 12:32:46.745 [opensc-pkcs11] reader-pcsc.c:449:pcsc_detect_card_presence: returning with: -1101 (No readers found)
P:6933; T:0x139932029773696 12:32:46.745 [opensc-pkcs11] sc.c:320:sc_detect_card_presence: returning with: -1101 (No readers found)
P:6933; T:0x139932029773696 12:32:46.746 [opensc-pkcs11] slot.c:224:card_detect: Broadcom Corp 58200 [Contacted SmartCard] (0123456789ABCD) 00 00: failed, No readers found
P:6933; T:0x139932029773696 12:32:46.746 [opensc-pkcs11] misc.c:71:sc_to_cryptoki_error_common: libopensc return value: -1101 (No readers found)
P:6933; T:0x139932029773696 12:32:46.746 [opensc-pkcs11] pkcs11-global.c:603:C_GetSlotInfo: C_GetSlotInfo() card detect rv 0x5
P:6933; T:0x139932029773696 12:32:46.747 [opensc-pkcs11] pkcs11-global.c:620:C_GetSlotInfo: C_GetSlotInfo() flags 0x7FFE478CC348
P:6933; T:0x139932029773696 12:32:46.747 [opensc-pkcs11] pkcs11-global.c:621:C_GetSlotInfo: C_GetSlotInfo(0x0) = CKR_GENERAL_ERROR

Related PID:

j.satte+    6933    6423  4 12:13 pts/1    00:01:17 /usr/lib64/firefox/firefox -contentproc -childID 5 -isForBrowser -prefsLen 6761 -prefMapSize 243033 -jsInit 285716 -parentBuildID 20211105152524 -appdir /usr/lib64/firefox/browser 6423 tab

There are also custom polkit-1 rules to allow access to org.debian.pcsc-lite.access_card and org.debian.pcsc-lite.access_pcsc based on user (gdm) or group membership. Are these still necessary? Similar to RHBZ#1928154, RHBZ#1478345.

Please, try changing only one thing at a time to isolate the problem so lets keep the current opensc. The polkit rules are needed for the pcscd to work correctly, but the test pcsc-lite-1.9.5 has already the upstream version, which should not cause issues as described in bug #1928154 nor in bug #1478345.

From what you describe, this looks like the pcsc-lite update fixes the issue for you. I am not sure how relevant are the GENERAL_ERROR messages from C_GetSlotInfo() though and `SCardGetStatusChange` failures, but that is certainly better than infinite hanging.

Could you get also the logs from the pcscd around the time you get the above errors? They might show some more useful information.

Created attachment 1845535 [details]
gdb.txt

PIDs for reference:

> j.satte+  186505  186124  1 12:53 pts/0    00:00:10 /usr/lib64/firefox/firefox -contentproc -childID 4 -isForBrowser -prefsLen 6704 -prefMapSize 243023 -jsInit 285716 -parentBuildID 20211105152524 -appdir /usr/lib64/firefox/browser 186124 tab
> root        3719       1  0 Dec08 ?        00:04:14 /usr/sbin/pcscd --foreground --auto-exit

> P:186505; T:0x140480811558784 13:05:00.632 [opensc-pkcs11] pkcs11-global.c:642:C_GetSlotInfo: C_GetSlotInfo() flags 0x7FFEC871B0A8
> P:186505; T:0x140480811558784 13:05:00.633 [opensc-pkcs11] pkcs11-global.c:643:C_GetSlotInfo: C_GetSlotInfo(0x0) = CKR_GENERAL_ERROR

Attached to the firefox tab generating the errors. Stopped mid-error. Hopefully I grabbed them at the right moment for both firefox and pcscd.

Looks like the newer pcsc-lite fixes the problem, switching component.

Thanks for all your support, Jan Horak!

We are seeing possibly different behavior at my site. Are the pcsc package updates meant to fix the issue *without* making any modifications to opensc.module?

[root@carrera-rhel8 ~]# rpm -qa | grep pcsc
pcsc-lite-ccid-1.4.36-2.el8.x86_64
pcsc-lite-libs-1.9.5-1.el8.x86_64
pcsc-lite-1.9.5-1.el8.x86_64

[root@carrera-rhel8 ~]# rpm -q firefox
firefox-91.4.0-1.el8_5.x86_64

[root@carrera-rhel8 ~]# rpm -q redhat-release
redhat-release-8.5-0.8.el8.x86_64

I get prompted for my yubikey PIN every few minutes on this test host (I did a complete reboot after updating the packages). If I add the workaround to opensc.module, the prompts go away on this system, but other users are reporting that there is still an issue.

(In reply to James T from comment #62)
> We are seeing possibly different behavior at my site. Are the pcsc package
> updates meant to fix the issue *without* making any modifications to
> opensc.module?

Can you be more specific about the modifications to the opensc.module. I did not see them mentioned anywhere in this bug.

> I get prompted for my yubikey PIN every few minutes on this test host (I did
> a complete reboot after updating the packages). If I add the workaround to
> opensc.module, the prompts go away on this system, but other users are
> reporting that there is still an issue.

Where do you get the prompt?

Anyway, this sounds like a different issue. Can you open a new support ticket with all the needed information?

 
> Anyway, this sounds like a different issue. Can you open a new support
> ticket with all the needed information?

Sorry, I think I got my bug reports mixed up as there are several that are somewhat related. I will either create a new one or find one that closely matches the issue.

Just for reference, the prompt is 'Please enter the password for the PKCS#11 token <my name>'.

And the opensc.module changes were to add 'disable-in: firefox thunderbird' to /usr/share/p11-kit/modules/opensc.module

(In reply to James T from comment #64)
>  
> > Anyway, this sounds like a different issue. Can you open a new support
> > ticket with all the needed information?
> 
> Sorry, I think I got my bug reports mixed up as there are several that are
> somewhat related. I will either create a new one or find one that closely
> matches the issue.
> 
> Just for reference, the prompt is 'Please enter the password for the PKCS#11
> token <my name>'.
> 
> And the opensc.module changes were to add 'disable-in: firefox thunderbird'
> to /usr/share/p11-kit/modules/opensc.module

That's the bug #1892137. I am not sure if we have also RHEL8 version, but this
is certainly on different layer and this can not be fixed with pcsc-lite package
update. This is somehow between firefox/nss and p11-kit/opensc to fix.

Just to add another data point, I've been testing with Jakub's pcsc-lite 1.9.5 packages for over a week now and firefox has not locked up at all, so this solution seems to work for me. I'm running RHEL 8.5 with all available errata and using smartcards extensively.

(In reply to Ray Rocker from comment #68)
> Just to add another data point, I've been testing with Jakub's pcsc-lite
> 1.9.5 packages for over a week now and firefox has not locked up at all, so
> this solution seems to work for me. I'm running RHEL 8.5 with all available
> errata and using smartcards extensively.

Thank you very much for testing this! It looks good also on our side. You can expect it will land with the next update.

The provided pcsc-lite has also resolved the issue for us.  Thanks for the help!!!

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (pcsc-lite bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2022:2089