Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix USB handling and timeouts for newer devices #329

Closed
wants to merge 1 commit into from

Conversation

deriamis
Copy link

This commit should fix #228 #230 #209 #276 #190 #307 #141 #225 #286 for most new devices (they were all related to the same problems). The issues found were:

  • kEmptyTransferAfter should no longer be the default (apparently) in most cases. I've instances where this was being used by default to explicit kEmptyTransferNone, which fixed a lot of the warnings my S5 was getting. I assume this is the case for all newer devices, but it may need customization of some kind if there are further problems.
  • libusb_reset_device() must now be called after releasing the interface, since this is no longer being done by the device itself upon ending the session. Again, I assume this is the case for newer devices, but doing it ourselves simply ensures the reset happens even if the device also does it. Not resetting the device can result in --no-reboot leaving the device non-responsive to further sessions until it's unplugged and reattached.
  • The packet timeout was too short, which was causing occasional timeout reports. It was especially bad when the device was connected to a USB3.0 port, since the speed negotiations seemed to be pushing the response times just past the timeouts, making it impossible to connect to the device at all. Doubling the default send and receive timeout seems to have resolved all of these issues on my S5.

@deriamis
Copy link
Author

I'm going to take back the last one being completely fixed on USB3.0, but it is significantly better at least when downloading the PIT. USB2.0 works without any problems. I still get the occasional "WARNING: Empty bulk transfer after sending packet failed. Continuing anyway..." as well, but far fewer and they don't really cause problems.

@Benjamin-Dobell
Copy link
Owner

Could you please separate these into 3 separate commits?

  • libusb_reset_device() must now be called after releasing the interface, since this is no longer being done by the device itself upon ending the session. Again, I assume this is the case for newer devices, but doing it ourselves simply ensures the reset happens even if the device also does it. Not resetting the device can result in --no-reboot leaving the device non-responsive to further sessions until it's unplugged and reattached.
  • The packet timeout was too short, which was causing occasional timeout reports. It was especially bad when the device was connected to a USB3.0 port, since the speed negotiations seemed to be pushing the response times just past the timeouts, making it impossible to connect to the device at all. Doubling the default send and receive timeout seems to have resolved all of these issues on my S5.

I will very happily merge both of these - thanks for the awesome work.

  • kEmptyTransferAfter should no longer be the default (apparently) in most cases. I've instances where this was being used by default to explicit kEmptyTransferNone, which fixed a lot of the warnings my S5 was getting. I assume this is the case for all newer devices, but it may need customization of some kind if there are further problems.

Definitely useful information, unfortunately I can't merge this because older devices do require the use of kEmptyTransferAfter, and we really don't want to break backwards compatibility or it will really confuse users. Ideally we need to come up with a solution that works for all devices.

Also, what model is your S5 and what is the firmware version the secondary bootloader was included with? I ask this because I also own a S5 (G900I) and it's running flawlessly with whatever secondary bootloader I have on there (it's not with me at the moment so I can't provide the version unfortunately).

@Benjamin-Dobell
Copy link
Owner

I also own a S5 (G900I) and it's running flawlessly with whatever secondary bootloader I have on there

Sorry, to clarify, I mean running flawlessly with the current master build i.e. It doesn't require the changes you've mentioned.

@deriamis
Copy link
Author

deriamis commented Mar 2, 2016

Sorry for the delay - this week has been... hectic. I'll certainly split those commits for you later on this week. I actually have Cyanogenmod installed right now, but at the time I was seeing these issues, I had a stock 5.1.1 ROM on a T-Mobile SM-G900T. It was factory reconditioned when I bought it, so I imagine it would have been the latest SBL. I'm not sure how to get the actual SBL version, though - I'm a Linux administrator with some programming experience, not an Android expert. How would I get that information for you?

@Arzte
Copy link

Arzte commented Apr 15, 2016

Any update on this?

@ghost
Copy link

ghost commented Apr 17, 2016

I'm having this same issue, Samsung Galaxy S4, international, non-LTE version (GT-i9500)

C:.......\Heimdall Suite>heimdall detect
Device detected

C:.......\Heimdall Suite>heimdall flash --RECOVERY ....\cm-12.1-20160417-NIGHTLY-i9500-recovery.img --no-reboot --verbose
Heimdall v1.4.0

Copyright (c) 2010-2013, Benjamin Dobell, Glass Echidna
http://www.glassechidna.com.au/

This software is provided free of charge. Copying and redistribution is
encouraged.

If you appreciate this software and you would like to support future
development please consider donating:
http://www.glassechidna.com.au/donate/

Initialising connection...
Detecting device...
Manufacturer: "SAMSUNG"
Product: "Gadget Serial"

        length: 18
  device class: 2
           S/N: 0
       VID:PID: 04E8:685D
     bcdDevice: 021B

iMan:iProd:iSer: 1:2:0
nb confs: 1

interface[0].altsetting[0]: num endpoints = 1
Class.SubClass.Protocol: 02.02.01
endpoint[0].address: 83
max packet size: 0010
polling interval: 09

interface[1].altsetting[0]: num endpoints = 2
Class.SubClass.Protocol: 0A.00.00
endpoint[0].address: 81
max packet size: 0200
polling interval: 00
endpoint[1].address: 02
max packet size: 0200
polling interval: 00
Claiming interface...
Setting up interface...

Initialising protocol...
WARNING: Control transfer #2 failed. Result: -7
WARNING: Control transfer #3 failed. Result: -7
WARNING: Control transfer #4 failed. Result: -7
WARNING: Control transfer #5 failed. Result: -7
WARNING: Control transfer #6 failed. Result: -9
ERROR: Failed to send data: "ODIN"
Releasing device interface...

C:.......\Heimdall Suite>

@Benjamin-Dobell
Copy link
Owner

@richieacc You're running 1.4.0, please try the latest from master before commenting on issues that may have already been fixed.

@ghost
Copy link

ghost commented Apr 18, 2016

@Benjamin-Dobell Thanks! I read about the update after posting the comment. I have built Heimdall from source, and it worked.

@sosnet
Copy link

sosnet commented Apr 22, 2016

Hey, I just cloned and built Heimdall from source and get this error for a GT-S7580:

sudo heimdall print-pit --verbose

Heimdall v1.4.1

Copyright (c) 2010-2014 Benjamin Dobell, Glass Echidna
http://www.glassechidna.com.au/

This software is provided free of charge. Copying and redistribution is
encouraged.

If you appreciate this software and you would like to support future
development please consider donating:
http://www.glassechidna.com.au/donate/

Initialising connection...
Detecting device...

            length: 18
      device class: 2
               S/N: 3
           VID:PID: 04E8:685D
         bcdDevice: 0001
   iMan:iProd:iSer: 2:1:3
          nb confs: 1

