Ticket #131 (accepted defect)

Opened 5 years ago

Last modified 4 years ago

Some application programs ( gqrx, gnuradio ) crash with libusb-1.0.9

Reported by: dl1ksv Owned by: stuge
Milestone: 1.0.10 Component: libusb-1.0 Linux backend
Keywords: Cc: alan.ott
Blocked By: Blocks:

Description

Some application programs that run with libusb-1.0.8 without problems crash with libusb-1.0.9 ( Segmentation fault )
The system is a gentoo linux 64 bit, kernel 3.3.5, gcc 4.5.3
The backtrace shows

Program terminated with signal 11, Segmentation fault.
#0  0x00007f23d2014a44 in add_to_flying_list (transfer=0x7f23c4000910) at io.c:1185
1185if (!timerisset(cur_tv) || (cur_tv->tv_sec > timeout->tv_sec) ||
(gdb) bt
#0  0x00007f23d2014a44 in add_to_flying_list (transfer=0x7f23c4000910) at io.c:1185
#1  0x00007f23d2014cc3 in libusb_submit_transfer (transfer=0x7f23c4000968) at io.c:1305
#2  0x00007f23d66853fc in read_thread (param=0x18abd50) at /gnuradiocomponents/gnuradio/gr-fcd/lib/hid/hid-libusb.c:697
#3  0x00007f23d4614f26 in start_thread () from /lib64/libpthread.so.0
#4  0x00007f23d3b37a4d in clone () from /lib64/libc.so.6

(gdb) p cur
$1 = (struct usbi_transfer *) 0xfffffffffffffff8

(gdb) p ctx->flying_transfers
$2 = {prev = 0x7f23c4000078, next = 0x7f23c4000918}
(gdb) p ctx->flying_transfers->next
$3 = (struct list_head *) 0x7f23c4000918
(gdb) p ctx->flying_transfers->next->next
$4 = (struct list_head *) 0x0

It seems that the end of the list is not recognized in the list_for_each_entry loop.

I have no ideas why this happens in 1.0.9 but not in 1.0.8.

I possible solution that avoids the crash:

Replace

#define list_for_each_entry(pos, head, member, type) 
    for (pos = list_entry((head)->next, type, member);[[BR]]
      &pos->member!=(head);
       pos = list_entry(pos->member.next, type, member))

by

#define list_for_each_entry(pos, head, member, type) 
    for (pos = list_entry((head)->next, type, member);[[BR]]
      (&pos->member!=(head)) &&(pos->member.next != 0 );
       pos = list_entry(pos->member.next, type, member))




Change History

comment:1 Changed 5 years ago by xiaofan

http://gnuradio.org/redmine/projects/gnuradio/repository/revisions/master/show/gr-fcd/lib/hid
This seems to be an older version of hidapi, what if you upgrade to the git version of hidapi to see
if that helps.

HIDAPI git:
https://github.com/signal11/hidapi

comment:2 Changed 5 years ago by sping

  • Milestone set to 1.0.10

comment:3 in reply to: ↑ description Changed 5 years ago by stuge

  • Owner set to stuge
  • Status changed from new to accepted

Thanks for the problem report! This is a regression that we must fix.

Replying to dl1ksv:

The backtrace shows

(gdb) p cur
$1 = (struct usbi_transfer *) 0xfffffffffffffff8
(gdb) p ctx->flying_transfers
$2 = {prev = 0x7f23c4000078, next = 0x7f23c4000918}
(gdb) p ctx->flying_transfers->next
$3 = (struct list_head *) 0x7f23c4000918
(gdb) p ctx->flying_transfers->next->next
$4 = (struct list_head *) 0x0

I can not reproduce on amd64 Gentoo here. I would very much like to, in order to further explore the state of the crashed program. If possible, could you join #libusb on irc.freenode.net in order to do some live debugging?

It seems that the end of the list is not recognized in the list_for_each_entry loop.

'next' in the very last list entry must always point to the list head. Anything else is an error, and 0 in this case is broken. The question is of course how the 0 was introduced. I've done some static code analysis but not found anything conclusive. I need your help to solve this, since I can't reproduce the problem locally.

git bisect between the v1.0.8 and 1.0.9 tags could be helpful.

The suggested change is unfortunately not a suitable fix, since the list must end with a pointer to the list head. Introducing 0 as a second end-of-list-marker will only add new problems.

Thanks again for the report - I hope we can find the solution!

comment:4 Changed 5 years ago by stuge

  • Cc alan.ott added

Ccing Alan since the backtrace includes HIDAPI.

The version of HIDAPI used in the crashing application doesn't check for libusb_alloc_transfer() failure, which is a problem, but which I believe is unrelated. If allocation had failed then the crash would be in libusb_fill_interrupt_transfer() instead.

Xiaofan is of course correct that it could be good to try the latest HIDAPI code, but it does not seem like HIDAPI is causing this crash.

We need more info from the crashed program state. Hopefully the reporter can assist.

comment:5 follow-up: Changed 5 years ago by dl1ksv

I did some regression tests this evening:
This is the result

011f1f297bc134188fab9960da1b1b9f0bd541aa is the first bad commit
commit 011f1f297bc134188fab9960da1b1b9f0bd541aa
Author: Peter Stuge <peter@stuge.se>
Date:   Sun Oct 17 08:19:56 2010 +0200

    Linux: Refactor discarding of URBs into a function and return all errors
    
    The Linux backend did not always return errors according to the
    libusb_cancel_transfer() documentation.

:040000 040000 484ad43cb30621f93656fa8d93654bbdb8529d43 f0e1100735a40f56b4ec6dfece640e20699846b0 M	libusb

I had a first rough test with the latest version of HIDAPI.
There was no crash but the program freezes.
I have to have a deeper look.

The problem is that the problem seems to be non deterministic, that means it depends on many factors like computer utilization and so on.

comment:6 in reply to: ↑ 5 Changed 5 years ago by stuge

Replying to dl1ksv:

I did some regression tests this evening:

Thanks for the help!

This is the result

011f1f297bc134188fab9960da1b1b9f0bd541aa is the first bad commit
commit 011f1f297bc134188fab9960da1b1b9f0bd541aa
Author: Peter Stuge <peter@stuge.se>
Date:   Sun Oct 17 08:19:56 2010 +0200

    Linux: Refactor discarding of URBs into a function and return all errors

This commit should indeed only be refactoring. I just re-reviewed it, and I don't spot any functional change in the code. Since I'm the author it's possible that I have tunnel vision, but the commit was also reviewed by at least one more person, where an off-by-one error was indicated. In any case, even if we assume that the commit is causing the problem, I don't quite understand how, because the commit doesn't touch the list of flying transfers at all. There would have to be some weird race between multiple threads, so that URBs which are discarded only after my commit suddenly make the transfer get wiped in-place in the list. But the list macros were reviewed during the weekend and they don't seem to be capable of causing a NULL pointer.

I had a first rough test with the latest version of HIDAPI.
There was no crash but the program freezes.

That's also not acceptable. It suggests that indeed the problem is not with HIDAPI.

I have to have a deeper look.

Please provide a debug log from libusb-1.0.9 configured with --enable-debug-log. Let the application run with such a debug-enabled libusb, and there will be significant useful output on the terminal, that you could attach (text file please) or simply paste into a ticket comment.

The problem is that the problem seems to be non deterministic,

How much testing of commit 011f1f did you do? If the test case is not so deterministic it is difficult to rely on git bisect for finding the bad commit.

I am absolutely not saying that my commit is perfect, it can certainly be the cause, but a debug log and a reliable test case would be helpful. Please see https://libusb.org/ticket/132#comment:2 for an example of how to easily build and use a debug-enabled libusb.

Also, perhaps you could say something about your toolchain? Version of sys-devel/gcc and binutils? hardened profile or normal? Any USE affecting code generation? I'm fishing after a possible problem with the binaries. The error behaves a lot like memory corruption.

Thanks again!

comment:7 follow-up: Changed 5 years ago by dl1ksv

libusb: 0.000146 debug [find_usbfs_path] found usbfs at /dev/bus/usb
libusb: 0.000211 debug [op_init] bulk continuation flag supported
libusb: 0.000258 debug [op_init] zero length packet flag supported
libusb: 0.000399 debug [op_init] found usb devices in sysfs
libusb: 0.000637 debug [usbi_add_pollfd] add fd 8 events 1
libusb: 0.000713 debug [usbi_io_init] using timerfd for timeouts
libusb: 0.000764 debug [usbi_add_pollfd] add fd 11 events 1
libusb: 0.000807 debug [libusb_init] created default context
libusb: 0.000855 debug [libusb_get_device_list] 
libusb: 0.000922 debug [sysfs_scan_device] scan 1-5
libusb: 0.001132 debug [sysfs_scan_device] bus=1 dev=4
libusb: 0.001191 debug [enumerate_device] busnum 1 devaddr 4 session_id 260
libusb: 0.001259 debug [enumerate_device] allocating new device for 1/4 (session 260)
libusb: 0.001434 debug [sysfs_scan_device] scan 3-1
libusb: 0.001738 debug [sysfs_scan_device] bus=3 dev=2
libusb: 0.001761 debug [enumerate_device] busnum 3 devaddr 2 session_id 770
libusb: 0.001779 debug [enumerate_device] allocating new device for 3/2 (session 770)
libusb: 0.001894 debug [sysfs_scan_device] scan 3-2
libusb: 0.002017 debug [sysfs_scan_device] bus=3 dev=3
libusb: 0.002036 debug [enumerate_device] busnum 3 devaddr 3 session_id 771
libusb: 0.002050 debug [enumerate_device] allocating new device for 3/3 (session 771)
libusb: 0.002146 debug [sysfs_scan_device] scan usb1
libusb: 0.002256 debug [sysfs_scan_device] bus=1 dev=1
libusb: 0.002272 debug [enumerate_device] busnum 1 devaddr 1 session_id 257
libusb: 0.002286 debug [enumerate_device] allocating new device for 1/1 (session 257)
libusb: 0.002380 debug [sysfs_scan_device] scan usb2
libusb: 0.002523 debug [sysfs_scan_device] bus=2 dev=1
libusb: 0.002541 debug [enumerate_device] busnum 2 devaddr 1 session_id 513
libusb: 0.002554 debug [enumerate_device] allocating new device for 2/1 (session 513)
libusb: 0.002648 debug [sysfs_scan_device] scan usb3
libusb: 0.002766 debug [sysfs_scan_device] bus=3 dev=1
libusb: 0.002782 debug [enumerate_device] busnum 3 devaddr 1 session_id 769
libusb: 0.002797 debug [enumerate_device] allocating new device for 3/1 (session 769)
libusb: 0.002891 debug [sysfs_scan_device] scan usb4
libusb: 0.003008 debug [sysfs_scan_device] bus=4 dev=1
libusb: 0.003024 debug [enumerate_device] busnum 4 devaddr 1 session_id 1025
libusb: 0.003039 debug [enumerate_device] allocating new device for 4/1 (session 1025)
libusb: 0.003132 debug [sysfs_scan_device] scan usb5
libusb: 0.003254 debug [sysfs_scan_device] bus=5 dev=1
libusb: 0.003272 debug [enumerate_device] busnum 5 devaddr 1 session_id 1281
libusb: 0.003286 debug [enumerate_device] allocating new device for 5/1 (session 1281)
libusb: 0.003380 debug [sysfs_scan_device] scan usb6
libusb: 0.003532 debug [sysfs_scan_device] bus=6 dev=1
libusb: 0.003551 debug [enumerate_device] busnum 6 devaddr 1 session_id 1537
libusb: 0.003565 debug [enumerate_device] allocating new device for 6/1 (session 1537)
libusb: 0.003662 debug [discovered_devs_append] need to increase capacity
libusb: 0.003696 debug [sysfs_scan_device] scan usb7
libusb: 0.003812 debug [sysfs_scan_device] bus=7 dev=1
libusb: 0.003829 debug [enumerate_device] busnum 7 devaddr 1 session_id 1793
libusb: 0.003844 debug [enumerate_device] allocating new device for 7/1 (session 1793)
libusb: 0.003938 debug [sysfs_scan_device] scan 1-5.1
libusb: 0.004063 debug [sysfs_scan_device] bus=1 dev=5
libusb: 0.004080 debug [enumerate_device] busnum 1 devaddr 5 session_id 261
libusb: 0.004095 debug [enumerate_device] allocating new device for 1/5 (session 261)
libusb: 0.004242 debug [libusb_get_device_descriptor] 
libusb: 0.004283 debug [libusb_get_device_descriptor] 
libusb: 0.004322 debug [libusb_get_active_config_descriptor] 
libusb: 0.004373 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.004468 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.004524 debug [libusb_get_device_descriptor] 
libusb: 0.004560 debug [libusb_get_active_config_descriptor] 
libusb: 0.004599 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.004662 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.004704 debug [libusb_get_device_descriptor] 
libusb: 0.004737 debug [libusb_get_device_descriptor] 
libusb: 0.004769 debug [libusb_get_device_descriptor] 
libusb: 0.004800 debug [libusb_get_device_descriptor] 
libusb: 0.004831 debug [libusb_get_device_descriptor] 
libusb: 0.004863 debug [libusb_get_device_descriptor] 
libusb: 0.004896 debug [libusb_get_device_descriptor] 
libusb: 0.004929 debug [libusb_get_device_descriptor] 
libusb: 0.004963 debug [libusb_get_active_config_descriptor] 
libusb: 0.005002 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.005065 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.005110 debug [parse_endpoint] skipping descriptor 25
libusb: 0.005157 debug [libusb_open] open 1.5
libusb: 0.005174 debug [op_open] opening /dev/bus/usb/001/005
libusb: 0.005215 debug [usbi_add_pollfd] add fd 12 events 4
libusb: 0.005318 debug [libusb_submit_transfer] arm timerfd for timeout in 1000ms (first in line)
libusb: 0.005357 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.005372 debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb: 0.005663 debug [handle_events] poll() returned 1
libusb: 0.005737 debug [reap_for_handle] urb type=2 status=0 transferred=4
libusb: 0.005771 debug [handle_control_completion] handling completion status 0
libusb: 0.005805 debug [disarm_timerfd] 
libusb: 0.005830 debug [usbi_handle_transfer_completion] transfer 0xdf7a98 has callback 0x7f691491faab
libusb: 0.005864 debug [ctrl_transfer_cb] actual_length=4
libusb: 0.005940 debug [libusb_submit_transfer] arm timerfd for timeout in 1000ms (first in line)
libusb: 0.005980 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.006013 debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb: 0.006120 debug [handle_events] poll() returned 1
libusb: 0.006158 debug [reap_for_handle] urb type=2 status=0 transferred=4
libusb: 0.006190 debug [handle_control_completion] handling completion status 0
libusb: 0.006222 debug [disarm_timerfd] 
libusb: 0.006245 debug [usbi_handle_transfer_completion] transfer 0xdf7a98 has callback 0x7f691491faab
libusb: 0.006278 debug [ctrl_transfer_cb] actual_length=4
libusb: 0.006318 debug [libusb_submit_transfer] arm timerfd for timeout in 1000ms (first in line)
libusb: 0.006354 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.006386 debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb: 0.006871 debug [handle_events] poll() returned 1
libusb: 0.006908 debug [reap_for_handle] urb type=2 status=0 transferred=52
libusb: 0.006939 debug [handle_control_completion] handling completion status 0
libusb: 0.006971 debug [disarm_timerfd] 
libusb: 0.006993 debug [usbi_handle_transfer_completion] transfer 0xdf7a98 has callback 0x7f691491faab
libusb: 0.007025 debug [ctrl_transfer_cb] actual_length=52
libusb: 0.030246 debug [libusb_submit_transfer] arm timerfd for timeout in 1000ms (first in line)
libusb: 0.030299 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.030316 debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb: 0.030630 debug [handle_events] poll() returned 1
libusb: 0.030656 debug [reap_for_handle] urb type=2 status=0 transferred=4
libusb: 0.030672 debug [handle_control_completion] handling completion status 0
libusb: 0.030687 debug [disarm_timerfd] 
libusb: 0.030699 debug [usbi_handle_transfer_completion] transfer 0xdf7b78 has callback 0x7f691491faab
libusb: 0.030714 debug [ctrl_transfer_cb] actual_length=4
libusb: 0.030739 debug [libusb_submit_transfer] arm timerfd for timeout in 1000ms (first in line)
libusb: 0.030756 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.030770 debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb: 0.030872 debug [handle_events] poll() returned 1
libusb: 0.030894 debug [reap_for_handle] urb type=2 status=0 transferred=4
libusb: 0.030907 debug [handle_control_completion] handling completion status 0
libusb: 0.030920 debug [disarm_timerfd] 
libusb: 0.030931 debug [usbi_handle_transfer_completion] transfer 0xdf7b78 has callback 0x7f691491faab
libusb: 0.030944 debug [ctrl_transfer_cb] actual_length=4
libusb: 0.030969 debug [libusb_submit_transfer] arm timerfd for timeout in 1000ms (first in line)
libusb: 0.030985 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.030999 debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb: 0.031516 debug [handle_events] poll() returned 1
libusb: 0.031556 debug [reap_for_handle] urb type=2 status=0 transferred=44
libusb: 0.031570 debug [handle_control_completion] handling completion status 0
libusb: 0.031584 debug [disarm_timerfd] 
libusb: 0.031596 debug [usbi_handle_transfer_completion] transfer 0xdf7b78 has callback 0x7f691491faab
libusb: 0.031609 debug [ctrl_transfer_cb] actual_length=44
libusb: 0.031650 debug [libusb_close] 
libusb: 0.031673 debug [usbi_remove_pollfd] remove fd 12
libusb: 0.031709 debug [libusb_unref_device] destroy device 1.4
libusb: 0.031724 debug [libusb_unref_device] destroy device 3.2
libusb: 0.031738 debug [libusb_unref_device] destroy device 3.3
libusb: 0.031750 debug [libusb_unref_device] destroy device 1.1
libusb: 0.031764 debug [libusb_unref_device] destroy device 2.1
libusb: 0.031776 debug [libusb_unref_device] destroy device 3.1
libusb: 0.031789 debug [libusb_unref_device] destroy device 4.1
libusb: 0.031801 debug [libusb_unref_device] destroy device 5.1
libusb: 0.031814 debug [libusb_unref_device] destroy device 6.1
libusb: 0.031827 debug [libusb_unref_device] destroy device 7.1
libusb: 0.031839 debug [libusb_unref_device] destroy device 1.5
libusb: 0.031902 debug [libusb_get_device_list] 
libusb: 0.031969 debug [sysfs_scan_device] scan 1-5
libusb: 0.032131 debug [sysfs_scan_device] bus=1 dev=4
libusb: 0.032149 debug [enumerate_device] busnum 1 devaddr 4 session_id 260
libusb: 0.032164 debug [enumerate_device] allocating new device for 1/4 (session 260)
libusb: 0.032266 debug [sysfs_scan_device] scan 3-1
libusb: 0.032382 debug [sysfs_scan_device] bus=3 dev=2
libusb: 0.032399 debug [enumerate_device] busnum 3 devaddr 2 session_id 770
libusb: 0.032414 debug [enumerate_device] allocating new device for 3/2 (session 770)
libusb: 0.032547 debug [sysfs_scan_device] scan 3-2
libusb: 0.032662 debug [sysfs_scan_device] bus=3 dev=3
libusb: 0.032679 debug [enumerate_device] busnum 3 devaddr 3 session_id 771
libusb: 0.032694 debug [enumerate_device] allocating new device for 3/3 (session 771)
libusb: 0.032786 debug [sysfs_scan_device] scan usb1
libusb: 0.032893 debug [sysfs_scan_device] bus=1 dev=1
libusb: 0.032910 debug [enumerate_device] busnum 1 devaddr 1 session_id 257
libusb: 0.032924 debug [enumerate_device] allocating new device for 1/1 (session 257)
libusb: 0.033012 debug [sysfs_scan_device] scan usb2
libusb: 0.033126 debug [sysfs_scan_device] bus=2 dev=1
libusb: 0.033142 debug [enumerate_device] busnum 2 devaddr 1 session_id 513
libusb: 0.033156 debug [enumerate_device] allocating new device for 2/1 (session 513)
libusb: 0.033245 debug [sysfs_scan_device] scan usb3
libusb: 0.033356 debug [sysfs_scan_device] bus=3 dev=1
libusb: 0.033373 debug [enumerate_device] busnum 3 devaddr 1 session_id 769
libusb: 0.033387 debug [enumerate_device] allocating new device for 3/1 (session 769)
libusb: 0.033494 debug [sysfs_scan_device] scan usb4
libusb: 0.033605 debug [sysfs_scan_device] bus=4 dev=1
libusb: 0.033621 debug [enumerate_device] busnum 4 devaddr 1 session_id 1025
libusb: 0.033636 debug [enumerate_device] allocating new device for 4/1 (session 1025)
libusb: 0.033724 debug [sysfs_scan_device] scan usb5
libusb: 0.033832 debug [sysfs_scan_device] bus=5 dev=1
libusb: 0.033849 debug [enumerate_device] busnum 5 devaddr 1 session_id 1281
libusb: 0.033863 debug [enumerate_device] allocating new device for 5/1 (session 1281)
libusb: 0.033950 debug [sysfs_scan_device] scan usb6
libusb: 0.034059 debug [sysfs_scan_device] bus=6 dev=1
libusb: 0.034077 debug [enumerate_device] busnum 6 devaddr 1 session_id 1537
libusb: 0.034091 debug [enumerate_device] allocating new device for 6/1 (session 1537)
libusb: 0.034177 debug [discovered_devs_append] need to increase capacity
libusb: 0.034197 debug [sysfs_scan_device] scan usb7
libusb: 0.034300 debug [sysfs_scan_device] bus=7 dev=1
libusb: 0.034317 debug [enumerate_device] busnum 7 devaddr 1 session_id 1793
libusb: 0.034331 debug [enumerate_device] allocating new device for 7/1 (session 1793)
libusb: 0.034419 debug [sysfs_scan_device] scan 1-5.1
libusb: 0.034545 debug [sysfs_scan_device] bus=1 dev=5
libusb: 0.034562 debug [enumerate_device] busnum 1 devaddr 5 session_id 261
libusb: 0.034577 debug [enumerate_device] allocating new device for 1/5 (session 261)
libusb: 0.034680 debug [libusb_get_device_descriptor] 
libusb: 0.034717 debug [libusb_get_active_config_descriptor] 
libusb: 0.034768 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.034834 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.034880 debug [libusb_get_device_descriptor] 
libusb: 0.034914 debug [libusb_get_active_config_descriptor] 
libusb: 0.034950 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.035011 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.035066 debug [libusb_get_device_descriptor] 
libusb: 0.035100 debug [libusb_get_active_config_descriptor] 
libusb: 0.035135 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.035195 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.035239 debug [libusb_get_device_descriptor] 
libusb: 0.035271 debug [libusb_get_active_config_descriptor] 
libusb: 0.035306 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.035366 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.035410 debug [libusb_get_device_descriptor] 
libusb: 0.035458 debug [libusb_get_active_config_descriptor] 
libusb: 0.035604 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.035801 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.035853 debug [libusb_get_device_descriptor] 
libusb: 0.035892 debug [libusb_get_active_config_descriptor] 
libusb: 0.035939 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.036000 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.036040 debug [libusb_get_device_descriptor] 
libusb: 0.036076 debug [libusb_get_active_config_descriptor] 
libusb: 0.036114 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.036171 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.036210 debug [libusb_get_device_descriptor] 
libusb: 0.036245 debug [libusb_get_active_config_descriptor] 
libusb: 0.036282 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.036342 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.036382 debug [libusb_get_device_descriptor] 
libusb: 0.036416 debug [libusb_get_active_config_descriptor] 
libusb: 0.036483 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.036543 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.036583 debug [libusb_get_device_descriptor] 
libusb: 0.036618 debug [libusb_get_active_config_descriptor] 
libusb: 0.036655 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.036713 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.036753 debug [libusb_get_device_descriptor] 
libusb: 0.036791 debug [libusb_get_active_config_descriptor] 
libusb: 0.036827 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.036890 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.036940 debug [parse_endpoint] skipping descriptor 25
libusb: 0.036965 debug [libusb_open] open 1.5
libusb: 0.036982 debug [op_open] opening /dev/bus/usb/001/005
libusb: 0.037020 debug [usbi_add_pollfd] add fd 12 events 4
libusb: 0.037060 debug [libusb_kernel_driver_active] interface 2
libusb: 0.037085 debug [libusb_detach_kernel_driver] interface 2
libusb: 0.041649 debug [libusb_claim_interface] interface 2
libusb: 0.041925 debug [submit_bulk_transfer] need 1 urbs for new transfer with length 64
libusb: 0.042133 debug [libusb_submit_transfer] arm timerfd for timeout in 5000ms (first in line)
libusb: 0.042172 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.042176 debug [libusb_unref_device] destroy device 1.4
libusb: 0.042235 debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb: 0.042310 debug [libusb_unref_device] destroy device 3.2
libusb: 0.042412 debug [libusb_unref_device] destroy device 3.3
libusb: 0.042460 debug [libusb_unref_device] destroy device 1.1
libusb: 0.042495 debug [libusb_unref_device] destroy device 2.1
libusb: 0.042531 debug [libusb_unref_device] destroy device 3.1
libusb: 0.042569 debug [libusb_unref_device] destroy device 4.1
libusb: 0.042603 debug [libusb_unref_device] destroy device 5.1
libusb: 0.042637 debug [libusb_unref_device] destroy device 6.1
libusb: 0.042671 debug [libusb_unref_device] destroy device 7.1
libusb: 0.042719 debug [submit_bulk_transfer] need 1 urbs for new transfer with length 64
libusb: 0.042927 debug [libusb_submit_transfer] arm timerfd for timeout in 1000ms (first in line)
libusb: 0.042981 debug [libusb_handle_events_timeout_completed] another thread is doing event handling
libusb: 0.043637 debug [handle_events] poll() returned 1
libusb: 0.043682 debug [reap_for_handle] urb type=1 status=0 transferred=64
libusb: 0.043699 debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
libusb: 0.043716 debug [handle_bulk_completion] last URB in transfer --> complete!
libusb: 0.043732 debug [arm_timerfd_for_next_timeout] next timeout originally 5000ms
libusb: 0.043751 debug [disarm_timerfd] 
libusb: 0.043762 debug [usbi_handle_transfer_completion] transfer 0xdef7c8 has callback 0x7f691491fd8d
libusb: 0.043777 debug [bulk_transfer_cb] actual_length=64
libusb: 0.043809 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.043826 debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb: 0.045627 debug [handle_events] poll() returned 1
libusb: 0.045671 debug [reap_for_handle] urb type=1 status=0 transferred=64
libusb: 0.045686 debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
libusb: 0.045700 debug [handle_bulk_completion] last URB in transfer --> complete!
libusb: 0.045715 debug [disarm_timerfd] 
libusb: 0.045727 debug [usbi_handle_transfer_completion] transfer 0xdf81a8 has callback 0x7f6918e8c490
libusb: 0.045778 debug [submit_bulk_transfer] need 1 urbs for new transfer with length 64
libusb: 0.045805 debug [libusb_cancel_transfer] 
libusb: 0.045948 debug [libusb_submit_transfer] arm timerfd for timeout in 5000ms (first in line)
libusb: 0.045978 debug [libusb_cancel_transfer] 
libusb: 0.046049 debug [discard_urbs] URB not found --> assuming ready to be reaped
libusb: 0.046068 debug [libusb_cancel_transfer] cancel transfer failed error -5
libusb: 0.046135 debug [libusb_release_interface] interface 2
libusb: 0.046190 debug [libusb_close] 
libusb: 0.046227 error [do_close] Device handle closed while transfer was still being processed, but the device is still connected as far as we know
libusb: 0.046261 warning [do_close] A cancellation for an in-flight transfer hasn't completed but closing the device handle
libusb: 0.046293 debug [do_close] Removed transfer 0xdf81a8 from the in-flight list because device handle 0xdc6b70 closed
libusb: 0.046327 debug [usbi_remove_pollfd] remove fd 12
libusb: 0.046369 debug [libusb_unref_device] destroy device 1.5
libusb: 0.046485 debug [libusb_get_device_list] 
libusb: 0.046563 debug [sysfs_scan_device] scan 1-5
libusb: 0.046754 debug [sysfs_scan_device] bus=1 dev=4
libusb: 0.046793 debug [enumerate_device] busnum 1 devaddr 4 session_id 260
libusb: 0.046827 debug [enumerate_device] allocating new device for 1/4 (session 260)
libusb: 0.046950 debug [sysfs_scan_device] scan 3-1
libusb: 0.047090 debug [sysfs_scan_device] bus=3 dev=2
libusb: 0.047128 debug [enumerate_device] busnum 3 devaddr 2 session_id 770
libusb: 0.047160 debug [enumerate_device] allocating new device for 3/2 (session 770)
libusb: 0.047276 debug [sysfs_scan_device] scan 3-2
libusb: 0.047411 debug [sysfs_scan_device] bus=3 dev=3
libusb: 0.047466 debug [enumerate_device] busnum 3 devaddr 3 session_id 771
libusb: 0.047499 debug [enumerate_device] allocating new device for 3/3 (session 771)
libusb: 0.047620 debug [sysfs_scan_device] scan usb1
libusb: 0.047759 debug [sysfs_scan_device] bus=1 dev=1
libusb: 0.047798 debug [enumerate_device] busnum 1 devaddr 1 session_id 257
libusb: 0.047831 debug [enumerate_device] allocating new device for 1/1 (session 257)
libusb: 0.047947 debug [sysfs_scan_device] scan usb2
libusb: 0.048085 debug [sysfs_scan_device] bus=2 dev=1
libusb: 0.048123 debug [enumerate_device] busnum 2 devaddr 1 session_id 513
libusb: 0.048157 debug [enumerate_device] allocating new device for 2/1 (session 513)
libusb: 0.048272 debug [sysfs_scan_device] scan usb3
libusb: 0.048423 debug [sysfs_scan_device] bus=3 dev=1
libusb: 0.048474 debug [enumerate_device] busnum 3 devaddr 1 session_id 769
libusb: 0.048507 debug [enumerate_device] allocating new device for 3/1 (session 769)
libusb: 0.048685 debug [sysfs_scan_device] scan usb4
libusb: 0.048919 debug [sysfs_scan_device] bus=4 dev=1
libusb: 0.048959 debug [enumerate_device] busnum 4 devaddr 1 session_id 1025
libusb: 0.048993 debug [enumerate_device] allocating new device for 4/1 (session 1025)
libusb: 0.049181 debug [sysfs_scan_device] scan usb5
libusb: 0.049436 debug [sysfs_scan_device] bus=5 dev=1
libusb: 0.049486 debug [enumerate_device] busnum 5 devaddr 1 session_id 1281
libusb: 0.049520 debug [enumerate_device] allocating new device for 5/1 (session 1281)
libusb: 0.049680 debug [sysfs_scan_device] scan usb6
libusb: 0.049845 debug [sysfs_scan_device] bus=6 dev=1
libusb: 0.049884 debug [enumerate_device] busnum 6 devaddr 1 session_id 1537
libusb: 0.049917 debug [enumerate_device] allocating new device for 6/1 (session 1537)
libusb: 0.050090 debug [discovered_devs_append] need to increase capacity
libusb: 0.050136 debug [sysfs_scan_device] scan usb7
libusb: 0.050287 debug [sysfs_scan_device] bus=7 dev=1
libusb: 0.050327 debug [enumerate_device] busnum 7 devaddr 1 session_id 1793
libusb: 0.050360 debug [enumerate_device] allocating new device for 7/1 (session 1793)
libusb: 0.050502 debug [sysfs_scan_device] scan 1-5.1
libusb: 0.050658 debug [sysfs_scan_device] bus=1 dev=5
libusb: 0.050696 debug [enumerate_device] busnum 1 devaddr 5 session_id 261
libusb: 0.050730 debug [enumerate_device] allocating new device for 1/5 (session 261)
libusb: 0.050870 debug [libusb_get_device_descriptor] 
libusb: 0.050943 debug [libusb_get_device_descriptor] 
libusb: 0.051002 debug [libusb_get_active_config_descriptor] 
libusb: 0.051075 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.051186 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.051266 debug [libusb_get_device_descriptor] 
libusb: 0.051331 debug [libusb_get_active_config_descriptor] 
libusb: 0.051396 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.051508 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.051576 debug [libusb_get_device_descriptor] 
libusb: 0.051628 debug [libusb_get_device_descriptor] 
libusb: 0.051677 debug [libusb_get_device_descriptor] 
libusb: 0.051725 debug [libusb_get_device_descriptor] 
libusb: 0.051774 debug [libusb_get_device_descriptor] 
libusb: 0.051822 debug [libusb_get_device_descriptor] 
libusb: 0.051871 debug [libusb_get_device_descriptor] 
libusb: 0.051919 debug [libusb_get_device_descriptor] 
libusb: 0.051971 debug [libusb_get_active_config_descriptor] 
libusb: 0.052025 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.052112 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.052181 debug [parse_endpoint] skipping descriptor 25
libusb: 0.052227 debug [libusb_open] open 1.5
libusb: 0.052262 debug [op_open] opening /dev/bus/usb/001/005
libusb: 0.052332 debug [usbi_add_pollfd] add fd 12 events 4
Speicherzugriffsfehler (Speicherabzug geschrieben)
Core was generated by `./gqrx'.
Program terminated with signal 11, Segmentation fault.
#0  0x00007f691491d38a in list_add_tail (entry=0xdf7a38, head=0xdf8158) at libusbi.h:103
103		head->prev->next = entry;
(gdb) bt
#0  0x00007f691491d38a in list_add_tail (entry=0xdf7a38, head=0xdf8158) at libusbi.h:103
#1  0x00007f691491d9ff in add_to_flying_list (transfer=0xdf7a30) at io.c:1188
#2  0x00007f691491dc12 in libusb_submit_transfer (transfer=0xdf7a88) at io.c:1305
#3  0x00007f691491fc04 in libusb_control_transfer (dev_handle=0xdb0870, bmRequestType=128 '\200', bRequest=6 '\006', wValue=768, wIndex=0, 
    data=0x7fffbc0e0780 "\260\a\016\274\377\177", wLength=64, timeout=1000) at sync.c:98
#4  0x00007f6918e8d199 in get_usb_string () from /usr/local/gnuradio/lib/libgnuradio-fcd-3.6.1git.so.0.0.0
#5  0x00007f6918e8d731 in hid_enumerate () from /usr/local/gnuradio/lib/libgnuradio-fcd-3.6.1git.so.0.0.0
#6  0x00007f6918e8ee3d in fcdAppSetParam () from /usr/local/gnuradio/lib/libgnuradio-fcd-3.6.1git.so.0.0.0
#7  0x00007f6918e8f2b6 in fcd_source_c_impl::set_lna_gain(float) () from /usr/local/gnuradio/lib/libgnuradio-fcd-3.6.1git.so.0.0.0
#8  0x000000000044daef in rx_source_fcd::rx_source_fcd(std::string) ()
#9  0x000000000044ddbd in make_rx_source_fcd(std::string) ()
#10 0x0000000000413739 in receiver::receiver(std::string, std::string) ()
#11 0x0000000000418cf9 in MainWindow::MainWindow(QWidget*) ()
#12 0x0000000000412d8a in main ()

In most cases the program crashes during startup.
I suppose that in case of a crash the linked list contains more than one element.

Some weeks ago I tried tu run gqrx in gdb and set some breakpoints and no crash happened. Running without gdb crashed at once.

gcc:

Es werden eingebaute Spezifikationen verwendet.
COLLECT_GCC=/usr/x86_64-pc-linux-gnu/gcc-bin/4.6.3/gcc
COLLECT_LTO_WRAPPER=/usr/libexec/gcc/x86_64-pc-linux-gnu/4.6.3/lto-wrapper
Ziel: x86_64-pc-linux-gnu
Konfiguriert mit: /var/tmp/portage/sys-devel/gcc-4.6.3/work/gcc-4.6.3/configure --prefix=/usr --bindir=/usr/x86_64-pc-linux-gnu/gcc-bin/4.6.3 --includedir=/usr/lib/gcc/x86_64-pc-linux-gnu/4.6.3/include --datadir=/usr/share/gcc-data/x86_64-pc-linux-gnu/4.6.3 --mandir=/usr/share/gcc-data/x86_64-pc-linux-gnu/4.6.3/man --infodir=/usr/share/gcc-data/x86_64-pc-linux-gnu/4.6.3/info --with-gxx-include-dir=/usr/lib/gcc/x86_64-pc-linux-gnu/4.6.3/include/g++-v4 --host=x86_64-pc-linux-gnu --build=x86_64-pc-linux-gnu --disable-altivec --disable-fixed-point --without-ppl --without-cloog --enable-lto --enable-nls --without-included-gettext --with-system-zlib --enable-obsolete --disable-werror --enable-secureplt --enable-multilib --enable-libmudflap --disable-libssp --enable-libgomp --with-python-dir=/share/gcc-data/x86_64-pc-linux-gnu/4.6.3/python --enable-checking=release --disable-libgcj --disable-libquadmath --enable-languages=c,c++ --enable-shared --enable-threads=posix --enable-__cxa_atexit --enable-clocale=gnu --enable-targets=all --with-bugurl=http://bugs.gentoo.org/ --with-pkgversion='Gentoo 4.6.3 p1.3, pie-0.5.1'
Thread-Modell: posix
gcc-Version 4.6.3 (Gentoo 4.6.3 p1.3, pie-0.5.1)

comment:8 Changed 5 years ago by dl1ksv

I just made a regression test with another program ( qthid ) using libusb and it led to the same result.
This is the rest of a very long debug output

libusb:debug [sysfs_scan_device] scan usb6
libusb:debug [sysfs_scan_device] bus=6 dev=1
libusb:debug [enumerate_device] busnum 6 devaddr 1 session_id 1537
libusb:debug [enumerate_device] allocating new device for 6/1 (session 1537)
libusb:debug [discovered_devs_append] need to increase capacity
libusb:debug [sysfs_scan_device] scan usb7
libusb:debug [sysfs_scan_device] bus=7 dev=1
libusb:debug [enumerate_device] busnum 7 devaddr 1 session_id 1793
libusb:debug [enumerate_device] allocating new device for 7/1 (session 1793)
libusb:debug [sysfs_scan_device] scan 1-6.1
libusb:debug [sysfs_scan_device] bus=1 dev=19
libusb:debug [enumerate_device] busnum 1 devaddr 19 session_id 275
libusb:debug [enumerate_device] allocating new device for 1/19 (session 275)
libusb:debug [libusb_get_device_descriptor] 
libusb:debug [libusb_get_device_descriptor] 
libusb:debug [libusb_get_active_config_descriptor] 
libusb:debug [sysfs_get_active_config_descriptor] active configuration 1
libusb:debug [sysfs_get_active_config_descriptor] active configuration 1
libusb:debug [libusb_get_device_descriptor] 
libusb:debug [libusb_get_active_config_descriptor] 
libusb:debug [sysfs_get_active_config_descriptor] active configuration 1
libusb:debug [sysfs_get_active_config_descriptor] active configuration 1
libusb:debug [libusb_get_device_descriptor] 
libusb:debug [libusb_get_device_descriptor] 
libusb:debug [libusb_get_device_descriptor] 
libusb:debug [libusb_get_device_descriptor] 
libusb:debug [libusb_get_device_descriptor] 
libusb:debug [libusb_get_device_descriptor] 
libusb:debug [libusb_get_device_descriptor] 
libusb:debug [libusb_get_device_descriptor] 
libusb:debug [libusb_get_active_config_descriptor] 
libusb:debug [sysfs_get_active_config_descriptor] active configuration 1
libusb:debug [sysfs_get_active_config_descriptor] active configuration 1
libusb:debug [parse_endpoint] skipping descriptor 25
libusb:debug [libusb_open] open 1.19
libusb:debug [usbi_add_pollfd] add fd 11 events 4

Core was generated by `./qthid'.
Program terminated with signal 11, Segmentation fault.
#0 0x00007f19b90c5d66 in list_add_tail (entry=0x8cd868, head=0x8cd9b8) at libusbi.h:98
98 head->prev->next = entry;

comment:9 follow-up: Changed 5 years ago by xiaofan

I do not have the USB HID device you have. For what it is worth, I build and run qthid under Ubuntu 12.04 and the GUI comes up with no problems. Of course it says that "No FCD Detected".

Last edited 5 years ago by xiaofan (previous) (diff)

comment:10 in reply to: ↑ 9 Changed 5 years ago by dl1ksv

Replying to xiaofan:

I do not have the USB HID device you have. For what it is worth, I build and run qthid under Ubuntu 12.04 and the GUI comes up with no problems. Of course it says that "No FCD Detected".

qthid controls the funcube dongle ( fcd ), a satelite receiver. Without a fcd attached you won't get the crash

comment:11 follow-up: Changed 5 years ago by dl1ksv

The problem results from cancel_bulk_transfer.
Removing discard_urbs(itransfer, 0, tpriv->num_urbs) from cancel_bulk_transfer with the code from the last working revision ,
that is

	for (i = tpriv->num_urbs - 1; i >= 0; i--) {
		int tmp = ioctl(dpriv->fd, IOCTL_USBFS_DISCARDURB, &tpriv->urbs[i]);
		if (tmp && errno != EINVAL)
			usbi_warn(TRANSFER_CTX(transfer),
				"unrecognised discard errno %d", errno);
	}

avoids the crash.
But I get a lot of

libusb:debug [libusb_unref_device] destroy device 7.1
libusb:debug [submit_bulk_transfer] need 1 urbs for new transfer with length 64
libusb:debug [libusb_submit_transfer] arm timerfd for timeout in 1000ms (first in line)
libusb:debug [libusb_handle_events_timeout] another thread is doing event handling
libusb:debug [handle_events] poll() returned 1
libusb:debug [reap_for_handle] urb type=1 status=0 transferred=64
libusb:debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
libusb:debug [handle_bulk_completion] last URB in transfer --> complete!
libusb:debug [arm_timerfd_for_next_timeout] next timeout originally 5000ms
libusb:debug [bulk_transfer_cb] actual_length=64
libusb:debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb:debug [handle_events] poll() returned 1
libusb:debug [reap_for_handle] urb type=1 status=0 transferred=64
libusb:debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
libusb:debug [handle_bulk_completion] last URB in transfer --> complete!
libusb:debug [disarm_timerfd] 
libusb:debug [submit_bulk_transfer] need 1 urbs for new transfer with length 64
libusb:debug [libusb_cancel_transfer] 
libusb:debug [libusb_submit_transfer] arm timerfd for timeout in 5000ms (first in line)
libusb:debug [libusb_cancel_transfer] 
libusb:debug [cancel_bulk_transfer] cancel bulk transfer
libusb:debug [cancel_bulk_transfer] cancel bulk transfer
libusb:debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb:debug [handle_events] poll() returned 1
libusb:debug [reap_for_handle] urb type=1 status=-2 transferred=0
libusb:debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
libusb:debug [handle_bulk_completion] abnormal reap: urb status -2
libusb:debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
libusb:debug [disarm_timerfd] 
libusb:debug [libusb_release_interface] interface 2
libusb:debug [libusb_close] 
libusb:debug [usbi_remove_pollfd] remove fd 11
libusb:debug [libusb_unref_device] destroy device 1.9

messages.

comment:12 in reply to: ↑ 11 ; follow-up: Changed 5 years ago by stuge

Replying to dl1ksv:

The problem results from cancel_bulk_transfer.

Note that this function no longer exists in 1.0.9.

Removing discard_urbs(itransfer, 0, tpriv->num_urbs) from cancel_bulk_transfer with the code from the last working revision ,
that is

	for (i = tpriv->num_urbs - 1; i >= 0; i--) {
		int tmp = ioctl(dpriv->fd, IOCTL_USBFS_DISCARDURB, &tpriv->urbs[i]);
		if (tmp && errno != EINVAL)
			usbi_warn(TRANSFER_CTX(transfer),
				"unrecognised discard errno %d", errno);
	}

avoids the crash.

I did one more review of the discard_urbs() function and I don't see a functional difference to the code above. I can't exclude a toolchain problem, but I certainly want to get to the bottom of this issue.

libusb:debug [reap_for_handle] urb type=1 status=-2 transferred=0
libusb:debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
libusb:debug [handle_bulk_completion] abnormal reap: urb status -2
...

messages.

I believe this means that the URB has already completed when it was cancelled. In any case the message isn't really harmful.

comment:13 in reply to: ↑ 7 ; follow-up: Changed 5 years ago by stuge

Replying to dl1ksv:

Core was generated by `./gqrx'.
Program terminated with signal 11, Segmentation fault.
#0  0x00007f691491d38a in list_add_tail (entry=0xdf7a38, head=0xdf8158) at libusbi.h:103
103		head->prev->next = entry;
(gdb) bt
#0  0x00007f691491d38a in list_add_tail (entry=0xdf7a38, head=0xdf8158) at libusbi.h:103
#1  0x00007f691491d9ff in add_to_flying_list (transfer=0xdf7a30) at io.c:1188
#2  0x00007f691491dc12 in libusb_submit_transfer (transfer=0xdf7a88) at io.c:1305
#3  0x00007f691491fc04 in libusb_control_transfer (dev_handle=0xdb0870, bmRequestType=128 '\200', bRequest=6 '\006', wValue=768, wIndex=0, 
    data=0x7fffbc0e0780 "\260\a\016\274\377\177", wLength=64, timeout=1000) at sync.c:98
#4  0x00007f6918e8d199 in get_usb_string () from /usr/local/gnuradio/lib/libgnuradio-fcd-3.6.1git.so.0.0.0

In most cases the program crashes during startup.
I suppose that in case of a crash the linked list contains more than one element.

This is part of what needs to be looked into in more detail. Somehow head->prev is an invalid pointer in the above situation, we need to find out how that happened. I'll prepare a patch which adds various strategic debug output, which will hopefully clear things up.

gcc-Version 4.6.3 (Gentoo 4.6.3 p1.3, pie-0.5.1)

It would be interesting to know if the problem persists with sys-devel/gcc emerged with USE=vanilla.

comment:14 in reply to: ↑ 13 Changed 5 years ago by dl1ksv

Replying to stuge:

Replying to dl1ksv:

Core was generated by `./gqrx'.
Program terminated with signal 11, Segmentation fault.
#0  0x00007f691491d38a in list_add_tail (entry=0xdf7a38, head=0xdf8158) at libusbi.h:103
103		head->prev->next = entry;
(gdb) bt
#0  0x00007f691491d38a in list_add_tail (entry=0xdf7a38, head=0xdf8158) at libusbi.h:103
#1  0x00007f691491d9ff in add_to_flying_list (transfer=0xdf7a30) at io.c:1188
#2  0x00007f691491dc12 in libusb_submit_transfer (transfer=0xdf7a88) at io.c:1305
#3  0x00007f691491fc04 in libusb_control_transfer (dev_handle=0xdb0870, bmRequestType=128 '\200', bRequest=6 '\006', wValue=768, wIndex=0, 
    data=0x7fffbc0e0780 "\260\a\016\274\377\177", wLength=64, timeout=1000) at sync.c:98
