Important!

Blog moved to https://blog.apdu.fr/

I moved my blog from https://ludovicrousseau.blogspot.com/ to https://blog.apdu.fr/ . Why? I wanted to move away from Blogger (owne...

Monday, July 4, 2011

pcscd debug output

pcscd output

pcscd is a daemon (PC/SC Daemon) and as such do not send any message to a terminal since, in general, no terminal is connected to the process standard output.

By default pcscd run as a daemon and any message is sent to the syslog system. These messages are then written in a log file like /var/log/messages.

Silent logs

Since version 1.7.3 some error messages are now debug messages and not logged by default. An error message was generated when the PC/SC call SCardConnect() failed because no card was in the reader. Since a PC/SC failure may be a normal behavior in some cases the file /var/log/messages was growing up to filling the disk. This problem was reported as Red Hat bug 707412 "PCSCD filling /var/log/messages".

Now pcscd will be much more silent by default. And system logs should not fill disks anymore.

Debug logs

Of course it is still possible to activate logs. In general you also run pcscd in the foreground (instead of in the background).

Example:
$ pcscd --foreground --debug
00000000 debuglog.c:269:DebugLogSetLevel() debug level=debug
00000174 configfile.l:245:DBGetReaderListDir() Parsing conf directory: /etc/reader.conf.d
00000012 configfile.l:287:DBGetReaderList() Parsing conf file: /etc/reader.conf.d/libccidtwin
00000050 pcscdaemon.c:552:main() pcsc-lite 1.7.4 daemon ready.
00001897 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/003/001
00000161 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/004/001
00000125 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/004/001
00000130 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x046D, PID: 0xC063, path: /dev/bus/usb/004/002
00000124 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/004/001
00000129 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x413C, PID: 0x2003, path: /dev/bus/usb/004/003
00000161 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/005/001
00000159 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000159 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/006/001
00000157 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/007/001
00000160 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/008/001
00000127 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/008/001
00000130 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x04CC, PID: 0x1122, path: /dev/bus/usb/008/002
00000136 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x08E6, PID: 0x8180, path: /dev/bus/usb/008/014
00000132 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x08E6, PID: 0x8180, path: /dev/bus/usb/008/014
00000126 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x04CC, PID: 0x1122, path: /dev/bus/usb/008/002
00000136 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x04B4, PID: 0xAEF3, path: /dev/bus/usb/008/013
00000127 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x04CC, PID: 0x1122, path: /dev/bus/usb/008/002
00000139 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x08E6, PID: 0x3437, path: /dev/bus/usb/008/018
00000028 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x08E6, PID: 0x3437, path: /dev/bus/usb/008/018
00000004 hotplug_libudev.c:309:HPAddDevice() Adding USB device: Gemalto GemPC Twin
00000028 readerfactory.c:934:RFInitializeReader() Attempting startup of Gemalto GemPC Twin 00 00 using /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
00000202 readerfactory.c:824:RFBindFunctions() Loading IFD Handler 3.0
00000026 ifdhandler.c:1750:init_driver() Driver version: 1.4.4
00000490 ifdhandler.c:1767:init_driver() LogLevel: 0x0003
00000004 ifdhandler.c:1778:init_driver() DriverOptions: 0x0000
00000081 ifdhandler.c:79:IFDHCreateChannelByName() lun: 0, device: usb:08e6/3437:libudev:0:/dev/bus/usb/008/018
00000396 ccid_usb.c:245:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rousseau@free.fr)
00000004 ccid_usb.c:246:OpenUSBByName() ifdProductString: Generic CCID driver
00000004 ccid_usb.c:247:OpenUSBByName() Copyright: This driver is protected by terms of the GNU Lesser General Public License version 2.1, or (at your option) any later version.
00054079 ccid_usb.c:504:OpenUSBByName() Found Vendor/Product: 08E6/3437 (Gemalto GemPC Twin)
00000004 ccid_usb.c:506:OpenUSBByName() Using USB bus/device: 8/18
00003836 ccid_usb.c:972:get_data_rates() declared: 10753 bps
00000003 ccid_usb.c:972:get_data_rates() declared: 14337 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 15625 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 17204 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 20833 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 21505 bps
00000001 ccid_usb.c:972:get_data_rates() declared: 23438 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 25806 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 28674 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 31250 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 32258 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 34409 bps
00000001 ccid_usb.c:972:get_data_rates() declared: 39063 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 41667 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 43011 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 46875 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 52083 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 53763 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 57348 bps
00000001 ccid_usb.c:972:get_data_rates() declared: 62500 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 64516 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 68817 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 71685 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 78125 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 83333 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 86022 bps
00000001 ccid_usb.c:972:get_data_rates() declared: 93750 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 104167 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 107527 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 114695 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 125000 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 129032 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 143369 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 156250 bps
00000001 ccid_usb.c:972:get_data_rates() declared: 166667 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 172043 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 215054 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 229391 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 250000 bps
00000002 ccid_usb.c:972:get_data_rates() declared: 344086 bps
00009925 ifdhandler.c:401:IFDHGetCapabilities() tag: 0xFB3, usb:08e6/3437:libudev:0:/dev/bus/usb/008/018 (lun: 0)
00000003 readerfactory.c:295:RFAddReader() Using the reader polling thread
00002046 ifdhandler.c:401:IFDHGetCapabilities() tag: 0xFAE, usb:08e6/3437:libudev:0:/dev/bus/usb/008/018 (lun: 0)
00000003 ifdhandler.c:489:IFDHGetCapabilities() Reader supports 1 slot(s)
00000192 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x04CC, PID: 0x1122, path: /dev/bus/usb/008/002
00000183 hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/002/001
00000077 readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Gemalto GemPC Twin 00 00
03633021 ifdhandler.c:1151:IFDHPowerICC() action: PowerUp, usb:08e6/3437:libudev:0:/dev/bus/usb/008/018 (lun: 0)
00055002 commands.c:233:CmdPowerOn Card absent or mute
00000004 ifdhandler.c:1204:IFDHPowerICC() PowerUp failed
00000003 eventhandler.c:378:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED
00000003 eventhandler.c:387:EHStatusHandlerThread() Card inserted into Gemalto GemPC Twin 00 00
00000003 eventhandler.c:403:EHStatusHandlerThread() Error powering up card.
01620802 pcscdaemon.c:678:signal_trap() Received signal: 2
00000005 pcscdaemon.c:691:signal_trap() Preparing for suicide
00000017 pcscdaemon.c:678:signal_trap() Received signal: 2
00000004 readerfactory.c:1254:RFCleanupReaders() entering cleaning function
00000003 readerfactory.c:1263:RFCleanupReaders() Stopping reader: Gemalto GemPC Twin 00 00
00000004 eventhandler.c:148:EHDestroyEventHandler() Stomping thread.
00000005 ifdhandler.c:401:IFDHGetCapabilities() tag: 0xFB1, usb:08e6/3437:libudev:0:/dev/bus/usb/008/018 (lun: 0)
00000003 ifdhandler.c:401:IFDHGetCapabilities() tag: 0xFB2, usb:08e6/3437:libudev:0:/dev/bus/usb/008/018 (lun: 0)
00000002 eventhandler.c:173:EHDestroyEventHandler() Request stoping of polling thread
00000003 ifdhandler.c:366:IFDHStopPolling() usb:08e6/3437:libudev:0:/dev/bus/usb/008/018 (lun: 0)
00401452 eventhandler.c:469:EHStatusHandlerThread() Die
00000211 eventhandler.c:188:EHDestroyEventHandler() Thread stomped.
00000004 readerfactory.c:985:RFUnInitializeReader() Attempting shutdown of Gemalto GemPC Twin 00 00.
00000006 ifdhandler.c:293:IFDHCloseChannel() usb:08e6/3437:libudev:0:/dev/bus/usb/008/018 (lun: 0)
00002768 readerfactory.c:861:RFUnloadReader() Unloading reader driver.
00000035 winscard_svc.c:130:ContextsDeinitialize() remaining threads: 0
00000002 pcscdaemon.c:630:at_exit() cleaning /var/run/pcscd