interface[0].altsetting[0]: num endpoints = 1
   Class.SubClass.Protocol: 02.02.01
       endpoint[0].address: 83
           max packet size: 0040
          polling interval: 05

interface[1].altsetting[0]: num endpoints = 2
   Class.SubClass.Protocol: 0A.00.00
       endpoint[0].address: 81
           max packet size: 0200
          polling interval: 20
       endpoint[1].address: 02
           max packet size: 0200
          polling interval: 20
Claiming interface...
Setting up interface...
libusbx: error [op_set_interface] setintf failed error -1 errno 110
ERROR: Setting up interface failed!
Releasing device interface...

Edit: Ok, like always.. After posting this and restarting the device again it successfully goes further now:

Setting up interface...

Initialising protocol...
Protocol initialisation successful.

Beginning session...
WARNING: Empty bulk transfer after sending packet failed. Continuing anyway...

Some devices may take up to 2 minutes to respond.
Please be patient!

WARNING: Empty bulk transfer after sending packet failed. Continuing anyway...
Session begun.

Downloading device's PIT file...
WARNING: Empty bulk transfer after sending packet failed. Continuing anyway...
WARNING: Empty bulk transfer after sending packet failed. Continuing anyway...

It's writing this message several times until the phone restarts...

@EvanCarroll
Copy link

@sosnet did you apply this patch?

@sosnet
Copy link

sosnet commented Apr 24, 2016

@EvanCarroll
Oh sorry, my mistake. I thought this commit was already merged into the master branch.
Anyway, it worker after some more tries.

@EvanCarroll
Copy link

@sosnet still shows not merged.. Just hit the merge button.

@Benjamin-Dobell
Copy link
Owner

Just hit the merge button.

And break support for thousands of people's devices? No, thanks 😉

As mentioned, if the pull request is split up into 2-3 smaller pieces it's easier for me to test and merge each of the functional changes individually.

@GilesBathgate
Copy link

I tried this patch and it didn't work for me:

giles@BP0039a:~/Heimdall/build/bin$ git log -1
commit 81d2964b6c254d09506121bce16e482292c29c4b
Author: Ryan Egesdahl <[email protected]>
Date:   Fri Feb 26 03:24:43 2016 -0600

    Fix USB handling and timeouts for newer devices
giles@BP0039a:~/Heimdall/build/bin$ sudo ./heimdall print-pit --verbose --usb-log-level debug
Heimdall v1.4.1

Copyright (c) 2010-2014 Benjamin Dobell, Glass Echidna
http://www.glassechidna.com.au/

This software is provided free of charge. Copying and redistribution is
encouraged.

If you appreciate this software and you would like to support future
development please consider donating:
http://www.glassechidna.com.au/donate/

Initialising connection...
Detecting device...
[timestamp] [threadID] facility level [function call] <message>
--------------------------------------------------------------------------------
[ 0.008205] [00001b3c] libusb: debug [libusb_get_device_list] 
[ 0.008274] [00001b3c] libusb: debug [discovered_devs_append] need to increase capacity
[ 0.008297] [00001b3c] libusb: debug [libusb_get_device_descriptor] 
[ 0.008312] [00001b3c] libusb: debug [libusb_get_device_descriptor] 
[ 0.008327] [00001b3c] libusb: debug [libusb_get_device_descriptor] 
[ 0.008341] [00001b3c] libusb: debug [libusb_get_device_descriptor] 
[ 0.008355] [00001b3c] libusb: debug [libusb_get_device_descriptor] 
[ 0.008369] [00001b3c] libusb: debug [libusb_get_device_descriptor] 
[ 0.008383] [00001b3c] libusb: debug [libusb_get_device_descriptor] 
[ 0.008397] [00001b3c] libusb: debug [libusb_get_device_descriptor] 
[ 0.008416] [00001b3c] libusb: debug [libusb_open] open 1.18
[ 0.008489] [00001b3c] libusb: debug [usbi_add_pollfd] add fd 11 events 4
[ 0.008525] [00001b3c] libusb: debug [libusb_get_device_descriptor] 
[ 0.008545] [00001b3c] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.008600] [00001b3c] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.008622] [00001b3c] libusb: debug [handle_events] poll() 4 fds with timeout in 60000ms
[ 0.008729] [00001b3c] libusb: debug [handle_events] poll() returned 1
[ 0.008789] [00001b3c] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.008818] [00001b3c] libusb: debug [handle_control_completion] handling completion status 0
[ 0.008846] [00001b3c] libusb: debug [disarm_timerfd] 
[ 0.008874] [00001b3c] libusb: debug [usbi_handle_transfer_completion] transfer 0x1350350 has callback 0x7ff3b72d80b0
[ 0.008900] [00001b3c] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.008947] [00001b3c] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.008995] [00001b3c] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.009023] [00001b3c] libusb: debug [handle_events] poll() 4 fds with timeout in 60000ms
[ 0.009115] [00001b3c] libusb: debug [handle_events] poll() returned 1
[ 0.009169] [00001b3c] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=16
[ 0.009196] [00001b3c] libusb: debug [handle_control_completion] handling completion status 0
[ 0.009222] [00001b3c] libusb: debug [disarm_timerfd] 
[ 0.009248] [00001b3c] libusb: debug [usbi_handle_transfer_completion] transfer 0x1350350 has callback 0x7ff3b72d80b0
[ 0.009274] [00001b3c] libusb: debug [sync_transfer_cb] actual_length=16
      Manufacturer: "SAMSUNG"
[ 0.009329] [00001b3c] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.009366] [00001b3c] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.009393] [00001b3c] libusb: debug [handle_events] poll() 4 fds with timeout in 60000ms
[ 0.009480] [00001b3c] libusb: debug [handle_events] poll() returned 1
[ 0.009509] [00001b3c] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.009532] [00001b3c] libusb: debug [handle_control_completion] handling completion status 0
[ 0.009558] [00001b3c] libusb: debug [disarm_timerfd] 
[ 0.009583] [00001b3c] libusb: debug [usbi_handle_transfer_completion] transfer 0x1350350 has callback 0x7ff3b72d80b0
[ 0.009609] [00001b3c] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.009638] [00001b3c] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.009674] [00001b3c] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.009701] [00001b3c] libusb: debug [handle_events] poll() 4 fds with timeout in 60000ms
[ 0.009773] [00001b3c] libusb: debug [handle_events] poll() returned 1
[ 0.009803] [00001b3c] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=38
[ 0.009827] [00001b3c] libusb: debug [handle_control_completion] handling completion status 0
[ 0.009853] [00001b3c] libusb: debug [disarm_timerfd] 
[ 0.009878] [00001b3c] libusb: debug [usbi_handle_transfer_completion] transfer 0x1350350 has callback 0x7ff3b72d80b0
[ 0.009903] [00001b3c] libusb: debug [sync_transfer_cb] actual_length=38
           Product: "SAMSUNG USB DRIVER"