#4  0x00007f6918e8d199 in get_usb_string () from /usr/local/gnuradio/lib/libgnuradio-fcd-3.6.1git.so.0.0.0

In most cases the program crashes during startup.
I suppose that in case of a crash the linked list contains more than one element.

This is part of what needs to be looked into in more detail. Somehow head->prev is an invalid pointer in the above situation, we need to find out how that happened. I'll prepare a patch which adds various strategic debug output, which will hopefully clear things up.

gcc-Version 4.6.3 (Gentoo 4.6.3 p1.3, pie-0.5.1)

It would be interesting to know if the problem persists with sys-devel/gcc emerged with USE=vanilla.

Well I remerged gcc with USE=vanilla and applied it to the latest git version.
Now qthid comes up and displays the gui and than crashes but at a different point.

Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `./qthid'.
Program terminated with signal 11, Segmentation fault.
#0  0x00007f2f6cceabf6 in _int_malloc () from /lib64/libc.so.6
(gdb) bt
#0  0x00007f2f6cceabf6 in _int_malloc () from /lib64/libc.so.6
#1  0x00007f2f6ccecbe2 in malloc () from /lib64/libc.so.6
#2  0x00007f2f6f2dbb5d in libusb_control_transfer (dev_handle=0x2560f20, bmRequestType=128 '\200', bRequest=6 '\006', wValue=770, wIndex=0, data=0x7fff2c7d5090 "0", 
    wLength=512, timeout=1000) at sync.c:84
#3  0x000000000041ea51 in get_usb_string ()
#4  0x000000000041eeae in hid_enumerate ()
#5  0x0000000000411db2 in fcdOpen ()
#6  0x0000000000413020 in fcdAppGetParam ()
#7  0x000000000040c35f in MainWindow::enableControls() ()
#8  0x000000000041f347 in MainWindow::qt_metacall(QMetaObject::Call, int, void**) ()
#9  0x00007f2f6e28dc1b in QMetaObject::activate(QObject*, QMetaObject const*, int, void**) () from /usr/lib64/qt4/libQtCore.so.4
#10 0x00007f2f6e28cb39 in QObject::event(QEvent*) () from /usr/lib64/qt4/libQtCore.so.4
#11 0x00007f2f6e7b5d3c in QApplicationPrivate::notify_helper(QObject*, QEvent*) () from /usr/lib64/qt4/libQtGui.so.4
#12 0x00007f2f6e7ba80f in QApplication::notify(QObject*, QEvent*) () from /usr/lib64/qt4/libQtGui.so.4
#13 0x00007f2f6e27804b in QCoreApplication::notifyInternal(QObject*, QEvent*) () from /usr/lib64/qt4/libQtCore.so.4
#14 0x00007f2f6e2a9b69 in QTimerInfoList::activateTimers() () from /usr/lib64/qt4/libQtCore.so.4
#15 0x00007f2f6e2a6b7d in timerSourceDispatch(_GSource*, int (*)(void*), void*) () from /usr/lib64/qt4/libQtCore.so.4
#16 0x00007f2f6e2a6bb1 in idleTimerSourceDispatch(_GSource*, int (*)(void*), void*) () from /usr/lib64/qt4/libQtCore.so.4
#17 0x00007f2f6da0e6da in g_main_context_dispatch () from /usr/lib64/libglib-2.0.so.0
#18 0x00007f2f6da0ea38 in g_main_context_iterate.clone.6 () from /usr/lib64/libglib-2.0.so.0
#19 0x00007f2f6da0eaec in g_main_context_iteration () from /usr/lib64/libglib-2.0.so.0
#20 0x00007f2f6e2a727a in QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib64/qt4/libQtCore.so.4
#21 0x00007f2f6e85bac6 in QGuiEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib64/qt4/libQtGui.so.4
#22 0x00007f2f6e276d32 in QEventLoop::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib64/qt4/libQtCore.so.4
#23 0x00007f2f6e277025 in QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>) () from /usr/lib64/qt4/libQtCore.so.4
#24 0x00007f2f6e27badb in QCoreApplication::exec() () from /usr/lib64/qt4/libQtCore.so.4
#25 0x0000000000411c6f in main ()

And this is the rest of the debug output

libusb: 1.110023 debug [libusb_submit_transfer] arm timerfd for timeout in 1000ms (first in line)
libusb: 1.110093 debug [libusb_handle_events_timeout_completed] another thread is doing event handling
libusb: 1.110916 debug [handle_events] poll() returned 1
libusb: 1.110975 debug [reap_for_handle] urb type=1 status=0 transferred=64
libusb: 1.111010 debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
libusb: 1.111044 debug [handle_bulk_completion] last URB in transfer --> complete!
libusb: 1.111100 debug [arm_timerfd_for_next_timeout] next timeout originally 5000ms
libusb: 1.111138 debug [disarm_timerfd] 
libusb: 1.111165 debug [usbi_handle_transfer_completion] transfer 0x26000f8 has callback 0x7f2f6f2dbd8d
libusb: 1.111199 debug [bulk_transfer_cb] actual_length=64
libusb: 1.111282 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 1.111323 debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb: 1.111909 debug [handle_events] poll() returned 1
libusb: 1.111968 debug [reap_for_handle] urb type=1 status=0 transferred=64
libusb: 1.112002 debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
libusb: 1.112036 debug [handle_bulk_completion] last URB in transfer --> complete!
libusb: 1.112093 debug [disarm_timerfd] 
libusb: 1.112122 debug [usbi_handle_transfer_completion] transfer 0x2600038 has callback 0x41de40
libusb: 1.112291 debug [submit_bulk_transfer] need 1 urbs for new transfer with length 64
libusb: 1.112293 debug [libusb_cancel_transfer] 
libusb: 1.112495 debug [libusb_submit_transfer] arm timerfd for timeout in 5000ms (first in line)
libusb: 1.112544 debug [libusb_cancel_transfer] 
libusb: 1.112572 debug [discard_urbs] URB not found --> assuming ready to be reaped
libusb: 1.112605 debug [libusb_cancel_transfer] cancel transfer failed error -5
libusb: 1.112670 debug [libusb_release_interface] interface 2
libusb: 1.112697 debug [libusb_close] 
libusb: 1.112707 error [do_close] Device handle closed while transfer was still being processed, but the device is still connected as far as we know
libusb: 1.112712 warning [do_close] A cancellation for an in-flight transfer hasn't completed but closing the device handle
libusb: 1.112716 debug [do_close] Removed transfer 0x2600038 from the in-flight list because device handle 0x25f7d40 closed
libusb: 1.112721 debug [usbi_remove_pollfd] remove fd 11
libusb: 1.112731 debug [libusb_unref_device] destroy device 1.5
libusb: 1.112799 debug [libusb_get_device_list] 
libusb: 1.112836 debug [sysfs_scan_device] scan 1-5
libusb: 1.112916 debug [sysfs_scan_device] bus=1 dev=4
libusb: 1.112921 debug [enumerate_device] busnum 1 devaddr 4 session_id 260
libusb: 1.112926 debug [enumerate_device] allocating new device for 1/4 (session 260)
libusb: 1.112957 debug [sysfs_scan_device] scan 3-1
libusb: 1.112990 debug [sysfs_scan_device] bus=3 dev=2
libusb: 1.112994 debug [enumerate_device] busnum 3 devaddr 2 session_id 770
libusb: 1.112998 debug [enumerate_device] allocating new device for 3/2 (session 770)
libusb: 1.113022 debug [sysfs_scan_device] scan 3-2
libusb: 1.113053 debug [sysfs_scan_device] bus=3 dev=3
libusb: 1.113057 debug [enumerate_device] busnum 3 devaddr 3 session_id 771
libusb: 1.113060 debug [enumerate_device] allocating new device for 3/3 (session 771)
libusb: 1.113101 debug [sysfs_scan_device] scan usb1
libusb: 1.113131 debug [sysfs_scan_device] bus=1 dev=1
libusb: 1.113136 debug [enumerate_device] busnum 1 devaddr 1 session_id 257
libusb: 1.113140 debug [enumerate_device] allocating new device for 1/1 (session 257)
libusb: 1.113172 debug [sysfs_scan_device] scan usb2
libusb: 1.113213 debug [sysfs_scan_device] bus=2 dev=1
libusb: 1.113217 debug [enumerate_device] busnum 2 devaddr 1 session_id 513
libusb: 1.113221 debug [enumerate_device] allocating new device for 2/1 (session 513)
libusb: 1.113246 debug [sysfs_scan_device] scan usb3
libusb: 1.113274 debug [sysfs_scan_device] bus=3 dev=1
libusb: 1.113278 debug [enumerate_device] busnum 3 devaddr 1 session_id 769
libusb: 1.113282 debug [enumerate_device] allocating new device for 3/1 (session 769)
libusb: 1.113307 debug [sysfs_scan_device] scan usb4
libusb: 1.113339 debug [sysfs_scan_device] bus=4 dev=1
libusb: 1.113344 debug [enumerate_device] busnum 4 devaddr 1 session_id 1025
libusb: 1.113347 debug [enumerate_device] allocating new device for 4/1 (session 1025)
libusb: 1.113371 debug [sysfs_scan_device] scan usb5
libusb: 1.113402 debug [sysfs_scan_device] bus=5 dev=1
libusb: 1.113407 debug [enumerate_device] busnum 5 devaddr 1 session_id 1281
libusb: 1.113410 debug [enumerate_device] allocating new device for 5/1 (session 1281)
libusb: 1.113435 debug [sysfs_scan_device] scan usb6
libusb: 1.113467 debug [sysfs_scan_device] bus=6 dev=1
libusb: 1.113471 debug [enumerate_device] busnum 6 devaddr 1 session_id 1537
libusb: 1.113475 debug [enumerate_device] allocating new device for 6/1 (session 1537)
libusb: 1.113499 debug [discovered_devs_append] need to increase capacity
libusb: 1.113505 debug [sysfs_scan_device] scan usb7
libusb: 1.113534 debug [sysfs_scan_device] bus=7 dev=1
libusb: 1.113539 debug [enumerate_device] busnum 7 devaddr 1 session_id 1793
libusb: 1.113543 debug [enumerate_device] allocating new device for 7/1 (session 1793)
libusb: 1.113568 debug [sysfs_scan_device] scan 1-5.1
libusb: 1.113599 debug [sysfs_scan_device] bus=1 dev=5
libusb: 1.113603 debug [enumerate_device] busnum 1 devaddr 5 session_id 261
libusb: 1.113607 debug [enumerate_device] allocating new device for 1/5 (session 261)
libusb: 1.113636 debug [libusb_get_device_descriptor] 
libusb: 1.113646 debug [libusb_get_device_descriptor] 
libusb: 1.113654 debug [libusb_get_active_config_descriptor] 
libusb: 1.113665 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 1.138281 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 1.138309 debug [libusb_get_device_descriptor] 
libusb: 1.138327 debug [libusb_get_active_config_descriptor] 
libusb: 1.138342 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 1.138363 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 1.138379 debug [libusb_get_device_descriptor] 
libusb: 1.138395 debug [libusb_get_device_descriptor] 
libusb: 1.138411 debug [libusb_get_device_descriptor] 
libusb: 1.138423 debug [libusb_get_device_descriptor] 
libusb: 1.138437 debug [libusb_get_device_descriptor] 
libusb: 1.138452 debug [libusb_get_device_descriptor] 
libusb: 1.138466 debug [libusb_get_device_descriptor] 
libusb: 1.138482 debug [libusb_get_device_descriptor] 
libusb: 1.138498 debug [libusb_get_active_config_descriptor] 
libusb: 1.138512 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 1.138534 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 1.138554 debug [parse_endpoint] skipping descriptor 25
libusb: 1.138569 debug [libusb_open] open 1.5
libusb: 1.138580 debug [op_open] opening /dev/bus/usb/001/005
libusb: 1.138602 debug [usbi_add_pollfd] add fd 11 events 4
libusb: 1.138635 debug [libusb_submit_transfer] arm timerfd for timeout in 1000ms (first in line)
libusb: 1.138648 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 1.138656 debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb: 1.139408 debug [handle_events] poll() returned 1
libusb: 1.139489 debug [reap_for_handle] urb type=2 status=0 transferred=4
libusb: 1.139521 debug [handle_control_completion] handling completion status 0
libusb: 1.139557 debug [disarm_timerfd] 
libusb: 1.139582 debug [usbi_handle_transfer_completion] transfer 0x25651c8 has callback 0x7f2f6f2dbaab
libusb: 1.139615 debug [ctrl_transfer_cb] actual_length=4
libusb: 1.139673 debug [libusb_submit_transfer] arm timerfd for timeout in 1000ms (first in line)
libusb: 1.139710 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 1.139741 debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb: 1.139843 debug [handle_events] poll() returned 1
libusb: 1.139880 debug [reap_for_handle] urb type=2 status=0 transferred=4
libusb: 1.139911 debug [handle_control_completion] handling completion status 0
libusb: 1.139942 debug [disarm_timerfd] 
libusb: 1.139964 debug [usbi_handle_transfer_completion] transfer 0x25651c8 has callback 0x7f2f6f2dbaab
libusb: 1.139995 debug [ctrl_transfer_cb] actual_length=4
libusb: 1.140035 debug [libusb_submit_transfer] arm timerfd for timeout in 1000ms (first in line)
libusb: 1.140106 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 1.140156 debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb: 1.140593 debug [handle_events] poll() returned 1
libusb: 1.140628 debug [reap_for_handle] urb type=2 status=0 transferred=52
libusb: 1.140659 debug [handle_control_completion] handling completion status 0
libusb: 1.140689 debug [arm_timerfd_for_next_timeout] next timeout originally 0ms
libusb: 1.140721 error [handle_events] backend handle_events failed with error -99
libusb: 1.140758 debug [libusb_cancel_transfer] 
libusb: 1.140779 debug [libusb_cancel_transfer] cancel transfer failed error -5
libusb: 1.140811 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 1.140841 debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb: 2.140097 debug [handle_events] poll() returned 1
libusb: 2.140139 debug [handle_events] timerfd triggered
libusb: 2.140153 debug [disarm_timerfd] 
libusb: 2.140169 debug [arm_timerfd_for_next_timeout] next timeout originally 0ms
libusb: 2.140229 debug [libusb_submit_transfer] arm timerfd for timeout in 1000ms (first in line)
libusb: 2.140250 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 2.140264 debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb: 2.140614 debug [handle_events] poll() returned 1
libusb: 2.140636 debug [reap_for_handle] urb type=2 status=0 transferred=4
libusb: 2.140650 debug [handle_control_completion] handling completion status 0
libusb: 2.140664 debug [arm_timerfd_for_next_timeout] next timeout originally 0ms
libusb: 2.140679 error [handle_events] backend handle_events failed with error -99
libusb: 2.140692 debug [libusb_cancel_transfer] 
libusb: 2.140702 debug [libusb_cancel_transfer] cancel transfer failed error -5
libusb: 2.140716 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 2.140729 debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb: 3.140259 debug [handle_events] poll() returned 1
libusb: 3.140300 debug [handle_events] timerfd triggered
libusb: 3.140313 debug [disarm_timerfd] 
libusb: 3.140329 debug [arm_timerfd_for_next_timeout] next timeout originally 0ms
libusb: 3.140378 debug [libusb_submit_transfer] arm timerfd for timeout in 1000ms (first in line)
libusb: 3.140398 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 3.140413 debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb: 3.140607 debug [handle_events] poll() returned 1
libusb: 3.140631 debug [reap_for_handle] urb type=2 status=0 transferred=4
libusb: 3.140652 debug [handle_control_completion] handling completion status 0
libusb: 3.140666 debug [arm_timerfd_for_next_timeout] next timeout originally 0ms
libusb: 3.140680 error [handle_events] backend handle_events failed with error -99
libusb: 3.140694 debug [libusb_cancel_transfer] 
libusb: 3.140703 debug [libusb_cancel_transfer] cancel transfer failed error -5
libusb: 3.140717 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 3.140730 debug [handle_events] poll() 3 fds with timeout in 60000ms
libusb: 4.140407 debug [handle_events] poll() returned 1
libusb: 4.140447 debug [handle_events] timerfd triggered
libusb: 4.140461 debug [disarm_timerfd] 
libusb: 4.140477 debug [arm_timerfd_for_next_timeout] next timeout originally 0ms
Speicherzugriffsfehler (Speicherabzug geschrieben)

This is in /var/log/messages

Jun 10 15:30:44 tux64 kernel: [ 2048.305404] usb 1-5.1: link qh1-0e01/ffff88006a0f1d00 start 0 [1/3 us]
Jun 10 15:30:44 tux64 kernel: [ 2048.305980] ehci_hcd 0000:00:12.2: reused qh ffff88006bf41b80 schedule
Jun 10 15:30:44 tux64 kernel: [ 2048.305991] usb 1-5.1: link qh1-0e01/ffff88006bf41b80 start 0 [3/1 us]
Jun 10 15:30:44 tux64 kernel: [ 2048.306867] usb 1-5.1: unlink qh1-0e01/ffff88006bf41b80 start 0 [3/1 us]
Jun 10 15:30:44 tux64 kernel: [ 2048.307866] usb 1-5.1: unlink qh1-0e01/ffff88006a0f1d00 start 0 [1/3 us]
Jun 10 15:30:44 tux64 kernel: [ 2048.308449] ehci_hcd 0000:00:12.2: reused qh ffff88006a0f1d00 schedule
Jun 10 15:30:44 tux64 kernel: [ 2048.308458] usb 1-5.1: link qh1-0e01/ffff88006a0f1d00 start 0 [1/3 us]
Jun 10 15:30:44 tux64 kernel: [ 2048.308537] usb 1-5.1: unlink qh1-0e01/ffff88006a0f1d00 start 0 [1/3 us]
Jun 10 15:30:47 tux64 kernel: [ 2051.331433] qthid[6186]: segfault at 4b5e758 ip 00007f2f6cceabf6 sp 00007fff2c7d4b50 error 6 in libc-2.14.1.so[7f2f6cc72000+188000]

Should I recompile glibc , too ?

Last edited 5 years ago by dl1ksv (previous) (diff)

comment:15 in reply to: ↑ 12 Changed 5 years ago by dl1ksv

Replying to stuge:

Replying to dl1ksv:

The problem results from cancel_bulk_transfer.

Note that this function no longer exists in 1.0.9.

Removing discard_urbs(itransfer, 0, tpriv->num_urbs) from cancel_bulk_transfer with the code from the last working revision ,
that is

	for (i = tpriv->num_urbs - 1; i >= 0; i--) {
		int tmp = ioctl(dpriv->fd, IOCTL_USBFS_DISCARDURB, &tpriv->urbs[i]);
		if (tmp && errno != EINVAL)
			usbi_warn(TRANSFER_CTX(transfer),
				"unrecognised discard errno %d", errno);
	}

avoids the crash.

I did one more review of the discard_urbs() function and I don't see a functional difference to the code above. I can't exclude a toolchain problem, but I certainly want to get to the bottom of this issue.

Well there is a small difference. In the last working revision the return code of cancel_bulk_transfer is always 0, but in the first non working revision it is the result of discard_urbs and so it can be nonzero.
I modified the code accordingly, but that didn't the trick.

libusb:debug [reap_for_handle] urb type=1 status=-2 transferred=0
libusb:debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
libusb:debug [handle_bulk_completion] abnormal reap: urb status -2
...

messages.

I believe this means that the URB has already completed when it was cancelled. In any case the message isn't really harmful.

comment:16 follow-up: Changed 5 years ago by dl1ksv

I'm getting crazy. This evening I get:

libusb: 0.016407 debug [libusb_submit_transfer] arm timerfd for timeout in 5000ms (first in line)
libusb: 0.016429 debug [libusb_cancel_transfer] 
libusb: 0.016470 debug [discard_urbs] URB not found --> assuming ready to be reaped
libusb: 0.016484 debug [libusb_cancel_transfer] cancel transfer failed error -5
libusb: 0.016525 debug [libusb_release_interface] interface 2
libusb: 0.016554 debug [libusb_close] 
libusb: 0.016569 error [do_close] Device handle closed while transfer was still being processed, but the device is still connected as far as we know
libusb: 0.016574 warning [do_close] A cancellation for an in-flight transfer hasn't completed but closing the device handle
Speicherzugriffsfehler (Speicherabzug geschrieben)

And

Core was generated by `./qthid'.
Program terminated with signal 11, Segmentation fault.
#0  0x00007f1777cdfe0c in list_del (entry=0x1afc5e8) at libusbi.h:109
109		entry->next->prev = entry->prev;
(gdb) bt
#0  0x00007f1777cdfe0c in list_del (entry=0x1afc5e8) at libusbi.h:109
#1  0x00007f1777ce0cf6 in do_close (ctx=0x1afb2d0, dev_handle=0x1afc350) at core.c:1074
#2  0x00007f1777ce0f8d in libusb_close (dev_handle=0x1afc350) at core.c:1153
#3  0x000000000041e814 in hid_close ()
#4  0x0000000000412577 in fcdAppSetFreqkHz ()
#5  0x000000000041f0f2 in MainWindow::qt_metacall(QMetaObject::Call, int, void**) ()
#6  0x00007f1776c97c1b in QMetaObject::activate(QObject*, QMetaObject const*, int, void**) () from /usr/lib64/qt4/libQtCore.so.4
#7  0x00007f17778443ee in QSpinBox::valueChanged(int) () from /usr/lib64/qt4/libQtGui.so.4
#8  0x00007f1777613372 in QSpinBoxPrivate::emitSignals(EmitPolicy, QVariant const&) () from /usr/lib64/qt4/libQtGui.so.4
#9  0x00007f17775857be in QAbstractSpinBoxPrivate::setValue(QVariant const&, EmitPolicy, bool) () from /usr/lib64/qt4/libQtGui.so.4
#10 0x00007f1777613484 in QSpinBox::setValue(int) () from /usr/lib64/qt4/libQtGui.so.4
#11 0x000000000040c6ac in MainWindow::MainWindow(QWidget*) ()
#12 0x0000000000411c5b in main ()
(gdb) p *entry
$1 = {prev = 0x7f1775a09ef8, next = 0x0}

