Qtox: [regression] Some profiles fail to connect after the upgrade to 1.10.0

[yurivict]

Some profiles fail to connect in 1.10.0, see log below.
Some other instance connect fine.

This is a show-stopper regression.

[16:38:03.735 UTC] widget/systemtrayicon.cpp:61 : Debug: Using GTK backend
[16:38:04.538 UTC] core/core.cpp:415 : Debug: "Connecting to 2a02:7aa0:1619::bdbd:17b8:33445 (Rotkaermota)"
[16:38:04.538 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from Rotkaermota"
[16:38:04.538 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from Rotkaermota"
[16:38:04.538 UTC] core/core.cpp:415 : Debug: "Connecting to 95.215.46.114:33445 (Rotkaermota)"
[16:38:04.538 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from Rotkaermota"
[16:38:04.538 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from Rotkaermota"
[16:38:09.170 UTC] core/core.cpp:415 : Debug: "Connecting to 104.223.122.15:33445 (ru_maniac)"
[16:38:09.170 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from ru_maniac"
[16:38:09.170 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from ru_maniac"
[16:38:09.170 UTC] core/core.cpp:415 : Debug: "Connecting to 185.58.206.164:33445 (ru_maniac)"
[16:38:09.170 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from ru_maniac"
[16:38:09.170 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from ru_maniac"
[16:38:13.805 UTC] core/core.cpp:415 : Debug: "Connecting to 2a02:f680:1:1100::3313:33445 (ru_maniac)"
[16:38:13.805 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from ru_maniac"
[16:38:13.805 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from ru_maniac"
[16:38:13.805 UTC] core/core.cpp:415 : Debug: "Connecting to 5.135.59.163:33445 (Skey)"
[16:38:13.805 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from Skey"
[16:38:13.805 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from Skey"
[16:38:18.485 UTC] core/core.cpp:415 : Debug: "Connecting to sorunome.de:33445 (Sorunome)"
[16:38:18.485 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from Sorunome"
[16:38:18.485 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from Sorunome"
[16:38:18.485 UTC] core/core.cpp:415 : Debug: "Connecting to tox.zodiaclabs.org:33445 (stal)"
[16:38:18.485 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from stal"
[16:38:18.485 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from stal"
[16:38:23.172 UTC] core/core.cpp:415 : Debug: "Connecting to v6.tox.zodiaclabs.org:33445 (stal)"
[16:38:23.172 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from stal"
[16:38:23.172 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from stal"
[16:38:23.172 UTC] core/core.cpp:415 : Debug: "Connecting to 195.93.190.6:33445 (strngr)"
[16:38:23.172 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from strngr"
[16:38:23.172 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from strngr"
[16:38:27.842 UTC] core/core.cpp:415 : Debug: "Connecting to 2a01:d0:ffff:a8a::2:33445 (strngr)"
[16:38:27.842 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from strngr"
[16:38:27.842 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from strngr"
[16:38:27.842 UTC] core/core.cpp:415 : Debug: "Connecting to 92.54.84.70:33445 (t3mp)"
[16:38:27.842 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from t3mp"
[16:38:27.842 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from t3mp"
[16:38:32.524 UTC] core/core.cpp:415 : Debug: "Connecting to 5.189.176.217:5190 (tastytea)"
[16:38:32.524 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from tastytea"
[16:38:32.524 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from tastytea"
[16:38:32.525 UTC] core/core.cpp:415 : Debug: "Connecting to 2a00:d880:3:2::8bdc:f19:33445 (tibietigni)"
[16:38:32.525 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from tibietigni"
[16:38:32.525 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from tibietigni"
[16:38:37.159 UTC] core/core.cpp:415 : Debug: "Connecting to 81.4.110.149:33445 (tibietigni)"
[16:38:37.159 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from tibietigni"
[16:38:37.159 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from tibietigni"
[16:38:37.159 UTC] core/core.cpp:415 : Debug: "Connecting to 192.99.168.140:33445 (WIeschie)"
[16:38:37.159 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from WIeschie"
[16:38:37.159 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from WIeschie"
[16:38:41.808 UTC] core/core.cpp:415 : Debug: "Connecting to 128.199.199.197:33445 (wiiaam)"
[16:38:41.808 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from wiiaam"
[16:38:41.808 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from wiiaam"
[16:38:41.808 UTC] core/core.cpp:415 : Debug: "Connecting to 2400:6180:0:d0::17a:a001:33445 (wiiaam)"
[16:38:41.808 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from wiiaam"
[16:38:41.808 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from wiiaam"
[16:38:46.451 UTC] core/core.cpp:415 : Debug: "Connecting to 37.97.185.116:33445 (Yani)"
[16:38:46.451 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from Yani"
[16:38:46.451 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from Yani"
[16:38:46.451 UTC] core/core.cpp:415 : Debug: "Connecting to 51.254.84.212:33445 (a68366)"
[16:38:46.451 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from a68366"
[16:38:46.451 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from a68366"
[16:38:51.140 UTC] core/core.cpp:415 : Debug: "Connecting to loki.uplinklabs.net:33445 (AbacusAvenger)"
[16:38:51.140 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from AbacusAvenger"
[16:38:51.140 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from AbacusAvenger"
[16:38:51.140 UTC] core/core.cpp:415 : Debug: "Connecting to tox.ntp.moscow:33445 (abbat)"
[16:38:51.140 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from abbat"
[16:38:51.140 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from abbat"
[16:38:55.822 UTC] core/core.cpp:415 : Debug: "Connecting to bootybay.club:33445 (AssPirate)"
[16:38:55.823 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from AssPirate"
[16:38:55.823 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from AssPirate"
[16:38:55.823 UTC] core/core.cpp:415 : Debug: "Connecting to tox.neverlocate.me:33445 (brandon)"
[16:38:55.823 UTC] core/core.cpp:422 : Debug: "Error bootstrapping from brandon"
[16:38:55.823 UTC] core/core.cpp:426 : Debug: "Error adding TCP relay from brandon"

[Diadlo]

Do you use proxy?

[yurivict]

There's no proxy.

[zetok]

I also have the same error, regardless of whether proxy is used.

[sudden6]

@zetok can you test with a fresh nodes list?

[ghost]

Is it possible that this affects the latest Windows binary too? I unable to connect in Linux with e4d4f147936c0481e7d20d20109be236be59bc24 and Windows with 5d117e6af854de194dc16575f1fe5c95a43741c8. No proxy, Windows runs in a VM.

[dolohow]

Downgrading toxcore to 0.1.7 fixes problem.

[cebe]

Downgrading toxcore to 0.1.7 fixes problem.

could someone run a git bisect to figure out the breaking commit?

[ghost]

I can confirm that downgrading toxcore to 0.1.7 fixes the problem.
But toxic on the same profile works with 0.1.8 (qTox does not).
So it may be a qTox bug.

[yurivict]

Downgrading qTox to 1.9.0 also fixes the problem.

[nurupo]

Just an observation (it might not be what causes this issue) but qTox's bootstrap node list is a bit outdated, probably about of half of the nodes don't exist anymore. 31 nodes were removed from nodes.tox.chat as they were offline for over 1 month.

[nurupo]

It would be nice if qTox reported the exact error that tox_bootstrap() errors. Can someone re-compile qTox with that change? Just printing the error enum number is enough.

[nurupo]

The only reasons why tox_boostrap() would error are: NULL as argument for non-Nullable argument, bad address or bad port. https://github.com/TokTok/c-toxcore/blob/master/toxcore/tox.h#L869-L892

[nurupo]

@yurivict do you have "Creating a new profile" or "Loading user profile" in your log?

[yurivict]

Now the current head works for me.
It says: Debug: Loading user profile

[yurivict]

Now it still fails several times, but later it connects.
I can't tell if it's just that all bootstrap nodes happened to be down before, or there is a legit error in the code.

[17:07:21.206 UTC] widget/systemtrayicon.cpp:61 : Debug: Using GTK backend
[17:07:22.066 UTC] core/core.cpp:414 : Debug: "Connecting to 95.31.20.151:33445 (IgorNovgorodov)"
[17:07:22.066 UTC] core/core.cpp:421 : Debug: "Error bootstrapping from IgorNovgorodov"
[17:07:22.066 UTC] core/core.cpp:425 : Debug: "Error adding TCP relay from IgorNovgorodov"
[17:07:22.066 UTC] core/core.cpp:414 : Debug: "Connecting to 178.62.250.138:33445 (Impyy)"
[17:07:22.066 UTC] core/core.cpp:421 : Debug: "Error bootstrapping from Impyy"
[17:07:22.066 UTC] core/core.cpp:425 : Debug: "Error adding TCP relay from Impyy"
[17:07:26.720 UTC] core/core.cpp:414 : Debug: "Connecting to 2a03:b0c0:2:d0::16:1:33445 (Impyy)"
[17:07:26.720 UTC] core/core.cpp:421 : Debug: "Error bootstrapping from Impyy"
[17:07:26.720 UTC] core/core.cpp:425 : Debug: "Error adding TCP relay from Impyy"
[17:07:26.720 UTC] core/core.cpp:414 : Debug: "Connecting to initramfs.io:33445 (initramfs)"
[17:07:26.720 UTC] core/core.cpp:421 : Debug: "Error bootstrapping from initramfs"
[17:07:26.720 UTC] core/core.cpp:425 : Debug: "Error adding TCP relay from initramfs"
[17:07:31.357 UTC] core/core.cpp:414 : Debug: "Connecting to 139.162.217.110:33445 (Kr9r0x)"
[17:07:31.357 UTC] core/core.cpp:421 : Debug: "Error bootstrapping from Kr9r0x"
[17:07:31.357 UTC] core/core.cpp:425 : Debug: "Error adding TCP relay from Kr9r0x"
[17:07:31.357 UTC] core/core.cpp:414 : Debug: "Connecting to 80.87.193.193:33445 (linxon)"
[17:07:31.357 UTC] core/core.cpp:421 : Debug: "Error bootstrapping from linxon"
[17:07:31.357 UTC] core/core.cpp:425 : Debug: "Error adding TCP relay from linxon"
[17:07:35.259 UTC] core/core.cpp:382 : Debug: Connected to the DHT
[17:07:35.260 UTC] persistence/profile.cpp:311 : Debug: Saving tox save to  "/home/yuri/.config/tox/yuri-other.tox"
[17:07:38.230 UTC] core/core.cpp:385 : Debug: Disconnected from the DHT
[17:07:39.226 UTC] core/core.cpp:382 : Debug: Connected to the DHT
[17:07:39.226 UTC] persistence/profile.cpp:311 : Debug: Saving tox save to  "/home/yuri/.config/tox/yuri-other.tox"
[17:07:40.223 UTC] core/core.cpp:385 : Debug: Disconnected from the DHT
[17:07:40.801 UTC] core/corefile.cpp:307 : Debug: "Received avatar request 3:65536, accept, since we don't have it in cache."
[17:07:40.857 UTC] core/core.cpp:506 : Debug: "Text group invite by 3"
[17:07:40.865 UTC] audio/backend/openal.cpp:288 : Debug: Opening audio output "OSS Default"
[17:07:40.866 UTC] audio/backend/openal.cpp:300 : Debug: Opened audio output "OSS Default"
[17:07:41.727 UTC] core/core.cpp:414 : Debug: "Connecting to 146.185.136.123:33445 (LittleVulpix)"
[17:07:41.727 UTC] core/core.cpp:421 : Debug: "Error bootstrapping from LittleVulpix"
[17:07:41.728 UTC] core/core.cpp:425 : Debug: "Error adding TCP relay from LittleVulpix"
[17:07:41.728 UTC] core/core.cpp:414 : Debug: "Connecting to 163.172.136.118:33445 (LittleVulpix)"
[17:07:41.728 UTC] core/core.cpp:421 : Debug: "Error bootstrapping from LittleVulpix"
[17:07:41.728 UTC] core/core.cpp:425 : Debug: "Error adding TCP relay from LittleVulpix"
[17:07:43.225 UTC] core/core.cpp:382 : Debug: Connected to the DHT

[nurupo]

It's qTox issue. For some reason it passes NULL as public key to tox_bootstrap() and tox_add_relay().

I have made the following change on top of the commit that current qTox download is based on https://github.com/nurupo/qTox/commit/246fd9f20ea12339e13e46dbf35bdd3fb43d64ce

Here is the log of the modified qTox

[18:20:56.549 UTC] persistence/settings.cpp:129 : Debug: No settings file found, using defaults
[18:20:56.549 UTC] persistence/settings.cpp:133 : Debug: "Loading settings from :/conf/qtox.ini"
[18:20:56.555 UTC] ipc.cpp:62 : Debug: Our global IPC ID is  3169903406987816468
[18:20:56.559 UTC] main.cpp:218 : Debug: built on:  18:10:53 May 11 2017 ( 1494526204 )
[18:20:56.559 UTC] main.cpp:219 : Debug: commit:  246fd9f20ea12339e13e46dbf35bdd3fb43d64ce 

[18:20:56.559 UTC] nexus.cpp:90 : Debug: Starting up
[18:21:07.914 UTC] persistence/settings.cpp:2282 : Debug: Creating new profile settings in  "C:/Users/nurupo/AppData/Roaming/tox\\\\bootstrap-test.ini"
[18:21:07.920 UTC] persistence/settings.cpp:477 : Debug: "Saving global settings at C:/Users/nurupo/AppData/Roaming/tox\\qtox.ini"
[18:21:07.926 UTC] persistence/settings.cpp:343 : Debug: Loading personal settings from "C:/Users/nurupo/AppData/Roaming/tox/bootstrap-test.ini"
[18:21:07.963 UTC] core/core.cpp:256 : Debug: Creating a new profile
[18:21:07.963 UTC] core/core.cpp:129 : Debug: Core starting with IPv6 enabled
[18:21:07.967 UTC] core/core.cpp:317 : Debug: Self avatar not found, will broadcast empty avatar to friends
[18:21:07.967 UTC] persistence/profile.cpp:311 : Debug: Saving tox save to  "C:/Users/nurupo/AppData/Roaming/tox\\bootstrap-test.tox"
[18:21:08.940 UTC] widget/systemtrayicon.cpp:82 : Debug: Using the Qt backend
[18:21:09.785 UTC] core/core.cpp:411 : Debug: "Connecting to 5.189.176.217:5190 (tastytea)"
[18:21:09.785 UTC] core/core.cpp:418 : Debug: 0x5868440, 5.189.176.217, 5190, 0x0

[18:21:09.785 UTC] core/core.cpp:420 : Debug: "Error bootstrapping from tastytea error code: \u0001"
[18:21:09.785 UTC] core/core.cpp:424 : Debug: "Error adding TCP relay from tastytea"
[18:21:09.785 UTC] core/core.cpp:411 : Debug: "Connecting to 2a00:d880:3:2::8bdc:f19:33445 (tibietigni)"
[18:21:09.785 UTC] core/core.cpp:418 : Debug: 0x5868440, 2a00:d880:3:2::8bdc:f19, 33445, 0x0

[18:21:09.785 UTC] core/core.cpp:420 : Debug: "Error bootstrapping from tibietigni error code: \u0001"
[18:21:09.785 UTC] core/core.cpp:424 : Debug: "Error adding TCP relay from tibietigni"
[18:21:15.401 UTC] core/core.cpp:411 : Debug: "Connecting to 81.4.110.149:33445 (tibietigni)"
[18:21:15.401 UTC] core/core.cpp:418 : Debug: 0x5868440, 81.4.110.149, 33445, 0x0

[18:21:15.401 UTC] core/core.cpp:420 : Debug: "Error bootstrapping from tibietigni error code: \u0001"
[18:21:15.401 UTC] core/core.cpp:424 : Debug: "Error adding TCP relay from tibietigni"
[18:21:15.401 UTC] core/core.cpp:411 : Debug: "Connecting to 192.99.168.140:33445 (WIeschie)"
[18:21:15.401 UTC] core/core.cpp:418 : Debug: 0x5868440, 192.99.168.140, 33445, 0x0

[18:21:15.401 UTC] core/core.cpp:420 : Debug: "Error bootstrapping from WIeschie error code: \u0001"
[18:21:15.401 UTC] core/core.cpp:424 : Debug: "Error adding TCP relay from WIeschie"
[18:21:21.016 UTC] core/core.cpp:411 : Debug: "Connecting to 128.199.199.197:33445 (wiiaam)"
[18:21:21.016 UTC] core/core.cpp:418 : Debug: 0x5868440, 128.199.199.197, 33445, 0x0

[18:21:21.016 UTC] core/core.cpp:420 : Debug: "Error bootstrapping from wiiaam error code: \u0001"
[18:21:21.016 UTC] core/core.cpp:424 : Debug: "Error adding TCP relay from wiiaam"
[18:21:21.016 UTC] core/core.cpp:411 : Debug: "Connecting to 2400:6180:0:d0::17a:a001:33445 (wiiaam)"
[18:21:21.016 UTC] core/core.cpp:418 : Debug: 0x5868440, 2400:6180:0:d0::17a:a001, 33445, 0x0

[18:21:21.016 UTC] core/core.cpp:420 : Debug: "Error bootstrapping from wiiaam error code: \u0001"
[18:21:21.016 UTC] core/core.cpp:424 : Debug: "Error adding TCP relay from wiiaam"
[18:21:26.632 UTC] core/core.cpp:411 : Debug: "Connecting to 37.97.185.116:33445 (Yani)"
[18:21:26.632 UTC] core/core.cpp:418 : Debug: 0x5868440, 37.97.185.116, 33445, 0x0

[18:21:26.632 UTC] core/core.cpp:420 : Debug: "Error bootstrapping from Yani error code: \u0001"
[18:21:26.632 UTC] core/core.cpp:424 : Debug: "Error adding TCP relay from Yani"
[18:21:26.632 UTC] core/core.cpp:411 : Debug: "Connecting to 51.254.84.212:33445 (a68366)"
[18:21:26.632 UTC] core/core.cpp:418 : Debug: 0x5868440, 51.254.84.212, 33445, 0x0

As you can see, pkPtr is 0x0, i.e. null. Toxcore returns 1 as error, which is TOX_ERR_BOOTSTRAP_NULL.

[nurupo]

The bug was introduced by https://github.com/qTox/qTox/commit/d126b18d76150700caa52c801e91d94460fe4346 commit.

The bug is in line https://github.com/qTox/qTox/blob/d126b18d76150700caa52c801e91d94460fe4346/src/core/core.cpp#L397

ToxPk pk{dhtServer.userId.toLatin1()};

ToxPk's constructor for QByteArray argument expects the argument to be the byte representation of ToxID (which is 32 bytes long, TOX_PUBLIC_KEY_SIZE), while dhtServer.userId.toLatin1() is ASCII (Latin1) byte representation of ToxId (which is 64 bytes), so it constructs an empty ToxPk.