[ 0.009955] [00001b3c] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.009990] [00001b3c] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.010024] [00001b3c] libusb: debug [handle_events] poll() 4 fds with timeout in 60000ms
[ 0.010097] [00001b3c] libusb: debug [handle_events] poll() returned 1
[ 0.010129] [00001b3c] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.010152] [00001b3c] libusb: debug [handle_control_completion] handling completion status 0
[ 0.010174] [00001b3c] libusb: debug [disarm_timerfd] 
[ 0.010198] [00001b3c] libusb: debug [usbi_handle_transfer_completion] transfer 0x1350350 has callback 0x7ff3b72d80b0
[ 0.010222] [00001b3c] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.010251] [00001b3c] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.010284] [00001b3c] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.010308] [00001b3c] libusb: debug [handle_events] poll() 4 fds with timeout in 60000ms
[ 0.010390] [00001b3c] libusb: debug [handle_events] poll() returned 1
[ 0.010417] [00001b3c] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=42
[ 0.010442] [00001b3c] libusb: debug [handle_control_completion] handling completion status 0
[ 0.010466] [00001b3c] libusb: debug [disarm_timerfd] 
[ 0.010491] [00001b3c] libusb: debug [usbi_handle_transfer_completion] transfer 0x1350350 has callback 0x7ff3b72d80b0
[ 0.010515] [00001b3c] libusb: debug [sync_transfer_cb] actual_length=42
         Serial No: "   SAMSUNG SERIAL BULK"

            length: 18
      device class: 2
               S/N: 3
           VID:PID: 04E8:685D
         bcdDevice: 0000
   iMan:iProd:iSer: 1:2:3
          nb confs: 1
[ 0.010735] [00001b3c] libusb: debug [libusb_get_config_descriptor] index 0

interface[0].altsetting[0]: num endpoints = 1
   Class.SubClass.Protocol: 02.02.01
       endpoint[0].address: 83
           max packet size: 0010
          polling interval: 09

interface[1].altsetting[0]: num endpoints = 2
   Class.SubClass.Protocol: 0A.00.00
       endpoint[0].address: 81
           max packet size: 0200
          polling interval: 00
       endpoint[1].address: 02
           max packet size: 0200
          polling interval: 00
Claiming interface...
[ 0.011081] [00001b3c] libusb: debug [libusb_claim_interface] interface 1
Setting up interface...
[ 0.011157] [00001b3c] libusb: debug [libusb_set_interface_alt_setting] interface 1 altsetting 0

Initialising protocol...
[ 0.018845] [00001b3c] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.018870] [00001b3c] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 4
[ 0.018897] [00001b3c] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.018921] [00001b3c] libusb: debug [handle_events] poll() 4 fds with timeout in 60000ms
[ 0.018950] [00001b3c] libusb: debug [handle_events] poll() returned 1
[ 0.018966] [00001b3c] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=4
[ 0.018980] [00001b3c] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.018995] [00001b3c] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.019010] [00001b3c] libusb: debug [disarm_timerfd] 
[ 0.019024] [00001b3c] libusb: debug [usbi_handle_transfer_completion] transfer 0x1350350 has callback 0x7ff3b72d80b0
[ 0.019038] [00001b3c] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.019057] [00001b3c] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.019073] [00001b3c] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 7
[ 0.019091] [00001b3c] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.019123] [00001b3c] libusb: debug [handle_events] poll() 4 fds with timeout in 60000ms
[ 1.019170] [00001b3c] libusb: debug [handle_events] poll() returned 1
[ 1.019244] [00001b3c] libusb: debug [handle_events] timerfd triggered
[ 1.019268] [00001b3c] libusb: debug [libusb_cancel_transfer] 
[ 1.019403] [00001b3c] libusb: debug [disarm_timerfd] 
[ 1.019446] [00001b3c] libusb: debug [handle_events] poll() 4 fds with timeout in 0ms
[ 1.019465] [00001b3c] libusb: debug [handle_events] poll() returned 1
[ 1.019485] [00001b3c] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[ 1.019520] [00001b3c] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[ 1.019537] [00001b3c] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[ 1.019552] [00001b3c] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[ 1.019569] [00001b3c] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 1.019584] [00001b3c] libusb: debug [disarm_timerfd] 
[ 1.019599] [00001b3c] libusb: debug [usbi_handle_transfer_completion] transfer 0x1350350 has callback 0x7ff3b72d80b0
[ 1.019616] [00001b3c] libusb: debug [sync_transfer_cb] actual_length=0
ERROR: Failed to receive handshake response. Result: -7
ERROR: Protocol initialisation failed!

Releasing device interface...
[ 1.019724] [00001b3c] libusb: debug [libusb_release_interface] interface 1

[ 1.019777] [00001b3c] libusb: debug [libusb_close] 
[ 1.019806] [00001b3c] libusb: debug [usbi_remove_pollfd] remove fd 11
[ 1.019849] [00001b3c] libusb: debug [libusb_exit] 
[ 1.019881] [00001b3c] libusb: debug [libusb_exit] destroying default context

@luis-pereira
Copy link

It doesn't work for me either: Log here.

@KOLANICH
Copy link

KOLANICH commented Jul 9, 2017

Neither does it for me
Heimdall v1.4.2

Copyright (c) 2010-2017 Benjamin Dobell, Glass Echidna
http://www.glassechidna.com.au/

This software is provided free of charge. Copying and redistribution is
encouraged.

If you appreciate this software and you would like to support future
development please consider donating:
http://www.glassechidna.com.au/donate/

Initialising connection...
Detecting device...
[timestamp] [threadID] facility level [function call] <message>
--------------------------------------------------------------------------------
[ 0.005821] [000012d6] libusb: debug [libusb_get_device_list] 
[ 0.005913] [000012d6] libusb: debug [libusb_get_device_descriptor] 
[ 0.005932] [000012d6] libusb: debug [libusb_get_device_descriptor] 
[ 0.005955] [000012d6] libusb: debug [libusb_open] open 1.6
[ 0.006030] [000012d6] libusb: debug [usbi_add_pollfd] add fd 10 events 4
[ 0.006051] [000012d6] libusb: debug [libusb_get_device_descriptor] 
[ 0.006076] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa998
[ 0.006097] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa998
[ 0.006118] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.006191] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.006217] [000012d6] libusb: debug [handle_events] poll fds modified, reallocating
[ 0.006244] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.008648] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 0.008690] [000012d6] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.008710] [000012d6] libusb: debug [handle_control_completion] handling completion status 0
[ 0.008732] [000012d6] libusb: debug [disarm_timerfd] 
[ 0.008757] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa998 has callback 0xb7787c60
[ 0.008775] [000012d6] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.008812] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa998
[ 0.008842] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa998
[ 0.008861] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa998
[ 0.008990] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.009053] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.009073] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.010621] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 0.010656] [000012d6] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=16
[ 0.010676] [000012d6] libusb: debug [handle_control_completion] handling completion status 0
[ 0.010695] [000012d6] libusb: debug [disarm_timerfd] 
[ 0.010717] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa998 has callback 0xb7787c60
[ 0.010735] [000012d6] libusb: debug [sync_transfer_cb] actual_length=16
[ 0.010757] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa998
      Manufacturer: "SAMSUNG"
