[SM-F926B] ERROR: Failed to send handshake!

Question

[SM-F926B] ERROR: Failed to send handshake!

Azkali opened this issue 3 years ago · 11 comments

Issue description

Heimdall version: Latest master build from source

During ./heimdall download-pit handshake is failing. Seems related to changes in download mode on recent model, as hinted by another issue here.

Log

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.016216] [0003d102] libusb: debug [libusb_get_device_list]  
[ 0.016249] [0003d102] libusb: debug [libusb_get_device_descriptor]  
[ 0.016262] [0003d102] libusb: debug [libusb_get_device_descriptor]  
[ 0.016276] [0003d102] libusb: debug [libusb_open] open 1.26
[ 0.016318] [0003d102] libusb: debug [usbi_add_event_source] add fd 8 events 4
[ 0.016331] [0003d102] libusb: debug [libusb_get_device_descriptor]  
[ 0.016344] [0003d102] libusb: debug [libusb_get_config_descriptor] index 0
Claiming interface...
[ 0.016369] [0003d102] libusb: debug [libusb_claim_interface] interface 1
Setting up interface...
[ 0.016427] [0003d102] libusb: debug [libusb_set_interface_alt_setting] interface 1 altsetting 0

Initialising protocol...
[ 0.017238] [0003d102] libusb: debug [libusb_alloc_transfer] transfer 0x493840
[ 0.017256] [0003d102] libusb: debug [libusb_submit_transfer] transfer 0x493840
[ 0.017266] [0003d102] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.017281] [0003d102] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 4
[ 0.017309] [0003d102] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.017320] [0003d102] libusb: debug [handle_events] event sources modified, reallocating event data
[ 0.017330] [0003d102] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 1.017435] [0003d102] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 1.017749] [0003d102] libusb: debug [libusb_cancel_transfer] transfer 0x493840
[ 1.018411] [0003d102] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 1.018670] [0003d102] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 1.018758] [0003d102] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 1.019017] [0003d102] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 1.019302] [0003d102] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[ 1.019971] [0003d102] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[ 1.020094] [0003d102] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[ 1.020183] [0003d102] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[ 1.020282] [0003d102] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 1.020378] [0003d102] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 1.020529] [0003d102] libusb: debug [usbi_handle_transfer_completion] transfer 0x493840 has callback 0x7fa3bc49e0
[ 1.020644] [0003d102] libusb: debug [sync_transfer_cb] actual_length=0
[ 1.020768] [0003d102] libusb: debug [libusb_free_transfer] transfer 0x493840
[ 1.271112] [0003d102] libusb: debug [libusb_alloc_transfer] transfer 0x474f10
[ 1.271303] [0003d102] libusb: debug [libusb_submit_transfer] transfer 0x474f10
[ 1.271394] [0003d102] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 1.271670] [0003d102] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 4
[ 1.271959] [0003d102] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 1.272068] [0003d102] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 2.272444] [0003d102] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 2.272516] [0003d102] libusb: debug [libusb_cancel_transfer] transfer 0x474f10
[ 2.272895] [0003d102] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 2.272926] [0003d102] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 2.272939] [0003d102] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 2.272982] [0003d102] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 2.273042] [0003d102] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[ 2.273056] [0003d102] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[ 2.273069] [0003d102] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[ 2.273079] [0003d102] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[ 2.273091] [0003d102] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 2.273103] [0003d102] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 2.273114] [0003d102] libusb: debug [usbi_handle_transfer_completion] transfer 0x474f10 has callback 0x7fa3bc49e0
[ 2.274155] [0003d102] libusb: debug [sync_transfer_cb] actual_length=0
[ 2.274172] [0003d102] libusb: debug [libusb_free_transfer] transfer 0x474f10
[ 2.774395] [0003d102] libusb: debug [libusb_alloc_transfer] transfer 0x4753b0
[ 2.774705] [0003d102] libusb: debug [libusb_submit_transfer] transfer 0x4753b0
[ 2.774850] [0003d102] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 2.774988] [0003d102] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 4
[ 2.775271] [0003d102] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 2.775385] [0003d102] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 3.775037] [0003d102] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 3.775194] [0003d102] libusb: debug [libusb_cancel_transfer] transfer 0x4753b0
[ 3.775929] [0003d102] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 3.776060] [0003d102] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 3.776120] [0003d102] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 3.776192] [0003d102] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 3.776264] [0003d102] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[ 3.776374] [0003d102] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[ 3.776562] [0003d102] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[ 3.776621] [0003d102] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[ 3.776751] [0003d102] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 3.776814] [0003d102] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 3.776888] [0003d102] libusb: debug [usbi_handle_transfer_completion] transfer 0x4753b0 has callback 0x7fa3bc49e0
[ 3.776949] [0003d102] libusb: debug [sync_transfer_cb] actual_length=0
[ 3.777022] [0003d102] libusb: debug [libusb_free_transfer] transfer 0x4753b0
[ 4.527422] [0003d102] libusb: debug [libusb_alloc_transfer] transfer 0x48d5f0
[ 4.527914] [0003d102] libusb: debug [libusb_submit_transfer] transfer 0x48d5f0
[ 4.528034] [0003d102] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 4.528756] [0003d102] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 4
[ 4.529180] [0003d102] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 4.529265] [0003d102] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 5.528379] [0003d102] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 5.528876] [0003d102] libusb: debug [libusb_cancel_transfer] transfer 0x48d5f0
[ 5.529980] [0003d102] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 5.530282] [0003d102] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 5.530453] [0003d102] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 5.530942] [0003d102] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 5.531250] [0003d102] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[ 5.532084] [0003d102] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[ 5.532163] [0003d102] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[ 5.532216] [0003d102] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[ 5.532278] [0003d102] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 5.532343] [0003d102] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 5.532421] [0003d102] libusb: debug [usbi_handle_transfer_completion] transfer 0x48d5f0 has callback 0x7fa3bc49e0
[ 5.532566] [0003d102] libusb: debug [sync_transfer_cb] actual_length=0
[ 5.532673] [0003d102] libusb: debug [libusb_free_transfer] transfer 0x48d5f0
[ 6.533280] [0003d102] libusb: debug [libusb_alloc_transfer] transfer 0x475a70
[ 6.533826] [0003d102] libusb: debug [libusb_submit_transfer] transfer 0x475a70
[ 6.534008] [0003d102] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 6.534223] [0003d102] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 4
[ 6.535166] [0003d102] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 6.535257] [0003d102] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 7.534453] [0003d102] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 7.534930] [0003d102] libusb: debug [libusb_cancel_transfer] transfer 0x475a70
[ 7.537070] [0003d102] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 7.537222] [0003d102] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 7.537289] [0003d102] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 7.537378] [0003d102] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 7.537469] [0003d102] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[ 7.537656] [0003d102] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[ 7.537728] [0003d102] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[ 7.537790] [0003d102] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[ 7.537862] [0003d102] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 7.537930] [0003d102] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 7.538008] [0003d102] libusb: debug [usbi_handle_transfer_completion] transfer 0x475a70 has callback 0x7fa3bc49e0
[ 7.538085] [0003d102] libusb: debug [sync_transfer_cb] actual_length=0
[ 7.538812] [0003d102] libusb: debug [libusb_free_transfer] transfer 0x475a70
[ 8.788993] [0003d102] libusb: debug [libusb_alloc_transfer] transfer 0x475b60
[ 8.789025] [0003d102] libusb: debug [libusb_submit_transfer] transfer 0x475b60
[ 8.789041] [0003d102] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 8.789102] [0003d102] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 4
[ 8.789150] [0003d102] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 8.789163] [0003d102] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 9.789201] [0003d102] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 9.789380] [0003d102] libusb: debug [libusb_cancel_transfer] transfer 0x475b60
[ 9.790017] [0003d102] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 9.790147] [0003d102] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 9.790194] [0003d102] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 9.790262] [0003d102] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 9.790327] [0003d102] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[ 9.790381] [0003d102] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[ 9.790429] [0003d102] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[ 9.790474] [0003d102] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[ 9.790614] [0003d102] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 9.790668] [0003d102] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 9.790723] [0003d102] libusb: debug [usbi_handle_transfer_completion] transfer 0x475b60 has callback 0x7fa3bc49e0
[ 9.790777] [0003d102] libusb: debug [sync_transfer_cb] actual_length=0
[ 9.790855] [0003d102] libusb: debug [libusb_free_transfer] transfer 0x475b60
ERROR: Failed to send handshake![ 9.791166] [0003d102] libusb: debug [libusb_alloc_transfer] transfer 0x48d0b0
[ 9.791207] [0003d102] libusb: debug [libusb_submit_transfer] transfer 0x48d0b0
[ 9.791235] [0003d102] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 9.791275] [0003d102] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 7
[ 9.791413] [0003d102] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 9.791454] [0003d102] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[10.791365] [0003d102] libusb: debug [usbi_wait_for_events] poll() returned 1
[10.791726] [0003d102] libusb: debug [libusb_cancel_transfer] transfer 0x48d0b0
[10.792411] [0003d102] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[10.792637] [0003d102] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[10.792716] [0003d102] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[10.792816] [0003d102] libusb: debug [usbi_wait_for_events] poll() returned 1
[10.792924] [0003d102] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[10.793011] [0003d102] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[10.793112] [0003d102] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[10.793184] [0003d102] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[10.793263] [0003d102] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[10.793408] [0003d102] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[10.793656] [0003d102] libusb: debug [usbi_handle_transfer_completion] transfer 0x48d0b0 has callback 0x7fa3bc49e0
[10.793802] [0003d102] libusb: debug [sync_transfer_cb] actual_length=0
[10.793937] [0003d102] libusb: debug [libusb_free_transfer] transfer 0x48d0b0
ERROR: Protocol initialisation failed!

