Bug 1751153

Summary: pcscd.service fails during shutdown
Product: [Fedora] Fedora Reporter: Zbigniew Jędrzejewski-Szmek <zbyszek>
Component: pcsc-liteAssignee: Jakub Jelen <jjelen>
Status: CLOSED CURRENTRELEASE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 32CC: crypto-team, jjelen, klember, ludovic.rousseau, rrelyea
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2021-03-18 14:03:51 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Zbigniew Jędrzejewski-Szmek 2019-09-11 09:52:47 UTC
Description of problem:

[fedora@workstation-uefi ~]$ journalctl -u pcscd.service
Sep 01 11:15:11 workstation-uefi systemd[1]: Started PC/SC Smart Card Daemon.
Sep 01 11:18:11 workstation-uefi systemd[1]: Stopping PC/SC Smart Card Daemon...
Sep 01 11:18:11 workstation-uefi systemd[1]: pcscd.service: Main process exited, code=exited, status=1/FAILURE
Sep 01 11:18:11 workstation-uefi systemd[1]: pcscd.service: Failed with result 'exit-code'.
Sep 01 11:18:11 workstation-uefi systemd[1]: Stopped PC/SC Smart Card Daemon.
-- Reboot --
Sep 01 11:18:32 workstation-uefi systemd[1]: Started PC/SC Smart Card Daemon.
Sep 01 11:25:07 workstation-uefi systemd[1]: Stopping PC/SC Smart Card Daemon...
Sep 01 11:25:07 workstation-uefi systemd[1]: pcscd.service: Main process exited, code=exited, status=1/FAILURE
Sep 01 11:25:07 workstation-uefi systemd[1]: pcscd.service: Failed with result 'exit-code'.
Sep 01 11:25:07 workstation-uefi systemd[1]: Stopped PC/SC Smart Card Daemon.
-- Reboot --
Sep 01 11:25:30 workstation-uefi systemd[1]: Started PC/SC Smart Card Daemon.
Sep 01 11:30:09 workstation-uefi systemd[1]: Stopping PC/SC Smart Card Daemon...
Sep 01 11:30:09 workstation-uefi systemd[1]: pcscd.service: Main process exited, code=exited, status=1/FAILURE
Sep 01 11:30:09 workstation-uefi systemd[1]: pcscd.service: Failed with result 'exit-code'.
Sep 01 11:30:09 workstation-uefi systemd[1]: Stopped PC/SC Smart Card Daemon.
-- Reboot --
Sep 01 11:30:32 workstation-uefi systemd[1]: Started PC/SC Smart Card Daemon.
Sep 01 11:33:25 workstation-uefi systemd[1]: Stopping PC/SC Smart Card Daemon...
Sep 01 11:33:25 workstation-uefi systemd[1]: pcscd.service: Main process exited, code=exited, status=1/FAILURE
Sep 01 11:33:25 workstation-uefi systemd[1]: pcscd.service: Failed with result 'exit-code'.
Sep 01 11:33:25 workstation-uefi systemd[1]: Stopped PC/SC Smart Card Daemon.
-- Reboot --
Sep 01 11:33:48 workstation-uefi systemd[1]: Started PC/SC Smart Card Daemon.
Sep 01 11:35:49 workstation-uefi systemd[1]: Stopping PC/SC Smart Card Daemon...
Sep 01 11:35:49 workstation-uefi systemd[1]: pcscd.service: Main process exited, code=exited, status=1/FAILURE
Sep 01 11:35:49 workstation-uefi systemd[1]: pcscd.service: Failed with result 'exit-code'.
Sep 01 11:35:49 workstation-uefi systemd[1]: Stopped PC/SC Smart Card Daemon.
-- Reboot --
Sep 01 11:36:10 workstation-uefi systemd[1]: Started PC/SC Smart Card Daemon.
Sep 01 11:37:53 workstation-uefi systemd[1]: Stopping PC/SC Smart Card Daemon...
Sep 01 11:37:53 workstation-uefi systemd[1]: pcscd.service: Main process exited, code=exited, status=1/FAILURE
Sep 01 11:37:53 workstation-uefi systemd[1]: pcscd.service: Failed with result 'exit-code'.
Sep 01 11:37:53 workstation-uefi systemd[1]: Stopped PC/SC Smart Card Daemon.
-- Reboot --
Sep 01 11:38:12 workstation-uefi systemd[1]: Started PC/SC Smart Card Daemon.
Sep 01 11:41:08 workstation-uefi systemd[1]: Stopping PC/SC Smart Card Daemon...
Sep 01 11:41:08 workstation-uefi systemd[1]: pcscd.service: Main process exited, code=exited, status=1/FAILURE
Sep 01 11:41:08 workstation-uefi systemd[1]: pcscd.service: Failed with result 'exit-code'.
Sep 01 11:41:08 workstation-uefi systemd[1]: Stopped PC/SC Smart Card Daemon.
-- Reboot --
Sep 01 11:41:30 workstation-uefi systemd[1]: Started PC/SC Smart Card Daemon.
Sep 01 11:44:14 workstation-uefi systemd[1]: Stopping PC/SC Smart Card Daemon...
Sep 01 11:44:14 workstation-uefi systemd[1]: pcscd.service: Main process exited, code=exited, status=1/FAILURE
Sep 01 11:44:14 workstation-uefi systemd[1]: pcscd.service: Failed with result 'exit-code'.
Sep 01 11:44:14 workstation-uefi systemd[1]: Stopped PC/SC Smart Card Daemon.
-- Reboot --
Sep 01 11:44:36 workstation-uefi systemd[1]: Started PC/SC Smart Card Daemon.
Sep 01 11:46:22 workstation-uefi systemd[1]: Stopping PC/SC Smart Card Daemon...
Sep 01 11:46:22 workstation-uefi systemd[1]: pcscd.service: Main process exited, code=exited, status=1/FAILURE
Sep 01 11:46:22 workstation-uefi systemd[1]: pcscd.service: Failed with result 'exit-code'.
Sep 01 11:46:22 workstation-uefi systemd[1]: Stopped PC/SC Smart Card Daemon.
-- Reboot --
Sep 01 11:46:45 workstation-uefi systemd[1]: Started PC/SC Smart Card Daemon.
Sep 01 11:47:39 workstation-uefi systemd[1]: Stopping PC/SC Smart Card Daemon...
Sep 01 11:47:39 workstation-uefi systemd[1]: pcscd.service: Main process exited, code=exited, status=1/FAILURE
Sep 01 11:47:39 workstation-uefi systemd[1]: pcscd.service: Failed with result 'exit-code'.
Sep 01 11:47:39 workstation-uefi systemd[1]: Stopped PC/SC Smart Card Daemon.
-- Reboot --
Sep 01 11:48:03 workstation-uefi systemd[1]: Started PC/SC Smart Card Daemon.
Sep 01 17:45:37 workstation-uefi systemd[1]: Stopping PC/SC Smart Card Daemon...
Sep 01 17:45:37 workstation-uefi systemd[1]: pcscd.service: Main process exited, code=exited, status=1/FAILURE
Sep 01 17:45:37 workstation-uefi systemd[1]: pcscd.service: Failed with result 'exit-code'.
Sep 01 17:45:37 workstation-uefi systemd[1]: Stopped PC/SC Smart Card Daemon.
...

This is a VM. It don't think it has any devices.

Version-Release number of selected component (if applicable):
pcsc-lite-1.8.25-2.fc31.x86_64

How reproducible:
100% (or close)

Steps to Reproduce:
1. Shut down the machine.
2. Observe bogus failure.

Expected results:
Shutdown is clean.

Comment 1 Jakub Jelen 2019-09-11 10:54:51 UTC
I see similar thing in my Fedora 30 machine (pcsc-lite-1.8.25-1.fc30.x86_64). I can see similar logs back to last year so it sounds like something that exists for quite a long time.

From my last reboot:

Aug 30 16:07:21 t470s.jjelen.redhat.com systemd[1]: Stopping PC/SC Smart Card Daemon...
Aug 30 16:07:21 t470s.jjelen.redhat.com systemd[1]: pcscd.service: Main process exited, code=exited, status=1/FAILURE
Aug 30 16:07:21 t470s.jjelen.redhat.com systemd[1]: pcscd.service: Failed with result 'exit-code'.
Aug 30 16:07:21 t470s.jjelen.redhat.com systemd[1]: Stopped PC/SC Smart Card Daemon.
-- Reboot --

Not sure what went wrong there. Collecting more debug logs by using --debug, or checking what was actually the exit code in your case would be helpful if you have the machine at hand.