May be this is of interest:
My impression is, that the problem arises due to many open and close calls on every device setting.
So I rewrote qthid to open and close the device only once. Then qthid runs without a crash. But why ?

comment:17 in reply to: ↑ 16 Changed 5 years ago by stuge

Replying to dl1ksv:

I'm getting crazy.

Just a note that I've reproduced the problem and am looking into the details.

May be this is of interest:
My impression is, that the problem arises due to many open and close calls on every device setting.
So I rewrote qthid to open and close the device only once. Then qthid runs without a crash. But why ?

From the look of the logs and the crashes my guess is that HIDAPI calls libusb_close() before all transfers have completed. Let's see.

comment:18 Changed 5 years ago by alan.ott

hidapi doesn't call libusb_close() until the read_thread() has finished, and transfers have been canceled and freed.

Reference link for convenience:
https://github.com/signal11/hidapi/blob/0a199c36ed6903340716e2b2d2ec6805cd1c3b87/libusb/hid.c#L1159

Maybe I misunderstand.

comment:19 follow-up: Changed 4 years ago by jleveque

Just checking in to see if any progress has been made with regards to this bug. Today I experienced a crash in this exact location running a proprietary program that calls libusb-1.0 directly (i.e. no HIDAPI). This is the first time I have seen this crash and we have been compiling multiple projects against libusb-1.0.9 since April 2012, so I'm not quite sure if I can reproduce it to help out. Any updates? Thanks in advance.

