pcscd - apache - NOT authorized for action: access_pcsc

[TedLyngmo]

After upgrading from Fedora 25 to F26 /var/log/messages started getting a pair of these lines 1-2 times a minute:

2017-09-21T10:54:35+02:00 ninja pcscd[2721]: 03445385 auth.c:137:IsClientAuthorized() Process 48952 (user: 48) is NOT authorized for action: access_pcsc
2017-09-21T10:54:35+02:00 ninja pcscd[2721]: 00000279 winscard_svc.c:335:ContextThread() Rejected unauthorized PC/SC client

User 48 is apache. I never saw these messages before the upgrade and I wonder what apache possibly could want with pcsc?

Any ideas what could be causing this?

Version: pcsc-lite.x86_64 1.8.22-1.fc26

[LudovicRousseau]

I propose you to report the problem to Fedora.
Please send the Fedora bug report here for history.

[TedLyngmo]

Ok, this is the report I wrote six days ago. So far no comments, which is rare: 315567 @ Fedora Forum

Perhaps I can help searching for the cause somehow but I don't know where to start. What triggers pcscd to call IsClientAuthorized? Is it a library call or someone trying to connect to the /var/run/pcscd/pcscd.comm socket or something else?

Edit: Just made a program that connected to the file system socket and got the same result (but with my userid), so it seems apache is really trying to connect to that socket too. Odd. I take it you don't know of any situation when that would make sense?

[LudovicRousseau]

pcscd is the daemon. The client is libpcsclite.so.1 library.

My first guess is that apache is configured to use a smart card to store a TLS private key. Maybe through a PKCS#11 library like OpenSC.

You will have to find why apache is, indirectly, using libpcsclite.so.1.

[LudovicRousseau]

So what was the problem exactly?

[TedLyngmo]

