www.cendio.com
Bug 4785 - SuisseID doesn't work with pcsctun
: SuisseID doesn't work with pcsctun
Status: CLOSED FIXED
: ThinLinc
Smart card
: 4.1.0
: PC Unknown
: P2 Normal
: 4.2.0
Assigned To:
:
:
: 4100
:
  Show dependency treegraph
 
Reported: 2013-08-29 10:46 by
Modified: 2014-04-04 13:39 (History)


Attachments
syslog output (9.44 KB, text/plain)
2014-03-19 15:59, Peter Åstrand
Details


Note

You need to log in before you can comment on or make changes to this bug.


Description From cendio 2013-08-29 10:46:52
We have had reports that it is not possible to publish a SuisseID token to the
remote session using pcsctun. We should investigate why this is.
------- Comment #3 From cendio 2014-02-18 14:24:23 -------
Tested with ThinLinc 4.1.1: 

* Server: eudemo (CentOS6) and Ubuntu 12.04

* Client: CentOS 6 workstation and Windows XP

No problems found with stock OpenSC. Well, pkcs15-tool --read-ssh-key fails to
decode the RSA key, but that's more or less expected. Otherwise, these commands
all work as expected:

pkcs15-tool -c
pkcs11-tool --module /usr/lib/opensc-pkcs11.so -L
pkcs11-tool --module /usr/lib/opensc-pkcs11.so -t

