Closed littleskunk closed 8 years ago
Wow, this does not look like an accident. Seems like this would only happen if a node close to you was spitting out contract publications signed by a renter keypair that is not on the network, causing you to perform a bunch of lookups for the renter, never to find her.
I wonder if someone is testing some attack vectors and intentionally causing other nodes (you) to spam FIND_NODEs to everyone.
This might also be related to @subwolf's connection count issues is some some way. Maybe we should implement some kind of rate limiter where we only try to negotiate n
contracts at a time or within a given timespan. That paired with some detection of misbehavior and automatic blacklisting may mitigate this type of issue.
This might also be related to #103, if these contracts are in fact coming from a node that is not our bridge it would explain the expire time discrepancy.
The "bad" node could be the bridge itself. storj://api.storj.io:8443/78cfca0e01235db817728aec056d007672ffac63
is "offline" because the answer comes from a different nodeid.
{"level":"info","message":"sending FIND_NODE message to {\"protocol\":\"0.6.15\",\"address\":\"api.storj.io\",\"port\":8443,\"nodeID\":\"78cfca0e01235db817728aec056d007672ffac63\",\"lastSeen\":1463852983694}","timestamp":"2016-05-21T17:49:43.695Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"104.196.56.59\",\"port\":8443,\"nodeID\":\"593844dc7f0076a1aeda9a6b9788af17e67c1052\",\"lastSeen\":1463852984289}","timestamp":"2016-05-21T17:49:44.289Z"}
Which nodeid has the bridge? I assume the new nodeid and nobody is able to contact that nodeid.
The reason for the different nodeID is due to there being two bridge nodes behind a load balancer. I'm not sure what the implication of this is. @phutchins, I think that both bridge nodes should be using the same private key, otherwise things might get weird since they share the same contract database.
@gordonwritescode I confirmed that both production API nodes behind the API Proxy Loadbalancer are using the same privatekey.
Well then the nodeID in the response is the correct one, @littleskunk. Didn't we recently update the default seed?
We did, where did we get that first nodeID from??
I updated the nodeID with the new one mentioned here: https://github.com/Storj/core/issues/95#issuecomment-219101074
root@subwolf-nas:~/.pm2/logs# grep "Could not locate renter for offer" farmer-out-0.log | grep '2016-05-20' | wc -l
31777
Average of 22 per minute. I see them in the log in batches, anywhere from 2 to 20 in one second. See this excerpt from that search:
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:31.204Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:31.204Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:31.205Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:31.270Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:31.271Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:31.271Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:31.272Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:31.766Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:31.971Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:31.972Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:31.972Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:31.973Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:32.072Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:32.072Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:32.073Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:32.074Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:32.074Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:32.075Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:32.075Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:32.141Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.407Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.408Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.408Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.409Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.410Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.410Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.411Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.412Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.412Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.413Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.414Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.414Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.415Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.416Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.416Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.417Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.418Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.418Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.419Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.455Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.456Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.456Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.457Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:00:44.457Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:05:48.058Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:20.608Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:20.610Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:20.611Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:20.612Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:20.614Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:20.615Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.284Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.285Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.287Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.288Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.290Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.291Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.292Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.294Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.295Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.297Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.298Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.335Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.335Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.336Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.337Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.403Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.404Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:06:36.404Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:03.637Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:03.784Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:05.056Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:08.034Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:11.472Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:11.472Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:13.932Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:16.686Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:18.620Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:22.019Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:22.187Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:30.475Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:32.379Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:39.406Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:39.481Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:39.628Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:39.702Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:40.204Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:40.277Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:40.351Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:41.107Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:41.182Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:45.611Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:45.611Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:45.612Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:56.491Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:07:56.492Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:08:31.368Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:08:31.369Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:08:31.369Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:08:40.127Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:08:40.203Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:08:43.687Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:08:44.270Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:08:44.345Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:08:45.669Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:08:45.818Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:08:45.969Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:08:46.044Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:08:48.259Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:08:49.529Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:08:50.821Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:08:52.287Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:08:55.233Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:02.640Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:02.713Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:02.861Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:02.934Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:04.022Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:04.167Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:06.544Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:06.545Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:06.546Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:27.208Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:49.585Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:50.268Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:52.660Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:59.368Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:59.369Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:59.370Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:59.407Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:09:59.443Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-20T00:10:02.111Z"}
Could not locate renterID 02d7885d60ee045907e51d3a1e5a5f2a7845d2e5 but I am receiving messages from that renter and I have all information I need. I never send any messages myself to that node.
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"server016.storj.dk\",\"port\":5016,\"nodeID\":\"02d7885d60ee045907e51d3a1e5a5f2a7845d2e5\",\"lastSeen\":1463906966473}","timestamp":"2016-05-22T08:49:26.473Z"}
Maybe this issue is the reason: https://github.com/kadtools/kad/issues/56
I think this calls for a explanation, since it looks like I'm part of this issue.
Storj.dk nodeID's : server012.storj.dk - c0792c4c2dcac1582a6d01c93d1d366c5321d94e server013.storj.dk - 869025a2c19c667adc13741ac7473b7908243949 server014.storj.dk - 52b49d39eee0e179374c6747746ad699f01a1ce2 server015.storj.dk - 0ffa306be0afaa347e0ecd21920c4415dc535f8a server016.storj.dk - 02d7885d60ee045907e51d3a1e5a5f2a7845d2e5 server017.storj.dk - 4e87fb4dadd9cdb672d7b1cadc864985639daaf6 server018.storj.dk - 1495a38adfec7117a2dc84135be8ea9612841a86 server019.storj.dk - bf55923a1b662436f3cb20c5ab1a9a2c48cb21e1 server020.storj.dk - c22b9d7cbd82924e031197ebf806ae26a0237e9d server021.storj.dk - cf5a9c4aa7a72ecb57cf3cb15244d1b18d5fad87
I've taken down the bridge and storjcli sw on all ten storj.dk servers @2016-05-22T12:11:09.305(CET), since i don't want people to believe that I'm attacking the storj network regarding the contract/keypair. (actually, it's just the opposite :) Basically, my intension was to send out test contract/shards to the storj network, since there wasn't that many being served from the original api servers (78c..c63 and 593..052), and people was getting a little frustrated waiting weeks for a single shard, and was starting to doubt that their driveshare / storjshare-gui/cli was even working at all. So, I figured that since TGC has not started yet, i could help people in getting hards, and confirm that driveshare / storjshare-gui/cli was working properly. I set up a bunch of storj.dk servers with the storjcli client and started sending out shards, but I quickly realized that the api servers could not handle the rate i was able to "spit" out shards, so i installed the bridge sw on all ten storj.dk servers (each with 8 cores and 16GB of mem) so everything is done "inhouse", and this seems to be working much better and it could handle the shards rate. All ten server has been running for a few weeks now and people has reported on slack, that they are getting more shards, but since this issue was created I guess I must have miss-configured my storj.dk servers and therefor I'm not serving shards anymore (at least not until someone from the storj dev team is having a say about it). @gordonwritescode , @phutchins or @littleskunk , if you like, i can give you root accces to all of the storj.dk servers, if you guys would like to investigave/help me fix the problem, or even delete the hole damn thing! ;)
Regards, Th3Van storj.dk
Don't worry. You did nothing wrong. My node is in your contact list and you are sending me messages. Everything fine with your node.
The problem is my node doesn't store your contact information and later it is unable to send you OFFER messages.
Thank you for the great support. It helps us finding issues like this one :)
Thank you @littleskunk
Always happy to help :) I'll fire up the bridge nodes again then, and try to collect some statistics, since I'm logging a ton of stuff. My offer still stands, if you or @gordonwritescode / @phutchins or anyone on the dev team, needs to access any the storj.dk servers for testing/investigating/etc., please don't hesitate so PM me.
Regards, Th3Van storj.dk
This is good news, it helps us narrow down the issue. @littleskunk, I wonder if you set that server 016 node as your seed, if it will fix the issue for you.
If it does then I'm pretty confident that the issue is in fact with that node not getting added to your routing table due to a bug in kad related to the previously referenced issue here: https://github.com/kadtools/kad/issues/56
I restartet my node with all storj.dk seeds.
At the beginning I get some shards.
{"level":"info","message":"authorizing data channel for cf5a9c4aa7a72ecb57cf3cb15244d1b18d5fad87","timestamp":"2016-05-22T15:10:35.440Z"}
{"level":"info","message":"replying to message to e83d291a0acce4f696d12e851c75ef94fa37d72c","timestamp":"2016-05-22T15:10:35.441Z"}
{"level":"info","message":"authorizing data channel for cf5a9c4aa7a72ecb57cf3cb15244d1b18d5fad87","timestamp":"2016-05-22T15:10:35.561Z"}
{"level":"info","message":"replying to message to 264ab16f1b8672e30808ccded12df89863989ce3","timestamp":"2016-05-22T15:10:35.561Z"}
{"level":"info","message":"authorizing data channel for cf5a9c4aa7a72ecb57cf3cb15244d1b18d5fad87","timestamp":"2016-05-22T15:10:35.627Z"}
{"level":"info","message":"replying to message to 022f4d900f9880887916e7537ec96a60254faeb7","timestamp":"2016-05-22T15:10:35.627Z"}
{"level":"info","message":"authorizing data channel for cf5a9c4aa7a72ecb57cf3cb15244d1b18d5fad87","timestamp":"2016-05-22T15:10:35.692Z"}
{"level":"info","message":"replying to message to 2edec798682a27160f979a68cd17371f5fd4150b","timestamp":"2016-05-22T15:10:35.693Z"}
{"level":"info","message":"authorizing data channel for cf5a9c4aa7a72ecb57cf3cb15244d1b18d5fad87","timestamp":"2016-05-22T15:10:35.814Z"}
{"level":"info","message":"replying to message to 6d2b27f82a9a627c012ac3e408bc017b763684ed","timestamp":"2016-05-22T15:10:35.815Z"}
{"level":"info","message":"authorizing data channel for cf5a9c4aa7a72ecb57cf3cb15244d1b18d5fad87","timestamp":"2016-05-22T15:10:35.937Z"}
{"level":"info","message":"replying to message to a236b8b778234936418b3285399dce8f289b67e1","timestamp":"2016-05-22T15:10:35.938Z"}
I lose connection to some nodes. I don't know which nodes and which query it was.
{"level":"warn","message":"query failed, removing contact for shortlist, reason RPC with ID `78a831419f67effac64d4dfcba21d7bddf52be97` timed out","timestamp":"2016-05-22T15:10:44.615Z"}
{"level":"error","message":"bf55923a1b662436f3cb20c5ab1a9a2c48cb21e1","timestamp":"2016-05-22T15:10:44.615Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-22T15:10:44.615Z"}
{"level":"warn","message":"rpc call 194f9c9952abd64d0bb99c0360475ef70bb0f2d3 timed out","timestamp":"2016-05-22T15:10:44.615Z"}
{"level":"warn","message":"query failed, removing contact for shortlist, reason RPC with ID `194f9c9952abd64d0bb99c0360475ef70bb0f2d3` timed out","timestamp":"2016-05-22T15:10:44.615Z"}
{"level":"error","message":"bf55923a1b662436f3cb20c5ab1a9a2c48cb21e1","timestamp":"2016-05-22T15:10:44.616Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-22T15:10:44.616Z"}
{"level":"warn","message":"rpc call 93e02426520290a856452a81d9608ae3e7cc3232 timed out","timestamp":"2016-05-22T15:10:44.616Z"}
{"level":"warn","message":"query failed, removing contact for shortlist, reason RPC with ID `93e02426520290a856452a81d9608ae3e7cc3232` timed out","timestamp":"2016-05-22T15:10:44.616Z"}
{"level":"error","message":"bf55923a1b662436f3cb20c5ab1a9a2c48cb21e1","timestamp":"2016-05-22T15:10:44.616Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-22T15:10:44.616Z"}
{"level":"warn","message":"rpc call 9906ae3408644ca77459a6300eff96008e4e3509 timed out","timestamp":"2016-05-22T15:10:44.616Z"}
{"level":"warn","message":"query failed, removing contact for shortlist, reason RPC with ID `9906ae3408644ca77459a6300eff96008e4e3509` timed out","timestamp":"2016-05-22T15:10:44.616Z"}
{"level":"error","message":"bf55923a1b662436f3cb20c5ab1a9a2c48cb21e1","timestamp":"2016-05-22T15:10:44.616Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-22T15:10:44.617Z"}
{"level":"warn","message":"rpc call 268b0eb1fc189d938066529f7c2ce83ec82f7561 timed out","timestamp":"2016-05-22T15:10:44.617Z"}
{"level":"warn","message":"query failed, removing contact for shortlist, reason RPC with ID `268b0eb1fc189d938066529f7c2ce83ec82f7561` timed out","timestamp":"2016-05-22T15:10:44.617Z"}
{"level":"error","message":"bf55923a1b662436f3cb20c5ab1a9a2c48cb21e1","timestamp":"2016-05-22T15:10:44.617Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-22T15:10:44.617Z"}
{"level":"warn","message":"rpc call bce69f534d4a39b710786e7195c0bf060516469f timed out","timestamp":"2016-05-22T15:10:44.617Z"}
{"level":"warn","message":"query failed, removing contact for shortlist, reason RPC with ID `bce69f534d4a39b710786e7195c0bf060516469f` timed out","timestamp":"2016-05-22T15:10:44.617Z"}
{"level":"error","message":"bf55923a1b662436f3cb20c5ab1a9a2c48cb21e1","timestamp":"2016-05-22T15:10:44.617Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-22T15:10:44.617Z"}
Could not find the renter I was connected to at the beginning.
{"level":"error","message":"cf5a9c4aa7a72ecb57cf3cb15244d1b18d5fad87","timestamp":"2016-05-22T15:48:51.481Z"}
{"level":"error","message":"Could not locate renter for offer","timestamp":"2016-05-22T15:48:51.481Z"}
(Note: I added a quick and dirty debug line for the renterID.)
@littleskunk Looks like I'm getting offers from you now, and you are victorious on some of them :)
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939542504}","timestamp":"2016-05-22T17:52:22.504Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939542794}","timestamp":"2016-05-22T17:52:22.794Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939544583}","timestamp":"2016-05-22T17:52:24.583Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939544802}","timestamp":"2016-05-22T17:52:24.802Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939550762}","timestamp":"2016-05-22T17:52:30.762Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939550837}","timestamp":"2016-05-22T17:52:30.837Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939551489}","timestamp":"2016-05-22T17:52:31.489Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939551564}","timestamp":"2016-05-22T17:52:31.564Z"}
{"level":"info","message":"sending PUBLISH message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939556129}","timestamp":"2016-05-22T17:52:36.129Z"}
{"level":"info","message":"sending PUBLISH message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939556410}","timestamp":"2016-05-22T17:52:36.410Z"}
{"level":"info","message":"sending PUBLISH message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939557363}","timestamp":"2016-05-22T17:52:37.363Z"}
{"level":"info","message":"sending PUBLISH message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939557603}","timestamp":"2016-05-22T17:52:37.603Z"}
{"level":"info","message":"sending PUBLISH message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939557677}","timestamp":"2016-05-22T17:52:37.677Z"}
{"level":"info","message":"sending PUBLISH message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939557876}","timestamp":"2016-05-22T17:52:37.876Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939557958}","timestamp":"2016-05-22T17:52:37.958Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939558116}","timestamp":"2016-05-22T17:52:38.116Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939558240}","timestamp":"2016-05-22T17:52:38.240Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939558365}","timestamp":"2016-05-22T17:52:38.365Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939558611}","timestamp":"2016-05-22T17:52:38.611Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939558755}","timestamp":"2016-05-22T17:52:38.755Z"}
{"level":"info","message":"handling storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:38.778Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939558792}","timestamp":"2016-05-22T17:52:38.792Z"}
{"level":"info","message":"handling storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:38.816Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939563115}","timestamp":"2016-05-22T17:52:43.115Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939566280}","timestamp":"2016-05-22T17:52:46.280Z"}
{"level":"info","message":"handling storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:46.303Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939566414}","timestamp":"2016-05-22T17:52:46.414Z"}
{"level":"info","message":"handling storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:46.441Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939566489}","timestamp":"2016-05-22T17:52:46.489Z"}
{"level":"info","message":"handling storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:46.519Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939566569}","timestamp":"2016-05-22T17:52:46.569Z"}
{"level":"info","message":"handling storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:46.599Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939566652}","timestamp":"2016-05-22T17:52:46.652Z"}
{"level":"info","message":"handling storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:46.693Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939566723}","timestamp":"2016-05-22T17:52:46.723Z"}
{"level":"info","message":"handling storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:46.747Z"}
{"level":"info","message":"accepting storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:46.845Z"}
{"level":"info","message":"accepting storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:46.868Z"}
{"level":"info","message":"accepting storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:46.890Z"}
{"level":"info","message":"accepting storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:46.904Z"}
{"level":"info","message":"accepting storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:46.930Z"}
{"level":"info","message":"accepting storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:46.952Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939567126}","timestamp":"2016-05-22T17:52:47.126Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939567138}","timestamp":"2016-05-22T17:52:47.138Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939567152}","timestamp":"2016-05-22T17:52:47.152Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939567169}","timestamp":"2016-05-22T17:52:47.169Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939567181}","timestamp":"2016-05-22T17:52:47.181Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939567193}","timestamp":"2016-05-22T17:52:47.193Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939569064}","timestamp":"2016-05-22T17:52:49.064Z"}
{"level":"info","message":"handling storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:49.087Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939569100}","timestamp":"2016-05-22T17:52:49.100Z"}
{"level":"info","message":"handling storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:49.124Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939569137}","timestamp":"2016-05-22T17:52:49.137Z"}
{"level":"info","message":"handling storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:49.160Z"}
{"level":"info","message":"accepting storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:49.202Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939569229}","timestamp":"2016-05-22T17:52:49.229Z"}
{"level":"info","message":"received valid message from {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939570236}","timestamp":"2016-05-22T17:52:50.236Z"}
{"level":"info","message":"handling storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:50.259Z"}
{"level":"info","message":"accepting storage contract offer from b408aeb67291e4d1994a95394e674c09eb683d3c","timestamp":"2016-05-22T17:52:50.315Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463939570333}","timestamp":"2016-05-22T17:52:50.333Z"}
root@Server014:~# cat /root/bridge/bin/storj-bridge.log | grep 'b408aeb67291e4d1994a95394e674c09eb683d3c' | grep "CONSIGN" | grep "2016-05-22T18"
(33 CONSIGN's so far.. )
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463940477380}","timestamp":"2016-05-22T18:07:57.380Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463940510971}","timestamp":"2016-05-22T18:08:30.971Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463940776813}","timestamp":"2016-05-22T18:12:56.813Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463940776845}","timestamp":"2016-05-22T18:12:56.845Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463940776871}","timestamp":"2016-05-22T18:12:56.871Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463940776963}","timestamp":"2016-05-22T18:12:56.964Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463940777003}","timestamp":"2016-05-22T18:12:57.003Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463940777015}","timestamp":"2016-05-22T18:12:57.015Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463940777027}","timestamp":"2016-05-22T18:12:57.027Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463940777039}","timestamp":"2016-05-22T18:12:57.039Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463940777060}","timestamp":"2016-05-22T18:12:57.060Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463940777081}","timestamp":"2016-05-22T18:12:57.081Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463940777094}","timestamp":"2016-05-22T18:12:57.094Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463940777121}","timestamp":"2016-05-22T18:12:57.122Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463941716377}","timestamp":"2016-05-22T18:28:36.377Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463941716398}","timestamp":"2016-05-22T18:28:36.398Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463941716420}","timestamp":"2016-05-22T18:28:36.420Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463941734042}","timestamp":"2016-05-22T18:28:54.043Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463941776773}","timestamp":"2016-05-22T18:29:36.773Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463941803078}","timestamp":"2016-05-22T18:30:03.078Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463941804545}","timestamp":"2016-05-22T18:30:04.545Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463941897037}","timestamp":"2016-05-22T18:31:37.037Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463941899524}","timestamp":"2016-05-22T18:31:39.524Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463941911265}","timestamp":"2016-05-22T18:31:51.265Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463941911288}","timestamp":"2016-05-22T18:31:51.288Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463941914273}","timestamp":"2016-05-22T18:31:54.273Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463941915715}","timestamp":"2016-05-22T18:31:55.715Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463941997785}","timestamp":"2016-05-22T18:33:17.785Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463941999928}","timestamp":"2016-05-22T18:33:19.928Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463941999970}","timestamp":"2016-05-22T18:33:19.970Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463942002707}","timestamp":"2016-05-22T18:33:22.708Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463942007221}","timestamp":"2016-05-22T18:33:27.221Z"}
{"level":"info","message":"sending CONSIGN message to {\"protocol\":\"0.6.15\",\"address\":\"littleskunk.myqnapcloud.com\",\"port\":4000,\"nodeID\":\"b408aeb67291e4d1994a95394e674c09eb683d3c\",\"lastSeen\":1463942007247}","timestamp":"2016-05-22T18:33:27.247Z"}
@gordonwritescode Restartet my node and found something strange. It looks like the offer itself is somehow the reason. In this logfile you find a data channel, only one removing from contract list and than the magic message could not locate renter. Everything in only 10 seconds. Maybe something wrong with the data channel and this removed the node from my contract list? That would explain why "big" nodes like robin or blackduck have the same problem.
Thanks @littleskunk I will catch up and investigate. Thanks for your help everyone, we'll get this fixed!
Data is starting to point to most of these issues pointing to the rate at which contract publications are being sent. Publish messages are sent to your closest neighbors, which will change as nodes join and leave, however what I've seen is that long lived nodes, like the ones you all are running tend to stay neighbors for a long time.
As a result renter nodes like storj.dk and storj.io end up sending all the contracts to the same neighbors, which is why you guys are the shard kings and everyone else gets very few. A consequence of this is that your farmers are receiving contracts faster than they can be handled and negotiated, causing a backup which can ultimately lead to timeouts and contacts being dropped from routing table, which I think is what's happening with "cannot locate renter".
I'm implementing a concurrency limit on the number of contracts that a farmer should attempt to negotiate, which will result in the farmer relaying the contract to others if its limit is reached at the time of receipt. This should help distribute data a little more evenly as well as mitigate the backup of contracts for a given farmer.
Looking at our bridge graphs, we show about ~1000 publish messages per 10m sent to @subwolf, a.storj.eu, and one other farmer. At 100 contracts per minute, with each negotiation triggering a database read/write, it is no surprise that there are issues with timeouts and @littleskunk's reported CPU usage.
There are several open issues right now that seem unrelated to each other but I am becoming confident that they all are related to the same thing, which is an overload of the "big" nodes that can lead to a number of different side effects.
I think that between #120 #121 and #122, these issues are likely to be resolved as the fixes for those 3 issues all aid in reducing "clogs" which ultimately lead to timeouts, dropped contacts, and issues with lookups.
I'm going to place this card in "needs review" with it's brothers and sisters to be closed upon merging #115, but will reopen if it is not resolved with v1.0.0.
Package Versions
Replace the values below using the output from
npm list storj
.Replace the values below using the output from
node --version
.Expected Behavior
Please describe the program's expected behavior. Include an example of your usage code in the back ticks below if applicable.
I expect some FIND_NODE messages to locate renter to send them an offer.
Actual Behavior
Please describe the program's actual behavior. Please include any stack traces or log output in the back ticks below.
My node is not able to locate the renter and is sending new FIND_NODE messages again and again. I receive FIND_NODE as well. I assume they have problems to locate the renter as well.
cat storjshare.log | grep 'Could not locate renter for offer'
cat storjshare.log | grep 'sending FIND_NODE'
Steps to Reproduce
Please include the steps the reproduce the issue, numbered below. Include as much detail as possible.