Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Test flakiness in SmartCardConnectorApplicationSingleClientTest.SCardConnectProtocolMismatch #1086

Open
emaxx-google opened this issue Oct 4, 2023 · 1 comment
Open

Test flakiness in SmartCardConnectorApplicationSingleClientTest.SCardConnectProtocolMismatch #1086

emaxx-google opened this issue Oct 4, 2023 · 1 comment
Labels
bug
Projects
Code Quality

Comments

@emaxx-google
Copy link
Collaborator

emaxx-google commented Oct 4, 2023 •
edited

Sample log (from the emscripten-debug bot) :

2023-10-04T14:38:27.2039590Z [ RUN      ] SmartCardConnectorApplicationSingleClientTest.SCardConnectProtocolMismatch
2023-10-04T14:38:27.2052956Z [DEBUG] Performing services initialization...
2023-10-04T14:38:27.2057036Z [DEBUG] [PC/SC-Lite NaCl port] Initialization...
2023-10-04T14:38:27.2059677Z [DEBUG] [PC/SC-Lite NaCl port] Setting up PC/SC-Lite logging...
2023-10-04T14:38:27.2063609Z [INFO] ../../../../../third_party/pcsc-lite/src/src/debuglog.c:390:DebugLogSetLevel() debug level=debug
2023-10-04T14:38:27.2092169Z [INFO] ../../../../../third_party/pcsc-lite/src/src/debuglog.c:411:DebugLogSetCategory() Debug options: APDU
2023-10-04T14:38:27.2092742Z [DEBUG] [PC/SC-Lite NaCl port] PC/SC-Lite logging was set up.
2023-10-04T14:38:27.2093249Z [DEBUG] [PC/SC-Lite NaCl port] Allocating reader structures...
2023-10-04T14:38:27.2093875Z [DEBUG] [PC/SC-Lite NaCl port] Reader structures allocation finished with the following result: "Command successful.".
2023-10-04T14:38:27.2094488Z [DEBUG] [PC/SC-Lite NaCl port] Performing initial hot plug drivers search...
2023-10-04T14:38:27.2395809Z [DEBUG] [emulated IPC] A blocking in-memory file 1 was created
2023-10-04T14:38:27.2398366Z [DEBUG] [emulated IPC] A blocking in-memory file 2 was created
2023-10-04T14:38:27.2401267Z [DEBUG] [emulated IPC] The in-memory file 1 connected to the in-memory file 2
2023-10-04T14:38:27.2405109Z [DEBUG] [emulated IPC] The in-memory file 2 connected to the in-memory file 1
2023-10-04T14:38:27.2413569Z [DEBUG] [libusb] libusb_init#1050(ctx=NULL): called...
2023-10-04T14:38:27.2429958Z [DEBUG] [libusb] libusb_init#1050: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:27.2430473Z [DEBUG] [libusb] libusb_get_device_list#1051(ctx=libusb_context<DEFAULT>, list=0x0047009C): called...
2023-10-04T14:38:27.2454529Z [DEBUG] [libusb] libusb_get_device_list#1051: returning 1, *list=0x00348288([0x00348298])
2023-10-04T14:38:27.2458076Z [DEBUG] [libusb] libusb_get_bus_number#1052(dev=0x00348298): called...
2023-10-04T14:38:27.2460730Z [DEBUG] [libusb] libusb_get_bus_number#1052: returning 1
2023-10-04T14:38:27.2464333Z [DEBUG] [libusb] libusb_get_device_address#1053(dev=0x00348298): called...
2023-10-04T14:38:27.2467047Z [DEBUG] [libusb] libusb_get_device_address#1053: returning 123
2023-10-04T14:38:27.2471444Z [DEBUG] [libusb] libusb_get_device_descriptor#1054(dev=0x00348298, desc=0x00470082): called...
2023-10-04T14:38:27.2479952Z [DEBUG] [libusb] libusb_get_device_descriptor#1054: returning "LIBUSB_SUCCESS" [0x00000000], *desc=libusb_device_descriptor(bLength=18, bDescriptorType=LIBUSB_DT_DEVICE, bcdUSB=0x0000, bDeviceClass=LIBUSB_CLASS_PER_INTERFACE, bDeviceSubClass=0x00, bDeviceProtocol=0x00, bMaxPacketSize0=0, idVendor=0x08E6, idProduct=0x3437, bcdDevice=0x0200, iManufacturer=0, iProduct=0, iSerialNumber=0, bNumConfigurations=0)
2023-10-04T14:38:27.2483732Z [DEBUG] [libusb] libusb_get_active_config_descriptor#1055(dev=0x00348298, config=0x0047007C): called...
2023-10-04T14:38:27.2586167Z [DEBUG] [libusb] libusb_get_active_config_descriptor#1055: returning "LIBUSB_SUCCESS" [0x00000000], *config=0x00347B60(libusb_config_descriptor(bLength=24, bDescriptorType=LIBUSB_DT_CONFIG, wTotalLength=24, bNumInterfaces=1, bConfigurationValue=1, iConfiguration=0, bmAttributes=0, MaxPower=0, interface=[libusb_interface(altsetting=[libusb_interface_descriptor(bLength=24, bDescriptorType=LIBUSB_DT_INTERFACE, bInterfaceNumber=0, bAlternateSetting=0, bNumEndpoints=3, bInterfaceClass=LIBUSB_CLASS_SMART_CARD, endpoint=[libusb_endpoint_descriptor(bLength=20, bDescriptorType=LIBUSB_DT_ENDPOINT, bEndpointAddress=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), bmAttributes=0x02(transfer_type=LIBUSB_TRANSFER_TYPE_BULK, iso_sync_type=0, iso_usage_type=0), wMaxPacketSize=64, bInterval=0, bRefresh=0, bSynchAddress=0, extra=<>, extra_length=0), libusb_endpoint_descriptor(bLength=20, bDescriptorType=LIBUSB_DT_ENDPOINT, bEndpointAddress=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), bmAttributes=0x02(transfer_type=LIBUSB_TRANSFER_TYPE_BULK, iso_sync_type=0, iso_usage_type=0), wMaxPacketSize=64, bInterval=0, bRefresh=0, bSynchAddress=0, extra=<>, extra_length=0), libusb_endpoint_descriptor(bLength=20, bDescriptorType=LIBUSB_DT_ENDPOINT, bEndpointAddress=0x83(number=3, direction=LIBUSB_ENDPOINT_IN), bmAttributes=0x03(transfer_type=LIBUSB_TRANSFER_TYPE_INTERRUPT, iso_sync_type=0, iso_usage_type=0), wMaxPacketSize=8, bInterval=0, bRefresh=0, bSynchAddress=0, extra=<>, extra_length=0)], extra=<0x36 0x21 0x01 0x01 0x00 0x07 0x03 0x00 0x00 0x00 0xC0 0x12 0x00 0x00 0xC0 0x12 0x00 0x00 0x00 0x67 0x32 0x00 0x00 0xCE 0x99 0x0C 0x00 0x35 0xFE 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x30 0x02 0x01 0x00 0x0F 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x01>, extra_length=54)], num_altsetting=1)], extra=<>, extra_length=0))
2023-10-04T14:38:27.2591368Z [INFO] ../../../../../third_party/pcsc-lite/src/src/hotplug_libusb.c:621:HPAddHotPluggable() Adding USB device: 1:123:0
2023-10-04T14:38:27.2600878Z [INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:1090:RFInitializeReader() Attempting startup of Gemalto PC Twin Reader 00 00 using executable-module-filesystem/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
2023-10-04T14:38:27.2605274Z [INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:964:RFBindFunctions() Loading IFD Handler 3.0
2023-10-04T14:38:27.2612860Z [INFO] 00061000 ../../src/src/ifdhandler.c:111:CreateChannelByNameOrChannel() Lun: 0, device: usb:08e6/3437:libusb-1.0:1:123:0
2023-10-04T14:38:27.2622251Z [INFO] 00001000 ../../src/src/ccid_usb.c:327:OpenUSBByName() Using: executable-module-filesystem/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
2023-10-04T14:38:27.2784815Z [INFO] 00016000 ../../src/src/ccid_usb.c:345:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rousseau@free.fr)
2023-10-04T14:38:27.2788123Z [INFO] 00001000 ../../src/src/ccid_usb.c:346:OpenUSBByName() ifdProductString: Generic CCID driver
2023-10-04T14:38:27.2793937Z [INFO] 00000000 ../../src/src/ccid_usb.c:347: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.
2023-10-04T14:38:27.2797222Z [DEBUG] [libusb] libusb_init#1056(ctx=0x001308F0): called...
2023-10-04T14:38:27.2802457Z [DEBUG] [libusb] libusb_init#1056: returning "LIBUSB_SUCCESS" [0x00000000], *ctx=libusb_context<0x0034DF54>
2023-10-04T14:38:27.2807599Z [DEBUG] [libusb] libusb_get_device_list#1057(ctx=libusb_context<0x0034DF54>, list=0x0046E8D4): called...
2023-10-04T14:38:27.2863802Z [DEBUG] [libusb] libusb_get_device_list#1057: returning 1, *list=0x0034EE28([0x0034EE38])
2023-10-04T14:38:27.2869181Z [DEBUG] [libusb] libusb_get_bus_number#1058(dev=0x0034EE38): called...
2023-10-04T14:38:27.2872809Z [DEBUG] [libusb] libusb_get_bus_number#1058: returning 1
2023-10-04T14:38:27.2877261Z [DEBUG] [libusb] libusb_get_device_address#1059(dev=0x0034EE38): called...
2023-10-04T14:38:27.2880724Z [DEBUG] [libusb] libusb_get_device_address#1059: returning 123
2023-10-04T14:38:27.2885780Z [DEBUG] [libusb] libusb_get_device_descriptor#1060(dev=0x0034EE38, desc=0x0046E84A): called...
2023-10-04T14:38:27.2894854Z [DEBUG] [libusb] libusb_get_device_descriptor#1060: returning "LIBUSB_SUCCESS" [0x00000000], *desc=libusb_device_descriptor(bLength=18, bDescriptorType=LIBUSB_DT_DEVICE, bcdUSB=0x0000, bDeviceClass=LIBUSB_CLASS_PER_INTERFACE, bDeviceSubClass=0x00, bDeviceProtocol=0x00, bMaxPacketSize0=0, idVendor=0x08E6, idProduct=0x3437, bcdDevice=0x0200, iManufacturer=0, iProduct=0, iSerialNumber=0, bNumConfigurations=0)
2023-10-04T14:38:27.2900428Z [DEBUG] [libusb] libusb_open#1061(dev=0x0034EE38, handle=0x0046F8FC): called...
2023-10-04T14:38:27.2926318Z [DEBUG] [libusb] libusb_open#1061: returning "LIBUSB_SUCCESS" [0x00000000], *handle=libusb_device_handle<0x0034EEC8>
2023-10-04T14:38:27.2931964Z [DEBUG] [libusb] libusb_get_active_config_descriptor#1062(dev=0x0034EE38, config=0x0046E844): called...
2023-10-04T14:38:27.3034870Z [DEBUG] [libusb] libusb_get_active_config_descriptor#1062: returning "LIBUSB_SUCCESS" [0x00000000], *config=0x003505F8(libusb_config_descriptor(bLength=24, bDescriptorType=LIBUSB_DT_CONFIG, wTotalLength=24, bNumInterfaces=1, bConfigurationValue=1, iConfiguration=0, bmAttributes=0, MaxPower=0, interface=[libusb_interface(altsetting=[libusb_interface_descriptor(bLength=24, bDescriptorType=LIBUSB_DT_INTERFACE, bInterfaceNumber=0, bAlternateSetting=0, bNumEndpoints=3, bInterfaceClass=LIBUSB_CLASS_SMART_CARD, endpoint=[libusb_endpoint_descriptor(bLength=20, bDescriptorType=LIBUSB_DT_ENDPOINT, bEndpointAddress=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), bmAttributes=0x02(transfer_type=LIBUSB_TRANSFER_TYPE_BULK, iso_sync_type=0, iso_usage_type=0), wMaxPacketSize=64, bInterval=0, bRefresh=0, bSynchAddress=0, extra=<>, extra_length=0), libusb_endpoint_descriptor(bLength=20, bDescriptorType=LIBUSB_DT_ENDPOINT, bEndpointAddress=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), bmAttributes=0x02(transfer_type=LIBUSB_TRANSFER_TYPE_BULK, iso_sync_type=0, iso_usage_type=0), wMaxPacketSize=64, bInterval=0, bRefresh=0, bSynchAddress=0, extra=<>, extra_length=0), libusb_endpoint_descriptor(bLength=20, bDescriptorType=LIBUSB_DT_ENDPOINT, bEndpointAddress=0x83(number=3, direction=LIBUSB_ENDPOINT_IN), bmAttributes=0x03(transfer_type=LIBUSB_TRANSFER_TYPE_INTERRUPT, iso_sync_type=0, iso_usage_type=0), wMaxPacketSize=8, bInterval=0, bRefresh=0, bSynchAddress=0, extra=<>, extra_length=0)], extra=<0x36 0x21 0x01 0x01 0x00 0x07 0x03 0x00 0x00 0x00 0xC0 0x12 0x00 0x00 0xC0 0x12 0x00 0x00 0x00 0x67 0x32 0x00 0x00 0xCE 0x99 0x0C 0x00 0x35 0xFE 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x30 0x02 0x01 0x00 0x0F 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x01>, extra_length=54)], num_altsetting=1)], extra=<>, extra_length=0))
2023-10-04T14:38:27.3046419Z [DEBUG] [libusb] libusb_claim_interface#1063(dev=libusb_device_handle<0x0034EEC8>, interface_number=0): called...
2023-10-04T14:38:27.3079604Z [DEBUG] [libusb] libusb_claim_interface#1063: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:27.3085173Z [INFO] 00030000 ../../src/src/ccid_usb.c:694:OpenUSBByName() Found Vendor/Product: 08E6/3437 (Gemalto PC Twin Reader)
2023-10-04T14:38:27.3089484Z [INFO] 00000000 ../../src/src/ccid_usb.c:696:OpenUSBByName() Using USB bus/device: 1/123
2023-10-04T14:38:27.3098926Z [DEBUG] [libusb] libusb_control_transfer#1064(dev=libusb_device_handle<0x0034EEC8>, bmRequestType=0xA1(recipient=LIBUSB_RECIPIENT_INTERFACE, type=LIBUSB_REQUEST_TYPE_CLASS, direction=LIBUSB_ENDPOINT_IN), bRequest=0x03, wValue=0x0000, wIndex=0x0000, data=0x0046DF20, wLength=212, timeout=3000): called...
2023-10-04T14:38:27.3266057Z [DEBUG] [libusb] libusb_control_transfer#1064: returning 212, data=0x0046DF20<0x67 0x32 0x00 0x00 0xCE 0x64 0x00 0x00 0x9D 0xC9 0x00 0x00 0x3A 0x93 0x01 0x00 0x74 0x26 0x03 0x00 0xE7 0x4C 0x06 0x00 0xCE 0x99 0x0C 0x00 0xD7 0x5C 0x02 0x00 0x11 0xF0 0x03 0x00 0x34 0x43 0x00 0x00 0x69 0x86 0x00 0x00 0xD1 0x0C 0x01 0x00 0xA2 0x19 0x02 0x00 0x45 0x33 0x04 0x00 0x8A 0x66 0x08 0x00 0x0B 0xA0 0x02 0x00 0x73 0x30 0x00 0x00 0xE6 0x60 0x00 0x00 0xCC 0xC1 0x00 0x00 0x99 0x83 0x01 0x00 0x32 0x07 0x03 0x00 0x63 0x0E 0x06 0x00 0xB3 0x22 0x01 0x00 0x7F 0xE4 0x01 0x00 0x06 0x50 0x01 0x00 0x36 0x97 0x00 0x00 0x04 0xFC 0x00 0x00 0x53 0x28 0x00 0x00 0xA5 0x50 0x00 0x00 0x4A 0xA1 0x00 0x00 0x95 0x42 0x01 0x00 0x29 0x85 0x02 0x00 0xF8 0x78 0x00 0x00 0x3E 0x49 0x00 0x00 0x7C 0x92 0x00 0x00 0xF8 0x24 0x01 0x00 0xF0 0x49 0x02 0x00 0xE0 0x93 0x04 0x00 0xC0 0x27 0x09 0x00 0x74 0xB7 0x01 0x00 0x6C 0xDC 0x02 0x00 0xD4 0x30 0x00 0x00 0xA8 0x61 0x00 0x00 0x50 0xC3 0x00 0x00 0xA0 0x86 0x01 0x00 0x40 0x0D 0x03 0x00 0x80 0x1A 0x06 0x00 0x48 0xE8 0x01 0x00 0xBA 0xDB 0x00 0x00 0x36 0x6E 0x01 0x00 0x24 0xF4 0x00 0x00 0xDD 0x6D 0x00 0x00 0x1B 0xB7 0x00 0x00>
2023-10-04T14:38:27.3272384Z [INFO] 00018000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 12903 bps
2023-10-04T14:38:27.3276708Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 25806 bps
2023-10-04T14:38:27.3280916Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 51613 bps
2023-10-04T14:38:27.3285069Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 103226 bps
2023-10-04T14:38:27.3289343Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 206452 bps
2023-10-04T14:38:27.3293515Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 412903 bps
2023-10-04T14:38:27.3297724Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 825806 bps
2023-10-04T14:38:27.3301833Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 154839 bps
2023-10-04T14:38:27.3307421Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 258065 bps
2023-10-04T14:38:27.3311913Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 17204 bps
2023-10-04T14:38:27.3316132Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 34409 bps
2023-10-04T14:38:27.3320306Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 68817 bps
2023-10-04T14:38:27.3324447Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 137634 bps
2023-10-04T14:38:27.3328954Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 275269 bps
2023-10-04T14:38:27.3333186Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 550538 bps
2023-10-04T14:38:27.3337420Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 172043 bps
2023-10-04T14:38:27.3341529Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 12403 bps
2023-10-04T14:38:27.3345732Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 24806 bps
2023-10-04T14:38:27.3349881Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 49612 bps
2023-10-04T14:38:27.3354039Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 99225 bps
2023-10-04T14:38:27.3358148Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 198450 bps
2023-10-04T14:38:27.3365467Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 396899 bps
2023-10-04T14:38:27.3370693Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 74419 bps
2023-10-04T14:38:27.3374847Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 124031 bps
2023-10-04T14:38:27.3378991Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 86022 bps
2023-10-04T14:38:27.3383065Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 38710 bps
2023-10-04T14:38:27.3387187Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 64516 bps
2023-10-04T14:38:27.3391445Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 10323 bps
2023-10-04T14:38:27.3395597Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 20645 bps
2023-10-04T14:38:27.3399686Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 41290 bps
2023-10-04T14:38:27.3403824Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 82581 bps
2023-10-04T14:38:27.3407908Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 165161 bps
2023-10-04T14:38:27.3411966Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 30968 bps
2023-10-04T14:38:27.3416115Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 18750 bps
2023-10-04T14:38:27.3420167Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 37500 bps
2023-10-04T14:38:27.3424277Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 75000 bps
2023-10-04T14:38:27.3428342Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 150000 bps
2023-10-04T14:38:27.3432982Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 300000 bps
2023-10-04T14:38:27.3437129Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 600000 bps
2023-10-04T14:38:27.3441213Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 112500 bps
2023-10-04T14:38:27.3445358Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 187500 bps
2023-10-04T14:38:27.3449425Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 12500 bps
2023-10-04T14:38:27.3453526Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 25000 bps
2023-10-04T14:38:27.3457578Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 50000 bps
2023-10-04T14:38:27.3461718Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 100000 bps
2023-10-04T14:38:27.3465784Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 200000 bps
2023-10-04T14:38:27.3470056Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 400000 bps
2023-10-04T14:38:27.3475040Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 125000 bps
2023-10-04T14:38:27.3479133Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 56250 bps
2023-10-04T14:38:27.3483194Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 93750 bps
2023-10-04T14:38:27.3487483Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 62500 bps
2023-10-04T14:38:27.3491695Z [INFO] 00000000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 28125 bps
2023-10-04T14:38:27.3495849Z [INFO] 00001000 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 46875 bps
2023-10-04T14:38:27.3500407Z [DEBUG] [libusb] libusb_free_config_descriptor#1065(config=0x003505F8): called...
2023-10-04T14:38:27.3503837Z [DEBUG] [libusb] libusb_free_config_descriptor#1065: returning
2023-10-04T14:38:27.3509360Z [DEBUG] [libusb] libusb_free_device_list#1066(list=0x0034EE28([0x0034EE38]), unref_devices=1): called...
2023-10-04T14:38:27.3512776Z [DEBUG] [libusb] libusb_free_device_list#1066: returning
2023-10-04T14:38:27.3586144Z [DEBUG] [libusb] libusb_alloc_transfer#1067(iso_packets=0): called...
2023-10-04T14:38:27.3590225Z [DEBUG] [libusb] libusb_alloc_transfer#1067: returning 0x003478F8
2023-10-04T14:38:27.3599800Z [DEBUG] [libusb] libusb_submit_transfer#1068(transfer=0x003478F8(libusb_transfer(dev_handle=libusb_device_handle<0x0034EEC8>, flags=0, endpoint=0x83(number=3, direction=LIBUSB_ENDPOINT_IN), type=LIBUSB_TRANSFER_TYPE_INTERRUPT, timeout=100, length=8, callback=0x00000AB8, user_data=0x0046F838, buffer=0x0046F840, num_iso_packets=0))): called...
2023-10-04T14:38:27.3634511Z [DEBUG] [libusb] libusb_submit_transfer#1068: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:27.3640005Z [DEBUG] [libusb] libusb_handle_events_completed#1069(ctx=libusb_context<0x0034DF54>, completed=0x0046F838): called...
2023-10-04T14:38:27.4627014Z [DEBUG] [libusb] libusb_transfer->callback#1070(libusb_transfer=0x003478F8(libusb_transfer(dev_handle=libusb_device_handle<0x0034EEC8>, flags=0, endpoint=0x83(number=3, direction=LIBUSB_ENDPOINT_IN), type=LIBUSB_TRANSFER_TYPE_INTERRUPT, timeout=100, status=LIBUSB_TRANSFER_ERROR, length=8, actual_length=0, callback=0x00000AB8, user_data=0x0046F838, buffer=0x0046F840<>, num_iso_packets=0))): called...
2023-10-04T14:38:27.4632307Z [DEBUG] [libusb] libusb_transfer->callback#1070: returning
2023-10-04T14:38:27.4637776Z [DEBUG] [libusb] libusb_handle_events_completed#1069: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:27.4643016Z [DEBUG] [libusb] libusb_free_transfer#1071(transfer=0x003478F8): called...
2023-10-04T14:38:27.4646875Z [DEBUG] [libusb] libusb_free_transfer#1071: returning
2023-10-04T14:38:27.4659825Z [DEBUG] [libusb] libusb_bulk_transfer#1072(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0x0046F8FA<0x65 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00>, length=10, actual_length=0x0046F878, timeout=5000): called...
2023-10-04T14:38:27.4712881Z [DEBUG] [libusb] libusb_bulk_transfer#1072: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
2023-10-04T14:38:27.4720986Z [DEBUG] [libusb] libusb_bulk_transfer#1073(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0x0046F99A, length=10, actual_length=0x0046F874, timeout=3000): called...
2023-10-04T14:38:27.4774809Z [DEBUG] [libusb] libusb_bulk_transfer#1073: returning "LIBUSB_SUCCESS" [0x00000000], data=0x0046F99A<0x81 0x00 0x00 0x00 0x00 0x00 0x00 0x01 0x00 0x00>, *actual_length=10
2023-10-04T14:38:27.4786372Z [DEBUG] [libusb] libusb_bulk_transfer#1074(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0x0046F8FA<0x65 0x00 0x00 0x00 0x00 0x00 0x01 0x00 0x00 0x00>, length=10, actual_length=0x0046F878, timeout=5000): called...
2023-10-04T14:38:27.4831497Z [DEBUG] [libusb] libusb_bulk_transfer#1074: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
2023-10-04T14:38:27.4839491Z [DEBUG] [libusb] libusb_bulk_transfer#1075(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0x0046F99A, length=10, actual_length=0x0046F874, timeout=100): called...
2023-10-04T14:38:27.4890875Z [DEBUG] [libusb] libusb_bulk_transfer#1075: returning "LIBUSB_SUCCESS" [0x00000000], data=0x0046F99A<0x81 0x00 0x00 0x00 0x00 0x00 0x01 0x01 0x00 0x00>, *actual_length=10
2023-10-04T14:38:27.4902804Z [DEBUG] [libusb] libusb_bulk_transfer#1076(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0x00352718<0x6B 0x01 0x00 0x00 0x00 0x00 0x02 0x00 0x00 0x00 0x6A>, length=11, actual_length=0x0046F588, timeout=5000): called...
2023-10-04T14:38:27.4950972Z [DEBUG] [libusb] libusb_bulk_transfer#1076: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=11
2023-10-04T14:38:27.4959008Z [DEBUG] [libusb] libusb_bulk_transfer#1077(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0x00352728, length=31, actual_length=0x0046F584, timeout=100): called...
2023-10-04T14:38:27.5011931Z [DEBUG] [libusb] libusb_bulk_transfer#1077: returning "LIBUSB_SUCCESS" [0x00000000], data=0x00352728<0x83 0x00 0x00 0x00 0x00 0x00 0x02 0x41 0x0A 0x00>, *actual_length=10
2023-10-04T14:38:27.5016650Z [INFO] 00152000 ../../src/src/commands.c:1048:CmdEscapeCheck error on byte 10
2023-10-04T14:38:27.5021862Z [INFO] 00000000 ../../src/src/ccid.c:274:set_gemalto_firmware_features() GET_FIRMWARE_FEATURES failed: 612, len=0
2023-10-04T14:38:27.5027566Z [INFO] 00001000 ../../src/src/ifdhandler.c:390:IFDHGetCapabilities() tag: 0xFB3, usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
2023-10-04T14:38:27.5033386Z [INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:394:RFAddReaderOriginal() Using the reader polling thread
2023-10-04T14:38:27.5044879Z [DEBUG] [libusb] libusb_bulk_transfer#1078(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0x0046F98A<0x65 0x00 0x00 0x00 0x00 0x00 0x03 0x00 0x00 0x00>, length=10, actual_length=0x0046F908, timeout=5000): called...
2023-10-04T14:38:27.5089671Z [DEBUG] [libusb] libusb_bulk_transfer#1078: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
2023-10-04T14:38:27.5099949Z [DEBUG] [libusb] libusb_bulk_transfer#1079(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0x0046F9DE, length=10, actual_length=0x0046F904, timeout=3000): called...
2023-10-04T14:38:27.5149656Z [DEBUG] [libusb] libusb_bulk_transfer#1079: returning "LIBUSB_SUCCESS" [0x00000000], data=0x0046F9DE<0x81 0x00 0x00 0x00 0x00 0x00 0x03 0x01 0x00 0x00>, *actual_length=10
2023-10-04T14:38:27.5164196Z [DEBUG] [libusb] libusb_bulk_transfer#1080(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0x0057038A<0x65 0x00 0x00 0x00 0x00 0x00 0x04 0x00 0x00 0x00>, length=10, actual_length=0x00570308, timeout=5000): called...
2023-10-04T14:38:27.5222963Z [DEBUG] [libusb] libusb_bulk_transfer#1080: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
2023-10-04T14:38:27.5224801Z [DEBUG] [libusb] libusb_bulk_transfer#1081(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0x005703DE, length=10, actual_length=0x00570304, timeout=3000): called...
2023-10-04T14:38:27.5267313Z [DEBUG] [libusb] libusb_bulk_transfer#1081: returning "LIBUSB_SUCCESS" [0x00000000], data=0x005703DE<0x81 0x00 0x00 0x00 0x00 0x00 0x04 0x01 0x00 0x00>, *actual_length=10
2023-10-04T14:38:27.5283427Z [INFO] 00024000 ../../src/src/ifdhandler.c:390:IFDHGetCapabilities() tag: 0xFAE, usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
2023-10-04T14:38:27.5284865Z [INFO] 00001000 ../../src/src/ifdhandler.c:487:IFDHGetCapabilities() Reader supports 1 slot(s)
2023-10-04T14:38:27.5302761Z [DEBUG] [libusb] libusb_free_config_descriptor#1083(config=0x00347B60): called...
2023-10-04T14:38:27.5306839Z [DEBUG] [libusb] libusb_free_config_descriptor#1083: returning
2023-10-04T14:38:27.5314751Z [DEBUG] [libusb] libusb_bulk_transfer#1082(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0x0057033A<0x65 0x00 0x00 0x00 0x00 0x00 0x05 0x00 0x00 0x00>, length=10, actual_length=0x005702B8, timeout=5000): called...
2023-10-04T14:38:27.5318856Z [DEBUG] [libusb] libusb_free_device_list#1084(list=0x00348288([0x00348298]), unref_devices=1): called...
2023-10-04T14:38:27.5324024Z [DEBUG] [libusb] libusb_free_device_list#1084: returning
2023-10-04T14:38:27.5325617Z [DEBUG] [emulated IPC] A blocking in-memory file 3 was created
2023-10-04T14:38:27.5329287Z [DEBUG] [emulated IPC] A blocking in-memory file 4 was created
2023-10-04T14:38:27.5330819Z [DEBUG] [emulated IPC] The in-memory file 3 connected to the in-memory file 4
2023-10-04T14:38:27.5337492Z [DEBUG] [emulated IPC] The in-memory file 4 connected to the in-memory file 3
2023-10-04T14:38:27.5339641Z [DEBUG] [emulated IPC] The in-memory file 1 was closed
2023-10-04T14:38:27.5346222Z [INFO] ../../../../../third_party/pcsc-lite/src/src/hotplug_libusb.c:492:HPEstablishUSBNotifications() Driver ifd-ccid.bundle does not support IFD_GENERATE_HOTPLUG. Using active polling instead.
2023-10-04T14:38:27.5348399Z [DEBUG] [emulated IPC] The in-memory file 2 was closed
2023-10-04T14:38:27.5350121Z [DEBUG] [emulated IPC] The in-memory file 1 was destroyed
2023-10-04T14:38:27.5362638Z [INFO] ../../../../../third_party/pcsc-lite/src/src/hotplug_libusb.c:501:HPEstablishUSBNotifications() Polling forced every 1 second(s)
2023-10-04T14:38:27.5378341Z [DEBUG] [emulated IPC] The in-memory file 2 was destroyed
2023-10-04T14:38:27.5380505Z [DEBUG] [PC/SC-Lite NaCl port] Initial hot plug drivers search finished with the following result code: 0.
2023-10-04T14:38:27.5381284Z [DEBUG] [PC/SC-Lite NaCl port] Registering for hot plug events...
2023-10-04T14:38:27.5382263Z [DEBUG] [PC/SC-Lite NaCl port] Registering for hot plug events finished with the following result code: 0.
2023-10-04T14:38:27.5383007Z [DEBUG] [PC/SC-Lite NaCl port] Allocating client structures...
2023-10-04T14:38:27.5384019Z [DEBUG] [PC/SC-Lite NaCl port] Client structures allocation finished with the following result code: 1...
2023-10-04T14:38:27.5384796Z [DEBUG] [PC/SC-Lite NaCl port] Waiting for the readers initialization...
2023-10-04T14:38:27.5385877Z [INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:1433:RFWaitForReaderInit() Waiting init for reader: Gemalto PC Twin Reader 00 00
2023-10-04T14:38:27.5386680Z [DEBUG] [libusb] libusb_bulk_transfer#1082: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
2023-10-04T14:38:27.5417925Z [DEBUG] [libusb] libusb_bulk_transfer#1085(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0x0057038E, length=10, actual_length=0x005702B4, timeout=3000): called...
2023-10-04T14:38:27.5449420Z [DEBUG] [libusb] libusb_bulk_transfer#1085: returning "LIBUSB_SUCCESS" [0x00000000], data=0x0057038E<0x81 0x00 0x00 0x00 0x00 0x00 0x05 0x01 0x00 0x00>, *actual_length=10
2023-10-04T14:38:27.5450958Z [INFO] 00017000 ../../src/src/ifdhandler.c:1247:IFDHPowerICC() action: PowerUp, usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
2023-10-04T14:38:27.5460197Z [DEBUG] [libusb] libusb_bulk_transfer#1086(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0x005702F2<0x62 0x00 0x00 0x00 0x00 0x00 0x06 0x01 0x00 0x00>, length=10, actual_length=0x005701A8, timeout=5000): called...
2023-10-04T14:38:27.5486829Z [INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:1433:RFWaitForReaderInit() Waiting init for reader: Gemalto PC Twin Reader 00 00
2023-10-04T14:38:27.5515243Z [DEBUG] [libusb] libusb_bulk_transfer#1086: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
2023-10-04T14:38:27.5516257Z [DEBUG] [libusb] libusb_bulk_transfer#1087(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0x00570380, length=43, actual_length=0x005701A4, timeout=60000): called...
2023-10-04T14:38:27.5583761Z [DEBUG] [libusb] libusb_bulk_transfer#1087: returning "LIBUSB_SUCCESS" [0x00000000], data=0x00570380<0x80 0x16 0x00 0x00 0x00 0x00 0x06 0x00 0x00 0x00 0x3B 0xDB 0x96 0x00 0x80 0xB1 0xFE 0x45 0x1F 0x83 0x00 0x31 0xC0 0x64 0xC7 0xFC 0x10 0x00 0x01 0x90 0x00 0x74>, *actual_length=32
2023-10-04T14:38:27.5585379Z [INFO] ../../../../../third_party/pcsc-lite/src/src/eventhandler.c:289:EHStatusHandlerThread() powerState: POWER_STATE_POWERED
2023-10-04T14:38:27.5620845Z [INFO] Card ATR: 3B DB 96 00 80 B1 FE 45 1F 83 00 31 C0 64 C7 FC 10 00 01 90 00 74 
2023-10-04T14:38:27.5703411Z [DEBUG] [PC/SC-Lite NaCl port] Waiting for the readers initialization finished.
2023-10-04T14:38:27.5704289Z [DEBUG] [PC/SC-Lite NaCl port] Starting PC/SC-Lite daemon thread...
2023-10-04T14:38:27.5705298Z [DEBUG] [PC/SC-Lite NaCl port] [daemon thread] Waiting for the new connected clients...
2023-10-04T14:38:27.5706071Z [DEBUG] [PC/SC-Lite NaCl port] PC/SC-Lite daemon thread has started.
2023-10-04T14:38:27.5706996Z [DEBUG] [PC/SC-Lite NaCl port] Initialization successfully finished.
2023-10-04T14:38:27.5707643Z [DEBUG] All services are successfully initialized, posting ready message...
2023-10-04T14:38:27.5708548Z [DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Created client handler
2023-10-04T14:38:27.5709734Z [DEBUG] [PC/SC-Lite clients manager] Created a new client handler for aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (handler id 1234)
2023-10-04T14:38:27.5710828Z [DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Started processing request SCardEstablishContext(0x02,null,null)...
2023-10-04T14:38:27.5711765Z [INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardEstablishContext#1088(dwScope=SCARD_SCOPE_SYSTEM, pvReserved1=null, pvReserved2=null): called...
2023-10-04T14:38:27.5712847Z [DEBUG] [emulated IPC] A non-blocking in-memory file 5 was created
2023-10-04T14:38:27.5713553Z [DEBUG] [emulated IPC] A non-blocking in-memory file 6 was created
2023-10-04T14:38:27.5715984Z [DEBUG] [emulated IPC] The in-memory file 5 connected to the in-memory file 6
2023-10-04T14:38:27.5716742Z [DEBUG] [emulated IPC] The in-memory file 6 connected to the in-memory file 5
2023-10-04T14:38:27.5717770Z [DEBUG] [PC/SC-Lite NaCl port] [daemon thread] A new client was connected, starting a handler thread...
2023-10-04T14:38:27.5718597Z [DEBUG] [PC/SC-Lite NaCl port] [daemon thread] Waiting for the new connected clients...
2023-10-04T14:38:27.5719685Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:341:ContextThread() Authorized PC/SC client
2023-10-04T14:38:27.5870461Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:345:ContextThread() Thread is started: dwClientID=6, threadContext @0x34b9c8
2023-10-04T14:38:27.5871527Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:363:ContextThread() Received command: CMD_VERSION from client 6
2023-10-04T14:38:27.5873050Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:375:ContextThread() Client is protocol version 4:4
2023-10-04T14:38:27.5873916Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:397:ContextThread() CMD_VERSION for client 6
2023-10-04T14:38:27.5875025Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_clnt.c:610:SCardEstablishContextTH() Server is protocol version 4:4
2023-10-04T14:38:27.5875971Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:363:ContextThread() Received command: ESTABLISH_CONTEXT from client 6
2023-10-04T14:38:27.5881836Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:210:SCardEstablishContextServer() Establishing Context: 0x320018B7
2023-10-04T14:38:27.5883133Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:466:ContextThread() ESTABLISH_CONTEXT for client 6
2023-10-04T14:38:27.5883815Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_clnt.c:3254:SCardAddContext() Allocating new SCONTEXTMAP @0x359718
2023-10-04T14:38:27.5884475Z [INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardEstablishContext#1088: returning 0x00000000 ["Command successful."], hContext=0x320018B7
2023-10-04T14:38:27.5885213Z [DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Request SCardEstablishContext finished successfully with the following results: [0x00, 0x320018B7]
2023-10-04T14:38:27.5886133Z [WARNING] Failed to parse admin policy message: Cannot convert value to struct AdminPolicy: Value is not a dictionary
2023-10-04T14:38:27.5886665Z [INFO] Received the following policy data from the managed storage: {}
2023-10-04T14:38:27.5887263Z [DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Started processing request SCardConnect(0x320018B7,"Gemalto PC Twin Reader 00 00",0x02,0x04)...
2023-10-04T14:38:27.5888075Z [INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardConnect#1089(hContext=0x320018B7, szReader="Gemalto PC Twin Reader 00 00", dwShareMode=SCARD_SHARE_SHARED, dwPreferredProtocols=SCARD_PROTOCOL_RAW): called...
2023-10-04T14:38:27.5888970Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:363:ContextThread() Received command: CONNECT from client 6
2023-10-04T14:38:27.5889689Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:504:ContextThread() Authorized client for 'Gemalto PC Twin Reader 00 00'
2023-10-04T14:38:27.5890475Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:254:SCardConnectServer() Attempting Connect to Gemalto PC Twin Reader 00 00 using protocol: 4
2023-10-04T14:38:27.5891166Z [INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:835:RFReaderInfo() RefReader() count was: 1
2023-10-04T14:38:27.5891789Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:307:SCardConnectServer() Card Not Inserted
2023-10-04T14:38:27.5892429Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:513:SCardConnectServer() UnrefReader() count was: 2
2023-10-04T14:38:27.5944736Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:524:ContextThread() CONNECT for client 6
2023-10-04T14:38:27.5945345Z [INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardConnect#1089: returning 0x8010000C ["No smart card inserted."]
2023-10-04T14:38:27.5946037Z [DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Request SCardConnect finished successfully with the following results: [0x8010000C]
2023-10-04T14:38:27.5960955Z ../../../src/application_unittest.cc:1559: Failure
2023-10-04T14:38:27.5961302Z Expected equality of these values:
2023-10-04T14:38:27.5961843Z   SimulateConnectCallFromJsClient( kFakeHandlerId, scard_context(), kGemaltoPcTwinReaderPcscName0, 0x0002, 0x0004, scard_handle, active_protocol)
2023-10-04T14:38:27.5962463Z     Which is: -2146435060
2023-10-04T14:38:27.5962708Z   ((LONG)0x00000000)
2023-10-04T14:38:27.5962937Z     Which is: 0
2023-10-04T14:38:27.5965111Z ../../../src/application_unittest.cc:1560: Failure
2023-10-04T14:38:27.5965728Z Expected equality of these values:
2023-10-04T14:38:27.5965996Z   active_protocol
2023-10-04T14:38:27.5966211Z     Which is: 0
2023-10-04T14:38:27.5966457Z   static_cast<DWORD>(0x0004)
2023-10-04T14:38:27.5968268Z     Which is: 4
2023-10-04T14:38:27.6035275Z [DEBUG] [libusb] libusb_bulk_transfer#1090(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0x0057038A<0x65 0x00 0x00 0x00 0x00 0x00 0x07 0x00 0x00 0x00>, length=10, actual_length=0x00570308, timeout=5000): called...
2023-10-04T14:38:27.6036063Z [DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Started processing request SCardDisconnect(0x00,0x00)...
2023-10-04T14:38:27.6041311Z [INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardDisconnect#1091(hCard=0x00000000, dwDisposition=SCARD_LEAVE_CARD): called...
2023-10-04T14:38:27.6043468Z [INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardDisconnect#1091: returning 0x80100003 ["Invalid handle."]
2023-10-04T14:38:27.6049665Z [DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Request SCardDisconnect finished successfully with the following results: [0x80100003]
2023-10-04T14:38:27.6072441Z ../../../src/application_unittest.cc:1563: Failure
2023-10-04T14:38:27.6072802Z Expected equality of these values:
2023-10-04T14:38:27.6073230Z   SimulateDisconnectCallFromJsClient(kFakeHandlerId, scard_handle, 0x0000)
2023-10-04T14:38:27.6073767Z     Which is: -2146435069
2023-10-04T14:38:27.6074294Z   ((LONG)0x00000000)
2023-10-04T14:38:27.6076308Z     Which is: 0
2023-10-04T14:38:27.6095723Z [DEBUG] [libusb] libusb_bulk_transfer#1090: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
2023-10-04T14:38:27.6102746Z [DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Started processing request SCardConnect(0x320018B7,"Gemalto PC Twin Reader 00 00",0x02,0x03)...
2023-10-04T14:38:27.6111385Z [INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardConnect#1092(hContext=0x320018B7, szReader="Gemalto PC Twin Reader 00 00", dwShareMode=SCARD_SHARE_SHARED, dwPreferredProtocols=SCARD_PROTOCOL_T0|SCARD_PROTOCOL_T1): called...
2023-10-04T14:38:27.6120045Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:363:ContextThread() Received command: CONNECT from client 6
2023-10-04T14:38:27.6139638Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:504:ContextThread() Authorized client for 'Gemalto PC Twin Reader 00 00'
2023-10-04T14:38:27.6140466Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:254:SCardConnectServer() Attempting Connect to Gemalto PC Twin Reader 00 00 using protocol: 3
2023-10-04T14:38:27.6141170Z [INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:835:RFReaderInfo() RefReader() count was: 1
2023-10-04T14:38:27.6141836Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:347:SCardConnectServer() powerState: POWER_STATE_IN_USE
2023-10-04T14:38:27.6151640Z [DEBUG] [libusb] libusb_bulk_transfer#1093(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0x005703DE, length=10, actual_length=0x00570304, timeout=3000): called...
2023-10-04T14:38:27.6201873Z [DEBUG] [libusb] libusb_bulk_transfer#1093: returning "LIBUSB_SUCCESS" [0x00000000], data=0x005703DE<0x81 0x00 0x00 0x00 0x00 0x00 0x07 0x00 0x00 0x00>, *actual_length=10
2023-10-04T14:38:27.6270438Z [INFO] ../../../../../third_party/pcsc-lite/src/src/prothandler.c:108:PHSetProtocol() Attempting PTS to T=1
2023-10-04T14:38:27.6271467Z [INFO] 00076000 ../../src/src/ifdhandler.c:744:IFDHSetProtocolParameters() protocol T=1, usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
2023-10-04T14:38:27.6272608Z [DEBUG] [libusb] libusb_bulk_transfer#1094(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0x00830230<0x6F 0x04 0x00 0x00 0x00 0x00 0x08 0x00 0x00 0x00 0xFF 0x11 0x96 0x78>, length=14, actual_length=0x00830218, timeout=5000): called...
2023-10-04T14:38:27.6278307Z [DEBUG] [libusb] libusb_alloc_transfer#1095(iso_packets=0): called...
2023-10-04T14:38:27.6284353Z [DEBUG] [libusb] libusb_alloc_transfer#1095: returning 0x003506C8
2023-10-04T14:38:27.6295391Z [DEBUG] [libusb] libusb_submit_transfer#1096(transfer=0x003506C8(libusb_transfer(dev_handle=libusb_device_handle<0x0034EEC8>, flags=0, endpoint=0x83(number=3, direction=LIBUSB_ENDPOINT_IN), type=LIBUSB_TRANSFER_TYPE_INTERRUPT, timeout=600000, length=8, callback=0x00000AB8, user_data=0x005703C8, buffer=0x005703D0, num_iso_packets=0))): called...
2023-10-04T14:38:27.6323891Z [DEBUG] [libusb] libusb_submit_transfer#1096: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:27.6326529Z [DEBUG] [libusb] libusb_bulk_transfer#1094: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=14
2023-10-04T14:38:27.6335308Z [DEBUG] [libusb] libusb_bulk_transfer#1097(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0x00820270, length=65556, actual_length=0x00820174, timeout=3000): called...
2023-10-04T14:38:27.6391867Z [DEBUG] [libusb] libusb_handle_events_completed#1098(ctx=libusb_context<0x0034DF54>, completed=0x005703C8): called...
2023-10-04T14:38:27.6396301Z [DEBUG] [libusb] libusb_bulk_transfer#1097: returning "LIBUSB_SUCCESS" [0x00000000], data=0x00820270<0x80 0x04 0x00 0x00 0x00 0x00 0x08 0x00 0x00 0x00 0xFF 0x11 0x96 0x78>, *actual_length=14
2023-10-04T14:38:27.6416806Z [DEBUG] [libusb] libusb_bulk_transfer#1099(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0x00830260<0x61 0x07 0x00 0x00 0x00 0x00 0x09 0x01 0x00 0x00 0x96 0x10 0x00 0x45 0x00 0xFE 0x00>, length=17, actual_length=0x00830248, timeout=5000): called...
2023-10-04T14:38:27.6488836Z [DEBUG] [libusb] libusb_handle_events_completed#1098: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:27.6489673Z [DEBUG] [libusb] libusb_handle_events_completed#1100(ctx=libusb_context<0x0034DF54>, completed=0x005703C8): called...
2023-10-04T14:38:27.6495806Z [DEBUG] [libusb] libusb_bulk_transfer#1099: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=17
2023-10-04T14:38:27.6504393Z [DEBUG] [libusb] libusb_bulk_transfer#1101(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0x00830260, length=17, actual_length=0x00830244, timeout=2237): called...
2023-10-04T14:38:27.6560290Z [DEBUG] [libusb] libusb_handle_events_completed#1100: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:27.6561092Z [DEBUG] [libusb] libusb_handle_events_completed#1102(ctx=libusb_context<0x0034DF54>, completed=0x005703C8): called...
2023-10-04T14:38:27.6572917Z [DEBUG] [libusb] libusb_bulk_transfer#1101: returning "LIBUSB_SUCCESS" [0x00000000], data=0x00830260<0x82 0x07 0x00 0x00 0x00 0x00 0x09 0x00 0x00 0x00 0x96 0x10 0x00 0x45 0x00 0xFE 0x00>, *actual_length=17
2023-10-04T14:38:27.6586713Z [DEBUG] [libusb] libusb_bulk_transfer#1103(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0x008300D0<0x6F 0x05 0x00 0x00 0x00 0x00 0x0A 0x00 0x00 0x00 0x00 0xC1 0x01 0xFE 0x3E>, length=15, actual_length=0x008300B8, timeout=5000): called...
2023-10-04T14:38:27.6641451Z [DEBUG] [libusb] libusb_handle_events_completed#1102: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:27.6642249Z [DEBUG] [libusb] libusb_handle_events_completed#1104(ctx=libusb_context<0x0034DF54>, completed=0x005703C8): called...
2023-10-04T14:38:27.6648216Z [DEBUG] [libusb] libusb_bulk_transfer#1103: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=15
2023-10-04T14:38:27.6656865Z [DEBUG] [libusb] libusb_bulk_transfer#1105(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0x00820110, length=65556, actual_length=0x00820014, timeout=2237): called...
2023-10-04T14:38:27.6710438Z [DEBUG] [libusb] libusb_handle_events_completed#1104: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:27.6711231Z [DEBUG] [libusb] libusb_handle_events_completed#1106(ctx=libusb_context<0x0034DF54>, completed=0x005703C8): called...
2023-10-04T14:38:27.6725191Z [DEBUG] [libusb] libusb_bulk_transfer#1105: returning "LIBUSB_SUCCESS" [0x00000000], data=0x00820110<0x80 0x05 0x00 0x00 0x00 0x00 0x0A 0x00 0x00 0x00 0x00 0xE1 0x01 0xFE 0x1E>, *actual_length=15
2023-10-04T14:38:27.6731787Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:426:SCardConnectServer() Active Protocol: T=1
2023-10-04T14:38:27.6737837Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:451:SCardConnectServer() hCard Identity: 100b211e
2023-10-04T14:38:27.6743727Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:513:SCardConnectServer() UnrefReader() count was: 2
2023-10-04T14:38:27.6750066Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:524:ContextThread() CONNECT for client 6
2023-10-04T14:38:27.6786104Z [INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardConnect#1092: returning 0x00000000 ["Command successful."], hCard=0x100B211E, dwActiveProtocol=SCARD_PROTOCOL_T1
2023-10-04T14:38:27.6786692Z ../../../src/application_unittest.cc:1571: Failure
2023-10-04T14:38:27.6788046Z [DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Request SCardConnect finished successfully with the following results: [0x00, 0x100B211E, 0x02]
2023-10-04T14:38:27.6788561Z Expected equality of these values:
2023-10-04T14:38:27.6789168Z   return_code
2023-10-04T14:38:27.6804568Z [DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Started processing request SCardReleaseContext(0x320018B7)...
2023-10-04T14:38:27.6805034Z     Which is: 0
2023-10-04T14:38:27.6805530Z   ((LONG)0x8010000F)
2023-10-04T14:38:27.6807033Z     Which is: -2146435057
2023-10-04T14:38:27.6811887Z [INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardReleaseContext#1107(hContext=0x320018B7): called...
2023-10-04T14:38:27.6819525Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:363:ContextThread() Received command: RELEASE_CONTEXT from client 6
2023-10-04T14:38:27.6826112Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:224:SCardReleaseContextServer() Releasing Context: 0x320018B7
2023-10-04T14:38:27.6832390Z [INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:862:RFReaderInfoById() RefReader() count was: 1
2023-10-04T14:38:27.6838270Z [INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:862:RFReaderInfoById() RefReader() count was: 2
2023-10-04T14:38:27.6844024Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:877:SCardDisconnectServer() Active Contexts: 1
2023-10-04T14:38:27.6849825Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:878:SCardDisconnectServer() dwDisposition: 0
2023-10-04T14:38:27.6860312Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:1013:SCardDisconnectServer() powerState: POWER_STATE_GRACE_PERIOD
2023-10-04T14:38:27.6866695Z [INFO] 00066000 ../../src/src/ifdhandler.c:390:IFDHGetCapabilities() tag: 0xFB2, usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
2023-10-04T14:38:27.6877292Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:1026:SCardDisconnectServer() Stopping polling thread
2023-10-04T14:38:27.6882846Z [INFO] 00001000 ../../src/src/ifdhandler.c:355:IFDHStopPolling() usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
2023-10-04T14:38:27.6888007Z [DEBUG] [libusb] libusb_cancel_transfer#1108(transfer=0x003506C8): called...
2023-10-04T14:38:27.6914259Z [DEBUG] [libusb] libusb_transfer->callback#1109(libusb_transfer=0x003506C8(libusb_transfer(dev_handle=libusb_device_handle<0x0034EEC8>, flags=0, endpoint=0x83(number=3, direction=LIBUSB_ENDPOINT_IN), type=LIBUSB_TRANSFER_TYPE_INTERRUPT, timeout=600000, status=LIBUSB_TRANSFER_CANCELLED, length=8, actual_length=0, callback=0x00000AB8, user_data=0x005703C8, buffer=0x005703D0<>, num_iso_packets=0))): called...
2023-10-04T14:38:27.6915429Z [DEBUG] [libusb] libusb_transfer->callback#1109: returning
2023-10-04T14:38:27.6916247Z [DEBUG] [libusb] libusb_handle_events_completed#1106: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:27.6917217Z [DEBUG] [libusb] libusb_free_transfer#1110(transfer=0x003506C8): called...
2023-10-04T14:38:27.6917972Z [DEBUG] [libusb] libusb_free_transfer#1110: returning
2023-10-04T14:38:27.6923122Z [DEBUG] [libusb] libusb_cancel_transfer#1108: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:27.6929100Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:1039:SCardDisconnectServer() UnrefReader() count was: 3
2023-10-04T14:38:27.6935062Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:947:MSGRemoveContext() UnrefReader() count was: 2
2023-10-04T14:38:27.6940950Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:481:ContextThread() RELEASE_CONTEXT for client 6
2023-10-04T14:38:27.6989736Z [DEBUG] [emulated IPC] The in-memory file 5 was closed
2023-10-04T14:38:27.6990469Z [DEBUG] [emulated IPC] The in-memory file 6 was closed
2023-10-04T14:38:27.6991441Z [INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardReleaseContext#1107: returning 0x00000000 ["Command successful."]
2023-10-04T14:38:27.6992344Z [DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Request SCardReleaseContext finished successfully with the following results: [0x00]
2023-10-04T14:38:27.6993519Z [DEBUG] [PC/SC-Lite clients manager] Deleted client handler for aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (handler id was 1234)
2023-10-04T14:38:27.6994344Z [DEBUG] [PC/SC-Lite NaCl port] Shutting down the PC/SC-Lite daemon thread...
2023-10-04T14:38:27.6995496Z [DEBUG] [PC/SC-Lite NaCl port] [daemon thread] Shutting down...
2023-10-04T14:38:27.6999840Z [DEBUG] [emulated IPC] The in-memory file 5 was destroyed
2023-10-04T14:38:27.7008140Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:355:ContextThread() Client die: 6
2023-10-04T14:38:27.7012745Z [DEBUG] [emulated IPC] The in-memory file 6 was destroyed
2023-10-04T14:38:27.7019644Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:1074:MSGCleanupClient() Thread is stopping: dwClientID=6, threadContext @0x34b9c8
2023-10-04T14:38:27.7025590Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:1080:MSGCleanupClient() Freeing SCONTEXT @0x34b9c8
2023-10-04T14:38:28.0936192Z [INFO] ../../../../../third_party/pcsc-lite/src/src/eventhandler.c:494:EHStatusHandlerThread() powerState: POWER_STATE_POWERED
2023-10-04T14:38:28.0946885Z [DEBUG] [libusb] libusb_bulk_transfer#1111(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0x0057038A<0x65 0x00 0x00 0x00 0x00 0x00 0x0B 0x00 0x00 0x00>, length=10, actual_length=0x00570308, timeout=5000): called...
2023-10-04T14:38:28.1004703Z [DEBUG] [libusb] libusb_bulk_transfer#1111: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
2023-10-04T14:38:28.1011531Z [DEBUG] [libusb] libusb_bulk_transfer#1112(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0x005703DE, length=10, actual_length=0x00570304, timeout=3000): called...
2023-10-04T14:38:28.1066747Z [DEBUG] [libusb] libusb_bulk_transfer#1112: returning "LIBUSB_SUCCESS" [0x00000000], data=0x005703DE<0x81 0x00 0x00 0x00 0x00 0x00 0x0B 0x00 0x00 0x00>, *actual_length=10
2023-10-04T14:38:28.1069896Z [DEBUG] [libusb] libusb_alloc_transfer#1113(iso_packets=0): called...
2023-10-04T14:38:28.1072856Z [DEBUG] [libusb] libusb_alloc_transfer#1113: returning 0x0034DF10
2023-10-04T14:38:28.1081602Z [DEBUG] [libusb] libusb_submit_transfer#1114(transfer=0x0034DF10(libusb_transfer(dev_handle=libusb_device_handle<0x0034EEC8>, flags=0, endpoint=0x83(number=3, direction=LIBUSB_ENDPOINT_IN), type=LIBUSB_TRANSFER_TYPE_INTERRUPT, timeout=5000, length=8, callback=0x00000AB8, user_data=0x005703C8, buffer=0x005703D0, num_iso_packets=0))): called...
2023-10-04T14:38:28.1111610Z [DEBUG] [libusb] libusb_submit_transfer#1114: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:28.1112365Z [DEBUG] [libusb] libusb_cancel_transfer#1115(transfer=0x0034DF10): called...
2023-10-04T14:38:28.1116493Z [DEBUG] [libusb] libusb_cancel_transfer#1115: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:28.1121038Z [DEBUG] [libusb] libusb_handle_events_completed#1116(ctx=libusb_context<0x0034DF54>, completed=0x005703C8): called...
2023-10-04T14:38:28.1140806Z [DEBUG] [libusb] libusb_transfer->callback#1117(libusb_transfer=0x0034DF10(libusb_transfer(dev_handle=libusb_device_handle<0x0034EEC8>, flags=0, endpoint=0x83(number=3, direction=LIBUSB_ENDPOINT_IN), type=LIBUSB_TRANSFER_TYPE_INTERRUPT, timeout=5000, status=LIBUSB_TRANSFER_CANCELLED, length=8, actual_length=0, callback=0x00000AB8, user_data=0x005703C8, buffer=0x005703D0<>, num_iso_packets=0))): called...
2023-10-04T14:38:28.1142152Z [DEBUG] [libusb] libusb_transfer->callback#1117: returning
2023-10-04T14:38:28.1145048Z [DEBUG] [libusb] libusb_handle_events_completed#1116: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:28.1148570Z [DEBUG] [libusb] libusb_free_transfer#1118(transfer=0x0034DF10): called...
2023-10-04T14:38:28.1151100Z [DEBUG] [libusb] libusb_free_transfer#1118: returning
2023-10-04T14:38:28.5170942Z [DEBUG] [libusb] libusb_bulk_transfer#1119(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0x0057033A<0x65 0x00 0x00 0x00 0x00 0x00 0x0C 0x00 0x00 0x00>, length=10, actual_length=0x005702B8, timeout=5000): called...
2023-10-04T14:38:28.5219297Z [DEBUG] [libusb] libusb_bulk_transfer#1119: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
2023-10-04T14:38:28.5226633Z [DEBUG] [libusb] libusb_bulk_transfer#1120(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0x0057038E, length=10, actual_length=0x005702B4, timeout=3000): called...
2023-10-04T14:38:28.5274613Z [DEBUG] [libusb] libusb_bulk_transfer#1120: returning "LIBUSB_SUCCESS" [0x00000000], data=0x0057038E<0x81 0x00 0x00 0x00 0x00 0x00 0x0C 0x00 0x00 0x00>, *actual_length=10
2023-10-04T14:38:28.5279362Z [INFO] 00840000 ../../src/src/ifdhandler.c:1247:IFDHPowerICC() action: PowerDown, usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
2023-10-04T14:38:28.5289282Z [DEBUG] [libusb] libusb_bulk_transfer#1121(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0x005702FE<0x63 0x00 0x00 0x00 0x00 0x00 0x0D 0x00 0x00 0x00>, length=10, actual_length=0x00570278, timeout=5000): called...
2023-10-04T14:38:28.5333271Z [DEBUG] [libusb] libusb_bulk_transfer#1121: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
2023-10-04T14:38:28.5340104Z [DEBUG] [libusb] libusb_bulk_transfer#1122(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0x005702FE, length=10, actual_length=0x00570274, timeout=2237): called...
2023-10-04T14:38:28.5412220Z [DEBUG] [libusb] libusb_get_device_list#1123(ctx=libusb_context<DEFAULT>, list=0x0047009C): called...
2023-10-04T14:38:28.5412809Z [DEBUG] [libusb] libusb_bulk_transfer#1122: returning "LIBUSB_SUCCESS" [0x00000000], data=0x005702FE<0x81 0x00 0x00 0x00 0x00 0x00 0x0D 0x01 0x00 0x00>, *actual_length=10
2023-10-04T14:38:28.5413541Z [DEBUG] [libusb] libusb_bulk_transfer#1124(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0x005702FE<0x63 0x00 0x00 0x00 0x00 0x00 0x0E 0x00 0x00 0x00>, length=10, actual_length=0x00570278, timeout=5000): called...
2023-10-04T14:38:28.5414186Z [DEBUG] [libusb] libusb_get_device_list#1123: returning 1, *list=0x0034DF38([0x00355788])
2023-10-04T14:38:28.5417301Z [DEBUG] [libusb] libusb_get_bus_number#1125(dev=0x00355788): called...
2023-10-04T14:38:28.5417707Z [DEBUG] [libusb] libusb_get_bus_number#1125: returning 1
2023-10-04T14:38:28.5422221Z [DEBUG] [libusb] libusb_get_device_address#1126(dev=0x00355788): called...
2023-10-04T14:38:28.5425956Z [DEBUG] [libusb] libusb_get_device_address#1126: returning 123
2023-10-04T14:38:28.5431347Z [DEBUG] [libusb] libusb_get_device_descriptor#1127(dev=0x00355788, desc=0x00470082): called...
2023-10-04T14:38:28.5440724Z [DEBUG] [libusb] libusb_get_device_descriptor#1127: returning "LIBUSB_SUCCESS" [0x00000000], *desc=libusb_device_descriptor(bLength=18, bDescriptorType=LIBUSB_DT_DEVICE, bcdUSB=0x0000, bDeviceClass=LIBUSB_CLASS_PER_INTERFACE, bDeviceSubClass=0x00, bDeviceProtocol=0x00, bMaxPacketSize0=0, idVendor=0x08E6, idProduct=0x3437, bcdDevice=0x0200, iManufacturer=0, iProduct=0, iSerialNumber=0, bNumConfigurations=0)
2023-10-04T14:38:28.5447495Z [DEBUG] [libusb] libusb_get_active_config_descriptor#1128(dev=0x00355788, config=0x0047007C): called...
2023-10-04T14:38:28.5451338Z [DEBUG] [libusb] libusb_bulk_transfer#1124: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
2023-10-04T14:38:28.5458513Z [DEBUG] [libusb] libusb_bulk_transfer#1129(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0x005702FE, length=10, actual_length=0x00570274, timeout=2237): called...
2023-10-04T14:38:28.5510218Z [DEBUG] [libusb] libusb_bulk_transfer#1129: returning "LIBUSB_SUCCESS" [0x00000000], data=0x005702FE<0x81 0x00 0x00 0x00 0x00 0x00 0x0E 0x01 0x00 0x00>, *actual_length=10
2023-10-04T14:38:28.5515371Z [INFO] ../../../../../third_party/pcsc-lite/src/src/eventhandler.c:482:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED
2023-10-04T14:38:28.5525513Z [DEBUG] [libusb] libusb_bulk_transfer#1130(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0x0057038A<0x65 0x00 0x00 0x00 0x00 0x00 0x0F 0x00 0x00 0x00>, length=10, actual_length=0x00570308, timeout=5000): called...
2023-10-04T14:38:28.5567188Z [DEBUG] [libusb] libusb_get_active_config_descriptor#1128: returning "LIBUSB_SUCCESS" [0x00000000], *config=0x00347520(libusb_config_descriptor(bLength=24, bDescriptorType=LIBUSB_DT_CONFIG, wTotalLength=24, bNumInterfaces=1, bConfigurationValue=1, iConfiguration=0, bmAttributes=0, MaxPower=0, interface=[libusb_interface(altsetting=[libusb_interface_descriptor(bLength=24, bDescriptorType=LIBUSB_DT_INTERFACE, bInterfaceNumber=0, bAlternateSetting=0, bNumEndpoints=3, bInterfaceClass=LIBUSB_CLASS_SMART_CARD, endpoint=[libusb_endpoint_descriptor(bLength=20, bDescriptorType=LIBUSB_DT_ENDPOINT, bEndpointAddress=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), bmAttributes=0x02(transfer_type=LIBUSB_TRANSFER_TYPE_BULK, iso_sync_type=0, iso_usage_type=0), wMaxPacketSize=64, bInterval=0, bRefresh=0, bSynchAddress=0, extra=<>, extra_length=0), libusb_endpoint_descriptor(bLength=20, bDescriptorType=LIBUSB_DT_ENDPOINT, bEndpointAddress=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), bmAttributes=0x02(transfer_type=LIBUSB_TRANSFER_TYPE_BULK, iso_sync_type=0, iso_usage_type=0), wMaxPacketSize=64, bInterval=0, bRefresh=0, bSynchAddress=0, extra=<>, extra_length=0), libusb_endpoint_descriptor(bLength=20, bDescriptorType=LIBUSB_DT_ENDPOINT, bEndpointAddress=0x83(number=3, direction=LIBUSB_ENDPOINT_IN), bmAttributes=0x03(transfer_type=LIBUSB_TRANSFER_TYPE_INTERRUPT, iso_sync_type=0, iso_usage_type=0), wMaxPacketSize=8, bInterval=0, bRefresh=0, bSynchAddress=0, extra=<>, extra_length=0)], extra=<0x36 0x21 0x01 0x01 0x00 0x07 0x03 0x00 0x00 0x00 0xC0 0x12 0x00 0x00 0xC0 0x12 0x00 0x00 0x00 0x67 0x32 0x00 0x00 0xCE 0x99 0x0C 0x00 0x35 0xFE 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x30 0x02 0x01 0x00 0x0F 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x01>, extra_length=54)], num_altsetting=1)], extra=<>, extra_length=0))
2023-10-04T14:38:28.5575403Z [DEBUG] [libusb] libusb_free_config_descriptor#1131(config=0x00347520): called...
2023-10-04T14:38:28.5577900Z [DEBUG] [libusb] libusb_free_config_descriptor#1131: returning
2023-10-04T14:38:28.5582365Z [DEBUG] [libusb] libusb_free_device_list#1132(list=0x0034DF38([0x00355788]), unref_devices=1): called...
2023-10-04T14:38:28.5585248Z [DEBUG] [libusb] libusb_free_device_list#1132: returning
2023-10-04T14:38:28.5588738Z [DEBUG] [libusb] libusb_exit#1133(ctx=libusb_context<DEFAULT>): called...
2023-10-04T14:38:28.5591378Z [DEBUG] [libusb] libusb_exit#1133: returning
2023-10-04T14:38:28.5603337Z [INFO] ../../../../../third_party/pcsc-lite/src/src/hotplug_libusb.c:544:HPEstablishUSBNotifications() Hotplug stopped
2023-10-04T14:38:28.5604429Z [DEBUG] [libusb] libusb_bulk_transfer#1130: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
2023-10-04T14:38:28.5609771Z [DEBUG] [libusb] libusb_bulk_transfer#1134(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0x005703DE, length=10, actual_length=0x00570304, timeout=3000): called...
2023-10-04T14:38:28.5656282Z [DEBUG] [emulated IPC] The in-memory file 3 was closed
2023-10-04T14:38:28.5657055Z [DEBUG] [emulated IPC] The in-memory file 4 was closed
2023-10-04T14:38:28.5658058Z [INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:1374:RFCleanupReaders() entering cleaning function
2023-10-04T14:38:28.5658976Z [INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:1383:RFCleanupReaders() Stopping reader: Gemalto PC Twin Reader 00 00
2023-10-04T14:38:28.5660082Z [INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:624:RFRemoveReaderOriginal() UnrefReader() count was: 1
2023-10-04T14:38:28.5660948Z [INFO] ../../../../../third_party/pcsc-lite/src/src/eventhandler.c:175:EHDestroyEventHandler() Stomping thread.
2023-10-04T14:38:28.5664789Z [DEBUG] [emulated IPC] The in-memory file 4 was destroyed
2023-10-04T14:38:28.5666220Z [DEBUG] [libusb] libusb_bulk_transfer#1134: returning "LIBUSB_SUCCESS" [0x00000000], data=0x005703DE<0x81 0x00 0x00 0x00 0x00 0x00 0x0F 0x01 0x00 0x00>, *actual_length=10
2023-10-04T14:38:28.5674808Z [DEBUG] [libusb] libusb_alloc_transfer#1135(iso_packets=0): called...
2023-10-04T14:38:28.5675569Z [INFO] 00039000 ../../src/src/ifdhandler.c:390:IFDHGetCapabilities() tag: 0xFB1, usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
2023-10-04T14:38:28.5676396Z [DEBUG] [libusb] libusb_alloc_transfer#1135: returning 0x0034CE40
2023-10-04T14:38:28.5686720Z [DEBUG] [libusb] libusb_submit_transfer#1136(transfer=0x0034CE40(libusb_transfer(dev_handle=libusb_device_handle<0x0034EEC8>, flags=0, endpoint=0x83(number=3, direction=LIBUSB_ENDPOINT_IN), type=LIBUSB_TRANSFER_TYPE_INTERRUPT, timeout=600000, length=8, callback=0x00000AB8, user_data=0x005703C8, buffer=0x005703D0, num_iso_packets=0))): called...
2023-10-04T14:38:28.5690232Z [INFO] 00001000 ../../src/src/ifdhandler.c:390:IFDHGetCapabilities() tag: 0xFB2, usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
2023-10-04T14:38:28.5694881Z [DEBUG] [emulated IPC] The in-memory file 3 was destroyed
2023-10-04T14:38:28.5698244Z [INFO] ../../../../../third_party/pcsc-lite/src/src/eventhandler.c:200:EHDestroyEventHandler() Request stopping of polling thread
2023-10-04T14:38:28.5702554Z [INFO] 00002000 ../../src/src/ifdhandler.c:355:IFDHStopPolling() usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
2023-10-04T14:38:28.5732500Z [DEBUG] [libusb] libusb_submit_transfer#1136: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:28.5737081Z [DEBUG] [libusb] libusb_cancel_transfer#1137(transfer=0x0034CE40): called...
2023-10-04T14:38:28.5741986Z [DEBUG] [libusb] libusb_cancel_transfer#1137: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:28.5747173Z [DEBUG] [libusb] libusb_handle_events_completed#1138(ctx=libusb_context<0x0034DF54>, completed=0x005703C8): called...
2023-10-04T14:38:28.5760531Z [DEBUG] [libusb] libusb_transfer->callback#1139(libusb_transfer=0x0034CE40(libusb_transfer(dev_handle=libusb_device_handle<0x0034EEC8>, flags=0, endpoint=0x83(number=3, direction=LIBUSB_ENDPOINT_IN), type=LIBUSB_TRANSFER_TYPE_INTERRUPT, timeout=600000, status=LIBUSB_TRANSFER_CANCELLED, length=8, actual_length=0, callback=0x00000AB8, user_data=0x005703C8, buffer=0x005703D0<>, num_iso_packets=0))): called...
2023-10-04T14:38:28.5764392Z [DEBUG] [libusb] libusb_transfer->callback#1139: returning
2023-10-04T14:38:28.5768948Z [DEBUG] [libusb] libusb_handle_events_completed#1138: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:28.5773337Z [DEBUG] [libusb] libusb_free_transfer#1140(transfer=0x0034CE40): called...
2023-10-04T14:38:28.5776563Z [DEBUG] [libusb] libusb_free_transfer#1140: returning
2023-10-04T14:38:28.9788600Z [INFO] ../../../../../third_party/pcsc-lite/src/src/eventhandler.c:504:EHStatusHandlerThread() Die
2023-10-04T14:38:28.9805890Z [INFO] ../../../../../third_party/pcsc-lite/src/src/eventhandler.c:215:EHDestroyEventHandler() Thread stomped.
2023-10-04T14:38:28.9812009Z [INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:1144:RFUnInitializeReader() Attempting shutdown of Gemalto PC Twin Reader 00 00.
2023-10-04T14:38:28.9816185Z [INFO] 00412000 ../../src/src/ifdhandler.c:293:IFDHCloseChannel() usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
2023-10-04T14:38:28.9828111Z [DEBUG] [libusb] libusb_bulk_transfer#1141(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0x006703DE<0x63 0x00 0x00 0x00 0x00 0x00 0x10 0x00 0x00 0x00>, length=10, actual_length=0x00670358, timeout=5000): called...
2023-10-04T14:38:28.9879411Z [DEBUG] [libusb] libusb_bulk_transfer#1141: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
2023-10-04T14:38:28.9886579Z [DEBUG] [libusb] libusb_bulk_transfer#1142(dev=libusb_device_handle<0x0034EEC8>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0x006703DE, length=10, actual_length=0x00670354, timeout=3000): called...
2023-10-04T14:38:28.9934901Z [DEBUG] [libusb] libusb_bulk_transfer#1142: returning "LIBUSB_SUCCESS" [0x00000000], data=0x006703DE<0x81 0x00 0x00 0x00 0x00 0x00 0x10 0x01 0x00 0x00>, *actual_length=10
2023-10-04T14:38:28.9939253Z [DEBUG] [libusb] libusb_release_interface#1143(dev=libusb_device_handle<0x0034EEC8>, interface_number=0): called...
2023-10-04T14:38:28.9966107Z [DEBUG] [libusb] libusb_release_interface#1143: returning "LIBUSB_SUCCESS" [0x00000000]
2023-10-04T14:38:28.9969545Z [DEBUG] [libusb] libusb_close#1144(handle=libusb_device_handle<0x0034EEC8>): called...
2023-10-04T14:38:29.0000454Z [DEBUG] [libusb] libusb_close#1144: returning
2023-10-04T14:38:29.0004014Z [INFO] 00019000 ../../src/src/ccid_usb.c:208:close_libusb_if_needed() libusb_exit
2023-10-04T14:38:29.0008093Z [DEBUG] [libusb] libusb_exit#1145(ctx=libusb_context<0x0034DF54>): called...
2023-10-04T14:38:29.0010080Z [DEBUG] [libusb] libusb_exit#1145: returning
2023-10-04T14:38:29.0014650Z [INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:1001:RFUnloadReader() Unloading reader driver.
2023-10-04T14:38:29.0018767Z [INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:156:ContextsDeinitialize() remaining threads: 0
2023-10-04T14:38:29.0023336Z [DEBUG] [PC/SC-Lite NaCl port] The PC/SC-Lite daemon thread shut down.
2023-10-04T14:38:29.0030909Z [  FAILED  ] SmartCardConnectorApplicationSingleClientTest.SCardConnectProtocolMismatch (1799 ms)
@emaxx-google
Copy link
Collaborator Author

It seems like the card wasn't initialized at the same time as the reader was: when the test tries to do SCardCancel it fails with 0x8010000C ["No smart card inserted."].

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
Code Quality
Awaiting triage
Milestone
No milestone
Development

No branches or pull requests
1 participant
@emaxx-google