Will also try
http://update.swisssign.com/media/stick/repository/dists/precise/non-free/binary-amd64/
------- Comment #4 From cendio 2014-02-18 14:41:12 -------
(In reply to comment #3)

> Will also try
> http://update.swisssign.com/media/stick/repository/dists/precise/non-free/binary-amd64/

Added to sources.list:

deb http://update.swisssign.com/media/stick/repository precise free non-free

Then executed:

sudo apt-get update
sudo apt-key adv --keyserver keyserver.ubuntu.com --recv-keys 9B6A7AEA62A25C47
sudo apt-get update
sudo apt-get install suisseid-pkcs11

Packages installed:
  libacsccid1 suisseid-pkcs11 swisssign-pin-entry

Then:

$ pkcs11-tool --module /usr/lib/libcvP11.so -L
LOGIN CALLBACK in libCVP11LCB: CK_RV CB_Initialize(CK_CONTEXT_PTR,
CK_C_INITIALIZE_ARGS_PTR, CK_ULONG_PTR)
Available slots:
No slots.
LOGIN CALLBACK in libCVP11LCB: CK_RV CB_Finalize(CK_VOID_PTR)
------- Comment #5 From cendio 2014-02-19 10:53:06 -------
After some more debugging, I've determined that /usr/lib/libcvP11.so is buggy
and subject to race conditions: It also fails on the VMware console from time
to time. Putting some load on the machine often triggers the bug, like running:

$ find /usr | grep sdkfjsdafjdsklfdjslfjdkfsd

...in the background. 

When the module fails, C_GetSlotList returns "count 0":

--- pkcs11-spy.fat    2014-02-19 00:51:36.985182690 -0800
+++ pkcs11-spy.tl    2014-02-19 00:40:56.125183571 -0800
@@ -16,61 +16,17 @@
 2: C_GetSlotList
 [in] tokenPresent = 0x0
 [out] pSlotList: 
-Count is 1
-[out] *pulCount = 0x1
+Count is 0
+[out] *pulCount = 0x0
 Returned:  0 CKR_OK

On the PCSC side, here's the difference:

--- pkcs11-tool.ltrace-dl.fat.works.scard       2014-02-19 01:44:21.945176386
-0800
+++ pkcs11-tool.ltrace-dl.fat.fails.scard       2014-02-19 01:44:30.933176368
-0800
@@ -1,126 +1,7 @@
-SCardIsValidContext@libpcsclite.so.1(0, 0, 0x70dd80, 0x708450, 0)    =
0x80100003
-SCardEstablishContext@libpcsclite.so.1(0, 0, 0, 0x7fffb1fa4f48,
0x7fa249375240) = 0
-SCardIsValidContext@libpcsclite.so.1(0x103d1cb, 0x103d1cb, 0x70dd80, 0x6f6880,
0x7fa24a986ac0) = 0
-SCardIsValidContext@libpcsclite.so.1(0x103d1cb, 0x103d1cb, 0x70dd80, 0x7083d0,
0x7fa249375240) = 0
-SCardIsValidContext@libpcsclite.so.1(0x103d1cb, 0x103d1cb, 0x70dd80, 0x70dd80,
0x7fa249375240) = 0
-SCardListReaders@libpcsclite.so.1(0x103d1cb, 0, 0x7fffb1fa4d48,
0x7fffb1fa4d40, 0x7fa249375240) = 0
-SCardIsValidContext@libpcsclite.so.1(0x103d1cb, 0x103d1cb, 0x70dd80, 0x70e170,
0) = 0
-SCardGetStatusChange@libpcsclite.so.1(0x103d1cb, 0, 0x7fffb1fa4ce0, 1,
0x7fa249375240) = 0
-SCardIsValidContext@libpcsclite.so.1(0x103d1cb, 0x103d1cb, 0x70dd80, 5136,
0x7fa249172a90) = 0
-SCardConnect@libpcsclite.so.1(0x103d1cb, 0x70e218, 2, 3, 0x7fffb1fa4dd8) = 0
-SCardControl@libpcsclite.so.1(77891, 0x42000d48, 0, 0, 0)            =
0x80100008
-SCardControl@libpcsclite.so.1(77891, 0x42000d48, 0, 0, 0x70e2b0)     = 0
-SCardDisconnect@libpcsclite.so.1(77891, 0, 0x70e2b0, 0, 3)           = 0
-SCardFreeMemory@libpcsclite.so.1(0x103d1cb, 0x70e120, 0x70dd80, 27, 0) = 0
-SCardIsValidContext@libpcsclite.so.1(0, 0, 0x70dd80, 0x7083d0, 3)    =
0x80100003
-SCardEstablishContext@libpcsclite.so.1(0, 0, 0, 0x7fffb1fa4e78,
0x7fa249375240) = 0
...
+SCardIsValidContext@libpcsclite.so.1(0, 0, 0x2553d80, 0x254e450, 0)  =
0x80100003
+SCardEstablishContext@libpcsclite.so.1(0, 0, 0, 0x7fff02f6bab8, 0x7fc7dfeb8240
<unfinished ...>
+<... SCardEstablishContext@libpcsclite.so.1 resumed> )               =
0x8010001d
+SCardIsValidContext@libpcsclite.so.1(0, 0, 0x2553d80, 0x253c880,
0x7fc7e14c9ac0) = 0x80100003
+SCardIsValidContext@libpcsclite.so.1(0, 0, 0x2553d80, 0, 0x7fc7dfeb8240) =
0x80100003
+SCardEstablishContext@libpcsclite.so.1(0, 0, 0, 0x7fff02f6b998, 0x7fc7dfeb8240
<unfinished ...>
+<... SCardEstablishContext@libpcsclite.so.1 resumed> )               =
0x8010001d

My conclusion is that /usr/lib/libcvP11.so has a very short internal timeout
for PCSC operations.
------- Comment #6 From cendio 2014-02-19 13:14:23 -------
> ...
> +SCardIsValidContext@libpcsclite.so.1(0, 0, 0x2553d80, 0x254e450, 0)  =
> 0x80100003
> +SCardEstablishContext@libpcsclite.so.1(0, 0, 0, 0x7fff02f6bab8, 0x7fc7dfeb8240
> <unfinished ...>
> +<... SCardEstablishContext@libpcsclite.so.1 resumed> )               =
> 0x8010001d

My analysis was not fully correct. This particular problem is different from
the problem with the ThinLinc PCSC tunnel. The problem above happens when the
Ubuntu pcsc daemon is autolaunched. Apparently, sometimes when this happens, it
takes too long time, causing SCardEstablishContext to return an error. 

The problem with pcsctun, OTOH, is still very strange. For some reason, the
libcvP11.so module never calls SCardEstablishContext at all! Don't know why..
Here's a combined ltrace/strace output for the working case (VMware console):

...
_init@libpcsclite.so.1(4, 0x7fff9d5745f8, 0x7fff9d574620, 0x7fff9d574620, 57) =
-1

SYS_munmap(0x7fd567a6a000, 66171)                = 0
SYS_gettid(1, 1, 0, 0, 0xffffffff)               = 7333
SYS_gettid(1, 1, 0, 0xffffffff, 104)             = 7333
_Znwm@libstdc++.so.6(536, 0, 0x1e0b460, 0, 104)  = 0x1e10d80
_Znwm@libstdc++.so.6(29, 0, 61, 0x7fd565dc34d8, 4) = 0x1e0ae20
__dynamic_cast@libstdc++.so.6(0x1e10da8, 0x7fd5664f1ac0, 0x7fd5664f1ad0, 0,
0x1e10df0 <unfinished ...>
_ZNK10__cxxabiv120__si_class_type_info12__do_dyncastElNS_17__class_type_info10__sub_kindEPKS1_PKvS4_S6_RNS1_16__dyncast_resultE@libstdc++.so.6(0x7fd5664f1ad0,
0, 6, 0x7fd5664f1ad0, 0x1e10da8) = 0
<... __dynamic_cast@libstdc++.so.6 resumed> )    = 0x1e10da8
SYS_gettid(1, 1, 6, 0x1e10da8, 0x7fd5664f1ac0)   = 7333
SYS_gettid(1, 1, 0, 45, 0xffffffff)              = 7333
_Znwm@libstdc++.so.6(56, 0, 0, 0x1e10d80, 0xffffffff) = 0x1e0b3d0
SCardIsValidContext@libpcsclite.so.1(0, 0, 0x1e10d80, 0x1e0b450, 0) =
0x80100003
SCardEstablishContext@libpcsclite.so.1(0, 0, 0, 0x7fff9d573558, 0x7fd564ee0240
<unfinished ...>
...

For the TL/pcsctun case, we have:
...
_init@libpcre.so.3(4, 0x7fffa7153128, 0x7fffa7153150, 0x7fffa7153150, 57) = -1
_init@libgthread-2.0.so.0(4, 0x7fffa7153128, 0x7fffa7153150, 0x7fffa7153150,
57) = -1
...
SYS_munmap(0x7fb1b5ccb000, 66171)                = 0
SYS_gettid(1, 1, 0, 0, 0x7fb1b4d13950)           = 8130
SYS_gettid(1, 1, 0, 0x7fb1b4d13950, 104)         = 8130
_Znwm@libstdc++.so.6(536, 0, 0x20e7460, 0, 104)  = 0x20f0000
_Znwm@libstdc++.so.6(29, 0, 61, 0x7fb1b40244d8, 4) = 0x20ee890
__dynamic_cast@libstdc++.so.6(0x20f0028, 0x7fb1b4752ac0, 0x7fb1b4752ad0, 0,
0x20f0070 <unfinished ...>
_ZNK10__cxxabiv120__si_class_type_info12__do_dyncastElNS_17__class_type_info10__sub_kindEPKS1_PKvS4_S6_RNS1_16__dyncast_resultE@libstdc++.so.6(0x7fb1b4752ad0,
0, 6, 0x7fb1b4752ad0, 0x20f0028) = 0
<... __dynamic_cast@libstdc++.so.6 resumed> )    = 0x20f0028
SYS_gettid(1, 1, 6, 0x20f0028, 0x7fb1b4752ac0)   = 8130
SYS_open("/usr/share/locale/locale.alias", 524288, 0666) = 4

Thus, SCardIsValidContext/SCardEstablishContext is never called.
------- Comment #7 From cendio 2014-03-19 15:59:50 -------
Created an attachment (id=515) [details]
syslog output

Apparently this library logs using syslog. In the output one can find:

Mar 19 15:55:17 scilla pkcs11-tool:
/home/cvdev/git_workspace/sci_build/sti.src/SecureToken/PCSCSystemLinux.inc(77)
: virtual act::PCSCModule* act::PCSCSystem::doBind(act::PCSCModul
e*): /opt/thinlinc/lib64/libpcsclite.so.1: undefined symbol:
SCardIsValidContext
Mar 19 15:55:17 scilla pkcs11-tool: actLog: ~PCSCSystem
Mar 19 15:55:17 scilla pkcs11-tool: virtual CK_RV
PKCS11::cvWrapper::InitSlotList() : N3act21NoSuchMethodExceptionE['0x00000000',
'fatal error: SCardIsValidContext not found', 'virt
ual act::PCSCModule* act::PCSCSystem::doBind(act::PCSCModule*)']

I guess this could be the problem.
------- Comment #8 From cendio 2014-03-27 13:56:27 -------
Hopefully this bug has finally been solved, using a series of fixes: r28722
r28724 r28727 r28729 r28733. 

A few notes to the tester:

* Both the client and the server must be upgraded. 

* At least on CentOS 6, you cannot use the Omnikey 3021 reader. See:
http://osdir.com/ml/encryption.opensc.user/2007-05/msg00059.html . I've been
using the SCM SCR3311 reader instead. 

* Things to test:

pkcs11-tool --module /usr/lib/libcvP11.so -L

pkcs11-tool --module /usr/lib/libcvP11.so -t

swisssign-init (known to hang or crash upon termination, likely an app and/or
local pcsclite bug)

Login to https://postsuisseid.ch/en/support/suisseid-check using Firefox. 

The software is somewhat tricky to find; I have a copy in
/home/astrand/customers/cryptovision/suisseid-lin-4245.344.tar.bz2 .
------- Comment #9 From cendio 2014-04-04 13:39:25 -------
Tested using build 4311, both using card for authentication (login) and
redirection (firefox + https://postsuisseid.ch/en/support/suisseid-check) works
as expected.

Also tested suissesign-init and pkcs11-tool in a session which worked out as
expected.