[ 0.010797] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa998
[ 0.010816] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa998
[ 0.010835] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.010874] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.010893] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.012612] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 0.012645] [000012d6] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.012664] [000012d6] libusb: debug [handle_control_completion] handling completion status 0
[ 0.012683] [000012d6] libusb: debug [disarm_timerfd] 
[ 0.012705] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa998 has callback 0xb7787c60
[ 0.012723] [000012d6] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.012744] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa998
[ 0.012829] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa998
[ 0.012849] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa998
[ 0.012868] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.013067] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.013088] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.014620] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 0.014657] [000012d6] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=38
[ 0.014677] [000012d6] libusb: debug [handle_control_completion] handling completion status 0
[ 0.014697] [000012d6] libusb: debug [disarm_timerfd] 
[ 0.014722] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa998 has callback 0xb7787c60
[ 0.014740] [000012d6] libusb: debug [sync_transfer_cb] actual_length=38
[ 0.014763] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa998
           Product: "SAMSUNG USB DRIVER"

            length: 18
      device class: 2
               S/N: 0
           VID:PID: 04E8:685D
         bcdDevice: 021B
   iMan:iProd:iSer: 1:2:0
          nb confs: 1
[ 0.014893] [000012d6] libusb: debug [libusb_get_config_descriptor] index 0

interface[0].altsetting[0]: num endpoints = 1
   Class.SubClass.Protocol: 02.02.01
       endpoint[0].address: 83
           max packet size: 0010
          polling interval: 09

interface[1].altsetting[0]: num endpoints = 2
   Class.SubClass.Protocol: 0A.00.00
       endpoint[0].address: 81
           max packet size: 0200
          polling interval: 00
       endpoint[1].address: 02
           max packet size: 0200
          polling interval: 00
Claiming interface...
[ 0.015110] [000012d6] libusb: debug [libusb_claim_interface] interface 1
Setting up interface...
[ 0.015219] [000012d6] libusb: debug [libusb_set_interface_alt_setting] interface 1 altsetting 0

Initialising protocol...
[ 0.015687] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa998
[ 0.015709] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa998
[ 0.015729] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.015755] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 4
[ 0.015799] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.015819] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.016619] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 0.016651] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=4
[ 0.016670] [000012d6] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.016688] [000012d6] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.016708] [000012d6] libusb: debug [disarm_timerfd] 
[ 0.016731] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa998 has callback 0xb7787c60
[ 0.016750] [000012d6] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.016772] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa998
[ 0.016795] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa998
[ 0.016813] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa998
[ 0.016831] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.016854] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 7
[ 0.016938] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.016965] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.017614] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 0.017647] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=4
[ 0.017665] [000012d6] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.017732] [000012d6] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.017753] [000012d6] libusb: debug [disarm_timerfd] 
[ 0.017778] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa998 has callback 0xb7787c60
[ 0.017796] [000012d6] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.017819] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa998
Protocol initialisation successful.

Beginning session...
[ 0.017907] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 0.017927] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 0.017946] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[ 0.017971] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 1024
[ 0.018022] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.018041] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.019607] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 0.019641] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=1024
[ 0.019660] [000012d6] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.019678] [000012d6] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.019696] [000012d6] libusb: debug [disarm_timerfd] 
[ 0.019720] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[ 0.019738] [000012d6] libusb: debug [sync_transfer_cb] actual_length=1024
[ 0.019760] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
[ 0.019783] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 0.019800] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 0.019818] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 100ms (first in line)
[ 0.019841] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 0
[ 0.019875] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.019894] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.119861] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 0.119941] [000012d6] libusb: debug [handle_events] timerfd triggered
[ 0.119964] [000012d6] libusb: debug [libusb_cancel_transfer] transfer 0x8baa808
[ 0.120389] [000012d6] libusb: debug [disarm_timerfd] 
[ 0.120422] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 0ms
[ 0.120445] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 0.120469] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[ 0.120488] [000012d6] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[ 0.120507] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[ 0.120524] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[ 0.120543] [000012d6] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 0.120561] [000012d6] libusb: debug [disarm_timerfd] 
[ 0.120581] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[ 0.120599] [000012d6] libusb: debug [sync_transfer_cb] actual_length=0
[ 0.120624] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
WARNING: Empty bulk transfer after sending packet failed. Continuing anyway...
[ 0.120736] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 0.120755] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 0.120774] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[ 0.120801] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 8
[ 0.120960] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.120992] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 0.121397] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 0.121434] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=8
[ 0.121453] [000012d6] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.121471] [000012d6] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.121491] [000012d6] libusb: debug [disarm_timerfd] 
[ 0.121516] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[ 0.121535] [000012d6] libusb: debug [sync_transfer_cb] actual_length=8
[ 0.121558] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808

Some devices may take up to 2 minutes to respond.
Please be patient!

[ 3.121752] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 3.121896] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 3.121920] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[ 3.121955] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 1024
[ 3.122037] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 3.122061] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 3.123660] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 3.123715] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=1024
[ 3.123735] [000012d6] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 3.123754] [000012d6] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 3.123775] [000012d6] libusb: debug [disarm_timerfd] 
[ 3.123802] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[ 3.123821] [000012d6] libusb: debug [sync_transfer_cb] actual_length=1024
[ 3.123846] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
[ 3.123874] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 3.123892] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 3.123910] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 100ms (first in line)
[ 3.123934] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 0
[ 3.123974] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 3.123992] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 3.224003] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 3.224045] [000012d6] libusb: debug [handle_events] timerfd triggered
[ 3.224065] [000012d6] libusb: debug [libusb_cancel_transfer] transfer 0x8baa808
[ 3.224388] [000012d6] libusb: debug [disarm_timerfd] 
[ 3.224422] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 0ms
[ 3.224444] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 3.224467] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[ 3.224486] [000012d6] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[ 3.224504] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[ 3.224520] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[ 3.224539] [000012d6] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 3.224556] [000012d6] libusb: debug [disarm_timerfd] 
[ 3.224576] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[ 3.224594] [000012d6] libusb: debug [sync_transfer_cb] actual_length=0
[ 3.224617] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
WARNING: Empty bulk transfer after sending packet failed. Continuing anyway...
[ 3.224744] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 3.224766] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 3.224785] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[ 3.224810] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 8
[ 3.224859] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 3.224923] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 3.225397] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 3.225435] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=8
[ 3.225454] [000012d6] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 3.225472] [000012d6] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 3.225490] [000012d6] libusb: debug [disarm_timerfd] 
[ 3.225515] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[ 3.225533] [000012d6] libusb: debug [sync_transfer_cb] actual_length=8
[ 3.225555] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
Session begun.

