Skip to content
This repository has been archived by the owner on Oct 30, 2018. It is now read-only.

to many SUBSCRIBE messages #204

Closed
littleskunk opened this issue Jun 22, 2016 · 8 comments
Closed

to many SUBSCRIBE messages #204

littleskunk opened this issue Jun 22, 2016 · 8 comments
Labels
discussion

Comments

@littleskunk
Copy link
Collaborator

littleskunk commented Jun 22, 2016 •
edited by tacticalchihuahua
Loading

Package Versions

Replace the values below using the output from npm list storj.

C:\Users\Laptop\AppData\Roaming\npm
└─┬ storjshare-cli@4.0.4
 └─┬ storj@1.3.0
   └── kad@1.5.15

Replace the values below using the output from node --version.

v4.4.5

Expected Behavior

Please describe the program's expected behavior. Include an example of your
usage code in the back ticks below if applicable.

I would expect 3 second delay beween each SUBSCRIBE message.

Actual Behavior

Please describe the program's actual behavior. Please include any stack traces
or log output in the back ticks below.

The node is sending to many SUBSCRIBE messages at the same time. At the end all messages timed out and the node is not able to connect to the network. Lets go on with the next seed and the same problem. Here is an example:
cat logfile | grep '24.23.171.239'

{"level":"info","message":"attempting to join network via storj://24.23.171.239:4000/4c25796a816b2cb9ed62854314f21df6788bb384","timestamp":"2016-06-22T10:56:
43.748Z"}
{"level":"debug","message":"entering overlay network via {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed6
2854314f21df6788bb384\",\"lastSeen\":1466593003752}","timestamp":"2016-06-22T10:56:43.753Z"}
{"level":"debug","message":"updating contact {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62854314f21df
6788bb384\",\"lastSeen\":1466593003752}","timestamp":"2016-06-22T10:56:43.757Z"}
{"level":"info","message":"sending FIND_NODE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593003766}","timestamp":"2016-06-22T10:56:43.766Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593013809}","timestamp":"2016-06-22T10:56:53.809Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593013887}","timestamp":"2016-06-22T10:56:53.887Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593013958}","timestamp":"2016-06-22T10:56:53.958Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593018882}","timestamp":"2016-06-22T10:56:58.882Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593018947}","timestamp":"2016-06-22T10:56:58.947Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593019049}","timestamp":"2016-06-22T10:56:59.049Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593019131}","timestamp":"2016-06-22T10:56:59.131Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593019197}","timestamp":"2016-06-22T10:56:59.197Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593019267}","timestamp":"2016-06-22T10:56:59.267Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593019346}","timestamp":"2016-06-22T10:56:59.346Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593019413}","timestamp":"2016-06-22T10:56:59.413Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593019492}","timestamp":"2016-06-22T10:56:59.492Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593019546}","timestamp":"2016-06-22T10:56:59.546Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593019612}","timestamp":"2016-06-22T10:56:59.612Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593019690}","timestamp":"2016-06-22T10:56:59.690Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593019782}","timestamp":"2016-06-22T10:56:59.782Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62
854314f21df6788bb384\",\"lastSeen\":1466593019854}","timestamp":"2016-06-22T10:56:59.854Z"}

Steps to Reproduce

Please include the steps the reproduce the issue, numbered below. Include as
much detail as possible.

  1. Start node with as many opcodes as possible.
@littleskunk
Copy link
Collaborator Author

Workaround: Only the three default opcodes are implemented at the moment. Remove all other opcodes as workaround.

    "opcodes": [
      "0f01020202",
      "0f02020202",
      "0f03020202"
    ],

@tacticalchihuahua
Copy link
Contributor

@littleskunk I can't reproduce this with my config, can you share yours?

{"level":"info","message":"you are configured to tunnel up to 24 connections","timestamp":"2016-06-22T15:20:46.212Z"}
{"level":"info","message":"node created with nodeID cc6d63e3328c104d264068d08f89cf6b29ba95f7","timestamp":"2016-06-22T15:20:46.226Z"}
{"level":"info","message":"resolving seeds from https://api.storj.io","timestamp":"2016-06-22T15:20:46.227Z"}
{"level":"info","message":"attempting to join network via storj://96.241.165.120:4000/059f9ee85790964dd71c5a009b5cbeee01b04aec","timestamp":"2016-06-22T15:20:46.449Z"}
{"level":"info","message":"sending FIND_NODE message to {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608846461}","timestamp":"2016-06-22T15:20:46.461Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608846576}","timestamp":"2016-06-22T15:20:46.576Z"}
{"level":"info","message":"connected to the storj network via storj://96.241.165.120:4000/059f9ee85790964dd71c5a009b5cbeee01b04aec","timestamp":"2016-06-22T15:20:46.683Z"}
{"level":"info","message":"publishing message on topic \"0e01\"","timestamp":"2016-06-22T15:20:46.685Z"}
{"level":"info","message":"sending PUBLISH message to {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608846686}","timestamp":"2016-06-22T15:20:46.686Z"}
{"level":"info","message":"subscribing to topic \"0e01\"","timestamp":"2016-06-22T15:20:46.747Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608846752}","timestamp":"2016-06-22T15:20:46.752Z"}
{"level":"info","message":"subscribing to topic \"0e00\"","timestamp":"2016-06-22T15:20:46.805Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608846806}","timestamp":"2016-06-22T15:20:46.806Z"}
{"level":"info","message":"subscribing to topic \"0f01020202\"","timestamp":"2016-06-22T15:20:46.822Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608846823}","timestamp":"2016-06-22T15:20:46.823Z"}
{"level":"info","message":"sending FIND_NODE message to {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608846865}","timestamp":"2016-06-22T15:20:46.865Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608846905}","timestamp":"2016-06-22T15:20:46.905Z"}
{"level":"info","message":"merging neighbor's bloom filter with our own","timestamp":"2016-06-22T15:20:46.955Z"}
{"level":"info","message":"sending UPDATE message to {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608846956}","timestamp":"2016-06-22T15:20:46.956Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608846981}","timestamp":"2016-06-22T15:20:46.982Z"}
{"level":"info","message":"merging neighbor's bloom filter with our own","timestamp":"2016-06-22T15:20:47.033Z"}
{"level":"info","message":"sending UPDATE message to {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608847034}","timestamp":"2016-06-22T15:20:47.034Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608847052}","timestamp":"2016-06-22T15:20:47.052Z"}
{"level":"info","message":"merging neighbor's bloom filter with our own","timestamp":"2016-06-22T15:20:47.111Z"}
{"level":"info","message":"sending UPDATE message to {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608847112}","timestamp":"2016-06-22T15:20:47.112Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608847144}","timestamp":"2016-06-22T15:20:47.144Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608847192}","timestamp":"2016-06-22T15:20:47.192Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608847323}","timestamp":"2016-06-22T15:20:47.323Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608847369}","timestamp":"2016-06-22T15:20:47.369Z"}
{"level":"info","message":"subscribing to topic \"0f02020202\"","timestamp":"2016-06-22T15:20:49.865Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608849866}","timestamp":"2016-06-22T15:20:49.866Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608850746}","timestamp":"2016-06-22T15:20:50.746Z"}
{"level":"info","message":"merging neighbor's bloom filter with our own","timestamp":"2016-06-22T15:20:50.801Z"}
{"level":"info","message":"sending UPDATE message to {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608850805}","timestamp":"2016-06-22T15:20:50.805Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608850865}","timestamp":"2016-06-22T15:20:50.865Z"}
{"level":"info","message":"subscribing to topic \"0f03020202\"","timestamp":"2016-06-22T15:20:52.940Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608852941}","timestamp":"2016-06-22T15:20:52.941Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608853019}","timestamp":"2016-06-22T15:20:53.019Z"}
{"level":"info","message":"merging neighbor's bloom filter with our own","timestamp":"2016-06-22T15:20:53.055Z"}
{"level":"info","message":"sending UPDATE message to {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608853056}","timestamp":"2016-06-22T15:20:53.056Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.7.0\",\"address\":\"96.241.165.120\",\"port\":4000,\"nodeID\":\"059f9ee85790964dd71c5a009b5cbeee01b04aec\",\"lastSeen\":1466608853109}","timestamp":"2016-06-22T15:20:53.109Z"}

@tacticalchihuahua tacticalchihuahua self-assigned this Jun 22, 2016
@matanbr
Copy link

matanbr commented Jun 22, 2016 •
edited
Loading

{ "keypath": "d:\\storjsharePrivateKEY", "address": "13qwHvDnyKXAh3HxoA4mteMszrFi11rDiL", "loglevel": 4, "storage": { "path": "d:\\StorjshareCLI", "size": 1000, "unit": "GB" }, "network": { "address": "***", "port": 5000, "seeds": [ ], "opcodes": [ "0f01020202", "0f02020202", "0f03020202" ], "forward": false, "tunnels": 3, "tunnelport": 5005, "gateways": { "min": 5011, "max": 5015 } }, "telemetry": { "service": "https://status.storj.io", "enabled": true } }

C:\>npm version { npm: '2.15.1', ares: '1.10.1-DEV', http_parser: '2.5.2', icu: '56.1', modules: '46', node: '4.4.4', openssl: '1.0.2h', uv: '1.8.0', v8: '4.5.103.35', zlib: '1.2.8' }

@littleskunk
Copy link
Collaborator Author

littleskunk commented Jun 22, 2016 •
edited
Loading

Looks like the SUBSCRIBE messages are triggered by incoming received messages.

{"level":"info","message":"sending FIND_NODE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62854314f21df6788bb384\",\"lastSeen\":1466593003766}","timestamp":"2016-06-22T10:56:43.766Z"}
{"level":"debug","message":"queuing callback for reponse to 6cebe5d9f7a9619f30a79c56911f80c3de809eef","timestamp":"2016-06-22T10:56:43.874Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.7.0\",\"address\":\"138.201.13.159\",\"port\":4323,\"nodeID\":\"364d0f5a80baa1d9668befa66f1b712761657ce7\",\"lastSeen\":1466593013687}","timestamp":"2016-06-22T10:56:53.688Z"}
{"level":"debug","message":"updating contact {\"protocol\":\"0.7.0\",\"address\":\"138.201.13.159\",\"port\":4323,\"nodeID\":\"364d0f5a80baa1d9668befa66f1b712761657ce7\",\"lastSeen\":1466593013687}","timestamp":"2016-06-22T10:56:53.688Z"}
{"level":"debug","message":"creating new bucket for contact at index 156","timestamp":"2016-06-22T10:56:53.688Z"}
{"level":"debug","message":"contact not in bucket, moving to head","timestamp":"2016-06-22T10:56:53.688Z"}
{"level":"info","message":"replying to message to 521552fa69b6ad4c301d455efd148f1de534b600","timestamp":"2016-06-22T10:56:53.691Z"}
{"level":"debug","message":"not waiting on callback for message 521552fa69b6ad4c301d455efd148f1de534b600","timestamp":"2016-06-22T10:56:53.763Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"138.201.13.159\",\"port\":4323,\"nodeID\":\"364d0f5a80baa1d9668befa66f1b712761657ce7\",\"lastSeen\":1466593013767}","timestamp":"2016-06-22T10:56:53.767Z"}
{"level":"debug","message":"queuing callback for reponse to 39f7447a9fc2ae1e2d0fdc6a24a398ca9a795cd3","timestamp":"2016-06-22T10:56:53.807Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62854314f21df6788bb384\",\"lastSeen\":1466593013809}","timestamp":"2016-06-22T10:56:53.809Z"}
{"level":"debug","message":"queuing callback for reponse to 4d6bd69adbd912d7672a90ceeaa2773a006c5d07","timestamp":"2016-06-22T10:56:53.845Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.7.0\",\"address\":\"138.201.13.159\",\"port\":4323,\"nodeID\":\"364d0f5a80baa1d9668befa66f1b712761657ce7\",\"lastSeen\":1466593013848}","timestamp":"2016-06-22T10:56:53.848Z"}
{"level":"debug","message":"updating contact {\"protocol\":\"0.7.0\",\"address\":\"138.201.13.159\",\"port\":4323,\"nodeID\":\"364d0f5a80baa1d9668befa66f1b712761657ce7\",\"lastSeen\":1466593013848}","timestamp":"2016-06-22T10:56:53.848Z"}
{"level":"debug","message":"contact already in bucket, moving to tail","timestamp":"2016-06-22T10:56:53.848Z"}
{"level":"info","message":"replying to message to db9e42a3d9138184365ac641b3d34832f9aafd55","timestamp":"2016-06-22T10:56:53.850Z"}
{"level":"debug","message":"not waiting on callback for message db9e42a3d9138184365ac641b3d34832f9aafd55","timestamp":"2016-06-22T10:56:53.869Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"138.201.13.159\",\"port\":4323,\"nodeID\":\"364d0f5a80baa1d9668befa66f1b712761657ce7\",\"lastSeen\":1466593013870}","timestamp":"2016-06-22T10:56:53.870Z"}
{"level":"debug","message":"queuing callback for reponse to 277e5a6acd43c1c46707b7199d85d5e10a06323f","timestamp":"2016-06-22T10:56:53.887Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62854314f21df6788bb384\",\"lastSeen\":1466593013887}","timestamp":"2016-06-22T10:56:53.887Z"}
{"level":"debug","message":"queuing callback for reponse to ebaefe441b09f7c734a3ac64063a78f58af6c8ab","timestamp":"2016-06-22T10:56:53.905Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.7.0\",\"address\":\"138.201.13.159\",\"port\":4323,\"nodeID\":\"364d0f5a80baa1d9668befa66f1b712761657ce7\",\"lastSeen\":1466593013907}","timestamp":"2016-06-22T10:56:53.907Z"}
{"level":"debug","message":"updating contact {\"protocol\":\"0.7.0\",\"address\":\"138.201.13.159\",\"port\":4323,\"nodeID\":\"364d0f5a80baa1d9668befa66f1b712761657ce7\",\"lastSeen\":1466593013907}","timestamp":"2016-06-22T10:56:53.907Z"}
{"level":"debug","message":"contact already in bucket, moving to tail","timestamp":"2016-06-22T10:56:53.907Z"}
{"level":"info","message":"replying to message to 5573265926c7d70f05dc6ab6572f70b31a23bef0","timestamp":"2016-06-22T10:56:53.908Z"}
{"level":"debug","message":"not waiting on callback for message 5573265926c7d70f05dc6ab6572f70b31a23bef0","timestamp":"2016-06-22T10:56:53.925Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"138.201.13.159\",\"port\":4323,\"nodeID\":\"364d0f5a80baa1d9668befa66f1b712761657ce7\",\"lastSeen\":1466593013926}","timestamp":"2016-06-22T10:56:53.926Z"}
{"level":"debug","message":"queuing callback for reponse to 84cc29d61a256f348c46ecde9570dff3735b021f","timestamp":"2016-06-22T10:56:53.958Z"}
{"level":"info","message":"sending SUBSCRIBE message to {\"protocol\":\"0.7.0\",\"address\":\"24.23.171.239\",\"port\":4000,\"nodeID\":\"4c25796a816b2cb9ed62854314f21df6788bb384\",\"lastSeen\":1466593013958}","timestamp":"2016-06-22T10:56:53.958Z"}
{"level":"debug","message":"queuing callback for reponse to a803d82bbbd01807a88a856f8d23203d96620e12","timestamp":"2016-06-22T10:56:53.981Z"}

That would mean my workaround is not correct. @matanbr can you stop your node for 10 minutes. Everyone should get timeouts and remove your node from the shortlist. Than start your node again and a new logfile for me please.

@littleskunk
Copy link
Collaborator Author

@bookchin confirmed with my own config. I restarted my node very quick. While I am sending my FIND_NODE to get a connection every incoming message will trigger SUBSCRIBE messages. 58 SUBSCRIBE messages

Second test: Stoped my node for a few minutes and start again. This time everything as expected. 5 SUBSCRIBE messages.

@tacticalchihuahua
Copy link
Contributor

Okay I think I tracked it down in kad-quasar. Basically, what happens when you receive a publish message, if you aren't subscribed to it then you relay it to your neighbors who are interested. In order to determine which neighbors are interested you request their bloom filters by sending a subscribe message to them before relaying the publication.

This would explain why the quick restart yielded the error and the other did not. A quick restart won't cause nodes to drop you, so when you start back up, you are receiving publications from the network before you have had a chance to subscribe to them, thus causing the mass relay.

Waiting a few minutes may cause nodes to drop you and a later restart will be much cleaner giving you time to subscribe to the configured opcodes and preventing the blind subscribe/relay loop.

I'm not sure if I'd consider this a bug - it is by design after all. But it does pose an issue in these cases. Especially if you have say 20 opcodes and the subscriptions are throttled by 3 seconds. It would take an entire minute for your node to finish the subscriptions and in that time you are likely to receive publications that you are not yet subscribed to.

I'm going to label this one discussion as well, so we can figure out the best way to approach this. The subscribe/relay logic is important for efficient publication propagation, but at high volume can cause these types of problems.

Will continue to give it some thought.

@tacticalchihuahua tacticalchihuahua removed their assignment Jun 22, 2016
@littleskunk
Copy link
Collaborator Author

At the end his system clock was out of sync. That was the reason he was not able to connect.
#206

@super3 super3 closed this as completed Jul 22, 2016
@littleskunk littleskunk mentioned this issue Aug 2, 2016
Closed
@littleskunk
Copy link
Collaborator Author

Duplicate #257

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
discussion
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@super3 @tacticalchihuahua @littleskunk @matanbr