Releasing device interface...
[10.794238] [0003d102] libusb: debug [libusb_release_interface] interface 1

[10.794615] [0003d102] libusb: debug [libusb_close]  
[10.794715] [0003d102] libusb: debug [usbi_remove_event_source] remove fd 8
[10.794856] [0003d102] libusb: debug [libusb_exit]  
[10.794901] [0003d102] libusb: debug [libusb_exit] destroying default context
[10.794944] [0003d102] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[10.794981] [0003d102] libusb: debug [handle_events] event sources modified, reallocating event data
[10.795027] [0003d102] libusb: debug [usbi_wait_for_events] poll() 2 fds with timeout in 0ms
[10.795075] [0003d102] libusb: debug [usbi_wait_for_events] poll() returned 0
[10.795119] [0003d102] libusb: debug [libusb_unref_device] destroy device 2.1
[10.795164] [0003d102] libusb: debug [libusb_unref_device] destroy device 1.26
[10.795209] [0003d102] libusb: debug [libusb_unref_device] destroy device 1.13
[10.795255] [0003d102] libusb: debug [libusb_unref_device] destroy device 1.12
[10.795299] [0003d102] libusb: debug [libusb_unref_device] destroy device 1.11
[10.795342] [0003d102] libusb: debug [libusb_unref_device] destroy device 1.10
[10.795387] [0003d102] libusb: debug [libusb_unref_device] destroy device 1.1
[10.795435] [0003d102] libusb: debug [usbi_remove_event_source] remove fd 7
[10.795572] [0003d102] libusb: debug [usbi_remove_event_source] remove fd 6
[10.795761] [0003d104] libusb: debug [linux_udev_event_thread_main] udev event thread exiting

