Приложение виснет в виртуалке
Добрый день.
Сталкивался ли кто-нибудь с такой проблемой: виснет демон pcscd при работе внутри виртуальной машины. Система устроена так: токен RuToken ECP с лицензией вставлен в машину под управлением Ubuntu 12.03. На ней установлен USB Redirector, который пробрасывает это устройство на клиентскую машину. Клиентская машина работает в виртуалке (OpenStack). Под управлением Ubuntu 14. Там основное приложение считывает информацию о лицензии с ключа. Эта система успешно работает несколько часов. Потом перестаёт.
В логах демона pcscd видно, что он регулярно опрашивает токен (раз в секунду) и получает ответ. Но спустя 0,5 — 3 часа после запуска на очередной запрос не приходит ответа. После этого момента pcsc_scan продолжает видеть токен, но пообщаться с токеном уже не возможно. Попытка отправить сигнал kill -9 демону pcscd ни к чему не приводит. Он просто переходит в состояние defunc.
Скажите, кто-нибудь сталкивался с такой проблемой?
Лог pscd:
00000004 winscard.c:1632:SCardTransmit() UnrefReader() count was: 2
00000003 winscard_svc.c:608:ContextThread() TRANSMIT rv=0x0 for client 14
00000061 winscard_svc.c:319:ContextThread() Received command: TRANSMIT from client 14
00000008 readerfactory.c:772:RFReaderInfoById() RefReader() count was: 1
00000003 winscard.c:1587:SCardTransmit() Send Protocol: T=1
00000004 APDU: 00 A4 00 04 02 00 01 00
00000003 ifdhandler.c:1266:IFDHTransmitToICC() usb:0a89/0030:libudev:0:/dev/bus/usb/002/002 (lun: 0)
00000003 commands.c:1645:CmdXfrBlockTPDU_T0() T=0: 8 bytes
00000006 -> 000000 6F 08 00 00 00 00 5C 00 00 00 00 A4 00 04 02 00 01 00
00003968 <- 000000 80 30 00 00 00 00 5C 00 00 00 62 2C 80 02 02 88 81 02 02 A8 85 06 23 00 09 FF 00 00 82 02 10 00 83 02 00 01 8A 01 05 86 0F 47 02 02 02 00 00 00 02 00 00 00 00 00 00 00 90 00
00000037 SW: 62 2C 80 02 02 88 81 02 02 A8 85 06 23 00 09 FF 00 00 82 02 10 00 83 02 00 01 8A 01 05 86 0F 47 02 02 02 00 00 00 02 00 00 00 00 00 00 00 90 00
00000004 winscard.c:1632:SCardTransmit() UnrefReader() count was: 2
00000004 winscard_svc.c:608:ContextThread() TRANSMIT rv=0x0 for client 14
00000092 winscard_svc.c:319:ContextThread() Received command: TRANSMIT from client 14
00000008 readerfactory.c:772:RFReaderInfoById() RefReader() count was: 1
00000004 winscard.c:1587:SCardTransmit() Send Protocol: T=1
00000003 APDU: 80 40 00 00 00
00000012 ifdhandler.c:1266:IFDHTransmitToICC() usb:0a89/0030:libudev:0:/dev/bus/usb/002/002 (lun: 0)
00000003 commands.c:1645:CmdXfrBlockTPDU_T0() T=0: 5 bytes
00000006 -> 000000 6F 05 00 00 00 00 5D 00 00 00 80 40 00 00 00
00003722 <- 000000 80 02 00 00 00 00 5D 00 00 00 90 00
00000027 SW: 90 00
00000004 winscard.c:1632:SCardTransmit() UnrefReader() count was: 2
00000003 winscard_svc.c:608:ContextThread() TRANSMIT rv=0x0 for client 14
00000037 winscard_svc.c:319:ContextThread() Received command: END_TRANSACTION from client 14
00000007 readerfactory.c:772:RFReaderInfoById() RefReader() count was: 1
00000003 winscard.c:1225:SCardEndTransaction() Status: 0x00000000
00000002 winscard.c:1228:SCardEndTransaction() UnrefReader() count was: 2
00000003 winscard_svc.c:521:ContextThread() END_TRANSACTION rv=0x0 for client 14
00003719 winscard_svc.c:319:ContextThread() Received command: CMD_GET_READERS_STATE from client 14
00000057 winscard_svc.c:319:ContextThread() Received command: STATUS from client 14
00000007 readerfactory.c:772:RFReaderInfoById() RefReader() count was: 1
00000003 winscard.c:1291:SCardStatus() UnrefReader() count was: 2
00000003 winscard_svc.c:561:ContextThread() STATUS rv=0x0 for client 14
00000024 winscard_svc.c:319:ContextThread() Received command: BEGIN_TRANSACTION from client 14
00000006 readerfactory.c:772:RFReaderInfoById() RefReader() count was: 1
00000003 winscard.c:1082:SCardBeginTransaction() Status: 0x00000000
00000002 winscard.c:1085:SCardBeginTransaction() UnrefReader() count was: 2
00000003 winscard_svc.c:505:ContextThread() BEGIN_TRANSACTION rv=0x0 for client 14
00000019 winscard_svc.c:319:ContextThread() Received command: CMD_GET_READERS_STATE from client 14
00000021 winscard_svc.c:319:ContextThread() Received command: STATUS from client 14
00000009 readerfactory.c:772:RFReaderInfoById() RefReader() count was: 1
00000003 winscard.c:1291:SCardStatus() UnrefReader() count was: 2
00000015 winscard_svc.c:561:ContextThread() STATUS rv=0x0 for client 14
00000337 winscard_svc.c:319:ContextThread() Received command: TRANSMIT from client 14
00000038 readerfactory.c:772:RFReaderInfoById() RefReader() count was: 1
00000003 winscard.c:1587:SCardTransmit() Send Protocol: T=1
00000004 APDU: 00 CA 01 32 FF
00000003 ifdhandler.c:1266:IFDHTransmitToICC() usb:0a89/0030:libudev:0:/dev/bus/usb/002/002 (lun: 0)
00000003 commands.c:1645:CmdXfrBlockTPDU_T0() T=0: 5 bytes
00000005 -> 000000 6F 05 00 00 00 00 5E 00 00 00 00 CA 01 32 FF В этом месте лог остановился.
Одновременно с этим обнаружилась такая ошибка в dmesg:
[305016.104010] BUG: soft lockup - CPU#1 stuck for 22s! [pcscd:3129]
[305016.104010] Modules linked in: tusbd(OX) kvm_intel cirrus kvm ttm drm_kms_helper crct10dif_pclmul drm crc32_pclmul joydev ghash_clmulni_intel i2c_piix4 syscopyarea sysfillrect sysimgblt aesni_intel aes_x86_64 lrw pvpanic gf128mul glue_helper ablk_helper cryptd mac_hid serio_raw lp parport hid_generic usbhid hid pata_acpi
[305016.104010] CPU: 1 PID: 3129 Comm: pcscd Tainted: G OX 3.13.0-49-generic #83-Ubuntu
[305016.104010] Hardware name: OpenStack Foundation OpenStack Nova, BIOS Bochs 01/01/2011
[305016.104010] task: ffff8807f27c9800 ti: ffff8807f2d18000 task.ti: ffff8807f2d18000
[305016.104010] RIP: 0010:[<ffffffff81543643>] [<ffffffff81543643>] usb_hcd_check_unlink_urb+0x23/0x60
[305016.104010] RSP: 0018:ffff8807f2d19d70 EFLAGS: 00000202
[305016.104010] RAX: ffff8807ef80ca10 RBX: ffffffff811d1e40 RCX: ffff8807efc69b60
[305016.104010] RDX: 00000000fffffffe RSI: ffff8807efc693c0 RDI: ffff8807efc693e0
[305016.104010] RBP: ffff8807f2d19d70 R08: 0000000000000202 R09: 0000000000004000
[305016.104010] R10: 0000000000000000 R11: 0000000000000246 R12: ffffffff00000000
[305016.104010] R13: 0000000000000019 R14: ffff8807f2e81700 R15: ffff880700000004
[305016.104010] FS: 00007f94ca84c700(0000) GS:ffff88081fc80000(0000) knlGS:0000000000000000
[305016.104010] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[305016.104010] CR2: 00007f683019f0b6 CR3: 00000007f087a000 CR4: 00000000000007e0
[305016.104010] Stack:
[305016.104010] ffff8807f2d19da0 ffffffffa0144738 ffff8807efc693c0 ffff8807f2051c00
[305016.104010] 00000000fffffffe ffff8807efc693c0 ffff8807f2d19dd0 ffffffff8154472d
[305016.104010] ffffffff81493d47 0000000000000202 ffff8807efc693c0 00000000fffffffe
[305016.104010] Call Trace:
[305016.104010] [<ffffffffa0144738>] llIIIIlI+0x28/0x160 [tusbd]
[305016.104010] [<ffffffff8154472d>] unlink1+0x2d/0x130
[305016.104010] [<ffffffff81493d47>] ? get_device+0x17/0x30
[305016.104010] [<ffffffff81546609>] usb_hcd_unlink_urb+0x59/0xe0
[305016.104010] [<ffffffff81547a6a>] usb_kill_urb+0x3a/0xa0
[305016.104010] [<ffffffff81552588>] ? free_async+0xd8/0x100
[305016.104010] [<ffffffff81553f81>] usbdev_do_ioctl+0x7f1/0xf30
[305016.104010] [<ffffffff815546ee>] usbdev_ioctl+0xe/0x20
[305016.104010] [<ffffffff811d1200>] do_vfs_ioctl+0x2e0/0x4c0
[305016.104010] [<ffffffff8104f2bf>] ? kvm_clock_get_cycles+0x1f/0x30
[305016.104010] [<ffffffff810cdba8>] ? ktime_get_ts+0x48/0xe0
[305016.104010] [<ffffffff811d1461>] SyS_ioctl+0x81/0xa0
[305016.104010] [<ffffffff8173263d>] system_call_fastpath+0x1a/0x1f
[305016.104010] Code: 00 5d c3 0f 1f 44 00 00 66 66 66 66 90 48 8b 46 50 55 48 8d 7e 20 48 89 e5 48 8b 48 10 48 83 c0 10 48 39 c1 75 0a eb 20 48 8b 09 <48> 39 c1 74 18 48 39 f9 75 f3 8b 46 18 85 c0 75 18 89 56 18 5d