Comment 2 Zbigniew Jędrzejewski-Szmek 2019-09-11 11:24:32 UTC
With --debug:
Sep 11 11:42:27 workstation-uefi systemd[1]: Started PC/SC Smart Card Daemon.
Sep 11 11:43:28 workstation-uefi systemd[1]: pcscd.service: Succeeded.
Sep 11 13:22:46 workstation-uefi systemd[1]: Started PC/SC Smart Card Daemon.
Sep 11 13:22:46 workstation-uefi pcscd[8750]: 00000000 debuglog.c:299:DebugLogSetLevel() debug level=debug
Sep 11 13:22:46 workstation-uefi pcscd[8750]: 00000056 pcscdaemon.c:450:main() Started by systemd
Sep 11 13:22:46 workstation-uefi pcscd[8750]: 00000165 configfile.l:284:DBGetReaderListDir() Parsing conf directory: /etc/reader.conf.d
Sep 11 13:22:46 workstation-uefi pcscd[8750]: 00000193 configfile.l:320:DBGetReaderListDir() Skipping non regular file: .
Sep 11 13:22:46 workstation-uefi pcscd[8750]: 00000007 configfile.l:320:DBGetReaderListDir() Skipping non regular file: ..
Sep 11 13:22:46 workstation-uefi pcscd[8750]: 00000002 configfile.l:360:DBGetReaderList() Parsing conf file: /etc/reader.conf.d/libccidtwin
Sep 11 13:22:46 workstation-uefi pcscd[8750]: 00000053 pcscdaemon.c:662:main() pcsc-lite 1.8.25 daemon ready.
Sep 11 13:22:46 workstation-uefi pcscd[8750]: 00002774 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
Sep 11 13:22:46 workstation-uefi pcscd[8750]: 00000155 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
Sep 11 13:22:46 workstation-uefi pcscd[8750]: 00000147 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x0627, PID: 0x0001, path: /dev/bus/usb/001/002
Sep 11 13:22:46 workstation-uefi pcscd[8750]: 00000238 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0003, path: /dev/bus/usb/002/001
Sep 11 13:22:54 workstation-uefi pcscd[8750]: 08450216 pcscdaemon.c:193:signal_thread() Received signal: 15
Sep 11 13:22:54 workstation-uefi pcscd[8750]: 00000015 pcscdaemon.c:213:signal_thread() Direct suicide
Sep 11 13:22:54 workstation-uefi pcscd[8750]: 00000004 pcscdaemon.c:786:at_exit() cleaning /var/run/pcscd
Sep 11 13:22:54 workstation-uefi systemd[1]: Stopping PC/SC Smart Card Daemon...
Sep 11 13:22:54 workstation-uefi systemd[1]: pcscd.service: Main process exited, code=exited, status=1/FAILURE
Sep 11 13:22:54 workstation-uefi systemd[1]: pcscd.service: Failed with result 'exit-code'.
Sep 11 13:22:54 workstation-uefi systemd[1]: Stopped PC/SC Smart Card Daemon.

Comment 3 Jakub Jelen 2019-09-11 11:54:27 UTC
If I read the code correctly, the pcscd exits with exit code 1 when it is killed by any signal other than SIGALRM [1] (exit after timeout when it is not used).

I think we can either modify pcscd to exit with 0 when killed (not sure if this is intentional) or modify systemd unit file to accept exit code 1 as a valid using SuccessExitStatus= or using - sign in front of the ExecStart (not sure if this is better).

What would be your suggestion for a correct solution from Fedora/systemd point of view?

[1] https://github.com/LudovicRousseau/PCSC/blob/master/src/pcscdaemon.c#L220

Comment 4 Zbigniew Jędrzejewski-Szmek 2019-09-11 12:52:11 UTC
Both solutions should work equivalently... I'd say just do whatever is easier.

Comment 5 Ludovic Rousseau 2019-09-11 13:50:38 UTC
Hello,
I fixed this upstream in https://github.com/LudovicRousseau/PCSC/commit/3896019ce7cbc8899d7150544dde6b0d619eeb27

Thanks for the report.

Comment 6 Jakub Jelen 2019-09-11 14:42:20 UTC
Thank you for prompt reply and fix.

This does not look like urgent issue so I will probably wait with update for the next upstream release or next update I will be doing.

Comment 7 Ben Cotton 2020-02-11 17:55:08 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 32 development cycle.
Changing version to 32.

Comment 8 Jakub Jelen 2021-03-18 14:03:51 UTC
This was fixed couple releases back with rebase to pcsc-lite-1.8.26-1 last year in Fedora 31:

https://src.fedoraproject.org/rpms/pcsc-lite/c/dd12aed2