No idea. I added more info to my thread on the Fedora site (but it's not been published yet) and closed the ticket here since it's very unlikely a problem in pcsc. I'll post an update here if I find out what causes it.

I've used lsof to try to find out if any process has loaded /usr/lib64/libpcsclite.so.1 and found only one, the gnome-settings-daemon (/usr/libexec/gsd-smartcard), but that process is run as user gdm.

/usr/libexec/nss_pcache and /usr/sbin/httpd has loaded /usr/lib64/pkcs11/p11-kit-trust.so though but I'm not sure if that could trigger this connection attempt. I'll dig some more but don't expect to find this out unless someone on the Fedora forum can help.

[LudovicRousseau]

I guess /usr/lib64/pkcs11/p11-kit-trust.so has loaded OpenSC (or another PKCS#11 library) and this library has loaded libpcsclite.so.1. If the PC/SC access failed then the libraries are unloaded and you can't see them using lsof.
I do not know an easy way to progress here.

[TedLyngmo]

Neither do I but for some sort of completeness I'll include the output from LIBCCID_ifdLogLevel=0x000F pcscd --foreground --debug --apdu --color here:

Startup:

00000000 debuglog.c:289:DebugLogSetLevel() debug level=debug
00000022 debuglog.c:310:DebugLogSetCategory() Debug options: APDU
00000006 pcscdaemon.c:350:main() Force colored logs
00000031 utils.c:82:GetDaemonPid() Can't open /var/run/pcscd/pcscd.pid: No such file or directory
00000122 configfile.l:285:DBGetReaderListDir() Parsing conf directory: /etc/reader.conf.d
00000023 configfile.l:322:DBGetReaderListDir() Skipping non regular file: .
00000004 configfile.l:322:DBGetReaderListDir() Skipping non regular file: ..
00000003 configfile.l:361:DBGetReaderList() Parsing conf file: /etc/reader.conf.d/libccidtwin
00031664 pcscdaemon.c:658:main() pcsc-lite 1.8.22 daemon ready.
00022060 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000149 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000150 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x8087, PID: 0x0024, path: /dev/bus/usb/001/002
00000156 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0624, PID: 0x0248, path: /dev/bus/usb/001/003
00000181 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0624, PID: 0x0249, path: /dev/bus/usb/001/004
00000180 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0624, PID: 0x0249, path: /dev/bus/usb/001/004
00000174 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0624, PID: 0x0249, path: /dev/bus/usb/001/004
00000154 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0624, PID: 0x0248, path: /dev/bus/usb/001/003
00000156 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x8087, PID: 0x0024, path: /dev/bus/usb/001/002
00000258 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/002/001
00000159 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/002/001
00000156 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x8087, PID: 0x0024, path: /dev/bus/usb/002/002
00000159 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x046D, PID: 0xC048, path: /dev/bus/usb/002/003
00000156 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x046D, PID: 0xC048, path: /dev/bus/usb/002/003
00000131 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x8087, PID: 0x0024, path: /dev/bus/usb/002/002
00000171 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0A81, PID: 0x0101, path: /dev/bus/usb/002/004
00000137 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0A81, PID: 0x0101, path: /dev/bus/usb/002/004
00000203 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x8087, PID: 0x0024, path: /dev/bus/usb/002/002

Connection attempt:

99999999 winscard_msg_srv.c:251:ProcessEventsServer() Common channel packet arrival
00000042 winscard_msg_srv.c:263:ProcessEventsServer() ProcessCommonChannelRequest detects: 7
00000005 pcscdaemon.c:131:SVCServiceRunLoop() A new context thread creation is requested: 7
00021057 auth.c:137:IsClientAuthorized() Process 43486 (user: 48) is NOT authorized for action: access_pcsc
00000240 winscard_svc.c:335:ContextThread() Rejected unauthorized PC/SC client
00000077 winscard_svc.c:1029:MSGCleanupClient() Thread is stopping: dwClientID=7, threadContext @0x559ede9cd4b0
00000008 winscard_svc.c:1035:MSGCleanupClient() Freeing SCONTEXT @0x559ede9cd4b0
20918992 winscard_msg_srv.c:251:ProcessEventsServer() Common channel packet arrival
00000030 winscard_msg_srv.c:263:ProcessEventsServer() ProcessCommonChannelRequest detects: 7
00000004 pcscdaemon.c:131:SVCServiceRunLoop() A new context thread creation is requested: 7
00020179 auth.c:137:IsClientAuthorized() Process 43507 (user: 48) is NOT authorized for action: access_pcsc
00000188 winscard_svc.c:335:ContextThread() Rejected unauthorized PC/SC client
00000020 winscard_svc.c:1029:MSGCleanupClient() Thread is stopping: dwClientID=7, threadContext @0x559ede9cd4b0
00000004 winscard_svc.c:1035:MSGCleanupClient() Freeing SCONTEXT @0x559ede9cd4b0
^C

Br,
Ted

[LudovicRousseau]

Who are the processes 43486 and 43507 I see in your log? apache processes?

[TedLyngmo]

I haven't confirmed it, but I'd say yes since your code checks the owner of the pid, and user 48 is apache and it also got my userid right when I made a small test program to connect to the socket.

I've noticed that the pcscd log entries seems to only be comming in between 06:00 and ~12:10 which seems to suggest that there's something going on my server in the morning hours but I haven't figured out what. The pcscd log entries don't match (in time) any other log entries (for apache or others).

[TedLyngmo]

I managed to narrow it down to a wget call made by my webserver to collect information about the daily lunches around my work. My site collects information from many places and only one of them enforces https instead of http and that seems to trigger the pcscd log entries. If I try one of the sites that accepts both http and https, only the https one will generate the log entries.

# tail -f /var/log/messages | grep pcscd &
[1] 20260
# inotifywait -m /usr/lib64/libpcsclite.so.1.0.0 &
[2] 20261
Setting up watches.
Watches established.
# sudo -u apache wget -qO/dev/null http:https://masalakitchen.se/lindholmen/lunchmeny/ ; echo $?
0
# sudo -u apache wget -qO/dev/null https://masalakitchen.se/lindholmen/lunchmeny/ ; echo $?
/usr/lib64/libpcsclite.so.1.0.0 OPEN
/usr/lib64/libpcsclite.so.1.0.0 ACCESS
2017-10-10T16:49:40+02:00 ninja pcscd[2758]: 83431667 auth.c:137:IsClientAuthorized() Process 20791 (user: 48) is NOT authorized for action: access_pcsc
2017-10-10T16:49:40+02:00 ninja pcscd[2758]: 00000231 winscard_svc.c:335:ContextThread() Rejected unauthorized PC/SC client
/usr/lib64/libpcsclite.so.1.0.0 CLOSE_NOWRITE,CLOSE
0
#

All users but root seems to trigger this but the returned data is ok for all of them. So, it's got nothing to do with apache but instead it's wget that's doing something funny whenever https is involved.

Edit: curl does not trigger the log entries.

[LudovicRousseau]

I guess wget is using a PKCS#11 library like OpenSC and OpenSC is then talking to PC/SC.

[TedLyngmo]

If only I could understand why and what I need to reconfigure to make it stop. :-(
Even running opensc-tool --info as someone else than root triggers it.

# sudo -u apache opensc-tool --info
OpenSC 0.17.0 [gcc  7.1.1 20170622 (Red Hat 7.1.1-3)]
Enabled features: locking zlib readline openssl pcsc(libpcsclite.so.1)
/usr/lib64/libpcsclite.so.1.0.0 OPEN
/usr/lib64/libpcsclite.so.1.0.0 ACCESS
/usr/lib64/libpcsclite.so.1.0.0 CLOSE_NOWRITE,CLOSE
2017-10-10T18:49:40+02:00 ninja pcscd[2758]: 83802128 auth.c:137:IsClientAuthorized() Process 22997 (user: 48) is NOT authorized for action: access_pcsc
2017-10-10T18:49:40+02:00 ninja pcscd[2758]: 00000245 winscard_svc.c:335:ContextThread() Rejected unauthorized PC/SC client

[LudovicRousseau]

You should have a look at Polkit.
See https://github.com/LudovicRousseau/PCSC/blob/master/doc/README.polkit for some documentation and an example to give access to PC/SC to a web server (exactly your use case).

I never used Polkit myself so I can't really help. The support was added for RedHat.

[TedLyngmo]

Thanks, I got that to work by changing subject.id == "www-data" to subject.active which more or less gives everyone access_pcsc rights - but I want everyone to be able to run wget without ending up in the log. What I don't understand is why wget (indirectly via libp11-kit.so.0->PC/SC->polkit I guess?) tries to perform this "org.debian.pcsc-lite.access_pcsc" action for secure protocols in the first place. I'd rather make that stop than to give all users access_pcsc rights but there are so many things connected so it's hard to know if I can configure this away or if it's a bug in wget or somewhere else.

[LudovicRousseau]

libp11-kit.so.0 is used to load PKCS#11 libraries. These libraries are used to perform cryptographic computations, for example using a smart card.
So I am not surprised that a smart card access (PC/SC) is done when a TLS connection to a web site is made.

[TedLyngmo]

Ok, I can see how that can be handy if requested. curl seems to have a command line option to specify a client certificate with a PKCS#11 URI that may direct it to a smart card if I understand it correctly. wget fails getting access - but still works just fine.

[TedLyngmo]

There is now a fresh build of GnuTLS (not on master yet) that fixes this issue!
https://gitlab.com/gnutls/gnutls/issues/315

Thanks for your help! It took some time to narrow this down :-)

[udf2457]

@TedLyngmo I am also seeing:

Apr 12 11:59:26 X pcscd[3753]: 99999999 auth.c:137:IsClientAuthorized() Process 3782 (user: 1000) is NOT authorized for action: access_pcsc                                      
Apr 12 11:59:26 X pcscd[3753]: 00000181 winscard_svc.c:335:ContextThread() Rejected unauthorized PC/SC client

When running a simple opensc-tool --list-readers from the command line.

How did you fix it in the end ? Its not clear from the thread here.

[TedLyngmo]

@udf2457 Sorry for the late reply. The problem was in GnuTLS and was fixed by that team in release gnutls-3.5.16-4.fc26 (and upstream versions).

The command you are using still triggers the log messages for unauthorized users for me too, which I'm guessing is correct.

So, with this /usr/share/polkit-1/rules.d/org.debian.pcsc-lite.rules:

polkit.addRule(function(action, subject) {
    if (action.id == "org.debian.pcsc-lite.access_pcsc" &&
        subject.user == "apache" ) {
            return polkit.Result.YES;
    }
});

polkit.addRule(function(action, subject) {
    if (action.id == "org.debian.pcsc-lite.access_card" &&
        action.lookup("reader") == 'name of reader' &&
        subject.user == "apache" ) {
            return polkit.Result.YES;
    }
});

I can run sudo -u apache opensc-tool --list-readers without triggering the log messages, but running it as myself will still trigger it. The problem in the GnuTLS library was that it tried to get pcscd access when it was uncalled for so these messages appeared whenever anyone did wget using a https URL.

[LudovicRousseau]

Thanks for the analysis.