Hello dear linux USB users and developers,
I've got a bit desperate question, but maybe somebody will have
some idea on what to try..
we're migrating lots (thousands) of users from very old opensuse running
2.6.13 kernel to new centos based system running 4.4.52 kernel.
There are security tokens in use on desktops - Ikey 4000. They work,
but on new system initialisation of token and reading certificates is taking
very long, slowing firefox (and other pkcs11 users) start by ~20seconds. Since
users are running those token using apps very often, this is causing lots of hassle..
The problem is, that token support is proprietary, I don't have any sources, just
those arcane opensc + openct binaries built for opensuse I'm forced to on new system
(therefore I'm also using 32bit firefox). Since the switch to new tokens with better
support is planned on next year, I'd really love to resolve this issue.
I've tried tracing all related binaries, and I think the problem is in ifdhandler
slow access to device..
sample ifdhandler debug output is here:
Debug: ifdhandler_process: ifdhandler_process(cmd=CT_CMD_TRANSACT, unit=0)
Debug: ifd_protocol_transceive: cmd: 00 b0 04 ec dd
Debug: t1_xcv: sending 00 00 05 00 b0 04 ec dd 80
Debug: ifd_usb_control: usb req type=x41 req=x17 val=x0000 ind=x0005 len=5
Debug: ifd_usb_control: send b0 04 ec dd 80
Debug: ifd_usb_control: usb req type=xc1 req=x01 val=x0000 ind=x0000 len=255
Debug: ifd_usb_control: recv 00 c3 01 26 e4 04 ec dd 80 02 10 00 34 8b 9f 8e 07 f4 22 de bc 60 fb a8 a0 8a a4 0c 11 0f 33 90 00 01 1c ad 80 1b 84 31 2a 40 11 fe 4d 18 23 08 c6 cd 90 b5 44 01 21 24 88 a6 0b 40 94 21 78 78 b0 95 72 19 20 e0 1a a6 07 e3 69 c4 41 4c 00 66 04 a3 01 b2 d0 c1 32 0a 60 05 56 d8 16 d1 b4 04 10 05 80 c4 87 8c 61 12 73 5a fa a8 61 b4 28 25 ba 4c 24 92 c9 28 9a 84 49 0b 00 4a 27 94 45 02 81 11 ed 42 a2 90 c0 aa b0 91 59 04 6a 20 a1 2b 40 c3 27 3c 05 a9 4a 2d 05 00 02 87 91 28 10 17 16 ad 00 41 42 92 20 94 18 20 83 cb ae 42 0e 58 52 d1 00 29 41 12 3c 40 00 c3 01 26 e4 04 ec dd 80 02 10 00 34 8b 9f 8e 07 f4 22 de bc 60 fb a8 a0 8a a4 0c 11 0f 33 90 00 01 1c ad 80 1b 84 31 2a 40 11 fe 4d 18 23 08 c6 cd 90 b5 44 01 21 24 88 a6 0b 40 94 21 78 78 b0 95 72 19 20 e0 1a
Debug: t1_xcv: received 00 c3 01 26 e4
Debug: t1_transceive: CT sent S-block with wtx=38
Debug: t1_xcv: sending 00 e3 01 26 c4
Debug: ifd_usb_control: usb req type=x41 req=x17 val=xe300 ind=x2601 len=1
Debug: ifd_usb_control: send c4
Debug: ifd_usb_control: usb req type=xc1 req=x01 val=x0000 ind=x0000 len=255
Debug: ifd_usb_control: recv 00 60 20 35 9c b6 98 cd e1 e2 18 08 f0 8b 42 8d c9 b2 3f f7 09 35 29 dc 95 cf 58 f5 91 c1 2d 86 37 2a dc 1a 80 1b 84 31 2a 40 11 fe 4d 18 23 08 c6 cd 90 b5 44 01 21 24 88 a6 0b 40 94 21 78 78 b0 95 72 19 20 e0 1a a6 07 e3 69 c4 41 4c 00 66 04 a3 01 b2 d0 c1 32 0a 60 05 56 d8 16 d1 b4 04 10 05 80 c4 87 8c 61 12 73 5a fa a8 61 b4 28 25 ba 4c 24 92 c9 28 9a 84 49 0b 00 4a 27 94 45 02 81 11 ed 42 a2 90 c0 aa b0 91 59 04 6a 20 a1 2b 40 c3 27 3c 05 a9 4a 2d 05 00 02 87 91 28 10 17 16 ad 00 41 42 92 20 94 18 20 83 cb ae 42 0e 58 52 d1 00 29 41 12 3c 40 00 60 20 35 9c b6 98 cd e1 e2 18 08 f0 8b 42 8d c9 b2 3f f7 09 35 29 dc 95 cf 58 f5 91 c1 2d 86 37 2a dc 1a 80 1b 84 31 2a 40 11 fe 4d 18 23 08 c6 cd 90 b5 44 01 21 24 88 a6 0b 40 94 21 78 78 b0 95 72 19 20 e0 1a
(repeats many times).
strace of the same process:
18:27:24 poll([{fd=3, events=POLLHUP}, {fd=4, events=POLLIN}, {fd=6, events=POLLOUT}], 3, 1000) = 1 ([{fd=6, revents=POLLOUT}])
18:27:24 time(NULL) = 1511717244
18:27:24 rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {SIG_IGN, [], 0}, 8) = 0
18:27:24 write(6, "\v\0\0\0\0\0\0\0\0\0)\0E\0&P1\t\355\17\17\17\17\17\17\0\0\1\0\0\0\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\0\0\1\0\220\0", 53) = 53
18:27:24 rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {SIG_IGN, [], 0}, 8) = 0
18:27:24 time(NULL) = 1511717244
18:27:24 poll([{fd=3, events=POLLHUP}, {fd=4, events=POLLIN}, {fd=6, events=POLLOUT}], 3, 1000) = 1 ([{fd=6, revents=POLLOUT}])
18:27:24 time(NULL) = 1511717244
18:27:24 rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {SIG_IGN, [], 0}, 8) = 0
18:27:24 rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {SIG_IGN, [], 0}, 8) = 0
18:27:24 time(NULL) = 1511717244
18:27:24 poll([{fd=3, events=POLLHUP}, {fd=4, events=POLLIN}, {fd=6, events=POLLIN}], 3, 1000) = 1 ([{fd=6, revents=POLLIN}])
18:27:24 time(NULL) = 1511717244
18:27:24 read(6, "\f\0\0\0\0\0\0\0\0\0\n\0!\0\304\0\5\0\260\0\0\374", 3857) = 22
18:27:24 time(NULL) = 1511717244
18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 5
18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 1
18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 0
18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 0
18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 0
18:27:24 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
18:27:25 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 0
18:27:25 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
18:27:25 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 0
18:27:25 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
18:27:25 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 0
18:27:25 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
18:27:25 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 0
18:27:25 ioctl(3, SNDRV_CTL_IOCTL_PVERSION or USBDEVFS_CONTROL, 0xffdd9304) = 255
18:27:25 time(NULL) = 1511717245
I have to admit I don't have much clue of what does ifdhandler mean, and also wasn't
able to find much about mentioned syscalls..
I know that I'm probably providing insufficient information here, but does
somebody have some Idea on what I should check or how to better debug this?
if I could provide some more relevant information, please let me know..
thanks a lot in advance
BR
nikola ciprich
--
-------------------------------------
Ing. Nikola CIPRICH
LinuxBox.cz, s.r.o.
28.rijna 168, 709 00 Ostrava
tel.: +420 591 166 214
fax: +420 596 621 273
mobil: +420 777 093 799
www.linuxbox.cz
mobil servis: +420 737 238 656
email servis: servis@xxxxxxxxxxx
-------------------------------------
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
