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.

Sign up for GitHub

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

Jump to bottom

"Failed handshake for version: socket disconnected" when trying to share #866

Closed
dragos240 opened this issue Feb 11, 2023 · 7 comments
Closed

"Failed handshake for version: socket disconnected" when trying to share #866

dragos240 opened this issue Feb 11, 2023 · 7 comments
Labels
bug Things that prevent or seriously impede people from doing their budget. included in next release The work is done, it's just waiting to be released. Next This is next on the list -- it might not get done, but this is the plan.

Comments

@dragos240
Copy link

dragos240 commented Feb 11, 2023 •
edited
Loading

I've tried the latest Buckets and Buckets Beta to share. It does initially connect, but it fails with Failed handshake for version: socket disconnected, then tries to initialize a new connection. I've deleted the connection on the phone several times, restarted Buckets each time.

When I enable sharing on the desktop side, I get this in buckets: INFO (peddler) listening on 22322. If I use netstat, I can confirm it's listening on that port:
image

I tried resetting everything: When I click "Add channel" on the phone after entering the IP, I see in the desktop console window that it tries to connect, but gets stuck on DEBUG (peddler) direct-server://0.0.0.0:22322 Waiting for saltyboat handshake to finish.

I've looked at another issue on here about sharing and I have checked my firewall settings. They are fine.

EDIT: I should mention I'm using the beta android client.
@iffy
Copy link
Contributor

iffy commented Feb 13, 2023

That it's failing the handshake for version mismatch means it's not your firewall. The devices are connecting but they're speaking different versions of the sync protocol. This is confusing to me, because I didn't think I'd released the newer version of the protocol (it's the one that will support the upcoming relay servers). Are you able to send the lines of the log files (for desktop and phone) that might include what version it's failing on?

Or what happens in the log if you do this (on the desktop)? Do you get the same messages in the log?

echo hello | nc 127.0.0.1 22322

@dragos240
Copy link
Author

dragos240 commented Feb 14, 2023 •
edited
Loading

Android log:

INFO [2023-02-11T05:43:39] Logging started
INFO [2023-02-11T05:43:39] Version 0.1.0
INFO [2023-02-11T05:43:39] Android
ERROR [2023-02-11T05:43:39] Flushing non-error
INFO [2023-02-11T05:43:49] Logging started
INFO [2023-02-11T05:43:49] Version 0.1.0
INFO [2023-02-11T05:43:49] Android
ERROR [2023-02-11T05:43:49] Flushing non-error
INFO [2023-02-11T05:43:49] (dbpatch) start
DEBUG [2023-02-11T05:43:49] (dbpatch) existing patches: @["0001-initial", "0002-convert-to-app-relative-paths", "0003-rollback convert-to-app-relative-paths"]
DEBUG [2023-02-11T05:43:49] (dbpatch) patch 0001-initial already applied
DEBUG [2023-02-11T05:43:49] (dbpatch) patch 0002-convert-to-app-relative-paths already applied
DEBUG [2023-02-11T05:43:49] (dbpatch) patch 0003-rollback convert-to-app-relative-paths already applied
INFO [2023-02-11T05:43:49] (dbpatch) end
DEBUG [2023-02-11T05:43:49] (peddler) loop starting ...
DEBUG [2023-02-11T05:43:50] Window added
DEBUG [2023-02-11T05:43:50] JS: progstate.connect ...
DEBUG [2023-02-11T05:43:50] JS: progstate changed
DEBUG [2023-02-11T05:43:50] JS: progstate connected!
DEBUG [2023-02-11T05:49:52] JS: progstate changed
INFO [2023-02-11T05:50:37] (peddler) direct-client://192.168.10.164 starting client
DEBUG [2023-02-11T05:50:37] JS: progstate changed
INFO [2023-02-11T05:50:40] (peddler) direct-client://192.168.10.164 starting client
WARN [2023-02-11T05:50:40] (peddler) service already added: direct-client://192.168.10.164
INFO [2023-02-11T05:51:05] (peddler) direct-client://192.168.10.164 starting client
WARN [2023-02-11T05:51:05] (peddler) service already added: direct-client://192.168.10.164
INFO [2023-02-11T05:51:12] (peddler) direct-client://192.168.10.164 starting client
WARN [2023-02-11T05:51:12] (peddler) service already added: direct-client://192.168.10.164
INFO [2023-02-11T05:52:02] (peddler) direct-client://direct-server://0.0.0.0:22322 starting client
WARN [2023-02-11T05:52:02] (peddler) Error dialing to direct-server:22322 - Additional info: No address associated with hostname
DEBUG [2023-02-11T05:52:02] (peddler) sleeping for 10000ms
INFO [2023-02-11T05:52:22] (peddler) direct-client://direct-server://192.168.10.164:22322 starting client
WARN [2023-02-11T05:52:22] (peddler) Error dialing to direct-server:22322 - Additional info: No address associated with hostname
DEBUG [2023-02-11T05:52:22] (peddler) sleeping for 10000ms
INFO [2023-02-11T05:52:32] (peddler) direct-client://direct-server://192.168.10.164:22322 starting client
WARN [2023-02-11T05:52:32] (peddler) service already added: direct-client://direct-server://192.168.10.164:22322
INFO [2023-02-11T05:52:35] (peddler) direct-client://direct-server://192.168.10.164:22322 starting client
WARN [2023-02-11T05:52:35] (peddler) service already added: direct-client://direct-server://192.168.10.164:22322
INFO [2023-02-11T05:52:47] (peddler) direct-client://192.168.10.164 starting client
WARN [2023-02-11T05:52:47] (peddler) service already added: direct-client://192.168.10.164
INFO [2023-02-11T05:53:26] (peddler) direct-client://192.168.10.164 starting client
WARN [2023-02-11T05:53:26] (peddler) service already added: direct-client://192.168.10.164
INFO [2023-02-11T05:54:01] (peddler) direct-client://192.168.10.164 starting client
WARN [2023-02-11T05:54:01] (peddler) service already added: direct-client://192.168.10.164
INFO [2023-02-11T05:54:20] (peddler) direct-client://192.168.10.164:22322 starting client
INFO [2023-02-11T05:54:21] (peddler) direct-client://192.168.10.164:22322 starting client
WARN [2023-02-11T05:54:21] (peddler) service already added: direct-client://192.168.10.164:22322
INFO [2023-02-11T05:54:32] (peddler) direct-client://192.168.10.164:22322 starting client
WARN [2023-02-11T05:54:32] (peddler) service already added: direct-client://192.168.10.164:22322
INFO [2023-02-11T05:54:33] (peddler) direct-client://192.168.10.164:22322 starting client
WARN [2023-02-11T05:54:33] (peddler) service already added: direct-client://192.168.10.164:22322
INFO [2023-02-11T05:55:00] (peddler) direct-client://192.168.10.164:22322 starting client
WARN [2023-02-11T05:55:00] (peddler) service already added: direct-client://192.168.10.164:22322
INFO [2023-02-11T05:55:06] (peddler) direct-client://192.168.10.164 starting client
WARN [2023-02-11T05:55:06] (peddler) service already added: direct-client://192.168.10.164
INFO [2023-02-11T05:55:14] (peddler) direct-client://192.168.INFO [2023-02-11T05:58:43] Logging started
INFO [2023-02-11T05:58:43] Version 0.1.0
INFO [2023-02-11T05:58:43] Android
ERROR [2023-02-11T05:58:43] Flushing non-error
INFO [2023-02-11T05:59:10] Logging started
INFO [2023-02-11T05:59:10] Version 0.1.0
INFO [2023-02-11T05:59:10] Android
ERROR [2023-02-11T05:59:10] Flushing non-error
INFO [2023-02-11T06:00:31] Logging started
INFO [2023-02-11T06:00:31] Version 0.1.0
INFO [2023-02-11T06:00:31] Android
ERROR [2023-02-11T06:00:31] Flushing non-error
INFO [2023-02-11T06:00:58] Logging started
INFO [2023-02-11T06:00:58] Version 0.1.0
INFO [2023-02-11T06:00:58] Android
ERROR [2023-02-11T06:00:58] Flushing non-error
INFO [2023-02-11T06:02:20] Logging started
INFO [2023-02-11T06:02:20] Version 0.1.0
INFO [2023-02-11T06:02:20] Android
ERROR [2023-02-11T06:02:20] Flushing non-error
INFO [2023-02-11T06:02:37] Logging started
INFO [2023-02-11T06:02:37] Version 0.1.0
INFO [2023-02-11T06:02:37] Android
ERROR [2023-02-11T06:02:37] Flushing non-error
INFO [2023-02-11T06:03:33] Logging started
INFO [2023-02-11T06:03:33] Version 0.1.0
INFO [2023-02-11T06:03:33] Android
ERROR [2023-02-11T06:03:33] Flushing non-error
INFO [2023-02-11T06:03:43] Logging started
INFO [2023-02-11T06:03:43] Version 0.1.0
INFO [2023-02-11T06:03:43] Android
ERROR [2023-02-11T06:03:43] Flushing non-error
INFO [2023-02-11T06:05:20] Logging started
INFO [2023-02-11T06:05:20] Version 0.1.0
INFO [2023-02-11T06:05:20] Android
ERROR [2023-02-11T06:05:20] Flushing non-error
INFO [2023-02-11T06:07:41] Logging started
INFO [2023-02-11T06:07:41] Version 0.1.0
INFO [2023-02-11T06:07:41] Android
ERROR [2023-02-11T06:07:41] Flushing non-error
INFO [2023-02-11T06:09:23] Logging started
INFO [2023-02-11T06:09:23] Version 0.1.0
INFO [2023-02-11T06:09:23] Android
ERROR [2023-02-11T06:09:23] Flushing non-error
INFO [2023-02-11T06:11:28] Logging started
INFO [2023-02-11T06:11:28] Version 0.1.0
INFO [2023-02-11T06:11:28] Android
ERROR [2023-02-11T06:11:28] Flushing non-error
INFO [2023-02-11T06:11:44] Logging started
INFO [2023-02-11T06:11:44] Version 0.1.0
INFO [2023-02-11T06:11:44] Android
ERROR [2023-02-11T06:11:44] Flushing non-error
INFO [2023-02-11T06:16:49] Logging started
INFO [2023-02-11T06:16:49] Version 0.1.0
INFO [2023-02-11T06:16:49] Android
ERROR [2023-02-11T06:16:49] Flushing non-error
INFO [2023-02-11T06:17:06] Logging started
INFO [2023-02-11T06:17:06] Version 0.1.0
INFO [2023-02-11T06:17:06] Android
ERROR [2023-02-11T06:17:06] Flushing non-error
INFO [2023-02-11T06:20:56] Logging started
INFO [2023-02-11T06:20:56] Version 0.1.0
INFO [2023-02-11T06:20:56] Android
ERROR [2023-02-11T06:20:56] Flushing non-error
INFO [2023-02-14T04:06:19] Logging started
INFO [2023-02-14T04:06:19] Version 0.1.0
INFO [2023-02-14T04:06:19] Android
ERROR [2023-02-14T04:06:19] Flushing non-error
INFO [2023-02-14T04:06:41] Logging started
INFO [2023-02-14T04:06:41] Version 0.1.0
INFO [2023-02-14T04:06:41] Android
ERROR [2023-02-14T04:06:41] Flushing non-error
INFO [2023-02-14T04:06:41] (dbpatch) start
DEBUG [2023-02-14T04:06:41] (dbpatch) existing patches: @["0001-initial", "0002-convert-to-app-relative-paths", "0003-rollback convert-to-app-relative-paths"]
DEBUG [2023-02-14T04:06:41] (dbpatch) patch 0001-initial already applied
DEBUG [2023-02-14T04:06:41] (dbpatch) patch 0002-convert-to-app-relative-paths already applied
DEBUG [2023-02-14T04:06:41] (dbpatch) patch 0003-rollback convert-to-app-relative-paths already applied
INFO [2023-02-14T04:06:41] (dbpatch) end
DEBUG [2023-02-14T04:06:41] (peddler) loop starting ...
DEBUG [2023-02-14T04:06:41] Window added
DEBUG [2023-02-14T04:06:42] JS: progstate.connect ...
DEBUG [2023-02-14T04:06:42] JS: progstate changed
DEBUG [2023-02-14T04:06:42] JS: progstate connected!
DEBUG [2023-02-14T04:06:47] JS: progstate changed
INFO [2023-02-14T04:07:02] (peddler) direct-client://192.168.10.164 starting client
ERROR [2023-02-14T04:07:34] JS: LOG FLUSHER