Downloading device's PIT file...
[ 3.225646] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 3.225664] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 3.225683] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[ 3.225707] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 1024
[ 3.225757] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 3.225777] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 3.227377] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 3.227412] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=1024
[ 3.227431] [000012d6] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 3.227449] [000012d6] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 3.227466] [000012d6] libusb: debug [disarm_timerfd] 
[ 3.227489] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[ 3.227507] [000012d6] libusb: debug [sync_transfer_cb] actual_length=1024
[ 3.227528] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
[ 3.227552] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 3.227569] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 3.227587] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 100ms (first in line)
[ 3.227609] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 0
[ 3.227644] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 3.227662] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 3.327620] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 3.327678] [000012d6] libusb: debug [handle_events] timerfd triggered
[ 3.327698] [000012d6] libusb: debug [libusb_cancel_transfer] transfer 0x8baa808
[ 3.328153] [000012d6] libusb: debug [disarm_timerfd] 
[ 3.328185] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 0ms
[ 3.328207] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 3.328230] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[ 3.328249] [000012d6] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[ 3.328267] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[ 3.328284] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[ 3.328303] [000012d6] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 3.328320] [000012d6] libusb: debug [disarm_timerfd] 
[ 3.328391] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[ 3.328409] [000012d6] libusb: debug [sync_transfer_cb] actual_length=0
[ 3.328433] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
WARNING: Empty bulk transfer after sending packet failed. Continuing anyway...
[ 3.328497] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 3.328515] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 3.328534] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[ 3.328559] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 8
[ 3.328609] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 3.328628] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 3.329164] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 3.329202] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=8
[ 3.329220] [000012d6] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 3.329238] [000012d6] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 3.329256] [000012d6] libusb: debug [disarm_timerfd] 
[ 3.329279] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[ 3.329297] [000012d6] libusb: debug [sync_transfer_cb] actual_length=8
[ 3.329319] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
[ 3.329389] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 3.329410] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 3.329428] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[ 3.329452] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 1024
[ 3.329501] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 3.329520] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 3.331141] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 3.331175] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=1024
[ 3.331194] [000012d6] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 3.331212] [000012d6] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 3.331230] [000012d6] libusb: debug [disarm_timerfd] 
[ 3.331252] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[ 3.331270] [000012d6] libusb: debug [sync_transfer_cb] actual_length=1024
[ 3.331292] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
[ 3.331315] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 3.331333] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 3.331351] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 100ms (first in line)
[ 3.331374] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 0
[ 3.331407] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 3.331426] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 3.431383] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 3.431429] [000012d6] libusb: debug [handle_events] timerfd triggered
[ 3.431447] [000012d6] libusb: debug [libusb_cancel_transfer] transfer 0x8baa808
[ 3.431913] [000012d6] libusb: debug [disarm_timerfd] 
[ 3.431944] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 0ms
[ 3.431967] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 3.431989] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[ 3.432008] [000012d6] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[ 3.432078] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[ 3.432096] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[ 3.432115] [000012d6] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 3.432133] [000012d6] libusb: debug [disarm_timerfd] 
[ 3.432153] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[ 3.432171] [000012d6] libusb: debug [sync_transfer_cb] actual_length=0
[ 3.432195] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
WARNING: Empty bulk transfer after sending packet failed. Continuing anyway...
[ 3.432260] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 3.432278] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 3.432297] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[ 3.432321] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 500
[ 3.432369] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 3.432388] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 3.432936] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 3.432976] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=-75 transferred=64
[ 3.432995] [000012d6] libusb: debug [handle_bulk_completion] handling completion status -75 of bulk urb 1/1
[ 3.433013] [000012d6] libusb: debug [handle_bulk_completion] overflow, actual_length=64
[ 3.433031] [000012d6] libusb: debug [disarm_timerfd] 
[ 3.433054] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[ 3.433073] [000012d6] libusb: debug [sync_transfer_cb] actual_length=64
[ 3.433094] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
ERROR: libusb error -8 whilst receiving bulk transfer. Retrying...
[ 3.683881] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 3.683920] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 3.683940] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[ 3.683966] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 500
[ 3.684009] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 3.684029] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 3.685609] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 3.685655] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=-75 transferred=64
[ 3.685673] [000012d6] libusb: debug [handle_bulk_completion] handling completion status -75 of bulk urb 1/1
[ 3.685692] [000012d6] libusb: debug [handle_bulk_completion] overflow, actual_length=64
[ 3.685710] [000012d6] libusb: debug [disarm_timerfd] 
[ 3.685735] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[ 3.685753] [000012d6] libusb: debug [sync_transfer_cb] actual_length=64
[ 3.685776] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
ERROR: libusb error -8 whilst receiving bulk transfer. Retrying...
[ 4.186493] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 4.188341] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 4.188402] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[ 4.188437] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 500
[ 4.188502] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 4.188524] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 4.190528] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 4.190579] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=-75 transferred=64
[ 4.190598] [000012d6] libusb: debug [handle_bulk_completion] handling completion status -75 of bulk urb 1/1
[ 4.190664] [000012d6] libusb: debug [handle_bulk_completion] overflow, actual_length=64
[ 4.190687] [000012d6] libusb: debug [disarm_timerfd] 
[ 4.190712] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[ 4.190730] [000012d6] libusb: debug [sync_transfer_cb] actual_length=64
[ 4.190754] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
ERROR: libusb error -8 whilst receiving bulk transfer. Retrying...
[ 4.941642] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 4.941787] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 4.941813] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[ 4.941850] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 500
[ 4.941927] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 4.941949] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 4.943413] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 4.943475] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=-75 transferred=64
[ 4.943494] [000012d6] libusb: debug [handle_bulk_completion] handling completion status -75 of bulk urb 1/1
[ 4.943513] [000012d6] libusb: debug [handle_bulk_completion] overflow, actual_length=64
[ 4.943535] [000012d6] libusb: debug [disarm_timerfd] 
[ 4.943563] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[ 4.943581] [000012d6] libusb: debug [sync_transfer_cb] actual_length=64
[ 4.943606] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
ERROR: libusb error -8 whilst receiving bulk transfer. Retrying...
[ 5.944759] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 5.944863] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 5.944906] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[ 5.944938] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 500
[ 5.945000] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 5.945021] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 5.946774] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 5.946816] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=-75 transferred=64
[ 5.946835] [000012d6] libusb: debug [handle_bulk_completion] handling completion status -75 of bulk urb 1/1
[ 5.946853] [000012d6] libusb: debug [handle_bulk_completion] overflow, actual_length=64
[ 5.946874] [000012d6] libusb: debug [disarm_timerfd] 
[ 5.946898] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[ 5.946917] [000012d6] libusb: debug [sync_transfer_cb] actual_length=64
[ 5.946940] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
ERROR: libusb error -8 whilst receiving bulk transfer. Retrying...
[ 7.197514] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 7.197643] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 7.197667] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[ 7.197701] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 500
[ 7.197771] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 7.197794] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[ 7.199078] [000012d6] libusb: debug [handle_events] poll() returned 1
[ 7.199125] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=-75 transferred=64
[ 7.199144] [000012d6] libusb: debug [handle_bulk_completion] handling completion status -75 of bulk urb 1/1
[ 7.199163] [000012d6] libusb: debug [handle_bulk_completion] overflow, actual_length=64
[ 7.199246] [000012d6] libusb: debug [disarm_timerfd] 
[ 7.199273] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[ 7.199292] [000012d6] libusb: debug [sync_transfer_cb] actual_length=64
[ 7.199317] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
ERROR: libusb error -8 whilst receiving bulk transfer.
ERROR: Failed to receive PIT file part #0!
ERROR: Failed to download PIT file!
Ending session...
[ 7.199466] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[ 7.199485] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[ 7.199504] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[ 7.199529] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 1024
[ 7.199581] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 7.199601] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[10.199811] [000012d6] libusb: debug [handle_events] poll() returned 1
[10.199952] [000012d6] libusb: debug [handle_events] timerfd triggered
[10.199979] [000012d6] libusb: debug [libusb_cancel_transfer] transfer 0x8baa808
[10.201073] [000012d6] libusb: debug [disarm_timerfd] 
[10.201129] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 0ms
[10.201154] [000012d6] libusb: debug [handle_events] poll() returned 1
[10.201180] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[10.201199] [000012d6] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[10.201217] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[10.201233] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[10.201253] [000012d6] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[10.201271] [000012d6] libusb: debug [disarm_timerfd] 
[10.201291] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[10.201309] [000012d6] libusb: debug [sync_transfer_cb] actual_length=0
[10.201336] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
ERROR: libusb error -7 whilst sending bulk transfer. Retrying...
[10.451560] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[10.451606] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[10.451626] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[10.451652] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 1024
[10.451718] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[10.451739] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[13.451813] [000012d6] libusb: debug [handle_events] poll() returned 1
[13.451951] [000012d6] libusb: debug [handle_events] timerfd triggered
[13.451975] [000012d6] libusb: debug [libusb_cancel_transfer] transfer 0x8baa808
[13.453744] [000012d6] libusb: debug [disarm_timerfd] 
[13.453787] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 0ms
[13.453811] [000012d6] libusb: debug [handle_events] poll() returned 1
[13.453839] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[13.453857] [000012d6] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[13.453876] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[13.453892] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[13.453913] [000012d6] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[13.453931] [000012d6] libusb: debug [disarm_timerfd] 
[13.453951] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[13.453969] [000012d6] libusb: debug [sync_transfer_cb] actual_length=0
[13.454060] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
ERROR: libusb error -7 whilst sending bulk transfer. Retrying...
[13.954814] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[13.954859] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[13.954880] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[13.954908] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 1024
[13.954977] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[13.954997] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[16.955058] [000012d6] libusb: debug [handle_events] poll() returned 1
[16.955217] [000012d6] libusb: debug [handle_events] timerfd triggered
[16.955244] [000012d6] libusb: debug [libusb_cancel_transfer] transfer 0x8baa808
[16.956789] [000012d6] libusb: debug [disarm_timerfd] 
[16.956839] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 0ms
[16.956864] [000012d6] libusb: debug [handle_events] poll() returned 1
[16.956961] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[16.956982] [000012d6] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[16.957001] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[16.957018] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[16.957038] [000012d6] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[16.957056] [000012d6] libusb: debug [disarm_timerfd] 
[16.957077] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[16.957096] [000012d6] libusb: debug [sync_transfer_cb] actual_length=0
[16.957122] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
ERROR: libusb error -7 whilst sending bulk transfer. Retrying...
[17.707290] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[17.707392] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[17.707414] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[17.707443] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 1024
[17.707514] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[17.707535] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[20.707495] [000012d6] libusb: debug [handle_events] poll() returned 1
[20.707623] [000012d6] libusb: debug [handle_events] timerfd triggered
[20.707647] [000012d6] libusb: debug [libusb_cancel_transfer] transfer 0x8baa808
[20.709050] [000012d6] libusb: debug [disarm_timerfd] 
[20.709088] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 0ms
[20.709112] [000012d6] libusb: debug [handle_events] poll() returned 1
[20.709138] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[20.709157] [000012d6] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[20.709175] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[20.709191] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[20.709211] [000012d6] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[20.709229] [000012d6] libusb: debug [disarm_timerfd] 
[20.709249] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[20.709267] [000012d6] libusb: debug [sync_transfer_cb] actual_length=0
[20.709293] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
ERROR: libusb error -7 whilst sending bulk transfer. Retrying...
[21.709500] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[21.709611] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[21.709683] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[21.709716] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 1024
[21.709788] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[21.709809] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[24.709787] [000012d6] libusb: debug [handle_events] poll() returned 1
[24.709910] [000012d6] libusb: debug [handle_events] timerfd triggered
[24.709933] [000012d6] libusb: debug [libusb_cancel_transfer] transfer 0x8baa808
[24.711129] [000012d6] libusb: debug [disarm_timerfd] 
[24.711165] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 0ms
[24.711189] [000012d6] libusb: debug [handle_events] poll() returned 1
[24.711214] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[24.711232] [000012d6] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[24.711251] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[24.711267] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[24.711287] [000012d6] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[24.711305] [000012d6] libusb: debug [disarm_timerfd] 
[24.711325] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[24.711343] [000012d6] libusb: debug [sync_transfer_cb] actual_length=0
[24.711368] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
ERROR: libusb error -7 whilst sending bulk transfer. Retrying...
[25.961599] [000012d6] libusb: debug [libusb_alloc_transfer] transfer 0x8baa808
[25.961725] [000012d6] libusb: debug [libusb_submit_transfer] transfer 0x8baa808
[25.961747] [000012d6] libusb: debug [add_to_flying_list] arm timerfd for timeout in 3000ms (first in line)
[25.961780] [000012d6] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 1024
[25.961854] [000012d6] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[25.961875] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 60000ms
[28.961871] [000012d6] libusb: debug [handle_events] poll() returned 1
[28.961997] [000012d6] libusb: debug [handle_events] timerfd triggered
[28.962020] [000012d6] libusb: debug [libusb_cancel_transfer] transfer 0x8baa808
[28.963553] [000012d6] libusb: debug [disarm_timerfd] 
[28.963589] [000012d6] libusb: debug [handle_events] poll() 3 fds with timeout in 0ms
[28.963613] [000012d6] libusb: debug [handle_events] poll() returned 1
[28.963638] [000012d6] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[28.963657] [000012d6] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[28.963675] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[28.963692] [000012d6] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[28.963711] [000012d6] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[28.963729] [000012d6] libusb: debug [disarm_timerfd] 
[28.963749] [000012d6] libusb: debug [usbi_handle_transfer_completion] transfer 0x8baa808 has callback 0xb7787c60
[28.963767] [000012d6] libusb: debug [sync_transfer_cb] actual_length=0
[28.963792] [000012d6] libusb: debug [libusb_free_transfer] transfer 0x8baa808
ERROR: libusb error -7 whilst sending bulk transfer.
ERROR: Failed to send end session packet!
Releasing device interface...
[28.963909] [000012d6] libusb: debug [libusb_release_interface] interface 1

