search

storj-archived / core

Deprecated. Implementation of the Storj v2 protocol for Node.js.
https://storj.io
Other
395 stars 88 forks source link

Network rejoin triggered every 10 minutes #646

Closed littleskunk closed 7 years ago

littleskunk commented 7 years ago

Package Versions

Replace the values below using the output from npm list storj. Use npm list -g storj if installed globally.

root@storj:~# storjshare --version
  * daemon: 2.3.0, core: 6.1.2, protocol: 1.1.0

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

v6.9.5

Expected Behavior

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

Rejoin the network in case of no incoming traffic.

Actual Behavior

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

I am sending OFFER and 2 seconds later the rejoin is triggered. In fact the rejoin is triggered every 10 minutes even if I get new shards.

{"level":"info","message":"sending OFFER message to {\"userAgent\":\"6.0.15\",\"protocol\":\"1.1.0\",\"hdKey\":\"xpub6AHweYHAxk1EhJSBctQD1nLWPog6Sy2eTpKQLExR1hfzTyyZQWvU4EYNXv1NJN7GpLYXnDLt4PzN874g6zSjAQdFCHZN7U7nbYKYVDUzD42\",\"hdIndex\":7682218,\"address\":\"104.196.195.61\",\"port\":8448,\"nodeID\":\"144d1265baf0908fe6c6bd272c701aac7811e3e4\",\"lastSeen\":1486483380280}","timestamp":"2017-02-07T16:03:00.280Z"}
{"level":"debug","message":"queuing callback for reponse to 8bdbea598fb9d0926218078f5fdaf0cb0e95b479","timestamp":"2017-02-07T16:03:00.319Z"}
{"level":"info","message":"received valid message from {\"userAgent\":\"6.0.15\",\"protocol\":\"1.1.0\",\"hdKey\":\"xpub6AHweYHAxk1EhJSBctQD1nLWPog6Sy2eTpKQLExR1hfzTyyZQWvU4EYNXv1NJN7GpLYXnDLt4PzN874g6zSjAQdFCHZN7U7nbYKYVDUzD42\",\"hdIndex\":7682218,\"address\":\"104.196.195.61\",\"port\":8448,\"nodeID\":\"144d1265baf0908fe6c6bd272c701aac7811e3e4\",\"lastSeen\":1486483380686}","timestamp":"2017-02-07T16:03:00.686Z"}
{"level":"debug","message":"updating contact {\"userAgent\":\"6.0.15\",\"protocol\":\"1.1.0\",\"hdKey\":\"xpub6AHweYHAxk1EhJSBctQD1nLWPog6Sy2eTpKQLExR1hfzTyyZQWvU4EYNXv1NJN7GpLYXnDLt4PzN874g6zSjAQdFCHZN7U7nbYKYVDUzD42\",\"hdIndex\":7682218,\"address\":\"104.196.195.61\",\"port\":8448,\"nodeID\":\"144d1265baf0908fe6c6bd272c701aac7811e3e4\",\"lastSeen\":1486483380686}","timestamp":"2017-02-07T16:03:00.686Z"}
{"level":"debug","message":"contact already in bucket, moving to tail","timestamp":"2017-02-07T16:03:00.686Z"}
{"level":"debug","message":"checking pending rpc callback stack for 8bdbea598fb9d0926218078f5fdaf0cb0e95b479","timestamp":"2017-02-07T16:03:00.688Z"}
{"level":"info","message":"received valid message from {\"userAgent\":\"6.0.15\",\"protocol\":\"1.1.0\",\"hdKey\":\"xpub6AHweYHAxk1EhJSBctQD1nLWPog6Sy2eTpKQLExR1hfzTyyZQWvU4EYNXv1NJN7GpLYXnDLt4PzN874g6zSjAQdFCHZN7U7nbYKYVDUzD42\",\"hdIndex\":6784741,\"address\":\"104.196.24.30\",\"port\":8446,\"nodeID\":\"184e85f159c8b616b39e4b9bb9fbbfeeb76ef659\",\"lastSeen\":1486483381335}","timestamp":"2017-02-07T16:03:01.335Z"}
{"level":"debug","message":"updating contact {\"userAgent\":\"6.0.15\",\"protocol\":\"1.1.0\",\"hdKey\":\"xpub6AHweYHAxk1EhJSBctQD1nLWPog6Sy2eTpKQLExR1hfzTyyZQWvU4EYNXv1NJN7GpLYXnDLt4PzN874g6zSjAQdFCHZN7U7nbYKYVDUzD42\",\"hdIndex\":6784741,\"address\":\"104.196.24.30\",\"port\":8446,\"nodeID\":\"184e85f159c8b616b39e4b9bb9fbbfeeb76ef659\",\"lastSeen\":1486483381335}","timestamp":"2017-02-07T16:03:01.335Z"}
{"level":"debug","message":"contact already in bucket, moving to tail","timestamp":"2017-02-07T16:03:01.335Z"}
{"level":"debug","message":"checking pending rpc callback stack for b8e26c2744e03c98651a3a261afdbaa70fcdadb3","timestamp":"2017-02-07T16:03:01.336Z"}
{"level":"debug","message":"checking pending rpc callbacks for expirations","timestamp":"2017-02-07T16:03:02.066Z"}
{"level":"warn","message":"rpc call fd33aa11b548f392b77d5337815c31367dc399d5 timed out","timestamp":"2017-02-07T16:03:02.066Z"}
{"level":"debug","message":"removing contact {\"userAgent\":\"6.1.2\",\"protocol\":\"1.1.0\",\"address\":\"193.107.107.124\",\"port\":34433,\"nodeID\":\"18a8cd73428488af01381d2b2c8cc57aa5ec1bc4\",\"lastSeen\":1486483364943}","timestamp":"2017-02-07T16:03:02.066Z"}
{"level":"info","message":"replying to message to 85dea9fa763031ebcf6caa7bea8f1d0c7059f92a","timestamp":"2017-02-07T16:03:02.066Z"}
{"level":"debug","message":"not waiting on callback for message 85dea9fa763031ebcf6caa7bea8f1d0c7059f92a","timestamp":"2017-02-07T16:03:02.106Z"}
{"level":"info","message":"received valid message from {\"userAgent\":\"6.1.2\",\"protocol\":\"1.1.0\",\"address\":\"193.107.107.124\",\"port\":34433,\"nodeID\":\"18a8cd73428488af01381d2b2c8cc57aa5ec1bc4\",\"lastSeen\":1486483382112}","timestamp":"2017-02-07T16:03:02.112Z"}
{"level":"debug","message":"updating contact {\"userAgent\":\"6.1.2\",\"protocol\":\"1.1.0\",\"address\":\"193.107.107.124\",\"port\":34433,\"nodeID\":\"18a8cd73428488af01381d2b2c8cc57aa5ec1bc4\",\"lastSeen\":1486483382112}","timestamp":"2017-02-07T16:03:02.112Z"}
{"level":"debug","message":"contact not in bucket, moving to head","timestamp":"2017-02-07T16:03:02.112Z"}
{"level":"debug","message":"checking pending rpc callback stack for fd33aa11b548f392b77d5337815c31367dc399d5","timestamp":"2017-02-07T16:03:02.114Z"}
{"level":"warn","message":"dropping received late response to fd33aa11b548f392b77d5337815c31367dc399d5","timestamp":"2017-02-07T16:03:02.114Z"}
{"level":"info","message":"attempting to join network via storj://163.172.80.93:5050/19cf28fed785407fc3481d78c44fe07a158c25a8","timestamp":"2017-02-07T16:03:02.487Z"}
{"level":"debug","message":"entering overlay network via {\"userAgent\":\"6.1.2\",\"protocol\":\"1.1.0\",\"address\":\"163.172.80.93\",\"port\":5050,\"nodeID\":\"19cf28fed785407fc3481d78c44fe07a158c25a8\",\"lastSeen\":1486483382488}","timestamp":"2017-02-07T16:03:02.488Z"}

