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

Flaky "No smart card inserted" SCardConnect errors in tests #1094

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

Flaky "No smart card inserted" SCardConnect errors in tests #1094

emaxx-google opened this issue Oct 5, 2023 · 1 comment
Assignees
@emaxx-google
Labels
bug

Comments

@emaxx-google
Copy link
Collaborator

Sample failure (although this issue occurs in various tests):

[ RUN      ] SmartCardConnectorApplicationConnectedReaderTest.GetAttribVendorIfdVersion
[DEBUG] Performing services initialization...
[DEBUG] [PC/SC-Lite NaCl port] Initialization...
[DEBUG] [PC/SC-Lite NaCl port] Setting up PC/SC-Lite logging...
[INFO] ../../../../../third_party/pcsc-lite/src/src/debuglog.c:390:DebugLogSetLevel() debug level=debug
[INFO] ../../../../../third_party/pcsc-lite/src/src/debuglog.c:411:DebugLogSetCategory() Debug options: APDU
[DEBUG] [PC/SC-Lite NaCl port] PC/SC-Lite logging was set up.
[DEBUG] [PC/SC-Lite NaCl port] Allocating reader structures...
[DEBUG] [PC/SC-Lite NaCl port] Reader structures allocation finished with the following result: "Command successful.".
[DEBUG] [PC/SC-Lite NaCl port] Performing initial hot plug drivers search...
[DEBUG] [emulated IPC] A blocking in-memory file 1 was created
[DEBUG] [emulated IPC] A blocking in-memory file 2 was created
[DEBUG] [emulated IPC] The in-memory file 1 connected to the in-memory file 2
[DEBUG] [emulated IPC] The in-memory file 2 connected to the in-memory file 1
[DEBUG] [libusb] libusb_init#3127(ctx=NULL): called...
[DEBUG] [libusb] libusb_init#3127: returning "LIBUSB_SUCCESS" [0x00000000]
[DEBUG] [libusb] libusb_get_device_list#3128(ctx=libusb_context<DEFAULT>, list=0xE92FEFE0): called...
[DEBUG] [libusb] libusb_get_device_list#3128: returning 1, *list=0xE314B690([0xE05786E0])
[DEBUG] [libusb] libusb_get_bus_number#3129(dev=0xE05786E0): called...
[DEBUG] [libusb] libusb_get_bus_number#3129: returning 1
[DEBUG] [libusb] libusb_get_device_address#3130(dev=0xE05786E0): called...
[DEBUG] [libusb] libusb_get_device_address#3130: returning 123
[DEBUG] [libusb] libusb_get_device_descriptor#3131(dev=0xE05786E0, desc=0xE92FEFF0): called...
[DEBUG] [libusb] libusb_get_device_descriptor#3131: 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)
[DEBUG] [libusb] libusb_get_active_config_descriptor#3132(dev=0xE05786E0, config=0xE92FF030): called...
[DEBUG] [libusb] libusb_get_active_config_descriptor#3132: returning "LIBUSB_SUCCESS" [0x00000000], *config=0xE0F064C0(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))
[INFO] ../../../../../third_party/pcsc-lite/src/src/hotplug_libusb.c:621:HPAddHotPluggable() Adding USB device: 1:123:0
[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
[INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:964:RFBindFunctions() Loading IFD Handler 3.0
[INFO] 00032039 ../../src/src/ifdhandler.c:111:CreateChannelByNameOrChannel() Lun: 0, device: usb:08e6/3437:libusb-1.0:1:123:0
[INFO] 00000051 ../../src/src/ccid_usb.c:327:OpenUSBByName() Using: executable-module-filesystem/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
[INFO] 00018728 ../../src/src/ccid_usb.c:345:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau ([email protected])
[INFO] 00000064 ../../src/src/ccid_usb.c:346:OpenUSBByName() ifdProductString: Generic CCID driver
[INFO] 00000026 ../../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.
[DEBUG] [libusb] libusb_init#3133(ctx=0x579E4480): called...
[DEBUG] [libusb] libusb_init#3133: returning "LIBUSB_SUCCESS" [0x00000000], *ctx=libusb_context<0xE1112C4C>
[DEBUG] [libusb] libusb_get_device_list#3134(ctx=libusb_context<0xE1112C4C>, list=0xE92FD5D0): called...
[DEBUG] [libusb] libusb_get_device_list#3134: returning 1, *list=0xE3162EF0([0xE0579BE0])
[DEBUG] [libusb] libusb_get_bus_number#3135(dev=0xE0579BE0): called...
[DEBUG] [libusb] libusb_get_bus_number#3135: returning 1
[DEBUG] [libusb] libusb_get_device_address#3136(dev=0xE0579BE0): called...
[DEBUG] [libusb] libusb_get_device_address#3136: returning 123
[DEBUG] [libusb] libusb_get_device_descriptor#3137(dev=0xE0579BE0, desc=0xE92FD680): called...
[DEBUG] [libusb] libusb_get_device_descriptor#3137: 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)
[DEBUG] [libusb] libusb_open#3138(dev=0xE0579BE0, handle=0xE92FC4F0): called...
[DEBUG] [libusb] libusb_open#3138: returning "LIBUSB_SUCCESS" [0x00000000], *handle=libusb_device_handle<0xE3163BF0>
[DEBUG] [libusb] libusb_get_active_config_descriptor#3139(dev=0xE0579BE0, config=0xE92FD6C0): called...
[DEBUG] [libusb] libusb_get_active_config_descriptor#3139: returning "LIBUSB_SUCCESS" [0x00000000], *config=0xE0F0E6B0(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))
[DEBUG] [libusb] libusb_claim_interface#3140(dev=libusb_device_handle<0xE3163BF0>, interface_number=0): called...
[DEBUG] [libusb] libusb_claim_interface#3140: returning "LIBUSB_SUCCESS" [0x00000000]
[INFO] 00003038 ../../src/src/ccid_usb.c:694:OpenUSBByName() Found Vendor/Product: 08E6/3437 (Gemalto PC Twin Reader)
[INFO] 00000033 ../../src/src/ccid_usb.c:696:OpenUSBByName() Using USB bus/device: 1/123
[DEBUG] [libusb] libusb_control_transfer#3141(dev=libusb_device_handle<0xE3163BF0>, bmRequestType=0xA1(recipient=LIBUSB_RECIPIENT_INTERFACE, type=LIBUSB_REQUEST_TYPE_CLASS, direction=LIBUSB_ENDPOINT_IN), bRequest=0x03, wValue=0x0000, wIndex=0x0000, data=0xE92FBF60, wLength=212, timeout=3000): called...
[DEBUG] [libusb] libusb_control_transfer#3141: returning 212, data=0xE92FBF60<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>
[INFO] 00001429 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 12903 bps
[INFO] 00000025 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 25806 bps
[INFO] 00000022 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 51613 bps
[INFO] 00000017 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 103226 bps
[INFO] 00000017 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 206452 bps
[INFO] 00000021 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 412903 bps
[INFO] 00000017 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 825806 bps
[INFO] 00000017 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 154839 bps
[INFO] 00000016 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 258065 bps
[INFO] 00000017 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 17204 bps
[INFO] 00000022 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 34409 bps
[INFO] 00000016 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 68817 bps
[INFO] 00000022 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 137634 bps
[INFO] 00000017 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 275269 bps
[INFO] 00000023 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 550538 bps
[INFO] 00000026 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 172043 bps
[INFO] 00000021 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 12403 bps
[INFO] 00000017 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 24806 bps
[INFO] 00000024 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 49612 bps
[INFO] 00000017 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 99225 bps
[INFO] 00000022 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 198450 bps
[INFO] 00000016 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 396899 bps
[INFO] 00000016 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 74419 bps
[INFO] 00000021 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 124031 bps
[INFO] 00000017 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 86022 bps
[INFO] 00000021 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 38710 bps
[INFO] 00000016 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 64516 bps
[INFO] 00000016 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 10323 bps
[INFO] 00000017 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 20645 bps
[INFO] 00000016 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 41290 bps
[INFO] 00000037 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 82581 bps
[INFO] 00000022 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 165161 bps
[INFO] 00000016 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 30968 bps
[INFO] 00000021 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 18750 bps
[INFO] 00000016 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 37500 bps
[INFO] 00000015 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 75000 bps
[INFO] 00000021 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 150000 bps
[INFO] 00000016 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 300000 bps
[INFO] 00000022 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 600000 bps
[INFO] 00000015 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 112500 bps
[INFO] 00000017 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 187500 bps
[INFO] 00000021 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 12500 bps
[INFO] 00000023 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 25000 bps
[INFO] 00000021 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 50000 bps
[INFO] 00000015 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 100000 bps
[INFO] 00000016 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 200000 bps
[INFO] 00000026 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 400000 bps
[INFO] 00000016 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 125000 bps
[INFO] 00000016 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 56250 bps
[INFO] 00000017 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 93750 bps
[INFO] 00000016 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 62500 bps
[INFO] 00000021 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 28125 bps
[INFO] 00000016 ../../src/src/ccid_usb.c:1425:get_data_rates() declared: 46875 bps
[DEBUG] [libusb] libusb_free_config_descriptor#3142(config=0xE0F0E6B0): called...
[DEBUG] [libusb] libusb_free_config_descriptor#3142: returning
[DEBUG] [libusb] libusb_free_device_list#3143(list=0xE3162EF0([0xE0579BE0]), unref_devices=1): called...
[DEBUG] [libusb] libusb_free_device_list#3143: returning
[DEBUG] [libusb] libusb_alloc_transfer#3144(iso_packets=0): called...
[DEBUG] [libusb] libusb_alloc_transfer#3144: returning 0xE456D650
[DEBUG] [libusb] libusb_submit_transfer#3145(transfer=0xE456D650(libusb_transfer(dev_handle=libusb_device_handle<0xE3163BF0>, flags=0, endpoint=0x83(number=3, direction=LIBUSB_ENDPOINT_IN), type=LIBUSB_TRANSFER_TYPE_INTERRUPT, timeout=100, length=8, callback=0x56CE6A10, user_data=0xE92FDA90, buffer=0xE92FDA70, num_iso_packets=0))): called...
[DEBUG] [libusb] libusb_submit_transfer#3145: returning "LIBUSB_SUCCESS" [0x00000000]
[DEBUG] [libusb] libusb_handle_events_completed#3146(ctx=libusb_context<0xE1112C4C>, completed=0xE92FDA90): called...
[DEBUG] [libusb] libusb_transfer->callback#3147(libusb_transfer=0xE456D650(libusb_transfer(dev_handle=libusb_device_handle<0xE3163BF0>, 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=0x56CE6A10, user_data=0xE92FDA90, buffer=0xE92FDA70<>, num_iso_packets=0))): called...
[DEBUG] [libusb] libusb_transfer->callback#3147: returning
[DEBUG] [libusb] libusb_handle_events_completed#3146: returning "LIBUSB_SUCCESS" [0x00000000]
[DEBUG] [libusb] libusb_free_transfer#3148(transfer=0xE456D650): called...
[DEBUG] [libusb] libusb_free_transfer#3148: returning
[DEBUG] [libusb] libusb_bulk_transfer#3149(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0xE92FDC70<0x65 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00>, length=10, actual_length=0xE92FDB50, timeout=5000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3149: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
[DEBUG] [libusb] libusb_bulk_transfer#3150(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0xE92FDE70, length=10, actual_length=0xE92FD9F0, timeout=3000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3150: returning "LIBUSB_SUCCESS" [0x00000000], data=0xE92FDE70<0x81 0x00 0x00 0x00 0x00 0x00 0x00 0x01 0x00 0x00>, *actual_length=10
[DEBUG] [libusb] libusb_bulk_transfer#3151(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0xE92FDC70<0x65 0x00 0x00 0x00 0x00 0x00 0x01 0x00 0x00 0x00>, length=10, actual_length=0xE92FDB50, timeout=5000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3151: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
[DEBUG] [libusb] libusb_bulk_transfer#3152(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0xE92FDE70, length=10, actual_length=0xE92FD9F0, timeout=100): called...
[DEBUG] [libusb] libusb_bulk_transfer#3152: returning "LIBUSB_SUCCESS" [0x00000000], data=0xE92FDE70<0x81 0x00 0x00 0x00 0x00 0x00 0x01 0x01 0x00 0x00>, *actual_length=10
[DEBUG] [libusb] libusb_bulk_transfer#3153(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0xE3166A50<0x6B 0x01 0x00 0x00 0x00 0x00 0x02 0x00 0x00 0x00 0x6A>, length=11, actual_length=0xE92FD470, timeout=5000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3153: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=11
[DEBUG] [libusb] libusb_bulk_transfer#3154(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0xE0F14E60, length=31, actual_length=0xE92FD310, timeout=100): called...
[DEBUG] [libusb] libusb_bulk_transfer#3154: returning "LIBUSB_SUCCESS" [0x00000000], data=0xE0F14E60<0x83 0x00 0x00 0x00 0x00 0x00 0x02 0x41 0x0A 0x00>, *actual_length=10
[INFO] 00106532 ../../src/src/commands.c:1048:CmdEscapeCheck error on byte 10
[INFO] 00000025 ../../src/src/ccid.c:274:set_gemalto_firmware_features() GET_FIRMWARE_FEATURES failed: 612, len=0
[INFO] 00000029 ../../src/src/ifdhandler.c:390:IFDHGetCapabilities() tag: 0xFB3, usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
[INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:394:RFAddReaderOriginal() Using the reader polling thread
[DEBUG] [libusb] libusb_bulk_transfer#3155(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0xE92FDC70<0x65 0x00 0x00 0x00 0x00 0x00 0x03 0x00 0x00 0x00>, length=10, actual_length=0xE92FDB50, timeout=5000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3155: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
[DEBUG] [libusb] libusb_bulk_transfer#3156(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0xE92FDE70, length=10, actual_length=0xE92FD9F0, timeout=3000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3156: returning "LIBUSB_SUCCESS" [0x00000000], data=0xE92FDE70<0x81 0x00 0x00 0x00 0x00 0x00 0x03 0x01 0x00 0x00>, *actual_length=10
[INFO] 00001505 ../../src/src/ifdhandler.c:390:IFDHGetCapabilities() tag: 0xFAE, usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
[INFO] 00000031 ../../src/src/ifdhandler.c:487:IFDHGetCapabilities() Reader supports 1 slot(s)
[DEBUG] [libusb] libusb_free_config_descriptor#3157(config=0xE0F064C0): called...
[DEBUG] [libusb] libusb_free_config_descriptor#3157: returning
[DEBUG] [libusb] libusb_free_device_list#3158(list=0xE314B690([0xE05786E0]), unref_devices=1): called...
[DEBUG] [libusb] libusb_free_device_list#3158: returning
[DEBUG] [emulated IPC] A blocking in-memory file 3 was created
[DEBUG] [emulated IPC] A blocking in-memory file 4 was created
[DEBUG] [emulated IPC] The in-memory file 3 connected to the in-memory file 4
[DEBUG] [emulated IPC] The in-memory file 4 connected to the in-memory file 3
[DEBUG] [emulated IPC] The in-memory file 1 was closed
[DEBUG] [emulated IPC] The in-memory file 2 was closed
[DEBUG] [PC/SC-Lite NaCl port] Initial hot plug drivers search finished with the following result code: 0.
[DEBUG] [PC/SC-Lite NaCl port] Registering for hot plug events...
[DEBUG] [PC/SC-Lite NaCl port] Registering for hot plug events finished with the following result code: 0.
[DEBUG] [PC/SC-Lite NaCl port] Allocating client structures...
[DEBUG] [PC/SC-Lite NaCl port] Client structures allocation finished with the following result code: 1...
[DEBUG] [PC/SC-Lite NaCl port] Waiting for the readers initialization...
[INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:1433:RFWaitForReaderInit() Waiting init for reader: Gemalto PC Twin Reader 00 00
[DEBUG] [emulated IPC] The in-memory file 1 was destroyed
[DEBUG] [emulated IPC] The in-memory file 2 was destroyed
[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.
[INFO] ../../../../../third_party/pcsc-lite/src/src/hotplug_libusb.c:501:HPEstablishUSBNotifications() Polling forced every 1 second(s)
[EMAXX] EHStatusHandlerThread: BEGIN{: readerName=Gemalto PC Twin Reader 00 00
[EMAXX] EHStatusHandlerThread: calling IFDStatusICC: BEGIN{: readerName=Gemalto PC Twin Reader 00 00
[DEBUG] [libusb] libusb_bulk_transfer#3159(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0xE84FEBB0<0x65 0x00 0x00 0x00 0x00 0x00 0x04 0x00 0x00 0x00>, length=10, actual_length=0xE84FEA90, timeout=5000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3159: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
[DEBUG] [libusb] libusb_bulk_transfer#3160(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0xE84FEDB0, length=10, actual_length=0xE84FE930, timeout=3000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3160: returning "LIBUSB_SUCCESS" [0x00000000], data=0xE84FEDB0<0x81 0x00 0x00 0x00 0x00 0x00 0x04 0x01 0x00 0x00>, *actual_length=10
[EMAXX] EHStatusHandlerThread: calling IFDStatusICC: }END: readerName=Gemalto PC Twin Reader 00 00 rv=0
[EMAXX] EHStatusHandlerThread: calling IFDPowerICC: BEGIN{: readerName=Gemalto PC Twin Reader 00 00
[DEBUG] [libusb] libusb_bulk_transfer#3161(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0xE84FEA50<0x65 0x00 0x00 0x00 0x00 0x00 0x05 0x00 0x00 0x00>, length=10, actual_length=0xE84FE930, timeout=5000): called...
[INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:1433:RFWaitForReaderInit() Waiting init for reader: Gemalto PC Twin Reader 00 00
[DEBUG] [libusb] libusb_bulk_transfer#3161: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
[DEBUG] [libusb] libusb_bulk_transfer#3162(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0xE84FEC50, length=10, actual_length=0xE84FE7D0, timeout=3000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3162: returning "LIBUSB_SUCCESS" [0x00000000], data=0xE84FEC50<0x81 0x00 0x00 0x00 0x00 0x00 0x05 0x01 0x00 0x00>, *actual_length=10
[INFO] 00011830 ../../src/src/ifdhandler.c:1247:IFDHPowerICC() action: PowerUp, usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
[DEBUG] [libusb] libusb_bulk_transfer#3163(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0xE84FE8B0<0x62 0x00 0x00 0x00 0x00 0x00 0x06 0x01 0x00 0x00>, length=10, actual_length=0xE84FE790, timeout=5000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3163: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
[DEBUG] [libusb] libusb_bulk_transfer#3164(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0xE84FEC40, length=43, actual_length=0xE84FE630, timeout=60000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3164: returning "LIBUSB_SUCCESS" [0x00000000], data=0xE84FEC40<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
[EMAXX] EHStatusHandlerThread: calling IFDPowerICC: }END: readerName=Gemalto PC Twin Reader 00 00 rv=0
[EMAXX] EHStatusHandlerThread: calling RFSetPowerState: BEGIN{: readerName=Gemalto PC Twin Reader 00 00
[EMAXX] EHStatusHandlerThread: calling RFSetPowerState: }END: readerName=Gemalto PC Twin Reader 00 00
[DEBUG] [PC/SC-Lite NaCl port] Waiting for the readers initialization finished.
[DEBUG] [PC/SC-Lite NaCl port] Starting PC/SC-Lite daemon thread...
[DEBUG] [PC/SC-Lite NaCl port] PC/SC-Lite daemon thread has started.
[DEBUG] [PC/SC-Lite NaCl port] Initialization successfully finished.
[DEBUG] All services are successfully initialized, posting ready message...
[DEBUG] [PC/SC-Lite NaCl port] [daemon thread] Waiting for the new connected clients...
[DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Created client handler
[DEBUG] [PC/SC-Lite clients manager] Created a new client handler for aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (handler id 1234)
[DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Started processing request SCardEstablishContext(0x02,null,null)...
[INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardEstablishContext#3165(dwScope=SCARD_SCOPE_SYSTEM, pvReserved1=null, pvReserved2=null): called...
[DEBUG] [emulated IPC] A non-blocking in-memory file 5 was created
[DEBUG] [emulated IPC] A non-blocking in-memory file 6 was created
[DEBUG] [emulated IPC] The in-memory file 5 connected to the in-memory file 6
[DEBUG] [emulated IPC] The in-memory file 6 connected to the in-memory file 5
[DEBUG] [PC/SC-Lite NaCl port] [daemon thread] A new client was connected, starting a handler thread...
[DEBUG] [PC/SC-Lite NaCl port] [daemon thread] Waiting for the new connected clients...
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:341:ContextThread() Authorized PC/SC client
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:345:ContextThread() Thread is started: dwClientID=6, threadContext @0xe0791140
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:363:ContextThread() Received command: CMD_VERSION from client 6
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:375:ContextThread() Client is protocol version 4:4
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:397:ContextThread() CMD_VERSION for client 6
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_clnt.c:610:SCardEstablishContextTH() Server is protocol version 4:4
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:363:ContextThread() Received command: ESTABLISH_CONTEXT from client 6
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:210:SCardEstablishContextServer() Establishing Context: 0x4A54EF33
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:466:ContextThread() ESTABLISH_CONTEXT for client 6
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_clnt.c:3254:SCardAddContext() Allocating new SCONTEXTMAP @0xe07a2700
[INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardEstablishContext#3165: returning 0x00000000 ["Command successful."], hContext=0x4A54EF33
[DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Request SCardEstablishContext finished successfully with the following results: [0x00, 0x4A54EF33]
[DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Started processing request SCardConnect(0x4A54EF33,"Gemalto PC Twin Reader 00 00",0x02,0x02)...
[INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardConnect#3166(hContext=0x4A54EF33, szReader="Gemalto PC Twin Reader 00 00", dwShareMode=SCARD_SHARE_SHARED, dwPreferredProtocols=SCARD_PROTOCOL_T1): called...
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:363:ContextThread() Received command: CONNECT from client 6
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:504:ContextThread() Authorized client for 'Gemalto PC Twin Reader 00 00'
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:254:SCardConnectServer() Attempting Connect to Gemalto PC Twin Reader 00 00 using protocol: 2
[INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:835:RFReaderInfo() RefReader() count was: 1
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:307:SCardConnectServer() Card Not Inserted
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:513:SCardConnectServer() UnrefReader() count was: 2
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:524:ContextThread() CONNECT for client 6
[INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardConnect#3166: returning 0x8010000C ["No smart card inserted."]
[DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Request SCardConnect finished successfully with the following results: [0x8010000C]
../../../src/application_unittest.cc:2200: Failure
Expected equality of these values:
  SimulateConnectCallFromJsClient( kFakeHandlerId, scard_context(), kGemaltoPcTwinReaderPcscName0, 0x0002, 0x0002, scard_handle_, active_protocol)
    Which is: -2146435060
  ((LONG)0x00000000)
    Which is: 0
../../../src/application_unittest.cc:2201: Failure
Expected equality of these values:
  active_protocol
    Which is: 0
  static_cast<DWORD>(0x0002)
    Which is: 2
[DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Started processing request SCardGetAttrib(0xBEBEBEBE,0x00010102)...
[INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardGetAttrib#3167(hCard=0xBEBEBEBE, dwAttrId=SCARD_ATTR_VENDOR_IFD_VERSION): called...
[INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardGetAttrib#3167: returning 0x80100003 ["Invalid handle."]
[DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Request SCardGetAttrib finished successfully with the following results: [0x80100003]
../../../src/application_unittest.cc:2541: Failure
Expected equality of these values:
  return_code
    Which is: -2146435069
  ((LONG)0x00000000)
    Which is: 0
../../../src/application_unittest.cc:2545: Failure
Value of: attr
Expected: has 4 elements where
element #0 is equal to '\0',
element #1 is equal to '\0',
element #2 is equal to '\0',
element #3 is equal to '\x2' (2)
  Actual: {}
[DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Started processing request SCardDisconnect(0xBEBEBEBE,0x00)...
[INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardDisconnect#3168(hCard=0xBEBEBEBE, dwDisposition=SCARD_LEAVE_CARD): called...
[INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardDisconnect#3168: returning 0x80100003 ["Invalid handle."]
[DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Request SCardDisconnect finished successfully with the following results: [0x80100003]
../../../src/application_unittest.cc:2207: Failure
Expected equality of these values:
  SimulateDisconnectCallFromJsClient(kFakeHandlerId, scard_handle_, 0x0000)
    Which is: -2146435069
  ((LONG)0x00000000)
    Which is: 0
[DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Started processing request SCardReleaseContext(0x4A54EF33)...
[INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardReleaseContext#3169(hContext=0x4A54EF33): called...
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:363:ContextThread() Received command: RELEASE_CONTEXT from client 6
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard.c:224:SCardReleaseContextServer() Releasing Context: 0x4A54EF33
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:481:ContextThread() RELEASE_CONTEXT for client 6
[DEBUG] [emulated IPC] The in-memory file 5 was closed
[DEBUG] [emulated IPC] The in-memory file 6 was closed
[DEBUG] [emulated IPC] The in-memory file 5 was destroyed
[INFO] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] SCardReleaseContext#3169: returning 0x00000000 ["Command successful."]
[DEBUG] [PC/SC from aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (id 1234)] Request SCardReleaseContext finished successfully with the following results: [0x00]
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:355:ContextThread() Client die: 6
[DEBUG] [emulated IPC] The in-memory file 6 was destroyed
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:1074:MSGCleanupClient() Thread is stopping: dwClientID=6, threadContext @0xe0791140
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:1080:MSGCleanupClient() Freeing SCONTEXT @0xe0791140
[DEBUG] [PC/SC-Lite clients manager] Deleted client handler for aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa (handler id was 1234)
[DEBUG] [PC/SC-Lite NaCl port] Shutting down the PC/SC-Lite daemon thread...
[DEBUG] [PC/SC-Lite NaCl port] [daemon thread] Shutting down...
[INFO] ../../../../../third_party/pcsc-lite/src/src/eventhandler.c:298:EHStatusHandlerThread() powerState: POWER_STATE_POWERED
[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 
[EMAXX] EHStatusHandlerThread: calling EHSignalEventToClients: BEGIN{: readerName=Gemalto PC Twin Reader 00 00
[EMAXX] EHStatusHandlerThread: calling EHSignalEventToClients: }END: readerName=Gemalto PC Twin Reader 00 00
[EMAXX] EHStatusHandlerThread: loop iteration: BEGIN{: readerName=Gemalto PC Twin Reader 00 00
[DEBUG] [libusb] libusb_bulk_transfer#3170(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0xE84FEBB0<0x65 0x00 0x00 0x00 0x00 0x00 0x07 0x00 0x00 0x00>, length=10, actual_length=0xE84FEA90, timeout=5000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3170: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
[DEBUG] [libusb] libusb_bulk_transfer#3171(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0xE84FEDB0, length=10, actual_length=0xE84FE930, timeout=3000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3171: returning "LIBUSB_SUCCESS" [0x00000000], data=0xE84FEDB0<0x81 0x00 0x00 0x00 0x00 0x00 0x07 0x00 0x00 0x00>, *actual_length=10
[DEBUG] [libusb] libusb_alloc_transfer#3172(iso_packets=0): called...
[DEBUG] [libusb] libusb_alloc_transfer#3172: returning 0xE4579DD0
[DEBUG] [libusb] libusb_submit_transfer#3173(transfer=0xE4579DD0(libusb_transfer(dev_handle=libusb_device_handle<0xE3163BF0>, flags=0, endpoint=0x83(number=3, direction=LIBUSB_ENDPOINT_IN), type=LIBUSB_TRANSFER_TYPE_INTERRUPT, timeout=5000, length=8, callback=0x56CE6A10, user_data=0xE84FEDB0, buffer=0xE84FED90, num_iso_packets=0))): called...
[DEBUG] [libusb] libusb_submit_transfer#3173: returning "LIBUSB_SUCCESS" [0x00000000]
[DEBUG] [libusb] libusb_handle_events_completed#3174(ctx=libusb_context<0xE1112C4C>, completed=0xE84FEDB0): called...
[DEBUG] [libusb] libusb_get_device_list#3175(ctx=libusb_context<DEFAULT>, list=0xE92FEFE0): called...
[DEBUG] [libusb] libusb_get_device_list#3175: returning 1, *list=0xE3167FB0([0xE057F820])
[DEBUG] [libusb] libusb_get_bus_number#3176(dev=0xE057F820): called...
[DEBUG] [libusb] libusb_get_bus_number#3176: returning 1
[DEBUG] [libusb] libusb_get_device_address#3177(dev=0xE057F820): called...
[DEBUG] [libusb] libusb_get_device_address#3177: returning 123
[DEBUG] [libusb] libusb_get_device_descriptor#3178(dev=0xE057F820, desc=0xE92FEFF0): called...
[DEBUG] [libusb] libusb_get_device_descriptor#3178: 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)
[DEBUG] [libusb] libusb_get_active_config_descriptor#3179(dev=0xE057F820, config=0xE92FF030): called...
[DEBUG] [libusb] libusb_get_active_config_descriptor#3179: returning "LIBUSB_SUCCESS" [0x00000000], *config=0xE0F26E30(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))
[DEBUG] [libusb] libusb_free_config_descriptor#3180(config=0xE0F26E30): called...
[DEBUG] [libusb] libusb_free_config_descriptor#3180: returning
[DEBUG] [libusb] libusb_free_device_list#3181(list=0xE3167FB0([0xE057F820]), unref_devices=1): called...
[DEBUG] [libusb] libusb_free_device_list#3181: returning
[DEBUG] [libusb] libusb_exit#3182(ctx=libusb_context<DEFAULT>): called...
[DEBUG] [libusb] libusb_exit#3182: returning
[INFO] ../../../../../third_party/pcsc-lite/src/src/hotplug_libusb.c:544:HPEstablishUSBNotifications() Hotplug stopped
[DEBUG] [emulated IPC] The in-memory file 3 was closed
[DEBUG] [emulated IPC] The in-memory file 4 was closed
[DEBUG] [emulated IPC] The in-memory file 3 was destroyed
[DEBUG] [emulated IPC] The in-memory file 4 was destroyed
[INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:1374:RFCleanupReaders() entering cleaning function
[INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:1383:RFCleanupReaders() Stopping reader: Gemalto PC Twin Reader 00 00
[INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:624:RFRemoveReaderOriginal() UnrefReader() count was: 1
[INFO] ../../../../../third_party/pcsc-lite/src/src/eventhandler.c:176:EHDestroyEventHandler() Stomping thread.
[INFO] 00993741 ../../src/src/ifdhandler.c:390:IFDHGetCapabilities() tag: 0xFB1, usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
[INFO] 00000049 ../../src/src/ifdhandler.c:390:IFDHGetCapabilities() tag: 0xFB2, usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
[INFO] ../../../../../third_party/pcsc-lite/src/src/eventhandler.c:201:EHDestroyEventHandler() Request stopping of polling thread
[INFO] 00000080 ../../src/src/ifdhandler.c:355:IFDHStopPolling() usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
[DEBUG] [libusb] libusb_cancel_transfer#3183(transfer=0xE4579DD0): called...
[DEBUG] [libusb] libusb_cancel_transfer#3183: returning "LIBUSB_SUCCESS" [0x00000000]
[DEBUG] [libusb] libusb_transfer->callback#3184(libusb_transfer=0xE4579DD0(libusb_transfer(dev_handle=libusb_device_handle<0xE3163BF0>, 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=0x56CE6A10, user_data=0xE84FEDB0, buffer=0xE84FED90<>, num_iso_packets=0))): called...
[DEBUG] [libusb] libusb_transfer->callback#3184: returning
[DEBUG] [libusb] libusb_handle_events_completed#3174: returning "LIBUSB_SUCCESS" [0x00000000]
[DEBUG] [libusb] libusb_free_transfer#3185(transfer=0xE4579DD0): called...
[DEBUG] [libusb] libusb_free_transfer#3185: returning
[DEBUG] [libusb] libusb_bulk_transfer#3186(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0xE84FEA50<0x65 0x00 0x00 0x00 0x00 0x00 0x08 0x00 0x00 0x00>, length=10, actual_length=0xE84FE930, timeout=5000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3186: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
[DEBUG] [libusb] libusb_bulk_transfer#3187(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0xE84FEC50, length=10, actual_length=0xE84FE7D0, timeout=3000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3187: returning "LIBUSB_SUCCESS" [0x00000000], data=0xE84FEC50<0x81 0x00 0x00 0x00 0x00 0x00 0x08 0x00 0x00 0x00>, *actual_length=10
[INFO] 00403043 ../../src/src/ifdhandler.c:1247:IFDHPowerICC() action: PowerDown, usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
[DEBUG] [libusb] libusb_bulk_transfer#3188(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0xE84FEA70<0x63 0x00 0x00 0x00 0x00 0x00 0x09 0x00 0x00 0x00>, length=10, actual_length=0xE84FE950, timeout=5000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3188: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
[DEBUG] [libusb] libusb_bulk_transfer#3189(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0xE84FEA70, length=10, actual_length=0xE84FE7F0, timeout=3000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3189: returning "LIBUSB_SUCCESS" [0x00000000], data=0xE84FEA70<0x81 0x00 0x00 0x00 0x00 0x00 0x09 0x01 0x00 0x00>, *actual_length=10
[DEBUG] [libusb] libusb_bulk_transfer#3190(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0xE84FEA70<0x63 0x00 0x00 0x00 0x00 0x00 0x0A 0x00 0x00 0x00>, length=10, actual_length=0xE84FE950, timeout=5000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3190: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
[DEBUG] [libusb] libusb_bulk_transfer#3191(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0xE84FEA70, length=10, actual_length=0xE84FE7F0, timeout=3000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3191: returning "LIBUSB_SUCCESS" [0x00000000], data=0xE84FEA70<0x81 0x00 0x00 0x00 0x00 0x00 0x0A 0x01 0x00 0x00>, *actual_length=10
[INFO] ../../../../../third_party/pcsc-lite/src/src/eventhandler.c:494:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED
[INFO] ../../../../../third_party/pcsc-lite/src/src/eventhandler.c:516:EHStatusHandlerThread() Die
[INFO] ../../../../../third_party/pcsc-lite/src/src/eventhandler.c:216:EHDestroyEventHandler() Thread stomped.
[INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:1144:RFUnInitializeReader() Attempting shutdown of Gemalto PC Twin Reader 00 00.
[INFO] 00004623 ../../src/src/ifdhandler.c:293:IFDHCloseChannel() usb:08e6/3437:libusb-1.0:1:123:0 (lun: 0)
[DEBUG] [libusb] libusb_bulk_transfer#3192(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x01(number=1, direction=LIBUSB_ENDPOINT_OUT), data=0xDF4FD3B0<0x63 0x00 0x00 0x00 0x00 0x00 0x0B 0x00 0x00 0x00>, length=10, actual_length=0xDF4FD290, timeout=5000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3192: returning "LIBUSB_SUCCESS" [0x00000000], *actual_length=10
[DEBUG] [libusb] libusb_bulk_transfer#3193(dev=libusb_device_handle<0xE3163BF0>, endpoint=0x82(number=2, direction=LIBUSB_ENDPOINT_IN), data=0xDF4FD3B0, length=10, actual_length=0xDF4FD130, timeout=3000): called...
[DEBUG] [libusb] libusb_bulk_transfer#3193: returning "LIBUSB_SUCCESS" [0x00000000], data=0xDF4FD3B0<0x81 0x00 0x00 0x00 0x00 0x00 0x0B 0x01 0x00 0x00>, *actual_length=10
[DEBUG] [libusb] libusb_release_interface#3194(dev=libusb_device_handle<0xE3163BF0>, interface_number=0): called...
[DEBUG] [libusb] libusb_release_interface#3194: returning "LIBUSB_SUCCESS" [0x00000000]
[DEBUG] [libusb] libusb_close#3195(handle=libusb_device_handle<0xE3163BF0>): called...
[DEBUG] [libusb] libusb_close#3195: returning
[INFO] 00004065 ../../src/src/ccid_usb.c:208:close_libusb_if_needed() libusb_exit
[DEBUG] [libusb] libusb_exit#3196(ctx=libusb_context<0xE1112C4C>): called...
[DEBUG] [libusb] libusb_exit#3196: returning
[INFO] ../../../../../third_party/pcsc-lite/src/src/readerfactory.c:1001:RFUnloadReader() Unloading reader driver.
[INFO] ../../../../../third_party/pcsc-lite/src/src/winscard_svc.c:156:ContextsDeinitialize() remaining threads: 0
[DEBUG] [PC/SC-Lite NaCl port] The PC/SC-Lite daemon thread shut down.
[  FAILED  ] SmartCardConnectorApplicationConnectedReaderTest.GetAttribVendorIfdVersion (1581 ms)
@emaxx-google emaxx-google self-assigned this Oct 5, 2023
@emaxx-google
Copy link
Collaborator Author

It seems that PC/SC-Lite doesn't let connecting to the card until the background thread completed some initialization (which is designated, in particular, by the Card ATR: log). So even if the card is present straight away, a quickly arriving SCardConnect() call may fail because of the timings.

This doesn't seem like a trivial thing to fix. Either we could try improving the PC/SC-Lite behavior, so that it actually finishes the card initialization together with the reader's one. Or we could try changing all the tests to wait until the card readiness is signaled.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@emaxx-google emaxx-google

Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@emaxx-google