Answer 1 · 2021-12-26T13:32:32.000Z

Are you on Ubuntu? It fails on the first handshake package, so it is unlikely that it is due to protocol changes (unless Samsung has re-done the protocol from scratch for this device). Seems more likely that the connection needs to be reset before handshake, as in this PR. You can download heimdall with this (and other) fixes here: ubuntu 20.04, archlinux and alpine linux.

Could also be a permission issue, try running heimdall as root, or make sure udev rules are installed

Answer 2 · 2022-01-04T08:24:32.000Z

Hi, I am using fedora 35 on a aarch64 SoC. But I was able to use Heimdall with a SGS8 with no problem previously.

The issue also happen as root and I do have the udev rules set and triggered properly.
It can only be an issue with a needed reset or in the worst case the protocl has been changed.
I am gonna build using the PR you provided and give my feedback after testing.

Answer 3 · 2022-01-04T10:33:41.000Z

Apparently odin 3.14.4 works for flashing this device, so seems unlikely that protocol has been fundamentally changed.

However, looking at the PIT is seems that it uses a 6th version of the Odin protocol (first time I see that, I only have devices using 4 or older):

$ heimdall print-pit --file Q2Q_EUR_OPENX.pit
Heimdall v2.0.0

Copyright (c) 2010-2017 Benjamin Dobell, Glass Echidna
https://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:
https://www.glassechidna.com.au/donate/

--- PIT Header ---
Entry Count: 96
Unknown string: COM_TAR2
CPU/bootloader tag: SM8350
Version(?): 0x0006

[...]

(printed with heimdall from this branch) so maybe something is different, but then again: seems unlikely they would change something as fundamental as the handshake.

Would be interesting to see usb traffic logs (captured with for example wireshark) of when stock android is flashed onto the device with odin. Such logs would be the only way to see if the transfer protocol is different.

Answer 4 · 2022-01-04T15:51:32.000Z

You can also try increasing the timeout (third arg to SendBulkTransfer) of the handshake package, and probably the response, to something higher like 6000.

Really seems more likely that issue is that libusb_reset is needed, or some issue with libusb on feodora/arm64, or just that the usb cable is bad, rather than that heimdall does something wrong (since heimdall doesn't even do anything, first packet fails)

Answer 5 · 2022-02-21T23:03:10.000Z

You can download heimdall with this (and other) fixes here: ubuntu 20.04, archlinux and alpine linux.

omg thank you i was having the same issue this took me so long to find

Answer 6 · 2022-05-27T10:17:22.000Z

Apparently odin 3.14.4 works for flashing this device, so seems unlikely that protocol has been fundamentally changed.

However, looking at the PIT is seems that it uses a 6th version of the Odin protocol (first time I see that, I only have devices using 4 or older):
$ heimdall print-pit --file Q2Q_EUR_OPENX.pit
Heimdall v2.0.0

Copyright (c) 2010-2017 Benjamin Dobell, Glass Echidna
https://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:
https://www.glassechidna.com.au/donate/

--- PIT Header ---
Entry Count: 96
Unknown string: COM_TAR2
CPU/bootloader tag: SM8350
Version(?): 0x0006

[...]
(printed with heimdall from this branch) so maybe something is different, but then again: seems unlikely they would change something as fundamental as the handshake.

Would be interesting to see usb traffic logs (captured with for example wireshark) of when stock android is flashed onto the device with odin. Such logs would be the only way to see if the transfer protocol is different.

It is not version of some sort. Odin, nor Thor (it's successor) use data after entries count,
Everything after is referenced as Project Name. In the PIT.h it is referenced as dummy data.
P.S. It seems to be LUN count, of it's an UFS one.

Answer 7 · 2022-09-29T06:06:45.000Z

Solved using the PR mentioned in the previous comment

Answer 8 · 2022-10-25T17:36:27.000Z

I am in the same situation. Linux Mint 21 (aka Ubuntu 22 LTS) and the heimdall in the standard repo (1.4.1) does not work.
"ERROR: Failed to send handshake!ERROR: Protocol initialisation failed! "

With the 2.0.0 of the link below , it works.

I guess I should report this to Mint folks ( or Ubuntu 22).

Answer 9 · 2022-10-28T19:51:12.000Z

I am in the same situation. Linux Mint 21 (aka Ubuntu 22 LTS) and the heimdall in the standard repo (1.4.1) does not work. "ERROR: Failed to send handshake!ERROR: Protocol initialisation failed! "

With the 2.0.0 of the link below , it works.

I guess I should report this to Mint folks ( or Ubuntu 22).

No, it is an unofficial fork. Maybe there is a chance they will use it, but who knows.