Desktop log (inspector window, not sure if there's a log functionality other than this):

[04:07:04.782] (core) DEBUG (peddler) direct-server://0.0.0.0:22322 Starting saltyboat...
DEBUG (peddler) direct-server://0.0.0.0:22322 Waiting for saltyboat handshake to finish...
[04:15:09.509] (core) ERROR (saltyboat54725) Failed handshake for version: Invalid netstring length char: 'h'
[04:15:09.509] (core) ERROR (peddler) direct-server://0.0.0.0:22322 Failed saltyboat: Disconnected

It just stops here.

As for the nc line:

$ echo hello | nc localhost 22322
6:["V1"],

Oh and this is on Windows 10. I used WSL to run the netcat line

@iffy
Copy link
Contributor

iffy commented Feb 14, 2023

Okay, I think the problem is that somehow the channel on Android was added as direct-client://direct-server://192.168.10.164:22322 when it should be direct-client://192.168.10.164:22322. It's probably a problem with the Android UI adding stuff to what you typed in. FWIW the UI should be much better in the next release (it's what I'm working on now).

@iffy iffy added bug Things that prevent or seriously impede people from doing their budget. Next This is next on the list -- it might not get done, but this is the plan. labels Feb 17, 2023
@dragos240
Copy link
Author

I think that may not be the issue. I went into the app.sqlite db and in table `sharing_Conns_to_make I found this
Screenshot_20230217-211022

@iffy
Copy link
Contributor

iffy commented Feb 18, 2023

Thanks for looking at that. I'm not exactly sure what's going on. The latest version (not yet released) has better logging for sharing, so I hope I can get it out soon and see if this problem goes away (or at least shows more information in the logs)

@iffy iffy added the included in next release The work is done, it's just waiting to be released. label Feb 22, 2023
@iffy
Copy link
Contributor

iffy commented Mar 1, 2023

Included in v0.70.0 release (AUTOMATED COMMENT)

@iffy iffy closed this as completed Mar 1, 2023
@dragos240
Copy link
Author

It works now. Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Things that prevent or seriously impede people from doing their budget. included in next release The work is done, it's just waiting to be released. Next This is next on the list -- it might not get done, but this is the plan.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@iffy @dragos240