Open timolehto opened 2 months ago
I've dug into the pcscd logs and I can see that the actual error seems to be that we start to see these SCARD_E_SHARING_VIOLATION
errors appear in the logs at some point during the install process and after bunch of those (I guess there's probalby some retry logic as the error seems to appera a bunch of times, but the exact amount varies quite a bit from 4 to 27), the command ultimately fails with the 0x6982 (Security status not satisfied) error. Any idea what could have changed related to handling these connections in https://github.com/martinpaljak/GlobalPlatformPro/commit/6347f0f5dc7eff1a48c22d498dc8007c8a0ff995? As said this is working fine prior to that commit and where I never see these errors or have any problems installing applets, but with that commit the issues begin. And also as said, strangely enough I also experience these exact same issues when using the GPShell from https://github.com/kaoh/globalplatform, which is presumably completely unrelated except of course for the underlying libpcsclite.so, but that's not bundled or updated and is also shared and used with the older GlobalPlatformPro versions that work fine, so how could that be the problem?
Here's a small excert of the logs
00000002 [139811161638592] winscard.c:352:SCardConnect() powerState: POWER_STATE_IN_USE
00004439 [139810981283520] <- 000000 80 2A 00 00 00 00 79 00 81 00 E3 26 4F 08 A0 00 00 01 51 00 00 00 9F 70 01 01 C5 03 9E FE 80 C4 07 A0 00 00 01 51 53 50 CC 08 A0 00 00 01 51 00 00 00 90 00
00000013 [139810981283520] SW: E3 26 4F 08 A0 00 00 01 51 00 00 00 9F 70 01 01 C5 03 9E FE 80 C4 07 A0 00 00 01 51 53 50 CC 08 A0 00 00 01 51 00 00 00 90 00
00000002 [139810981283520] winscard.c:1649:SCardTransmit() UnrefReader() count was: 3
00000002 [139811161638592] winscard.c:430:SCardConnect() Active Protocol: T=1
00000000 [139810981283520] winscard_svc.c:694:ContextThread() TRANSMIT for client 18, rv=SCARD_S_SUCCESS
00000012 [139811161638592] winscard.c:456:SCardConnect() hCard Identity: 4ff29d70
00000003 [139811161638592] winscard.c:518:SCardConnect() UnrefReader() count was: 2
00000002 [139811161638592] winscard_svc.c:523:ContextThread() CONNECT for client 13, rv=SCARD_S_SUCCESS
00000079 [139811161638592] winscard_svc.c:361:ContextThread() Received command: BEGIN_TRANSACTION from client 13
00000011 [139811161638592] readerfactory.c:866:RFReaderInfoById() RefReader() count was: 1
00000002 [139811161638592] winscard.c:1083:SCardBeginTransaction() Status: rv=SCARD_S_SUCCESS
00000001 [139811161638592] winscard.c:1086:SCardBeginTransaction() UnrefReader() count was: 2
00000001 [139811161638592] winscard_svc.c:575:ContextThread() BEGIN_TRANSACTION for client 13, rv=SCARD_S_SUCCESS
00000039 [139811161638592] winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 13
00000008 [139811161638592] readerfactory.c:866:RFReaderInfoById() RefReader() count was: 1
00000002 [139811161638592] winscard.c:1596:SCardTransmit() Send Protocol: T=1
00000003 [139811161638592] APDU: 00 A4 04 00 07 62 76 01 FF 00 00 00
00000003 [139811161638592] ifdhandler.c:1674:IFDHTransmitToICC() usb:072f/223b:libudev:0:/dev/bus/usb/001/027 (lun: 0)
00000002 [139811161638592] commands.c:1832:CmdXfrBlockAPDU_extended() T=0 (extended): 12 bytes
00000005 [139811161638592] -> 000000 6F 0C 00 00 00 00 7A 00 00 00 00 A4 04 00 07 62 76 01 FF 00 00 00
A<< (0040+2) (24ms) E3264F08A0000001510000009F700101C5039EFE80C407A0000001515350CC08A000000151000000 9000
A>> T=1 (4+0010) 84F24002 0A 4F00ECDBDCFB8FE84D16 00
00002448 [139810981283520] winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 18
00000009 [139810981283520] readerfactory.c:866:RFReaderInfoById() RefReader() count was: 2
00000001 [139810981283520] winscard.c:1649:SCardTransmit() UnrefReader() count was: 3
00000002 [139810981283520] winscard_svc.c:694:ContextThread() TRANSMIT for client 18, rv=SCARD_E_SHARING_VIOLATION
00006101 [139811161638592] <- 000000 80 02 00 00 00 00 7A 00 81 00 6A 82
00000006 [139811161638592] SW: 6A 82
00000002 [139811161638592] winscard.c:1649:SCardTransmit() UnrefReader() count was: 2
00000002 [139811161638592] winscard_svc.c:694:ContextThread() TRANSMIT for client 13, rv=SCARD_S_SUCCESS
00000060 [139811161638592] winscard_svc.c:361:ContextThread() Received command: END_TRANSACTION from client 13
After further analysing the pcscd logs, I think I know why this happens. In the logs I can see 2 primary clients. There's client 13, which I'm not entirely sure what that is actually, but I presume it's some system service polling for cards in the reader. It is continously acquiring and releasing a lock on the reader to do a short transmit.
And then there is client 18, which is GlobalPlatformaPro. With versions prior to the commit https://github.com/martinpaljak/GlobalPlatformPro/commit/6347f0f5dc7eff1a48c22d498dc8007c8a0ff995? the logs show clearly that all of the TRANSMIT commands are wrapped inside BEGIN_TRANSACTION - END_TRANSACTION and this cuts off the client 13. However, with newer versions of GPP there is no trace of BEGIN_TRANSACTION for client 18, instead it just goes on with the TRANSMIT commands without establishing a transaction and then at random moment in the middle of client 18 issuing its TRANSMIT commands, client 13 activates again issues CONNECT, followed by BEGING_TRANSACTION and that's when client 18 gets its first SCARD_E_SHARING_VIOLATION and is never able to recover.
So, this is actually quite clear now. The original connect lines handled connecting like this, clearly establishing an exclusive transaction: https://github.com/martinpaljak/GlobalPlatformPro/blob/2d4bb36c145bd8c13606f12aa14e6e29d8ecef78/tool/src/main/java/pro/javacard/gp/GPTool.java#L190-L194
but with the breaking commit, it was reduced to just this and no calls to begin (or end) exclusives exists https://github.com/martinpaljak/GlobalPlatformPro/blob/6347f0f5dc7eff1a48c22d498dc8007c8a0ff995/tool/src/main/java/pro/javacard/gp/GPTool.java#L67
So, the fix is to reintroduce exclusive transaction locks. Shouldn't be that difficult to recover the old behaviour.
I created a PR to restore the old behaviour. Works great for me: https://github.com/martinpaljak/GlobalPlatformPro/pull/356
This may or may not be the same issue as this https://github.com/martinpaljak/GlobalPlatformPro/issues/255, but since that issue hardly contained any useful information I figured a clean new issue is probably in order.
So, in short, I can not install (any) applet with any of the prereleases (or self built "next") to any of my JCOP cards. I can install applets with latest stable and self built up-to commit 2d4bb36c145bd8c13606f12aa14e6e29d8ecef78, but with the next commit 6347f0f5dc7eff1a48c22d498dc8007c8a0ff995 it no longer works. I suspect this is likely due to the apdu4j update, but I haven't yet gotten that far that I could definitely say that.
The card in question is NXP J3R180 SecId, I also have another card that is suppose to be pretty much the same, but reports different ATR, so I'm not entirely sure. It has the same issues. For additional context, I can tell that I actually have the same issues with the GPShell, but I haven't debugged that any deeper yet.
With our normal applet of code size of 6479 bytes it's always the CAP loading that fails.. usually around chunck 14 or 15, but sometimes even 16, but also sometimes it can also fail right off the bat on first chunk.
If I try to just install a minimal applet of code size 1206 bytes, it actually sometimes succeeds loading it, but at least so far, it then still fails with making it selectable.
Log of failure to make selectable
Log where it fails already during load