[28.963987] [000012d6] libusb: debug [libusb_close] 
[28.964017] [000012d6] libusb: debug [usbi_remove_pollfd] remove fd 10
[28.964062] [000012d6] libusb: debug [libusb_exit] 
[28.964079] [000012d6] libusb: debug [libusb_exit] destroying default context

@procrastinat0r
Copy link

procrastinat0r commented Mar 21, 2018

This patch worked for me to fix USB issues with Galaxy Tab S2 (Samsung SM-T813) on Ubuntu 16.04 LTS.
Log is here.

@KOLANICH
Copy link

KOLANICH commented Mar 21, 2018

@procrastinat0r could you share the pcap dump?

@sanimalp
Copy link

sanimalp commented Apr 11, 2018

SGS5 g900t user here. This patch changes nothing of the behavior for me on the S5. still get ERROR: Failed to receive handshake response. Result: -7

Heimdall v1.4.2

Copyright (c) 2010-2017 Benjamin Dobell, Glass Echidna
http://www.glassechidna.com.au/

This software is provided free of charge. Copying and redistribution is
encouraged.

If you appreciate this software and you would like to support future
development please consider donating:
http://www.glassechidna.com.au/donate/

Initialising connection...
Detecting device...
[timestamp] [threadID] facility level [function call]