The log contains messages from pcscd itself and also messages from the drivers. It may not be easy to differentiate the two sources of messages. The file name indicates the source.

Colorization

Lines have a different color depending on the importance of the log message. pcscd uses 4 log levels:
  • debug (in black)
  • info (in blue)
  • error (in magenta)
  • critical (in red)

In the previous example we have one sample of each level.

These two lines are from the CCID driver:
00055002 commands.c:233:CmdPowerOn Card absent or mute
00000004 ifdhandler.c:1204:IFDHPowerICC() PowerUp failed

This two lines are from pcscd:
00000003 eventhandler.c:387:EHStatusHandlerThread() Card inserted into Gemalto GemPC Twin 00 00
00000003 eventhandler.c:403:EHStatusHandlerThread() Error powering up card.

You may note that the CCID driver uses a higher level when logging a power up failure. Maybe that should be changed.

Time information

Each log line also contains a number on the first column. This is the time difference with the previous log line. This information is useful to detect timeout issues and also to perform some performance profiling using the pcscd_perfs.py tool.
The time information was used to improve performances. See "RAM and CPU improvements in pcsc-lite 1.6.x" for example.

Logs redirection

When you have a problem and I ask for logs, the best way to generate them is to redirect the output of pcscd to a file and send me the generated file.

By default the colorization is disabled when the pcscd output is redirected (using pcscd --foreground > log.txt) but it is possible to force the colorization using -T or --color. Colorized logs are much more easy to read for me.

Generating a colorized log file

The magic line to generate a log file with color is:

sudo pcscd --foreground --debug --apdu --color | tee log.txt

The use of the tee command will allow to redirect the pcscd output in the log file and also send this output to the screen. You can then also see the log and stop pcscd after the problem you want to report occurs.

You can use cat log.txt to display the log and you should see the colors. If you edit the log.txt file you should see control characters.

Conclusion

If I get nicer log files it will be more easy for me to spot problems. Logs are very important and in general the only way to find issues.


 Flattr this
Labels: