Red Hat Bugzilla – Bug 1249116
SmartCard does not appear in VM at initial connection with remote-viewer
Last modified: 2017-09-07 05:36:16 EDT
Description of problem: Guest OS does not recognize smart card. Guest OS & Host is RHEL 7.1 spice-gtk3-0.22-2.el7.x86_64 xorg-x11-drv-qxl-0.1.1-12.el7.x86_64 spice-vdagent-0.14.0-9.el7.x86_64 spice-server-0.12.4-9.el7.x86_64 kernel-3.10.0-229.7.2.el7.x86_64 nss-tools-3.19.1-3.el7_1.x86_64 coolkey-1.1.0-28.el7.x86_64 pam_pkcs11-0.6.2-18.el7.x86_64 p11-kit-0.20.7-3.el7.x86_64 How reproducible: always Steps to Reproduce: Connect SmartCard reader to Client machine. Check that client can see smart card: ~|⇒ pklogin_finder debug DEBUG:pam_config.c:248: Using config file /etc/pam_pkcs11/pam_pkcs11.conf DEBUG:pkcs11_lib.c:187: Initializing NSS ... DEBUG:pkcs11_lib.c:197: Initializing NSS ... database=/etc/pki/nssdb DEBUG:pkcs11_lib.c:215: ... NSS Complete DEBUG:pklogin_finder.c:71: loading pkcs #11 module... DEBUG:pkcs11_lib.c:227: Looking up module in list DEBUG:pkcs11_lib.c:230: modList = 0x24dbea0 next = 0x24eb400 DEBUG:pkcs11_lib.c:231: dllName= <null> DEBUG:pkcs11_lib.c:230: modList = 0x24eb400 next = 0x29ec6e0 DEBUG:pkcs11_lib.c:231: dllName= libcoolkeypk11.so DEBUG:pklogin_finder.c:79: initialising pkcs #11 module... PIN for token: Client recognized SM. ~|⇒ lsusb Bus 001 Device 047: ID 08e6:3437 Gemalto (was Gemplus) GemPC Twin SmartCard Reader Connect to guest with: remote-viewer 'spice://xxxxxxxx/?port=3000' --spice-smartcard Guest sees emulated device: [root@dhcp131-118 ~]# lsusb Bus 003 Device 002: ID 08e6:4433 Gemalto (was Gemplus) GemPC433-Swap But guest OS does not see smart card: # pkcs11_inspect debug DEBUG:pam_config.c:238: Using config file /etc/pam_pkcs11/pam_pkcs11.conf DEBUG:pkcs11_lib.c:182: Initializing NSS ... DEBUG:pkcs11_lib.c:192: Initializing NSS ... database=/etc/pki/nssdb DEBUG:pkcs11_lib.c:210: ... NSS Complete DEBUG:pkcs11_inspect.c:69: loading pkcs #11 module... DEBUG:pkcs11_lib.c:235: Looking up module in list DEBUG:pkcs11_lib.c:238: modList = 0x71a600 next = 0x7260f0 DEBUG:pkcs11_lib.c:239: dllName= <null> DEBUG:pkcs11_lib.c:238: modList = 0x7260f0 next = 0x0 DEBUG:pkcs11_lib.c:239: dllName= libcoolkeypk11.so DEBUG:pkcs11_inspect.c:78: initialising pkcs #11 module... DEBUG:pkcs11_inspect.c:95: no token available While active connection with remote-viewer: Plug off SmartCard reader from client's USB port. Plug in back. Guest now can see smart card: # pkcs11_inspect debug DEBUG:pam_config.c:238: Using config file /etc/pam_pkcs11/pam_pkcs11.conf DEBUG:pkcs11_lib.c:182: Initializing NSS ... DEBUG:pkcs11_lib.c:192: Initializing NSS ... database=/etc/pki/nssdb DEBUG:pkcs11_lib.c:210: ... NSS Complete DEBUG:pkcs11_inspect.c:69: loading pkcs #11 module... DEBUG:pkcs11_lib.c:235: Looking up module in list DEBUG:pkcs11_lib.c:238: modList = 0xa51600 next = 0xa5d0f0 DEBUG:pkcs11_lib.c:239: dllName= <null> DEBUG:pkcs11_lib.c:238: modList = 0xa5d0f0 next = 0x0 DEBUG:pkcs11_lib.c:239: dllName= libcoolkeypk11.so DEBUG:pkcs11_inspect.c:78: initialising pkcs #11 module... PIN for token: DEBUG:pkcs11_lib.c:48: PIN = [redhat] DEBUG:pkcs11_lib.c:759: cert 0: found (CoolKey:CAC ID Certificate), "UID=spiceqe,O=Token Key User" DEBUG:mapper_mgr.c:172: Retrieveing mapper module list DEBUG:mapper_mgr.c:73: Loading static module for mapper 'cn' DEBUG:mapper_mgr.c:197: Inserting mapper [cn] into list DEBUG:mapper_mgr.c:73: Loading static module for mapper 'uid' DEBUG:mapper_mgr.c:197: Inserting mapper [uid] into list DEBUG:mapper_mgr.c:73: Loading static module for mapper 'pwent' DEBUG:mapper_mgr.c:197: Inserting mapper [pwent] into list DEBUG:mapper_mgr.c:73: Loading static module for mapper 'null' DEBUG:mapper_mgr.c:197: Inserting mapper [null] into list DEBUG:pkcs11_inspect.c:128: Found '1' certificate(s) DEBUG:pkcs11_inspect.c:132: verifing the certificate #1 DEBUG:cert_vfy.c:34: Verifying Cert: CoolKey:CAC ID Certificate (UID=spiceqe,O=Token Key User) DEBUG:pkcs11_inspect.c:146: Inspecting certificate #1 DEBUG:mapper_mgr.c:243: Cannot find cert data for mapper cn Printing data for mapper uid: spiceqe DEBUG:mapper_mgr.c:243: Cannot find cert data for mapper pwent DEBUG:mapper_mgr.c:235: Mapper 'null' has no inspect() function DEBUG:mapper_mgr.c:214: unloading mapper module list DEBUG:mapper_mgr.c:137: calling mapper_module_end() cn DEBUG:mapper_mgr.c:148: Module cn is static: don't remove DEBUG:mapper_mgr.c:137: calling mapper_module_end() uid DEBUG:mapper_mgr.c:148: Module uid is static: don't remove DEBUG:mapper_mgr.c:137: calling mapper_module_end() pwent DEBUG:mapper_mgr.c:148: Module pwent is static: don't remove DEBUG:mapper_mgr.c:137: calling mapper_module_end() null DEBUG:mapper_mgr.c:148: Module null is static: don't remove DEBUG:pkcs11_inspect.c:163: releasing pkcs #11 module... DEBUG:pkcs11_inspect.c:166: Process completed qemu debug: # export QEMU_CCID_DEBUG=4 # export QEMU_CCID_PASSTHRU_DEBUG=4 # /usr/libexec/qemu-kvm -m 1024 -spice port=$SRCPORT,disable-ticketing,addr=$SRCIPADDR,seamless-migration=on, -vga qxl -device virtio-serial -chardev spicevmc,id=vdagent,name=vdagent -device virtserialport,chardev=vdagent,name=com.redhat.spice.0 -readconfig /etc/qemu-kvm/ich9-ehci-uhci.cfg -chardev spicevmc,name=usbredir,id=usbredirchardev1 -device usb-redir,chardev=usbredirchardev1,id=usbredirdev1,bus=ehci.0,debug=3 $GUEST_IMAGE_PATH -monitor stdio -device intel-hda -device hda-duplex -chardev spicevmc,server,host=127.0.0.1,name=smartcard,id=ccid -device usb-ccid -device ccid-card-passthru,chardev=ccid -usb QEMU 1.5.3 monitor - type 'help' for more information (qemu) usb-ccid: Reset usb-ccid: Reset usb-ccid: Reset usb-ccid: Reset usb-ccid: Reset usb-ccid: Reset usb-ccid: ccid_handle_control: got control (generic) set address (5), value 1 usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 100 usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 200 usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 200 main_channel_link: add main channel client main_channel_handle_parsed: net test: latency 6.302000 ms, bitrate 36945501 bps (35.233975 Mbps) qemu-kvm: usbredirparser: Peer version: spice-gtk 0.27, using 64-bits ids inputs_connect: inputs channel client create red_dispatcher_set_cursor_peer: usb-ccid: CCID Attach usb-ccid: CCID Attach usb-ccid: CCID Attach usb-ccid: Reset usb-ccid: Reset usb-ccid: Reset usb-ccid: Reset usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 100 usb-ccid: Reset usb-ccid: ccid_handle_control: got control (generic) set address (5), value 2 usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 100 usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 200 usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 200 usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 300 usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 302 usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 301 usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 303 usb-ccid: ccid_handle_control: got control (generic) set configuration (9), value 1 usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 304 usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 300 usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 304 main_channel_handle_parsed: agent start usb-ccid: ccid_handle_control: got control GET_DATA_RATES (a103), value 0 usb-ccid: ccid_control get data rates UNIMPLEMENTED usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 300 usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 303 usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 300 usb-ccid: ccid_handle_control: got control (generic) get descriptor (8006), value 301 usb-ccid: ccid_handle_bulk_out 65 GetSlotStatus usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 10 bytes usb-ccid: ccid_calc_status: status = 2 usb-ccid: ccid_bulk_in_copy_to_guest: 10/10 req/act to guest (BULK_IN) usb-ccid: ccid_handle_bulk_out 65 GetSlotStatus usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 10 bytes usb-ccid: ccid_calc_status: status = 2 usb-ccid: ccid_bulk_in_copy_to_guest: 10/10 req/act to guest (BULK_IN) usb-ccid: ccid_handle_bulk_out 6b Escape usb-ccid: handle_data: ERROR: unhandled message type 6Bh usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 10 bytes usb-ccid: ccid_calc_status: status = 66 usb-ccid: ccid_bulk_in_copy_to_guest: 31/10 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 10 < 31 usb-ccid: ccid_handle_bulk_out 65 GetSlotStatus usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 10 bytes usb-ccid: ccid_calc_status: status = 2 usb-ccid: ccid_bulk_in_copy_to_guest: 10/10 req/act to guest (BULK_IN) usb-ccid: ccid_handle_bulk_out 65 GetSlotStatus usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 10 bytes usb-ccid: ccid_calc_status: status = 2 usb-ccid: ccid_bulk_in_copy_to_guest: 10/10 req/act to guest (BULK_IN) usb-ccid: ccid_handle_bulk_out 65 GetSlotStatus usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 10 bytes usb-ccid: ccid_calc_status: status = 2 usb-ccid: ccid_bulk_in_copy_to_guest: 10/10 req/act to guest (BULK_IN) main_channel_handle_parsed: agent start guest doesn't see card. plug it off-on at client's USB, after guest can see it: (qemu) (qemu) ccid-card-passthru: VSC_ATR 12 ccid-card-passthru: atr passes check: 12 total length, 9 historical, 1 optional usb-ccid: handle_data: int_in: notify_slot_change 1, requested len 8 usb-ccid: ccid_handle_bulk_out 65 GetSlotStatus usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 10 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 10/10 req/act to guest (BULK_IN) usb-ccid: ccid_handle_bulk_out 65 GetSlotStatus usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 10 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 10/10 req/act to guest (BULK_IN) usb-ccid: ccid_handle_bulk_out 62 IccPowerOn usb-ccid: ccid_handle_bulk_out: PowerOn: 0 usb-ccid: ccid_write_data_block_atr: atr contains protocol=0 usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 22 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 43/22 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 22 < 43 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 9, len 14 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:9 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 2 (answer seq 9, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 10, len 12 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:10 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 2 (answer seq 10, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 11, len 12 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:11 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 2 (answer seq 11, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 12, len 12 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:12 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 2 (answer seq 12, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 13, len 5 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:13 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 9 (answer seq 13, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 19 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/19 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 19 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 14, len 12 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:14 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 2 (answer seq 14, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 15, len 5 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:15 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 9 (answer seq 15, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 19 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/19 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 19 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 16, len 12 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:16 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 2 (answer seq 16, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 17, len 12 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:17 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 2 (answer seq 17, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 18, len 5 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:18 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 9 (answer seq 18, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 19 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/19 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 19 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 19, len 5 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:19 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 102 (answer seq 19, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 112 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/64 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: 64/48 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 48 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 20, len 12 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:20 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 2 (answer seq 20, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 21, len 5 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:21 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 9 (answer seq 21, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 19 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/19 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 19 < 64 usb-ccid: ccid_handle_bulk_out 65 GetSlotStatus usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 10 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 10/10 req/act to guest (BULK_IN) usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 23, len 14 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:23 usb-ccid: APDU returned to guest 2 (answer seq 23, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 24, len 12 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:24 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 2 (answer seq 24, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 25, len 12 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:25 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 2 (answer seq 25, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 26, len 12 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:26 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 2 (answer seq 26, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 27, len 5 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:27 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 9 (answer seq 27, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 19 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/19 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 19 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 28, len 12 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:28 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 2 (answer seq 28, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 29, len 5 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:29 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 9 (answer seq 29, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 19 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/19 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 19 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 30, len 12 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:30 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 2 (answer seq 30, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 31, len 12 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:31 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 2 (answer seq 31, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 32, len 5 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:32 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 9 (answer seq 32, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 19 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/19 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 19 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 33, len 5 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:33 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 102 (answer seq 33, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 112 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/64 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: 64/48 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 48 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 34, len 12 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:34 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 2 (answer seq 34, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 35, len 5 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:35 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 9 (answer seq 35, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 19 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/19 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 19 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 36, len 12 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:36 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 2 (answer seq 36, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 37, len 5 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:37 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: APDU returned to guest 9 (answer seq 37, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 19 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/19 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 19 < 64 usb-ccid: ccid_handle_bulk_out 6f XfrBlock usb-ccid: ccid_on_apdu_from_guest: seq 38, len 13 usb-ccid: usb-ccid: pending answers:usb-ccid: 0:38 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 0 < 64 ... usb-ccid: APDU returned to guest 2 (answer seq 38, slot 0) usb-ccid: usb-ccid: pending answers:usb-ccid: empty usb-ccid: ccid_reserve_recv_buf: QUEUE: reserve 12 bytes usb-ccid: ccid_calc_status: status = 0 usb-ccid: ccid_bulk_in_copy_to_guest: 64/12 req/act to guest (BULK_IN) usb-ccid: ccid_bulk_in_copy_to_guest: returning short (EREMOTEIO) 12 < 64
It is not necessary to re-plug device. I just tried twice the same command. The first one fails, the second one is success: # pkcs11_inspect debug DEBUG:pam_config.c:238: Using config file /etc/pam_pkcs11/pam_pkcs11.conf DEBUG:pkcs11_lib.c:182: Initializing NSS ... DEBUG:pkcs11_lib.c:192: Initializing NSS ... database=/etc/pki/nssdb DEBUG:pkcs11_lib.c:210: ... NSS Complete DEBUG:pkcs11_inspect.c:69: loading pkcs #11 module... DEBUG:pkcs11_lib.c:235: Looking up module in list DEBUG:pkcs11_lib.c:238: modList = 0x16a1610 next = 0x16ad0d0 DEBUG:pkcs11_lib.c:239: dllName= <null> DEBUG:pkcs11_lib.c:238: modList = 0x16ad0d0 next = 0x0 DEBUG:pkcs11_lib.c:239: dllName= libcoolkeypk11.so DEBUG:pkcs11_inspect.c:78: initialising pkcs #11 module... DEBUG:pkcs11_inspect.c:95: no token available # pkcs11_inspect debug DEBUG:pam_config.c:238: Using config file /etc/pam_pkcs11/pam_pkcs11.conf DEBUG:pkcs11_lib.c:182: Initializing NSS ... DEBUG:pkcs11_lib.c:192: Initializing NSS ... database=/etc/pki/nssdb DEBUG:pkcs11_lib.c:210: ... NSS Complete DEBUG:pkcs11_inspect.c:69: loading pkcs #11 module... DEBUG:pkcs11_lib.c:235: Looking up module in list DEBUG:pkcs11_lib.c:238: modList = 0x214c610 next = 0x21580d0 DEBUG:pkcs11_lib.c:239: dllName= <null> DEBUG:pkcs11_lib.c:238: modList = 0x21580d0 next = 0x0 DEBUG:pkcs11_lib.c:239: dllName= libcoolkeypk11.so DEBUG:pkcs11_inspect.c:78: initialising pkcs #11 module... PIN for token: DEBUG:pkcs11_lib.c:48: PIN = [redhat] DEBUG:pkcs11_lib.c:759: cert 0: found (CoolKey:CAC ID Certificate), "UID=spiceqe,O=Token Key User" DEBUG:mapper_mgr.c:172: Retrieveing mapper module list DEBUG:mapper_mgr.c:73: Loading static module for mapper 'cn' DEBUG:mapper_mgr.c:197: Inserting mapper [cn] into list DEBUG:mapper_mgr.c:73: Loading static module for mapper 'uid' DEBUG:mapper_mgr.c:197: Inserting mapper [uid] into list DEBUG:mapper_mgr.c:73: Loading static module for mapper 'pwent' DEBUG:mapper_mgr.c:197: Inserting mapper [pwent] into list DEBUG:mapper_mgr.c:73: Loading static module for mapper 'null' DEBUG:mapper_mgr.c:197: Inserting mapper [null] into list DEBUG:pkcs11_inspect.c:128: Found '1' certificate(s) DEBUG:pkcs11_inspect.c:132: verifing the certificate #1 DEBUG:cert_vfy.c:34: Verifying Cert: CoolKey:CAC ID Certificate (UID=spiceqe,O=Token Key User) DEBUG:pkcs11_inspect.c:146: Inspecting certificate #1 DEBUG:mapper_mgr.c:243: Cannot find cert data for mapper cn Printing data for mapper uid: spiceqe DEBUG:mapper_mgr.c:243: Cannot find cert data for mapper pwent DEBUG:mapper_mgr.c:235: Mapper 'null' has no inspect() function DEBUG:mapper_mgr.c:214: unloading mapper module list DEBUG:mapper_mgr.c:137: calling mapper_module_end() cn DEBUG:mapper_mgr.c:148: Module cn is static: don't remove DEBUG:mapper_mgr.c:137: calling mapper_module_end() uid DEBUG:mapper_mgr.c:148: Module uid is static: don't remove DEBUG:mapper_mgr.c:137: calling mapper_module_end() pwent DEBUG:mapper_mgr.c:148: Module pwent is static: don't remove DEBUG:mapper_mgr.c:137: calling mapper_module_end() null DEBUG:mapper_mgr.c:148: Module null is static: don't remove DEBUG:pkcs11_inspect.c:163: releasing pkcs #11 module... DEBUG:pkcs11_inspect.c:166: Process completed
Do you have coolkey installed in the guest? (see http://www.spice-space.org/page/SmartcardUsage)
Yes # modutil -dbdir /etc/pki/nssdb/ -list ...... 2. CoolKey PKCS #11 Module library name: libcoolkeypk11.so slots: 1 slot attached status: loaded slot: Gemalto Gemplus USB SmartCard Reader 433-Swap [CCID Interface] ( token: CoolKey -----------------------------------------------------------
I'm wondering if this could be related to rhbz#1316495. Could you try reproducing with spice-0.12.4-15.el7_2.1 https://brewweb.engineering.redhat.com/brew/buildinfo?buildID=491704 when you get a chance?
Tested this with the aforementioned package, and still an issue. Here removing/reinserting the card was a more reliable 'fix' than unplugging/replugging the card reader.
For low-level testing purpose, I'd recommend using pcsc_scan from pscs-tools rather than pkcs11_inspect/pkcs11_login. libcacard does not seem to be able to cope with hot plug/hot unplug of smartcard readers. Here if I unplug/replug a USB card reader, the smartcard needs to be removed/reinserted for libcacard to notice there is a card in the reader, and it really is a limitation of how libcacard interacts with nss. I'm not familiar enough with nss to know the proper way to fix this. Maybe monitor readers coming/going through udev, and refresh libcacard state depending on this. Then figure out whether char devs can be dynamically added / removed in QEMU. Can you confirm that what you tested is - start client - connect reader ?
(In reply to Christophe Fergeau from comment #7) > Can you confirm that what you tested is > - start client > - connect reader > ? Andrei, are these the steps to follow to reproduce this bug? Or can you also reproduce the other way around (reader is connected, smartcard can be seen on the client, but when you then start the client, the guest is not seeing the smartcard)?
I cannot reproduce this bug with: Client: RHEL 7.4 virt-viewer-5.0-7.el7.x86_64 spice-gtk3-0.33-6.el7.x86_64 spice-glib-0.33-6.el7.x86_64 Guest: RHEL 7.4 spice-vdagent-0.14.0-14.el7.x86_64 Host: RHV 4.1 spice-server-0.12.8-2.el7.1.x86_64 Steps: 1. Install on the guest and client: yum group install smart-card or yum install coolkey esc pam_pkcs11 pcsc-lite-ccid pcsc-lite 2. Start pcscd on the guest and client: /bin/systemctl enable pcscd.service /bin/systemctl start pcscd.service 3. Install certificate on the guest and client: certutil -A -d /etc/pki/nssdb/ -n "IdmLab" -i IdmLabEngBosRedhatCom_2011-2019.pem -t "CT,CT,CT" 4. Check "Smartcard Enabled" in "Console" for VM in RHV 4.1. qemu process has: -chardev spicevmc,id=charsmartcard0,name=smartcard -device ccid-card-passthru,chardev=charsmartcard0,id=smartcard0,bus=ccid0.0 5. Connect from client to guest with remote-viewer. console.vv has: enable-smartcard=1 secure-channels=main;inputs;cursor;playback;record;display;smartcard;usbredir 6. In client: # modutil -list -dbdir /etc/pki/nssdb/ Listing of PKCS #11 Modules ----------------------------------------------------------- 1. NSS Internal PKCS #11 Module slots: 2 slots attached status: loaded slot: NSS Internal Cryptographic Services token: NSS Generic Crypto Services slot: NSS User Private Key and Certificate Services token: NSS Certificate DB 2. CoolKey PKCS #11 Module library name: libcoolkeypk11.so slots: 1 slot attached status: loaded slot: Gemalto PC Twin Reader 00 00 token: spice qe ----------------------------------------------------------- # certutil -L -d /etc/pki/nssdb -h all Certificate Nickname Trust Attributes SSL,S/MIME,JAR/XPI Enter Password or Pin for "spice qe": Idmqe CT,C,C spice qe:signing key for spiceqe u,u,u spice qe:encryption key for spiceqe u,u,u # lsusb | grep -i gem Bus 001 Device 004: ID 08e6:3437 Gemalto (was Gemplus) GemPC Twin SmartCard Reader # pklogin_finder PIN for token: spiceqe 8. In guest: # modutil -list -dbdir /etc/pki/nssdb/ Listing of PKCS #11 Modules ----------------------------------------------------------- 1. NSS Internal PKCS #11 Module slots: 2 slots attached status: loaded slot: NSS Internal Cryptographic Services token: NSS Generic Crypto Services slot: NSS User Private Key and Certificate Services token: NSS Certificate DB 2. CoolKey PKCS #11 Module library name: libcoolkeypk11.so slots: 1 slot attached status: loaded slot: Gemalto Gemplus USB SmartCard Reader 433-Swap [CCID Interface] ( token: CoolKey ----------------------------------------------------------- # certutil -L -d /etc/pki/nssdb -h all Certificate Nickname Trust Attributes SSL,S/MIME,JAR/XPI Enter Password or Pin for "CoolKey": Idmqe CT,C,C CoolKey:CAC ID Certificate u,u,u CoolKey:CAC Email Signature Certificate u,u,u # lsusb | grep -i gem Bus 002 Device 002: ID 08e6:4433 Gemalto (was Gemplus) GemPC433-Swap # pklogin_finder PIN for token: spiceqe Above commands works at the first try. Close the bug as "WORKSFORME".