usb/83863: Communication problem between opensc/openct via USB
with e-gate smart-card.
Janos Mohacsi
mohacsi at niif.hu
Thu Jul 28 17:20:19 GMT 2005
The following reply was made to PR usb/83863; it has been noted by GNATS.
From: Janos Mohacsi <mohacsi at niif.hu>
To: bug-followup at FreeBSD.org, janos.mohacsi at bsd.hu, hselasky at c2i.net
Cc:
Subject: Re: usb/83863: Communication problem between opensc/openct via USB
with e-gate smart-card.
Date: Thu, 28 Jul 2005 19:12:59 +0200
Here I send several debuging output.
relevant part of /var/log/debug:
Jul 28 19:01:54 scone ifdhandler[71277]: ifd_open: trying to open
egate@/dev/ugen0
Jul 28 19:01:54 scone ifdhandler[71277]: eg_open: device=/dev/ugen0
Jul 28 19:01:54 scone ifdhandler[71277]: ifd_sysdep_device_type: BSD:
ifd_sysdep_device_type(/dev/ugen0)
Jul 28 19:01:54 scone ifdhandler[71277]: ifd_sysdep_device_type: BSD:
returning IFD_DEVICE_TYPE_USB
Jul 28 19:01:54 scone ifdhandler[71277]: eg_activate: called.
Jul 28 19:01:54 scone ifdhandler[71277]: eg_card_status: slot=0
Jul 28 19:01:54 scone ifdhandler[71277]: ifdhandler_poll_presence: card
status change: 0 -> 1
Jul 28 19:01:55 scone ifdhandler[71277]: eg_card_status: slot=0
Jul 28 19:02:02 scone last message repeated 7 times
Jul 28 19:02:02 scone ifdhandler[71277]: ifdhandler_process:
ifdhandler_process(cmd=CT_CMD_RESET, unit=0)
Jul 28 19:02:02 scone ifdhandler[71277]: eg_card_reset: called.
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_usb_control: usb req
type=x40 req=x90 val=x0000 ind=x0000 len=0
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
ifd_sysdep_usb_control(0x90)
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
CTRL bmRequestType 0x40 bRequest 0x90 wValue 0x0 wIndex
0x0 wLength 0x0
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
ctrl.ucr_data == NULL
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
ifd_sysdep_usb_control(0xa0)
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
CTRL bmRequestType 0xc0 bRequest 0xa0 wValue 0x0 wIndex
0x0 wLength 0x1
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
CTRL SEND data f0
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
CTRL RECV data 00
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_usb_control: usb req
type=xc0 req=xa0 val=x0000 ind=x0000 len=1
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_usb_control: recv 00
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
ifd_sysdep_usb_control(0x83)
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
CTRL bmRequestType 0xc0 bRequest 0x83 wValue 0x0 wIndex
0x0 wLength 0x23
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
CTRL SEND data 05 00 00 00 05 00 00 00 00 01 07 28 00 0
0 00 01 64 ca 56 0d 66 84 07 28 00 01 07 28 10 ab bf bf 05 00 00
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
CTRL RECV data 3b 95 18 40 ff 62 01 02 01 04
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_usb_control: usb req
type=xc0 req=x83 val=x0000 ind=x0000 len=10
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_usb_control: recv 3b 95 18
40 ff 62 01 02 01 04
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_protocol_select: atr= 3b 95
18 40 ff 62 01 02 01 04
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_protocol_select: default
T=0, supported protocols=0x1
Jul 28 19:02:02 scone ifdhandler[71277]: eg_set_protocol: proto=0
Jul 28 19:02:02 scone ifdhandler[71277]: ifdhandler_process:
ifdhandler_process(cmd=CT_CMD_LOCK, unit=0)
Jul 28 19:02:02 scone ifdhandler[71277]: ifdhandler_lock: granted excl
lock 0 for slot 0 by uid=4294967294
Jul 28 19:02:02 scone ifdhandler[71277]: ifdhandler_process:
ifdhandler_process(cmd=CT_CMD_TRANSACT, unit=0)
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_protocol_transceive: cmd:
c0 a4 00 00 02 3f 00
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
ifd_sysdep_usb_control(0xa0)
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
CTRL bmRequestType 0xc0 bRequest 0xa0 wValue 0x0 wIndex
0x0 wLength 0x1
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
CTRL SEND data 28
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
CTRL RECV data 00
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_usb_control: usb req
type=xc0 req=xa0 val=x0000 ind=x0000 len=1
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_usb_control: recv 00
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_usb_control: usb req
type=x40 req=x80 val=x0000 ind=x0000 len=5
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_usb_control: send c0 a4 00
00 02
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
ifd_sysdep_usb_control(0x80)
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
CTRL bmRequestType 0x40 bRequest 0x80 wValue 0x0 wIndex
0x0 wLength 0x5
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control: BSD:
CTRL SEND data c0 a4 00 00 02
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_sysdep_usb_control:
USB_DO_REQUEST failed: -1
Jul 28 19:02:02 scone ifdhandler[71277]: ifd_protocol_transceive:
transceive error: Communication error
Jul 28 19:02:02 scone ifdhandler[71277]: ifdhandler_unlock_all: released
excl lock 0 for slot 0 by uid=4294967294
Jul 28 19:02:03 scone ifdhandler[71277]: eg_card_status: slot=0
The relevant part of /var/log/messages:
Jul 28 19:02:00 scone kernel: usb_event_thread: woke up
Jul 28 19:02:00 scone kernel: usb_discover
Jul 28 19:02:02 scone kernel: usbd_alloc_xfer() = 0xc43ca200
Jul 28 19:02:02 scone kernel: usbd_transfer: xfer=0xc43ca200, flags=6,
pipe=0xc2ee7380, running=0
Jul 28 19:02:02 scone kernel: usbd_dump_queue: pipe=0xc2ee7380
Jul 28 19:02:02 scone kernel: usb_insert_transfer: pipe=0xc2ee7380
running=0 timeout=10000
Jul 28 19:02:02 scone kernel: usb_schedsoftintr: polling=0
Jul 28 19:02:02 scone kernel: usb_transfer_complete: pipe=0xc2ee7380
xfer=0xc43ca200 status=0 actlen=0
Jul 28 19:02:02 scone kernel: usb_transfer_complete: repeat=0 new head=0
Jul 28 19:02:02 scone kernel: usbd_start_next: pipe=0xc2ee7380, xfer=0
Jul 28 19:02:02 scone kernel: usbd_free_xfer: 0xc43ca200
Jul 28 19:02:02 scone kernel: usbd_alloc_xfer() = 0xc43ca200
Jul 28 19:02:02 scone kernel: usbd_transfer: xfer=0xc43ca200, flags=6,
pipe=0xc2ee7380, running=0
Jul 28 19:02:02 scone kernel: usbd_dump_queue: pipe=0xc2ee7380
Jul 28 19:02:02 scone kernel: usb_allocmem: use frag=0xc1a81b80 size=1
Jul 28 19:02:02 scone kernel: usb_insert_transfer: pipe=0xc2ee7380
running=0 timeout=10000
Jul 28 19:02:02 scone kernel: usb_schedsoftintr: polling=0
Jul 28 19:02:02 scone kernel: usb_transfer_complete: pipe=0xc2ee7380
xfer=0xc43ca200 status=0 actlen=1
Jul 28 19:02:02 scone kernel: usb_freemem: frag=0xc1a81b80
Jul 28 19:02:02 scone kernel: usb_transfer_complete: repeat=0 new head=0
Jul 28 19:02:02 scone kernel: usbd_start_next: pipe=0xc2ee7380, xfer=0
Jul 28 19:02:02 scone kernel: usbd_free_xfer: 0xc43ca200
Jul 28 19:02:02 scone kernel: usbd_alloc_xfer() = 0xc43ca200
Jul 28 19:02:02 scone kernel: usbd_transfer: xfer=0xc43ca200, flags=6,
pipe=0xc2ee7380, running=0
Jul 28 19:02:02 scone kernel: usbd_dump_queue: pipe=0xc2ee7380
Jul 28 19:02:02 scone kernel: usb_allocmem: use frag=0xc1a81b80 size=35
Jul 28 19:02:02 scone kernel: usb_insert_transfer: pipe=0xc2ee7380
running=0 timeout=10000
Jul 28 19:02:02 scone kernel: usb_schedsoftintr: polling=0
Jul 28 19:02:02 scone kernel: usb_transfer_complete: pipe=0xc2ee7380
xfer=0xc43ca200 status=0 actlen=10
Jul 28 19:02:02 scone kernel: usb_freemem: frag=0xc1a81b80
Jul 28 19:02:02 scone kernel: usb_transfer_complete: repeat=0 new head=0
Jul 28 19:02:02 scone kernel: usbd_start_next: pipe=0xc2ee7380, xfer=0
Jul 28 19:02:02 scone kernel: usbd_free_xfer: 0xc43ca200
Jul 28 19:02:02 scone kernel: usbd_alloc_xfer() = 0xc43ca200
Jul 28 19:02:02 scone kernel: usbd_transfer: xfer=0xc43ca200, flags=6,
pipe=0xc2ee7380, running=0
Jul 28 19:02:02 scone kernel: usbd_dump_queue: pipe=0xc2ee7380
Jul 28 19:02:02 scone kernel: usb_allocmem: use frag=0xc1a81b80 size=1
Jul 28 19:02:02 scone kernel: usb_insert_transfer: pipe=0xc2ee7380
running=0 timeout=10000
Jul 28 19:02:02 scone kernel: usb_schedsoftintr: polling=0
Jul 28 19:02:02 scone kernel: usb_transfer_complete: pipe=0xc2ee7380
xfer=0xc43ca200 status=0 actlen=1
Jul 28 19:02:02 scone kernel: usb_freemem: frag=0xc1a81b80
Jul 28 19:02:02 scone kernel: usb_transfer_complete: repeat=0 new head=0
Jul 28 19:02:02 scone kernel: usbd_start_next: pipe=0xc2ee7380, xfer=0
Jul 28 19:02:02 scone kernel: usbd_free_xfer: 0xc43ca200
Jul 28 19:02:02 scone kernel: usbd_alloc_xfer() = 0xc43ca200
Jul 28 19:02:02 scone kernel: usbd_transfer: xfer=0xc43ca200, flags=6,
pipe=0xc2ee7380, running=0
Jul 28 19:02:02 scone kernel: usbd_dump_queue: pipe=0xc2ee7380
Jul 28 19:02:02 scone kernel: usb_allocmem: use frag=0xc1a81b80 size=5
Jul 28 19:02:02 scone kernel: usb_insert_transfer: pipe=0xc2ee7380
running=0 timeout=10000
Jul 28 19:02:02 scone kernel: usb_schedsoftintr: polling=0
Jul 28 19:02:02 scone kernel: usb_transfer_complete: pipe=0xc2ee7380
xfer=0xc43ca200 status=17 actlen=5
Jul 28 19:02:02 scone kernel: usb_freemem: frag=0xc1a81b80
Jul 28 19:02:02 scone kernel: usb_transfer_complete: repeat=0 new head=0
Jul 28 19:02:02 scone kernel: usbd_start_next: pipe=0xc2ee7380, xfer=0
Jul 28 19:02:02 scone kernel: usbd_transfer: xfer=0xc43ca200, flags=2,
pipe=0xc2ee7380, running=0
Jul 28 19:02:02 scone kernel: usbd_dump_queue: pipe=0xc2ee7380
Jul 28 19:02:02 scone kernel: usb_allocmem: use frag=0xc1a81b80 size=2
Jul 28 19:02:02 scone kernel: usb_insert_transfer: pipe=0xc2ee7380
running=0 timeout=5000
Jul 28 19:02:02 scone kernel: usb_schedsoftintr: polling=0
Jul 28 19:02:02 scone kernel: usb_transfer_complete: pipe=0xc2ee7380
xfer=0xc43ca200 status=0 actlen=2
Jul 28 19:02:02 scone kernel: usb_freemem: frag=0xc1a81b80
Jul 28 19:02:02 scone kernel: usb_transfer_complete: repeat=0 new head=0
Jul 28 19:02:02 scone kernel: usbd_start_next: pipe=0xc2ee7380, xfer=0
Jul 28 19:02:02 scone kernel: usbd_do_request: status = 0x0000
Jul 28 19:02:02 scone kernel: usbd_free_xfer: 0xc43ca200
Jul 28 19:02:02 scone ifdhandler[71277]: usb_do_request failed:
Input/output error (5)
The output of dmesg:
ums0: at uhub0 port 1 (addr 2) disconnected
ums0: detached
Jul 28 18:59:27 scone moused: unable to open /dev/ums0: No such file or
directory
ugen0: at uhub1 port 1 (addr 2) disconnected
All threads purged from ugen0
ugen0: detached
ugen0: SchlumbergerSema SchlumbergerSema Cryptoflex e-gate, rev
1.10/1.00, addr 2
usb_event_thread: woke up
usb_discover
usbd_alloc_xfer() = 0xc43ca200
usbd_transfer: xfer=0xc43ca200, flags=6, pipe=0xc2ee7380, running=0
usbd_dump_queue: pipe=0xc2ee7380
usb_insert_transfer: pipe=0xc2ee7380 running=0 timeout=10000
usb_schedsoftintr: polling=0
usb_transfer_complete: pipe=0xc2ee7380 xfer=0xc43ca200 status=0 actlen=0
usb_transfer_complete: repeat=0 new head=0
usbd_start_next: pipe=0xc2ee7380, xfer=0
usbd_free_xfer: 0xc43ca200
usbd_alloc_xfer() = 0xc43ca200
usbd_transfer: xfer=0xc43ca200, flags=6, pipe=0xc2ee7380, running=0
usbd_dump_queue: pipe=0xc2ee7380
usb_allocmem: use frag=0xc1a81b80 size=1
usb_insert_transfer: pipe=0xc2ee7380 running=0 timeout=10000
usb_schedsoftintr: polling=0
usb_transfer_complete: pipe=0xc2ee7380 xfer=0xc43ca200 status=0 actlen=1
usb_freemem: frag=0xc1a81b80
usb_transfer_complete: repeat=0 new head=0
usbd_start_next: pipe=0xc2ee7380, xfer=0
usbd_free_xfer: 0xc43ca200
usbd_alloc_xfer() = 0xc43ca200
usbd_transfer: xfer=0xc43ca200, flags=6, pipe=0xc2ee7380, running=0
usbd_dump_queue: pipe=0xc2ee7380
usb_allocmem: use frag=0xc1a81b80 size=35
usb_insert_transfer: pipe=0xc2ee7380 running=0 timeout=10000
usb_schedsoftintr: polling=0
usb_transfer_complete: pipe=0xc2ee7380 xfer=0xc43ca200 status=0 actlen=10
usb_freemem: frag=0xc1a81b80
usb_transfer_complete: repeat=0 new head=0
usbd_start_next: pipe=0xc2ee7380, xfer=0
usbd_free_xfer: 0xc43ca200
usbd_alloc_xfer() = 0xc43ca200
usbd_transfer: xfer=0xc43ca200, flags=6, pipe=0xc2ee7380, running=0
usbd_dump_queue: pipe=0xc2ee7380
usb_allocmem: use frag=0xc1a81b80 size=1
usb_insert_transfer: pipe=0xc2ee7380 running=0 timeout=10000
usb_schedsoftintr: polling=0
usb_transfer_complete: pipe=0xc2ee7380 xfer=0xc43ca200 status=0 actlen=1
usb_freemem: frag=0xc1a81b80
usb_transfer_complete: repeat=0 new head=0
usbd_start_next: pipe=0xc2ee7380, xfer=0
usbd_free_xfer: 0xc43ca200
usbd_alloc_xfer() = 0xc43ca200
usbd_transfer: xfer=0xc43ca200, flags=6, pipe=0xc2ee7380, running=0
usbd_dump_queue: pipe=0xc2ee7380
usb_allocmem: use frag=0xc1a81b80 size=5
usb_insert_transfer: pipe=0xc2ee7380 running=0 timeout=10000
usb_schedsoftintr: polling=0
usb_transfer_complete: pipe=0xc2ee7380 xfer=0xc43ca200 status=17 actlen=5
usb_freemem: frag=0xc1a81b80
usb_transfer_complete: repeat=0 new head=0
usbd_start_next: pipe=0xc2ee7380, xfer=0
usbd_transfer: xfer=0xc43ca200, flags=2, pipe=0xc2ee7380, running=0
usbd_dump_queue: pipe=0xc2ee7380
usb_allocmem: use frag=0xc1a81b80 size=2
usb_insert_transfer: pipe=0xc2ee7380 running=0 timeout=5000
usb_schedsoftintr: polling=0
usb_transfer_complete: pipe=0xc2ee7380 xfer=0xc43ca200 status=0 actlen=2
usb_freemem: frag=0xc1a81b80
usb_transfer_complete: repeat=0 new head=0
usbd_start_next: pipe=0xc2ee7380, xfer=0
usbd_do_request: status = 0x0000
usbd_free_xfer: 0xc43ca200
Any further debugging output needed?
More information about the freebsd-usb
mailing list