[ 0.012848] [00004528] libusb: debug [libusb_get_device_list]
[ 0.012861] [00004528] libusb: debug [discovered_devs_append] need to increase capacity
[ 0.012865] [00004528] libusb: debug [libusb_get_device_descriptor]
[ 0.012867] [00004528] libusb: debug [libusb_get_device_descriptor]
[ 0.012868] [00004528] libusb: debug [libusb_get_device_descriptor]
[ 0.012870] [00004528] libusb: debug [libusb_get_device_descriptor]
[ 0.012871] [00004528] libusb: debug [libusb_get_device_descriptor]
[ 0.012872] [00004528] libusb: debug [libusb_get_device_descriptor]
[ 0.012873] [00004528] libusb: debug [libusb_get_device_descriptor]
[ 0.012875] [00004528] libusb: debug [libusb_get_device_descriptor]
[ 0.012876] [00004528] libusb: debug [libusb_get_device_descriptor]
[ 0.012879] [00004528] libusb: debug [libusb_open] open 1.51
[ 0.012893] [00004528] libusb: debug [usbi_add_pollfd] add fd 11 events 4
[ 0.012900] [00004528] libusb: debug [libusb_get_device_descriptor]
[ 0.012904] [00004528] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.012917] [00004528] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.012919] [00004528] libusb: debug [handle_events] poll() 4 fds with timeout in 60000ms
[ 0.013005] [00004528] libusb: debug [handle_events] poll() returned 1
[ 0.013013] [00004528] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.013015] [00004528] libusb: debug [handle_control_completion] handling completion status 0
[ 0.013017] [00004528] libusb: debug [disarm_timerfd]
[ 0.013019] [00004528] libusb: debug [usbi_handle_transfer_completion] transfer 0x147f0f0 has callback 0x7fa37c28d1d0
[ 0.013021] [00004528] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.013029] [00004528] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.013034] [00004528] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.013036] [00004528] libusb: debug [handle_events] poll() 4 fds with timeout in 60000ms
[ 0.013125] [00004528] libusb: debug [handle_events] poll() returned 1
[ 0.013133] [00004528] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=18
[ 0.013135] [00004528] libusb: debug [handle_control_completion] handling completion status 0
[ 0.013136] [00004528] libusb: debug [disarm_timerfd]
[ 0.013138] [00004528] libusb: debug [usbi_handle_transfer_completion] transfer 0x147f0f0 has callback 0x7fa37c28d1d0
[ 0.013140] [00004528] libusb: debug [sync_transfer_cb] actual_length=18
Manufacturer: "Sasmsung"
[ 0.013145] [00004528] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.013150] [00004528] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.013152] [00004528] libusb: debug [handle_events] poll() 4 fds with timeout in 60000ms
[ 0.013239] [00004528] libusb: debug [handle_events] poll() returned 1
[ 0.013247] [00004528] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=4
[ 0.013249] [00004528] libusb: debug [handle_control_completion] handling completion status 0
[ 0.013251] [00004528] libusb: debug [disarm_timerfd]
[ 0.013252] [00004528] libusb: debug [usbi_handle_transfer_completion] transfer 0x147f0f0 has callback 0x7fa37c28d1d0
[ 0.013254] [00004528] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.013258] [00004528] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.013265] [00004528] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.013267] [00004528] libusb: debug [handle_events] poll() 4 fds with timeout in 60000ms
[ 0.013354] [00004528] libusb: debug [handle_events] poll() returned 1
[ 0.013361] [00004528] libusb: debug [reap_for_handle] urb type=2 status=0 transferred=16
[ 0.013363] [00004528] libusb: debug [handle_control_completion] handling completion status 0
[ 0.013365] [00004528] libusb: debug [disarm_timerfd]
[ 0.013367] [00004528] libusb: debug [usbi_handle_transfer_completion] transfer 0x147f0f0 has callback 0x7fa37c28d1d0
[ 0.013368] [00004528] libusb: debug [sync_transfer_cb] actual_length=16
Product: "MSM8960"

        length: 18
  device class: 2
           S/N: 0
       VID:PID: 04E8:685D
     bcdDevice: 0100

iMan:iProd:iSer: 1:2:0
nb confs: 1
[ 0.013380] [00004528] libusb: debug [libusb_get_config_descriptor] index 0

interface[0].altsetting[0]: num endpoints = 1
Class.SubClass.Protocol: 02.02.01
endpoint[0].address: 82
max packet size: 0010
polling interval: 09