{"level":"info","message":"attempting to join network via storj://163.172.80.93:5050/19cf28fed785407fc3481d78c44fe07a158c25a8","timestamp":"2017-02-07T03:01:02.085Z"}
{"level":"debug","message":"Shard upload completed","timestamp":"2017-02-07T03:11:16.470Z"}
{"level":"info","message":"attempting to join network via storj://163.172.80.93:5050/19cf28fed785407fc3481d78c44fe07a158c25a8","timestamp":"2017-02-07T03:11:29.719Z"}
{"level":"debug","message":"Shard download completed","timestamp":"2017-02-07T03:11:31.636Z"}
{"level":"debug","message":"Shard download completed","timestamp":"2017-02-07T03:11:35.403Z"}
{"level":"debug","message":"Shard download completed","timestamp":"2017-02-07T03:11:52.584Z"}
{"level":"debug","message":"Shard download completed","timestamp":"2017-02-07T03:11:57.289Z"}
{"level":"info","message":"attempting to join network via storj://163.172.80.93:5050/19cf28fed785407fc3481d78c44fe07a158c25a8","timestamp":"2017-02-07T03:21:31.976Z"}

Steps to Reproduce

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

  1. Start farming
  2. Grep logfile for Shard\|OFFER\|join
littleskunk commented 7 years ago 
{"level":"info","message":"attempting to join network via storj://104.196.200.16:8460/c8e21d194ff9dcfbd1afee31d661344207b78899","timestamp":"2017-02-14T13:07:45.348Z"}
{"level":"info","message":"sending OFFER message to {\"userAgent\":\"6.0.15\",\"protocol\":\"1.1.0\",\"hdKey\":\"xpub6AHweYHAxk1EhJSBctQD1nLWPog6Sy2eTpKQLExR1hfzTyyZQWvU4EYNXv1NJN7GpLYXnDLt4PzN874g6zSjAQdFCHZN7U7nbYKYVDUzD42\",\"hdIndex\":14237297,\"address\":\"104.196.150.202\",\"port\":8456,\"nodeID\":\"a1ea84dc339533d6c2666b064e03742f8aa199cb\",\"lastSeen\":1487078049474}","timestamp":"2017-02-14T13:14:09.474Z"}
{"level":"info","message":"attempting to join network via storj://w.storj.eu:8169/7c1e83c83c8aaf8447d76a865d7f4d03d3d5665f","timestamp":"2017-02-14T13:18:20.275Z"}
root@storj:~# npm list -g storj-lib
/usr/local/lib
├─┬ storj-cli@4.0.0
│ └── storj-lib@6.1.3
└─┬ storjshare-daemon@2.4.1
  └── storj-lib@6.1.3
