dht provides still broken.

[jbenet]

There's still something wrong with providers.

• I added some debug statements: mount-fix...more-dht-fixes
• i ran a few tests. here's one peculiar run: https://github.com/jbenet/ipfs-dockertest-logs/tree/master/log3
• See specifically https://raw.githubusercontent.com/jbenet/ipfs-dockertest-logs/master/log3/dht-provide:

segmented for your viewing pleasure:

server_1    | <peer.ID Qmbtc2> putProvider: <peer.ID QmNXuB> for QmcdNXWTJeBd4fKq1vsUWhP8Uy2azPXiRcVozsNgwzP1sf ([/ip4/172.17.0.136/tcp/4021 /ip6/fe80::42:acff:fe11:88/tcp/4021 /ip4/172.17.0.136/udp/4022/utp /ip6/fe80::42:acff:fe11:88/udp/4022/utp])
bootstrap_1 | <peer.ID QmNXuB> adding <peer.ID Qmbtc2> as a provider for 'QmcdNXWTJeBd4fKq1vsUWhP8Uy2azPXiRcVozsNgwzP1sf'

server_1    | <peer.ID Qmbtc2> putProvider: <peer.ID QmNXuB> for QmPpAnjeYyy9y4UNZAihtsw8fTA3wh8bS3kukYAiAAdpeq ([/ip4/172.17.0.136/tcp/4021 /ip6/fe80::42:acff:fe11:88/tcp/4021 /ip4/172.17.0.136/udp/4022/utp /ip6/fe80::42:acff:fe11:88/udp/4022/utp])
bootstrap_1 | <peer.ID QmNXuB> adding <peer.ID Qmbtc2> as a provider for 'QmPpAnjeYyy9y4UNZAihtsw8fTA3wh8bS3kukYAiAAdpeq'

client_1    | <peer.ID Qmbtc3> FindProviders QmcdNXWTJeBd4fKq1vsUWhP8Uy2azPXiRcVozsNgwzP1sf
client_1    | <peer.ID Qmbtc3> findProviders(QmcdNXWTJeBd4fKq1vsUWhP8Uy2azPXiRcVozsNgwzP1sf).Query(<peer.ID QmNXuB>):  begin
bootstrap_1 | <peer.ID QmNXuB> handleGetProviders(<peer.ID Qmbtc3>, QmcdNXWTJeBd4fKq1vsUWhP8Uy2azPXiRcVozsNgwzP1sf):  begin
bootstrap_1 | <peer.ID QmNXuB> handleGetProviders(<peer.ID Qmbtc3>, QmcdNXWTJeBd4fKq1vsUWhP8Uy2azPXiRcVozsNgwzP1sf):  have 1 providers: [{<peer.ID Qmbtc2> [/ip6/fe80::42:acff:fe11:88/tcp/4021 /ip4/172.17.0.136/udp/4022/utp /ip6/fe80::42:acff:fe11:88/udp/4022/utp /ip4/172.17.0.136/tcp/4021]}]
bootstrap_1 | <peer.ID QmNXuB> handleGetProviders(<peer.ID Qmbtc3>, QmcdNXWTJeBd4fKq1vsUWhP8Uy2azPXiRcVozsNgwzP1sf):  end
client_1    | <peer.ID Qmbtc3> findProviders(QmcdNXWTJeBd4fKq1vsUWhP8Uy2azPXiRcVozsNgwzP1sf).Query(<peer.ID QmNXuB>):  got 1 provider entries
client_1    | <peer.ID Qmbtc3> findProviders(QmcdNXWTJeBd4fKq1vsUWhP8Uy2azPXiRcVozsNgwzP1sf).Query(<peer.ID QmNXuB>):  got 1 provider entries decoded
client_1    | <peer.ID Qmbtc3> findProviders(QmcdNXWTJeBd4fKq1vsUWhP8Uy2azPXiRcVozsNgwzP1sf).Query(<peer.ID QmNXuB>):  got provider: {<peer.ID Qmbtc2> [/ip6/fe80::42:acff:fe11:88/tcp/4021 /ip4/172.17.0.136/udp/4022/utp /ip6/fe80::42:acff:fe11:88/udp/4022/utp /ip4/172.17.0.136/tcp/4021]}
client_1    | <peer.ID Qmbtc3> findProviders(QmcdNXWTJeBd4fKq1vsUWhP8Uy2azPXiRcVozsNgwzP1sf).Query(<peer.ID QmNXuB>):  using provider: {<peer.ID Qmbtc2> [/ip6/fe80::42:acff:fe11:88/tcp/4021 /ip4/172.17.0.136/udp/4022/utp /ip6/fe80::42:acff:fe11:88/udp/4022/utp /ip4/172.17.0.136/tcp/4021]}
client_1    | <peer.ID Qmbtc3> findProviders(QmcdNXWTJeBd4fKq1vsUWhP8Uy2azPXiRcVozsNgwzP1sf).Query(<peer.ID QmNXuB>):  got closer peers: []
client_1    | <peer.ID Qmbtc3> findProviders(QmcdNXWTJeBd4fKq1vsUWhP8Uy2azPXiRcVozsNgwzP1sf).Query(<peer.ID QmNXuB>):  end
client_1    | FindProviders Query error: routing: not found

Somehow, even though client_1 got a provider, it still chose not to use it (FindProviders Query error: routing: not found)

[jbenet]

cc @whyrusleeping

[jbenet]

More:

• The FindProviders Query error: routing: not found is a misleading debug log. the query ends with an error because it didnt get enough providers. can't get to return dhtQueryResult{success: true}.
• the ... using provider: ... log is written right before it sends it on the outgoing channel.
• so, ... is bitswap just not using it?? -- we require additional logs.

[jbenet]

• added more debug statements: mount-fix...more-dht-fixes
• results: https://github.com/jbenet/ipfs-dockertest-logs/tree/master/
• ran more tests.

Found 3 classes of errors (these repeat):

1. https://github.com/jbenet/ipfs-dockertest-logs/tree/master/log6 -- client_1 bitswap fails to send wantlist for second file
2. https://github.com/jbenet/ipfs-dockertest-logs/tree/master/log7 -- server_1 fails to provide all blocks.
3. https://github.com/jbenet/ipfs-dockertest-logs/tree/master/log8 -- Qmbtc2 should receive addrs from Qmbtc3. Somehow it's not. the transport may be broken.

To make sure it's not utp, i'll try rerunning without utp.

[jbenet]

.... yep. some (seems log7 and log8) of it was utp.

@whyrusleeping wins again.

[jbenet]

But, i just reproduced log6 in https://github.com/jbenet/ipfs-dockertest-logs/tree/master/log9 and https://github.com/jbenet/ipfs-dockertest-logs/tree/master/log10

So that (bitswap halting) is still a problem.

[whyrusleeping]

I'll take a look at the bitswap stuff, see if anything looks particularly offensive

[btc]

I'm unable to test this hypothesis myself (no landline Internet), but the rebroadcast delay is set to ten seconds. This may explain why the server doesn't receive the want list in time.

[whyrusleeping]

@briantigerchow Im not sure that would be the issue, the context that is timing out is an entire minute...

[jbenet]

fixed the last one-- was a map indeterminism problem...