search

nictuku / dht

Kademlia/Mainline DHT node in Go.
Other
826 stars 144 forks source link

End-to-end test using a micro network of DHT nodes #24

Closed nictuku closed 10 years ago

nictuku commented 10 years ago

Inspired by Taipei Torrent's swarm test, I want to make sure the DHT nodes are able to talk to each other properly.

Interoperability should be tested eventually but that would be a separate issue.

nictuku commented 10 years ago 
$ go test -c && ./dht.test -test.v=true -v 5 -alsologtostderr -test.run=TestDHTLocal
=== RUN TestDHTLocal
I0524 12:34:56.514543 16358 dht.go:186] Using a new random node ID: 99d593033f2f16052ee73f8051c886fd0f47f0b7 20
I0524 12:34:56.516399 16358 dht.go:324] DHT: Starting DHT node 99d593033f2f16052ee73f8051c886fd0f47f0b7 on port 32797.
I0524 12:34:57.516307 16358 dht.go:186] Using a new random node ID: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d 20
I0524 12:34:57.517734 16358 dht.go:555] DHT: ping => 127.0.0.1:32797
I0524 12:34:57.517877 16358 krpc.go:88] newQuery for , lastID 1
I0524 12:34:57.518069 16358 krpc.go:91] ... new id 2
I0524 12:34:57.518722 16358 dht.go:324] DHT: Starting DHT node e3f0aad9b5ad124e4bb8785461e872c3b838ed8d on port 52999.
I0524 12:34:57.519193 16358 dht.go:555] DHT: ping => 127.0.0.1:52999
I0524 12:34:57.519429 16358 krpc.go:88] newQuery for , lastID 1
I0524 12:34:57.519512 16358 krpc.go:91] ... new id 2
I0524 12:34:57.519820 16358 dht.go:744] DHT: reply ping => 127.0.0.1:52999
I0524 12:34:57.520287 16358 dht.go:744] DHT: reply ping => 127.0.0.1:32797
I0524 12:34:57.520816 16358 routing_table.go:271] New neighbor added to neighborhood with proximity 1
I0524 12:34:57.520948 16358 routing.go:229] wasContactedRecently for ih=e3f0aad9b5ad124e4bb8785461e872c3b838ed8d in node 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 returned false
I0524 12:34:57.521173 16358 krpc.go:88] newQuery for 99d593033f2f16052ee73f8051c886fd0f47f0b7, lastID 2
I0524 12:34:57.521260 16358 krpc.go:91] ... new id 3
I0524 12:34:57.521360 16358 dht.go:586] findNodeFrom adding pendingQueries transId=3 ih=e3f0aad9b5ad124e4bb8785461e872c3b838ed8d
I0524 12:34:57.521510 16358 dht.go:595] DHT sending find_node. nodeID: 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797, target ID: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d , distance: 7a2539da8a82044b655f47d43020f43eb77f1d3a
I0524 12:34:57.521854 16358 dht.go:501] DHT: Received ping reply
I0524 12:34:57.522255 16358 routing_table.go:271] New neighbor added to neighborhood with proximity 1
I0524 12:34:57.522429 16358 routing.go:229] wasContactedRecently for ih=99d593033f2f16052ee73f8051c886fd0f47f0b7 in node e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 returned false
I0524 12:34:57.522664 16358 krpc.go:88] newQuery for e3f0aad9b5ad124e4bb8785461e872c3b838ed8d, lastID 2
I0524 12:34:57.522766 16358 krpc.go:91] ... new id 3
I0524 12:34:57.522857 16358 dht.go:586] findNodeFrom adding pendingQueries transId=3 ih=99d593033f2f16052ee73f8051c886fd0f47f0b7
I0524 12:34:57.522961 16358 dht.go:595] DHT sending find_node. nodeID: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999, target ID: 99d593033f2f16052ee73f8051c886fd0f47f0b7 , distance: 7a2539da8a82044b655f47d43020f43eb77f1d3a
I0524 12:34:57.523285 16358 dht.go:501] DHT: Received ping reply
I0524 12:34:57.523568 16358 dht.go:719] DHT find_node. Host: 127.0.0.1:52999 , nodeId: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d , target ID: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d , distance to me: 7a2539da8a82044b655f47d43020f43eb77f1d3a
I0524 12:34:57.523705 16358 dht.go:738] replyFindNode: Nodes only. Giving 1
I0524 12:34:57.524124 16358 dht.go:719] DHT find_node. Host: 127.0.0.1:32797 , nodeId: 99d593033f2f16052ee73f8051c886fd0f47f0b7 , target ID: 99d593033f2f16052ee73f8051c886fd0f47f0b7 , distance to me: 7a2539da8a82044b655f47d43020f43eb77f1d3a
I0524 12:34:57.524260 16358 dht.go:738] replyFindNode: Nodes only. Giving 1
I0524 12:34:57.524742 16358 routing_table.go:271] New neighbor added to neighborhood with proximity 1
I0524 12:34:57.524868 16358 routing.go:229] wasContactedRecently for ih=e3f0aad9b5ad124e4bb8785461e872c3b838ed8d in node 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 returned true
I0524 12:34:57.525073 16358 dht.go:874] DHT: Got new node reference, query e3f0aad9b5ad124e4bb8785461e872c3b838ed8d: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 from 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797. Distance: 7a2539da8a82044b655f47d43020f43eb77f1d3a.
I0524 12:34:57.525329 16358 routing.go:229] wasContactedRecently for ih=e3f0aad9b5ad124e4bb8785461e872c3b838ed8d in node e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 returned false
I0524 12:34:57.525495 16358 routing.go:229] wasContactedRecently for ih=e3f0aad9b5ad124e4bb8785461e872c3b838ed8d in node 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 returned true
I0524 12:34:57.525633 16358 krpc.go:88] newQuery for e3f0aad9b5ad124e4bb8785461e872c3b838ed8d, lastID 1
I0524 12:34:57.525724 16358 krpc.go:91] ... new id 2
I0524 12:34:57.525803 16358 dht.go:586] findNodeFrom adding pendingQueries transId=2 ih=e3f0aad9b5ad124e4bb8785461e872c3b838ed8d
I0524 12:34:57.525911 16358 dht.go:595] DHT sending find_node. nodeID: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999, target ID: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d , distance: 0000000000000000000000000000000000000000
I0524 12:34:57.526520 16358 dht.go:719] DHT find_node. Host: 127.0.0.1:52999 , nodeId: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d , target ID: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d , distance to me: 0000000000000000000000000000000000000000
I0524 12:34:57.526699 16358 dht.go:738] replyFindNode: Nodes only. Giving 2
I0524 12:34:57.527228 16358 routing_table.go:271] New neighbor added to neighborhood with proximity 1
I0524 12:34:57.527349 16358 routing.go:229] wasContactedRecently for ih=99d593033f2f16052ee73f8051c886fd0f47f0b7 in node e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 returned true
I0524 12:34:57.527523 16358 dht.go:874] DHT: Got new node reference, query 99d593033f2f16052ee73f8051c886fd0f47f0b7: 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 from e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999. Distance: 7a2539da8a82044b655f47d43020f43eb77f1d3a.
I0524 12:34:57.527959 16358 routing.go:229] wasContactedRecently for ih=99d593033f2f16052ee73f8051c886fd0f47f0b7 in node 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 returned false
I0524 12:34:57.528131 16358 routing.go:229] wasContactedRecently for ih=99d593033f2f16052ee73f8051c886fd0f47f0b7 in node e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 returned true
I0524 12:34:57.528240 16358 krpc.go:88] newQuery for 99d593033f2f16052ee73f8051c886fd0f47f0b7, lastID 1
I0524 12:34:57.528345 16358 krpc.go:91] ... new id 2
I0524 12:34:57.528440 16358 dht.go:586] findNodeFrom adding pendingQueries transId=2 ih=99d593033f2f16052ee73f8051c886fd0f47f0b7
I0524 12:34:57.528598 16358 dht.go:595] DHT sending find_node. nodeID: 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797, target ID: 99d593033f2f16052ee73f8051c886fd0f47f0b7 , distance: 0000000000000000000000000000000000000000
I0524 12:34:57.529132 16358 routing_table.go:271] New neighbor added to neighborhood with proximity 1
I0524 12:34:57.529268 16358 routing.go:229] wasContactedRecently for ih=e3f0aad9b5ad124e4bb8785461e872c3b838ed8d in node e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 returned true
I0524 12:34:57.529398 16358 routing.go:229] wasContactedRecently for ih=e3f0aad9b5ad124e4bb8785461e872c3b838ed8d in node 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 returned true
I0524 12:34:57.529726 16358 dht.go:867] DHT: processFindNodeResults DUPE node reference, query e3f0aad9b5ad124e4bb8785461e872c3b838ed8d: 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 from e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999. Distance: 0000000000000000000000000000000000000000.
I0524 12:34:57.530220 16358 dht.go:719] DHT find_node. Host: 127.0.0.1:32797 , nodeId: 99d593033f2f16052ee73f8051c886fd0f47f0b7 , target ID: 99d593033f2f16052ee73f8051c886fd0f47f0b7 , distance to me: 0000000000000000000000000000000000000000
I0524 12:34:57.530399 16358 dht.go:738] replyFindNode: Nodes only. Giving 2
I0524 12:34:57.530935 16358 routing_table.go:271] New neighbor added to neighborhood with proximity 1
I0524 12:34:57.531053 16358 routing.go:229] wasContactedRecently for ih=99d593033f2f16052ee73f8051c886fd0f47f0b7 in node 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 returned true
I0524 12:34:57.531232 16358 routing.go:229] wasContactedRecently for ih=99d593033f2f16052ee73f8051c886fd0f47f0b7 in node e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 returned true
I0524 12:34:57.531455 16358 dht.go:867] DHT: processFindNodeResults DUPE node reference, query 99d593033f2f16052ee73f8051c886fd0f47f0b7: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 from 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797. Distance: 0000000000000000000000000000000000000000.
I0524 12:34:58.517079 16358 dht.go:186] Using a new random node ID: 8fb2a6d0280083af971af144a65fc2730a119d5c 20
I0524 12:34:58.517780 16358 dht.go:555] DHT: ping => 127.0.0.1:32797
I0524 12:34:58.517887 16358 krpc.go:88] newQuery for , lastID 1
I0524 12:34:58.517970 16358 krpc.go:91] ... new id 2
I0524 12:34:58.518417 16358 dht.go:324] DHT: Starting DHT node 8fb2a6d0280083af971af144a65fc2730a119d5c on port 42968.
I0524 12:34:58.518754 16358 dht.go:555] DHT: ping => 127.0.0.1:42968
I0524 12:34:58.518880 16358 krpc.go:88] newQuery for , lastID 1
I0524 12:34:58.518964 16358 krpc.go:91] ... new id 2
I0524 12:34:58.519166 16358 dht.go:744] DHT: reply ping => 127.0.0.1:42968
I0524 12:34:58.519626 16358 dht.go:744] DHT: reply ping => 127.0.0.1:32797
I0524 12:34:58.519982 16358 routing_table.go:271] New neighbor added to neighborhood with proximity 3
I0524 12:34:58.520036 16358 routing.go:229] wasContactedRecently for ih=8fb2a6d0280083af971af144a65fc2730a119d5c in node 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 returned false
I0524 12:34:58.520088 16358 krpc.go:88] newQuery for 99d593033f2f16052ee73f8051c886fd0f47f0b7, lastID 2
I0524 12:34:58.520121 16358 krpc.go:91] ... new id 3
I0524 12:34:58.520148 16358 dht.go:586] findNodeFrom adding pendingQueries transId=3 ih=8fb2a6d0280083af971af144a65fc2730a119d5c
I0524 12:34:58.520188 16358 dht.go:595] DHT sending find_node. nodeID: 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797, target ID: 8fb2a6d0280083af971af144a65fc2730a119d5c , distance: 166735d3172f95aab9fdcec4f797448e05566deb
I0524 12:34:58.520352 16358 dht.go:501] DHT: Received ping reply
I0524 12:34:58.520583 16358 routing_table.go:271] New neighbor added to neighborhood with proximity 1
I0524 12:34:58.520630 16358 routing.go:229] wasContactedRecently for ih=99d593033f2f16052ee73f8051c886fd0f47f0b7 in node 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 returned true
I0524 12:34:58.520683 16358 routing.go:229] wasContactedRecently for ih=99d593033f2f16052ee73f8051c886fd0f47f0b7 in node 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968 returned false
I0524 12:34:58.520731 16358 routing.go:229] wasContactedRecently for ih=99d593033f2f16052ee73f8051c886fd0f47f0b7 in node e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 returned true
I0524 12:34:58.520777 16358 krpc.go:88] newQuery for 8fb2a6d0280083af971af144a65fc2730a119d5c, lastID 2
I0524 12:34:58.520809 16358 krpc.go:91] ... new id 3
I0524 12:34:58.520836 16358 dht.go:586] findNodeFrom adding pendingQueries transId=3 ih=99d593033f2f16052ee73f8051c886fd0f47f0b7
I0524 12:34:58.520876 16358 dht.go:595] DHT sending find_node. nodeID: 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968, target ID: 99d593033f2f16052ee73f8051c886fd0f47f0b7 , distance: 166735d3172f95aab9fdcec4f797448e05566deb
I0524 12:34:58.521046 16358 dht.go:501] DHT: Received ping reply
I0524 12:34:58.521182 16358 dht.go:719] DHT find_node. Host: 127.0.0.1:42968 , nodeId: 8fb2a6d0280083af971af144a65fc2730a119d5c , target ID: 8fb2a6d0280083af971af144a65fc2730a119d5c , distance to me: 166735d3172f95aab9fdcec4f797448e05566deb
I0524 12:34:58.521239 16358 dht.go:738] replyFindNode: Nodes only. Giving 3
I0524 12:34:58.521568 16358 dht.go:719] DHT find_node. Host: 127.0.0.1:32797 , nodeId: 99d593033f2f16052ee73f8051c886fd0f47f0b7 , target ID: 99d593033f2f16052ee73f8051c886fd0f47f0b7 , distance to me: 166735d3172f95aab9fdcec4f797448e05566deb
I0524 12:34:58.521640 16358 dht.go:738] replyFindNode: Nodes only. Giving 1
I0524 12:34:58.521892 16358 routing_table.go:271] New neighbor added to neighborhood with proximity 3
I0524 12:34:58.521935 16358 routing.go:229] wasContactedRecently for ih=8fb2a6d0280083af971af144a65fc2730a119d5c in node 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 returned true
I0524 12:34:58.522041 16358 dht.go:874] DHT: Got new node reference, query 8fb2a6d0280083af971af144a65fc2730a119d5c: 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968 from 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797. Distance: 166735d3172f95aab9fdcec4f797448e05566deb.
I0524 12:34:58.522171 16358 dht.go:874] DHT: Got new node reference, query 8fb2a6d0280083af971af144a65fc2730a119d5c: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 from 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797. Distance: 166735d3172f95aab9fdcec4f797448e05566deb.
I0524 12:34:58.522343 16358 routing.go:229] wasContactedRecently for ih=8fb2a6d0280083af971af144a65fc2730a119d5c in node 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968 returned false
I0524 12:34:58.522397 16358 routing.go:229] wasContactedRecently for ih=8fb2a6d0280083af971af144a65fc2730a119d5c in node 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 returned true
I0524 12:34:58.522442 16358 routing.go:229] wasContactedRecently for ih=8fb2a6d0280083af971af144a65fc2730a119d5c in node e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 returned false
I0524 12:34:58.522488 16358 krpc.go:88] newQuery for 8fb2a6d0280083af971af144a65fc2730a119d5c, lastID 1
I0524 12:34:58.522520 16358 krpc.go:91] ... new id 2
I0524 12:34:58.522547 16358 dht.go:586] findNodeFrom adding pendingQueries transId=2 ih=8fb2a6d0280083af971af144a65fc2730a119d5c
I0524 12:34:58.522637 16358 dht.go:595] DHT sending find_node. nodeID: 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968, target ID: 8fb2a6d0280083af971af144a65fc2730a119d5c , distance: 0000000000000000000000000000000000000000
I0524 12:34:58.522835 16358 krpc.go:88] newQuery for e3f0aad9b5ad124e4bb8785461e872c3b838ed8d, lastID 1
I0524 12:34:58.522873 16358 krpc.go:91] ... new id 2
I0524 12:34:58.522901 16358 dht.go:586] findNodeFrom adding pendingQueries transId=2 ih=8fb2a6d0280083af971af144a65fc2730a119d5c
I0524 12:34:58.522941 16358 dht.go:595] DHT sending find_node. nodeID: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999, target ID: 8fb2a6d0280083af971af144a65fc2730a119d5c , distance: 6c420c099dad91e1dca28910c7b7b0b0b22970d1
I0524 12:34:58.523268 16358 dht.go:719] DHT find_node. Host: 127.0.0.1:42968 , nodeId: 8fb2a6d0280083af971af144a65fc2730a119d5c , target ID: 8fb2a6d0280083af971af144a65fc2730a119d5c , distance to me: 0000000000000000000000000000000000000000
I0524 12:34:58.523341 16358 dht.go:738] replyFindNode: Nodes only. Giving 3
I0524 12:34:58.523778 16358 dht.go:555] DHT: ping => 127.0.0.1:42968
I0524 12:34:58.523869 16358 krpc.go:88] newQuery for , lastID 1
I0524 12:34:58.523920 16358 krpc.go:91] ... new id 2
I0524 12:34:58.524163 16358 dht.go:719] DHT find_node. Host: 127.0.0.1:42968 , nodeId: 8fb2a6d0280083af971af144a65fc2730a119d5c , target ID: 8fb2a6d0280083af971af144a65fc2730a119d5c , distance to me: 6c420c099dad91e1dca28910c7b7b0b0b22970d1
I0524 12:34:58.524267 16358 dht.go:738] replyFindNode: Nodes only. Giving 2
I0524 12:34:58.524676 16358 routing_table.go:271] New neighbor added to neighborhood with proximity 1
I0524 12:34:58.524774 16358 routing.go:229] wasContactedRecently for ih=99d593033f2f16052ee73f8051c886fd0f47f0b7 in node 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 returned true
I0524 12:34:58.524861 16358 routing.go:229] wasContactedRecently for ih=99d593033f2f16052ee73f8051c886fd0f47f0b7 in node 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968 returned true
I0524 12:34:58.524938 16358 routing.go:229] wasContactedRecently for ih=99d593033f2f16052ee73f8051c886fd0f47f0b7 in node e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 returned true
I0524 12:34:58.525042 16358 dht.go:867] DHT: processFindNodeResults DUPE node reference, query 99d593033f2f16052ee73f8051c886fd0f47f0b7: 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 from 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968. Distance: 166735d3172f95aab9fdcec4f797448e05566deb.
I0524 12:34:58.525274 16358 routing_table.go:271] New neighbor added to neighborhood with proximity 1
I0524 12:34:58.525348 16358 routing.go:229] wasContactedRecently for ih=8fb2a6d0280083af971af144a65fc2730a119d5c in node 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968 returned true
I0524 12:34:58.525429 16358 routing.go:229] wasContactedRecently for ih=8fb2a6d0280083af971af144a65fc2730a119d5c in node 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 returned true
I0524 12:34:58.525504 16358 routing.go:229] wasContactedRecently for ih=8fb2a6d0280083af971af144a65fc2730a119d5c in node e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 returned true
I0524 12:34:58.525632 16358 dht.go:867] DHT: processFindNodeResults DUPE node reference, query 8fb2a6d0280083af971af144a65fc2730a119d5c: 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 from 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968. Distance: 0000000000000000000000000000000000000000.
I0524 12:34:58.525780 16358 dht.go:867] DHT: processFindNodeResults DUPE node reference, query 8fb2a6d0280083af971af144a65fc2730a119d5c: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 from 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968. Distance: 0000000000000000000000000000000000000000.
I0524 12:34:58.525989 16358 dht.go:744] DHT: reply ping => 127.0.0.1:52999
I0524 12:34:58.526335 16358 routing_table.go:271] New neighbor added to neighborhood with proximity 1
I0524 12:34:58.526451 16358 routing.go:229] wasContactedRecently for ih=8fb2a6d0280083af971af144a65fc2730a119d5c in node 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968 returned true
I0524 12:34:58.526540 16358 routing.go:229] wasContactedRecently for ih=8fb2a6d0280083af971af144a65fc2730a119d5c in node 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 returned true
I0524 12:34:58.526731 16358 routing.go:229] wasContactedRecently for ih=8fb2a6d0280083af971af144a65fc2730a119d5c in node e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 returned true
I0524 12:34:58.526854 16358 dht.go:867] DHT: processFindNodeResults DUPE node reference, query 8fb2a6d0280083af971af144a65fc2730a119d5c: 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 from e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999. Distance: 6c420c099dad91e1dca28910c7b7b0b0b22970d1.
I0524 12:34:58.527164 16358 routing_table.go:271] New neighbor added to neighborhood with proximity 1
I0524 12:34:58.527249 16358 routing.go:229] wasContactedRecently for ih=e3f0aad9b5ad124e4bb8785461e872c3b838ed8d in node e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 returned true
I0524 12:34:58.527329 16358 routing.go:229] wasContactedRecently for ih=e3f0aad9b5ad124e4bb8785461e872c3b838ed8d in node 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968 returned false
I0524 12:34:58.527405 16358 routing.go:229] wasContactedRecently for ih=e3f0aad9b5ad124e4bb8785461e872c3b838ed8d in node 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 returned true
I0524 12:34:58.527480 16358 krpc.go:88] newQuery for 8fb2a6d0280083af971af144a65fc2730a119d5c, lastID 2
I0524 12:34:58.527540 16358 krpc.go:91] ... new id 3
I0524 12:34:58.527598 16358 dht.go:586] findNodeFrom adding pendingQueries transId=3 ih=e3f0aad9b5ad124e4bb8785461e872c3b838ed8d
I0524 12:34:58.527668 16358 dht.go:595] DHT sending find_node. nodeID: 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968, target ID: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d , distance: 6c420c099dad91e1dca28910c7b7b0b0b22970d1
I0524 12:34:58.527881 16358 dht.go:501] DHT: Received ping reply
I0524 12:34:58.528095 16358 dht.go:719] DHT find_node. Host: 127.0.0.1:52999 , nodeId: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d , target ID: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d , distance to me: 6c420c099dad91e1dca28910c7b7b0b0b22970d1
I0524 12:34:58.528191 16358 dht.go:738] replyFindNode: Nodes only. Giving 3
I0524 12:34:58.528542 16358 routing_table.go:271] New neighbor added to neighborhood with proximity 1
I0524 12:34:58.528638 16358 routing.go:229] wasContactedRecently for ih=e3f0aad9b5ad124e4bb8785461e872c3b838ed8d in node e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 returned true
I0524 12:34:58.528724 16358 routing.go:229] wasContactedRecently for ih=e3f0aad9b5ad124e4bb8785461e872c3b838ed8d in node 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968 returned true
I0524 12:34:58.528807 16358 routing.go:229] wasContactedRecently for ih=e3f0aad9b5ad124e4bb8785461e872c3b838ed8d in node 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 returned true
I0524 12:34:58.528945 16358 dht.go:867] DHT: processFindNodeResults DUPE node reference, query e3f0aad9b5ad124e4bb8785461e872c3b838ed8d: 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 from 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968. Distance: 6c420c099dad91e1dca28910c7b7b0b0b22970d1.
I0524 12:34:58.529051 16358 dht.go:867] DHT: processFindNodeResults DUPE node reference, query e3f0aad9b5ad124e4bb8785461e872c3b838ed8d: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 from 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968. Distance: 6c420c099dad91e1dca28910c7b7b0b0b22970d1.
I0524 12:34:59.517378 16358 dht.go:231] DHT: torrent client asking more peers for b462c0a8bcef1ce5bb56b9fdb8cf37ffd02f5f59.
I0524 12:34:59.517501 16358 dht.go:231] DHT: torrent client asking more peers for b462c0a8bcef1ce5bb56b9fdb8cf37ffd02f5f59.
I0524 12:34:59.517592 16358 routing.go:229] wasContactedRecently for ih=b462c0a8bcef1ce5bb56b9fdb8cf37ffd02f5f59 in node 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 returned false
I0524 12:34:59.517685 16358 routing.go:229] wasContactedRecently for ih=b462c0a8bcef1ce5bb56b9fdb8cf37ffd02f5f59 in node 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968 returned false
I0524 12:34:59.517758 16358 routing.go:229] wasContactedRecently for ih=b462c0a8bcef1ce5bb56b9fdb8cf37ffd02f5f59 in node e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 returned false
I0524 12:34:59.517911 16358 krpc.go:88] newQuery for 99d593033f2f16052ee73f8051c886fd0f47f0b7, lastID 3
I0524 12:34:59.517971 16358 krpc.go:91] ... new id 4
I0524 12:34:59.518053 16358 dht.go:576] DHT sending get_peers. nodeID: 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797, InfoHash: b462c0a8bcef1ce5bb56b9fdb8cf37ffd02f5f59 , distance: 2db753ab83c00ae095b1867de907b102df68afee
I0524 12:34:59.518310 16358 krpc.go:88] newQuery for 8fb2a6d0280083af971af144a65fc2730a119d5c, lastID 3
I0524 12:34:59.518396 16358 krpc.go:91] ... new id 4
I0524 12:34:59.518472 16358 dht.go:576] DHT sending get_peers. nodeID: 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968, InfoHash: b462c0a8bcef1ce5bb56b9fdb8cf37ffd02f5f59 , distance: 3bd0667894ef9f4a2c4c48b91e90f58cda3ec205
I0524 12:34:59.518775 16358 krpc.go:88] newQuery for e3f0aad9b5ad124e4bb8785461e872c3b838ed8d, lastID 2
I0524 12:34:59.518844 16358 krpc.go:91] ... new id 3
I0524 12:34:59.518903 16358 dht.go:576] DHT sending get_peers. nodeID: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999, InfoHash: b462c0a8bcef1ce5bb56b9fdb8cf37ffd02f5f59 , distance: 57926a7109420eabf0eec1a9d927453c6817b2d4
I0524 12:34:59.519115 16358 routing.go:229] wasContactedRecently for ih=b462c0a8bcef1ce5bb56b9fdb8cf37ffd02f5f59 in node 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797 returned false
I0524 12:34:59.519201 16358 routing.go:229] wasContactedRecently for ih=b462c0a8bcef1ce5bb56b9fdb8cf37ffd02f5f59 in node 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968 returned false
I0524 12:34:59.519271 16358 routing.go:229] wasContactedRecently for ih=b462c0a8bcef1ce5bb56b9fdb8cf37ffd02f5f59 in node e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999 returned false
I0524 12:34:59.519338 16358 krpc.go:88] newQuery for 99d593033f2f16052ee73f8051c886fd0f47f0b7, lastID 3
I0524 12:34:59.519392 16358 krpc.go:91] ... new id 4
I0524 12:34:59.519447 16358 dht.go:576] DHT sending get_peers. nodeID: 99d593033f2f16052ee73f8051c886fd0f47f0b7@127.0.0.1:32797, InfoHash: b462c0a8bcef1ce5bb56b9fdb8cf37ffd02f5f59 , distance: 2db753ab83c00ae095b1867de907b102df68afee
I0524 12:34:59.519683 16358 krpc.go:88] newQuery for 8fb2a6d0280083af971af144a65fc2730a119d5c, lastID 2
I0524 12:34:59.519748 16358 krpc.go:91] ... new id 3
I0524 12:34:59.519845 16358 dht.go:576] DHT sending get_peers. nodeID: 8fb2a6d0280083af971af144a65fc2730a119d5c@127.0.0.1:42968, InfoHash: b462c0a8bcef1ce5bb56b9fdb8cf37ffd02f5f59 , distance: 3bd0667894ef9f4a2c4c48b91e90f58cda3ec205
I0524 12:34:59.520063 16358 krpc.go:88] newQuery for e3f0aad9b5ad124e4bb8785461e872c3b838ed8d, lastID 2
I0524 12:34:59.520129 16358 krpc.go:91] ... new id 3
I0524 12:34:59.520184 16358 dht.go:576] DHT sending get_peers. nodeID: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d@127.0.0.1:52999, InfoHash: b462c0a8bcef1ce5bb56b9fdb8cf37ffd02f5f59 , distance: 57926a7109420eabf0eec1a9d927453c6817b2d4
I0524 12:34:59.520746 16358 dht.go:665] DHT get_peers. Host: 127.0.0.1:52999 , nodeID: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d , InfoHash: b462c0a8bcef1ce5bb56b9fdb8cf37ffd02f5f59 , distance to me: 3bd0667894ef9f4a2c4c48b91e90f58cda3ec205
I0524 12:34:59.520922 16358 dht.go:702] replyGetPeers: Nodes only. Giving 3
I0524 12:34:59.521376 16358 dht.go:665] DHT get_peers. Host: 127.0.0.1:52999 , nodeID: e3f0aad9b5ad124e4bb8785461e872c3b838ed8d , InfoHash: b462c0a8bcef1ce5bb56b9fdb8cf37ffd02f5f59 , distance to me: 57926a7109420eabf0eec1a9d927453c6817b2d4
I0524 12:34:59.521530 16358 dht.go:702] replyGetPeers: Nodes only. Giving 3
--- PASS: TestDHTLocal (13.00 seconds)
    dht_test.go:133: drainResult n2: drainResult timed out
    dht_test.go:136: drainResult n3: drainResult timed out
PASS

Highlighting the problem: dht.go:702] replyGetPeers: Nodes only. Giving 3

This should be finding peers.

nictuku commented 10 years ago

e4d71ed4786260b1f8d6a3a11d77c5b8e28a0269 was identified and fixed after a long debugging session, all thanks to this test.

It appears to work every time now, except that it has an effective pause of 15 seconds which is the node retry interval enforcement.

I could potentially make the searchRetryPeriod a number that changes according to the number of known reachable nodes. (it's currently 15s). Opening a separate issue for that now.