comment:20 in reply to: ↑ 19 Changed 4 years ago by hansdegoede

Replying to jleveque:

Just checking in to see if any progress has been made with regards to this bug. Today I experienced a crash in this exact location running a proprietary program that calls libusb-1.0 directly (i.e. no HIDAPI). This is the first time I have seen this crash and we have been compiling multiple projects against libusb-1.0.9 since April 2012, so I'm not quite sure if I can reproduce it to help out. Any updates? Thanks in advance.

Hi,

I think this may be a variation on the issue explained in, and fixed by, this patch:
https://sourceforge.net/mailarchive/message.php?msg_id=30803244

Can you build the latest libusbx with that patch and see if it helps ?

Regards,

Hans

comment:21 follow-up: Changed 4 years ago by jleveque

Hans,

Thank you for the quick reply. I will try building libusbx with your patch and testing it, but as this problem has only occurred (to my knowledge) once in the past year, I don't know how to reproduce it, and because of the infrequency, I honestly won't know if it fixed my issue, therefore I won't be able to provide you any feedback. Out of curiosity, has this patch been approved/submitted to libusbx upstream?

comment:22 in reply to: ↑ 21 Changed 4 years ago by hansdegoede

Replying to jleveque:

Hans,

Thank you for the quick reply. I will try building libusbx with your patch and testing it, but as this problem has only occurred (to my knowledge) once in the past year, I don't know how to reproduce it, and because of the infrequency, I honestly won't know if it fixed my issue, therefore I won't be able to provide you any feedback. Out of curiosity, has this patch been approved/submitted to libusbx upstream?

Submitted yes, approved not yet, it is currently waiting for the Windows maintainer to take a closer look.

Note: See TracTickets for help on using tickets.