tacticalchihuahua commented 7 years ago

Why is this reopened? The log you posted looks right. The reentry timeout resets after every received request message. There is a ~10min gap between those two reentry logs and no log in between for "received XXX from XXX".

littleskunk commented 7 years ago

sending OFFER without receiving a contract PUBLISH ist not possible. I receive to many messages to list them all. I focused on OFFER to keep it simple. Let me add the received contract PUBLISH in a minute.

littleskunk commented 7 years ago 
{"level":"info","message":"attempting to join network via storj://104.196.200.16:8460/c8e21d194ff9dcfbd1afee31d661344207b78899","timestamp":"2017-02-14T13:07:45.348Z"}
[...]
{"level":"info","message":"received valid message from {\"userAgent\":\"6.0.15\",\"protocol\":\"1.1.0\",\"hdKey\":\"xpub6AHweYHAxk1EhJSBctQD1nLWPog6Sy2eTpKQLExR1hfzTyyZQWvU4EYNXv1NJN7GpLYXnDLt4PzN874g6zSjAQdFCHZN7U7nbYKYVDUzD42\",\"hdIndex\":7443736,\"address\":\"104.196.159.71\",\"port\":8466,\"nodeID\":\"2097c9957fb556f5f55442cc5e48f66cba13c363\",\"lastSeen\":1487078048009}","timestamp":"2017-02-14T13:14:08.009Z"}
{"level":"debug","message":"updating contact {\"userAgent\":\"6.0.15\",\"protocol\":\"1.1.0\",\"hdKey\":\"xpub6AHweYHAxk1EhJSBctQD1nLWPog6Sy2eTpKQLExR1hfzTyyZQWvU4EYNXv1NJN7GpLYXnDLt4PzN874g6zSjAQdFCHZN7U7nbYKYVDUzD42\",\"hdIndex\":7443736,\"address\":\"104.196.159.71\",\"port\":8466,\"nodeID\":\"2097c9957fb556f5f55442cc5e48f66cba13c363\",\"lastSeen\":1487078048009}","timestamp":"2017-02-14T13:14:08.009Z"}
{"level":"debug","message":"contact already in bucket, moving to tail","timestamp":"2017-02-14T13:14:08.010Z"}
{"level":"debug","message":"received contract offer...","timestamp":"2017-02-14T13:14:08.012Z"}
{"level":"debug","message":"pending offers 0 is less than concurrency true: 10","timestamp":"2017-02-14T13:14:08.012Z"}
{"level":"debug","message":"renter is whitelisted: true","timestamp":"2017-02-14T13:14:08.012Z"}
{"level":"info","message":"replying to message to f0a1a4890ea6c8a0a12e67d46b3bafce3544f95c","timestamp":"2017-02-14T13:14:08.013Z"}
{"level":"debug","message":"not waiting on callback for message f0a1a4890ea6c8a0a12e67d46b3bafce3544f95c","timestamp":"2017-02-14T13:14:08.080Z"}
{"level":"debug","message":"no storage item available for this shard","timestamp":"2017-02-14T13:14:08.083Z"}
{"level":"debug","message":"negotiator returned: true","timestamp":"2017-02-14T13:14:08.083Z"}
{"level":"debug","message":"we have enough free space: true","timestamp":"2017-02-14T13:14:08.103Z"}
{"level":"debug","message":"searching for nodes close to key a1ea84dc339533d6c2666b064e03742f8aa199cb","timestamp":"2017-02-14T13:14:08.209Z"}
{"level":"debug","message":"performing network walk for NODE a1ea84dc339533d6c2666b064e03742f8aa199cb","timestamp":"2017-02-14T13:14:08.210Z"}
{"level":"debug","message":"starting contact iteration for key a1ea84dc339533d6c2666b064e03742f8aa199cb","timestamp":"2017-02-14T13:14:08.210Z"}
{"level":"debug","message":"querying a2b37031ee192990231405f8c8838ae40f40b39c for key a1ea84dc339533d6c2666b064e03742f8aa199cb","timestamp":"2017-02-14T13:14:08.210Z"}
{"level":"info","message":"sending FIND_NODE message to {\"userAgent\":\"6.0.15\",\"protocol\":\"1.1.0\",\"hdKey\":\"xpub6AHweYHAxk1EhJSBctQD1nLWPog6Sy2eTpKQLExR1hfzTyyZQWvU4EYNXv1NJN7GpLYXnDLt4PzN874g6zSjAQdFCHZN7U7nbYKYVDUzD42\",\"hdIndex\":16105479,\"address\":\"104.196.106.231\",\"port\":8470,\"nodeID\":\"a2b37031ee192990231405f8c8838ae40f40b39c\",\"lastSeen\":1487078048210}","timestamp":"2017-02-14T13:14:08.210Z"}
{"level":"debug","message":"queuing callback for reponse to 5c3c552aa71fcd6802f5c971bb2b5d23f2bda259","timestamp":"2017-02-14T13:14:08.277Z"}
{"level":"debug","message":"querying a5b1fc21551f7698c4624f137f2b549f3ad3938c for key a1ea84dc339533d6c2666b064e03742f8aa199cb","timestamp":"2017-02-14T13:14:08.284Z"}
{"level":"info","message":"sending FIND_NODE message to {\"userAgent\":\"6.1.3\",\"protocol\":\"1.1.0\",\"address\":\"a.storj.eu\",\"port\":46016,\"nodeID\":\"a5b1fc21551f7698c4624f137f2b549f3ad3938c\",\"lastSeen\":1487078048284}","timestamp":"2017-02-14T13:14:08.284Z"}
{"level":"debug","message":"queuing callback for reponse to 741925088e42c6dce31864ffe1f0b2b3e39c60db","timestamp":"2017-02-14T13:14:08.351Z"}
{"level":"debug","message":"querying a872385ac7d0a4d9c46d7dda4709d41ba114d07d for key a1ea84dc339533d6c2666b064e03742f8aa199cb","timestamp":"2017-02-14T13:14:08.358Z"}
{"level":"info","message":"sending FIND_NODE message to {\"userAgent\":\"6.0.12\",\"protocol\":\"1.0.0\",\"address\":\"216.221.84.173\",\"port\":4000,\"nodeID\":\"a872385ac7d0a4d9c46d7dda4709d41ba114d07d\",\"lastSeen\":1487078048358}","timestamp":"2017-02-14T13:14:08.358Z"}
{"level":"debug","message":"queuing callback for reponse to a0b278c5b12c8437745ebafc3b72db4b783561b4","timestamp":"2017-02-14T13:14:08.426Z"}
[...]
{"level":"debug","message":"Sending offer for contract","timestamp":"2017-02-14T13:14:09.474Z"}
{"level":"info","message":"sending OFFER message to {\"userAgent\":\"6.0.15\",\"protocol\":\"1.1.0\",\"hdKey\":\"xpub6AHweYHAxk1EhJSBctQD1nLWPog6Sy2eTpKQLExR1hfzTyyZQWvU4EYNXv1NJN7GpLYXnDLt4PzN874g6zSjAQdFCHZN7U7nbYKYVDUzD42\",\"hdIndex\":14237297,\"address\":\"104.196.150.202\",\"port\":8456,\"nodeID\":\"a1ea84dc339533d6c2666b064e03742f8aa199cb\",\"lastSeen\":1487078049474}","timestamp":"2017-02-14T13:14:09.474Z"}
[...]
{"level":"info","message":"attempting to join network via storj://w.storj.eu:8169/7c1e83c83c8aaf8447d76a865d7f4d03d3d5665f","timestamp":"2017-02-14T13:18:20.275Z"}
braydonf commented 7 years ago

Grepping through debug with: pm2 log farmer-1 | grep 'join\|received' does produce join messages that are oddly consistent with the times. Running a few test farmers with decreased reentry time to 1 min and started 30 seconds apart and with https://github.com/Storj/core/pull/651 seemed to produce expected results, though the extra clearInterval seems unnecessary, perhaps a timeout is not referenced.