interface[1].altsetting[0]: num endpoints = 2
Class.SubClass.Protocol: 0A.00.00
endpoint[0].address: 81
max packet size: 0200
polling interval: 00
endpoint[1].address: 01
max packet size: 0200
polling interval: 00
Claiming interface...
[ 0.013397] [00004528] libusb: debug [libusb_claim_interface] interface 1
Setting up interface...
[ 0.013413] [00004528] libusb: debug [libusb_set_interface_alt_setting] interface 1 altsetting 0

Initialising protocol...
[ 0.013767] [00004528] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.013773] [00004528] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 4
[ 0.013779] [00004528] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.013781] [00004528] libusb: debug [handle_events] poll() 4 fds with timeout in 60000ms
[ 0.013790] [00004528] libusb: debug [handle_events] poll() returned 1
[ 0.013793] [00004528] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=4
[ 0.013795] [00004528] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.013796] [00004528] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[ 0.013798] [00004528] libusb: debug [disarm_timerfd]
[ 0.013800] [00004528] libusb: debug [usbi_handle_transfer_completion] transfer 0x147f120 has callback 0x7fa37c28d1d0
[ 0.013801] [00004528] libusb: debug [sync_transfer_cb] actual_length=4
[ 0.013804] [00004528] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[ 0.013806] [00004528] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 7
[ 0.013809] [00004528] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.013811] [00004528] libusb: debug [handle_events] poll() 4 fds with timeout in 60000ms
[ 1.013828] [00004528] libusb: debug [handle_events] poll() returned 1
[ 1.013840] [00004528] libusb: debug [handle_events] timerfd triggered
[ 1.013844] [00004528] libusb: debug [libusb_cancel_transfer]
[ 1.013889] [00004528] libusb: debug [disarm_timerfd]
[ 1.013898] [00004528] libusb: debug [handle_events] poll() 4 fds with timeout in 0ms
[ 1.013902] [00004528] libusb: debug [handle_events] poll() returned 1
[ 1.013907] [00004528] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[ 1.013909] [00004528] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[ 1.013911] [00004528] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[ 1.013912] [00004528] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[ 1.013914] [00004528] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 1.013916] [00004528] libusb: debug [disarm_timerfd]
[ 1.013918] [00004528] libusb: debug [usbi_handle_transfer_completion] transfer 0x147f120 has callback 0x7fa37c28d1d0
[ 1.013919] [00004528] libusb: debug [sync_transfer_cb] actual_length=0
ERROR: Failed to receive handshake response. Result: -7
ERROR: Failed to receive handshake response. Result: -7
ERROR: Protocol initialisation failed!

ERROR: Protocol initialisation failed!

Releasing device interface...
[ 1.013937] [00004528] libusb: debug [libusb_release_interface] interface 1

[ 1.013951] [00004528] libusb: debug [libusb_close]
[ 1.013956] [00004528] libusb: debug [usbi_remove_pollfd] remove fd 11
[ 1.013961] [00004528] libusb: debug [libusb_exit]
[ 1.013962] [00004528] libusb: debug [libusb_exit] destroying default context

@KOLANICH
Copy link

@sanimalp
1 could you hide the log under
<details> tag?
2 without pcap captures it's pretty useless

@beroset
Copy link

beroset commented Nov 24, 2021

I found that this patch plus one other change seemed to work for me. Specifically, within BridgeManager::InitialiseProtocol() I had to change the timeout for the "ODIN" message from 1000 to 6000. After that, it appears to work on my machine on either USB2 or USB3. Machine is Intel i7-6700 @ 3.40 GHz running Fedora 34 (kernel 5.14.14-200).

@amo13
Copy link

amo13 commented Nov 25, 2021

That sounds great, @beroset! I am thinking about merging this in my fork. Which was the other change that you needed for heimdall to work with your device? What was the error you were getting before? And what device do you have?

@beroset
Copy link

beroset commented Nov 25, 2021

@amo13 The device is a Samsung Galaxy Tab 4 (Model SM-T230NU, Android version 4.4.2). The error I was originally getting was this:

Initialising protocol...
ERROR: libusb error -7 (LIBUSB_ERROR_TIMEOUT) whilst sending bulk transfer. Retrying...
ERROR: libusb error -7 (LIBUSB_ERROR_TIMEOUT) whilst sending bulk transfer. Retrying...
ERROR: libusb error -7 (LIBUSB_ERROR_TIMEOUT) whilst sending bulk transfer. Retrying...
ERROR: libusb error -7 (LIBUSB_ERROR_TIMEOUT) whilst sending bulk transfer. Retrying...
ERROR: libusb error -7 (LIBUSB_ERROR_TIMEOUT) whilst sending bulk transfer. Retrying...
ERROR: libusb error -7 (LIBUSB_ERROR_TIMEOUT) whilst sending bulk transfer.
ERROR: Failed to send handshake!ERROR: Failed to receive handshake response. Result: -7
ERROR: Protocol initialisation failed!

(I added the part to translate the -7 into something a little more human readable.) In addition to changing the timeout for the ODIN message as mentioned above, I also found that I needed to modify the code to try twice to send the EndSessionPacket. It was able to flash both a RECOVERY and CACHE image but would fail on parsing the reply to that. Trying twice allowed it to finish the job and reboot. After I clean up my code a bit, I'll create a fork and a pull request.

@amo13
Copy link

amo13 commented Nov 25, 2021

After I clean up my code a bit, I'll create a fork and a pull request.

That would be awesome!

Thanks for the hints. Why the need to flash a CACHE image though?

@beroset
Copy link

beroset commented Nov 25, 2021

I have done some more thorough testing and believe that the problem is not timeouts at all. Specifically, I have determined with two Linux machines that I have, if I reset the Samsung tablet into ODIN mode and execute sudo heimdall print-pit --verbose --no-reboot --usb-log-level debug it works perfectly the first time regardless of timeout settings. The second time I execute the same command, I get errors. It seems that the tablet is left in a state that makes it unwilling to further communicate, but why? What's missing?

@amo13
Copy link

amo13 commented Nov 26, 2021

Oh, I have come across this issue quite a few times with a few different devices. I believe it is also somewhat known and you'll read about other users reporting this behavior in some other issues on here... Still, in my experience of flashing samsung devices with heimdall, even though I have seen this behavior a few times, most devices will also accept further commands.
As for why this is happening, unfortunately, I have no idea either. My only guess is that the --no-reboot flag somehow tricks the protocol that is not made to accept multiple commands.

@bobemoe
Copy link

bobemoe commented Jan 14, 2022

I too was suffering with the "ERROR: libusb error -7 whilst sending bulk transfer." issue on my Samsung s5e WIFI.

This patch alone did not seem to make any difference, but as soon as I tried @amo13 fork mentioned above then it started working perfectly :)

Thanks everyone!

@deriamis deriamis closed this Dec 16, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

unable to connect to samsing gs4 (i9500) on linux