Storj copy job error

dwtp · 4 April 2023 04:27

I’m able to upload chunks for around ten minutes before Storj errors out. Here is the end of my last job:

2023-04-03 21:14:33.667 INFO COPY_PROGRESS Copied chunk 5b57c9db6a9a2d92565a27f8ee56ac49572b2121bf2a6e6d908e4ecfe4a91ff1 (92/201819) 744KB/s 17 days 06:59:16 0.0%
2023-04-03 21:14:59.934 INFO COPY_PROGRESS Copied chunk 37fd3b26086fe8fc88fa8cad2ace13ab1ca36a3f4f0b20b7b02a066d7fa99b3a (95/201819) 723KB/s 17 days 09:22:11 0.0%
2023-04-03 21:15:06.555 ERROR UPLOAD_CHUNK Failed to upload the chunk 7eb2de813172e43f4c2519b3a94cff012c5eee6df7dde38522bcaf81c5d97747: uplink: stream: ecclient: successful puts (79) less than success threshold (80), ecclient: failed to dial (node:1WpsAmTYe5JFgED96mQUAErzscfxgRErk4WvrAyHkq8gjvXVBE): piecestore: rpc: tcp connector failed: rpc: dial tcp 51.161.91.140:28967: connect: connection refused; ecclient: failed to dial (node:12AfW4ZSUWVxjT8LU3hHxuSdDqyN4dSWwgVFyFmdnyAAHEudqrm): piecestore: rpc: tcp connector failed: rpc: dial tcp 213.32.245.249:28967: connect: no route to host; ecclient: upload failed (node:12MobUf67Ba4xhDt1bf4nBHvd3C76wEEgMdyB5kuzrTDZyGpnNc, address:95.217.12.194:28967): protocol: storage node overloaded, request limit: 32; ecclient: failed to dial (node:1UkpNUXB4vjRq9uNNeJQSyWZ8h4BJQ1deqwRVC1QWGiMtUGKKg): piecestore: rpc: tcp connector failed: rpc: dial tcp 46.29.162.156:29025: i/o timeout; ecclient: failed to dial (node:12bfHvpvZBi4HRmTh8YrNC5n2x9mYLaFYcNRcs8JrAsYJdopEtt): piecestore: rpc: tcp connector failed: rpc: dial tcp 45.129.2.46:29191: i/o timeout; ecclient: failed to dial (node:12PyFgAib2JdVAiCFeiwaz5vufJYDqRkStwzkqiqeYP2nY1JYyv): piecestore: rpc: tcp connector failed: rpc: dial tcp 46.241.125.18:28006: i/o timeout; ecclient: failed to dial (node:1KQs8vP9vbZL4VqDx98e7Qfdu5KJdmuMso4FSpkVrbMCEzvV7p): piecestore: rpc: tcp connector failed: rpc: dial tcp 37.220.82.246:28967: i/o timeout; ecclient: failed to dial (node:182WzkWv4xAb9grXVXDAfTwpHopk2cYZxZHQWqLXeYTPYZV3gJ): piecestore: rpc: tcp connector failed: rpc: dial tcp 185.117.154.118:28978: i/o timeout; ecclient: failed to dial (node:1DqhJBvU4WgYJgRyd5BXBrBY8oc9tk1gTqoB6PRHFRdfVYADfS): piecestore: rpc: tcp connector failed: rpc: dial tcp 45.8.98.152:29003: i/o timeout; ecclient: failed to dial (node:158kyhGAeic1szq5cWfeGDdtGScpzqGMPkrZTxmVJNJqHX7z5t): piecestore: rpc: tcp connector failed: rpc: dial tcp 193.109.79.135:28976: i/o timeout; ecclient: failed to dial (node:1cgYyDQ98ssRCRF8UJp1pvzghUZvV9JZZqjkKPYxfugVtCQxJp): piecestore: rpc: tcp connector failed: rpc: dial tcp 80.85.158.88:28978: i/o timeout; ecclient: failed to dial (node:1mT6ENWRZWbuYDLQrW5LfQqfiMf8AdjnwQVzA94diK8XyVigsX): piecestore: rpc: tcp connector failed: rpc: dial tcp 91.210.169.205:29106: i/o timeout; ecclient: failed to dial (node:129Hd51wiK3hDAF73tbqdV8gX7SsUWBr6hmUhzsUgUAZWeh8PUw): piecestore: rpc: tcp connector failed: rpc: dial tcp 185.31.163.23:40024: i/o timeout; ecclient: failed to dial (node:1kjQBzqfBm9dTui18LYm2tKBzZXhmDMqezvrqT1mSnJ7ENF9HU): piecestore: rpc: tcp connector failed: rpc: dial tcp 176.114.226.178:28967: i/o timeout; ecclient: failed to dial (node:12HYeHdE1K7UyoHNybBi3aV9Xyedyd5P5MXjFm1RWynQfVGY4eB): piecestore: rpc: tcp connector failed: rpc: dial tcp 87.237.47.211:28999: i/o timeout; ecclient: failed to dial (node:18A6EpBwJV2caLH7Z9QQCXgfizj3JFtvNEck6a5QNSho1EVEeJ): piecestore: rpc: tcp connector failed: rpc: dial tcp 178.250.157.154:40013: i/o timeout; ecclient: failed to dial (node:1FFFX4MHQKCUNaBuuEVc5Fyhe9qz2urcf8JzzrTan1VGCK2GbZ): piecestore: rpc: tcp connector failed: rpc: context deadline exceeded; ecclient: failed to dial (node:12iAtWvEZu1hMxRNcZaRYyqa4DrPTkQM34QtNzdYTKThbHNcM8A): piecestore: rpc: tcp connector failed: rpc: dial tcp 83.146.80.235:28967: i/o timeout; ecclient: failed to dial (node:122d78cfjZi6FoGwc2F9e4gcHYEHYMadtqYVmiX8TewLwTndCXJ): piecestore: rpc: tcp connector failed: rpc: dial tcp 62.109.26.14:28933: i/o timeout; ecclient: failed to dial (node:1ZqXsX4sfHHvaTxVyMHQcNwxi53erMBc6AThjtkMeA1UcnqSqd): piecestore: rpc: tcp connector failed: rpc: dial tcp 194.67.112.241:28936: i/o timeout; ecclient: failed to dial (node:12NVf9AvqBgDeKxSyJsoCpVKJrB5RYSg9NaVF9YAymkHumYe35q): piecestore: rpc: tcp connector failed: rpc: dial tcp 185.231.204.16:10141: i/o timeout; ecclient: failed to dial (node:1B24qCgo1TnMcwemqLgfJzQL7htKra2ZuQss6wXYgNGMdH69KL): piecestore: rpc: tcp connector failed: rpc: dial tcp 193.124.118.14:29132: i/o timeout; ecclient: failed to dial (node:12rfnjtzu4opGcrh85fb1nk36ff2yqFv9CpT4vxUxvf7ZpT4VAz): piecestore: rpc: tcp connector failed: rpc: dial tcp 81.200.144.227:29098: i/o timeout; ecclient: failed to dial (node:1kJK3vr1zjPCG7R6KyGimD3tb1DpdMzqXruCvYQotdfBU6Reb6): piecestore: rpc: tcp connector failed: rpc: dial tcp 194.87.210.83:29145: i/o timeout; ecclient: failed to dial (node:12MkEbqLJLpAMesAYmxtvic2WGzBR9niP5PuX6A2pVfC6t1SJeL): piecestore: rpc: tcp connector failed: rpc: dial tcp 95.165.14.7:28968: i/o timeout; ecclient: failed to dial (node:136eoyJWgDe1zkCT9TAzJiM4XyDg3C3ftiVKXrsR8c5PwCSo8k): piecestore: rpc: tcp connector failed: rpc: dial tcp 46.173.219.61:29118: i/o timeout; ecclient: failed to dial (node:1AVWugA48fnSnpLbEFRV5VPdEqZ7AaRvuPbszP3uTweuSqS1ST): piecestore: rpc: tcp connector failed: rpc: dial tcp 89.207.223.226:29245: i/o timeout; ecclient: failed to dial (node:12hNxck1huvWwg6SF6XJzq9KMp9zSWzButxTBz4pXRJeUQqdPBq): piecestore: rpc: tcp connector failed: rpc: dial tcp 83.217.5.100:29109: i/o timeout; ecclient: failed to dial (node:1AeqdQz11juwvKevB4BDpt4vLqMETY6ee9L7oR3edDkzYBgSbP): piecestore: rpc: tcp connector failed: rpc: dial tcp 94.142.143.113:28161: i/o timeout; ecclient: upload failed (node:1jm2eEmECZi5rbTdtmH2vUBxWPZr9sienRpwKZCH8KASRGGP9j, address:5.196.246.191:3051): protocol: expected piece hash; context canceled; EOF; ecclient: upload failed (node:12dn9bfb782GQZ4bQ45v19PHpfbo2aYssYAFD4vVNZWivaGyks3, address:15.235.105.121:28967): protocol: expected piece hash; message timeout; EOF
Failed to upload the chunk 7eb2de813172e43f4c2519b3a94cff012c5eee6df7dde38522bcaf81c5d97747: uplink: stream: ecclient: successful puts (79) less than success threshold (80), ecclient: failed to dial (node:1WpsAmTYe5JFgED96mQUAErzscfxgRErk4WvrAyHkq8gjvXVBE): piecestore: rpc: tcp connector failed: rpc: dial tcp 51.161.91.140:28967: connect: connection refused; ecclient: failed to dial (node:12AfW4ZSUWVxjT8LU3hHxuSdDqyN4dSWwgVFyFmdnyAAHEudqrm): piecestore: rpc: tcp connector failed: rpc: dial tcp 213.32.245.249:28967: connect: no route to host; ecclient: upload failed (node:12MobUf67Ba4xhDt1bf4nBHvd3C76wEEgMdyB5kuzrTDZyGpnNc, address:95.217.12.194:28967): protocol: storage node overloaded, request limit: 32; ecclient: failed to dial (node:1UkpNUXB4vjRq9uNNeJQSyWZ8h4BJQ1deqwRVC1QWGiMtUGKKg): piecestore: rpc: tcp connector failed: rpc: dial tcp 46.29.162.156:29025: i/o timeout; ecclient: failed to dial (node:12bfHvpvZBi4HRmTh8YrNC5n2x9mYLaFYcNRcs8JrAsYJdopEtt): piecestore: rpc: tcp connector failed: rpc: dial tcp 45.129.2.46:29191: i/o timeout; ecclient: failed to dial (node:12PyFgAib2JdVAiCFeiwaz5vufJYDqRkStwzkqiqeYP2nY1JYyv): piecestore: rpc: tcp connector failed: rpc: dial tcp 46.241.125.18:28006: i/o timeout; ecclient: failed to dial (node:1KQs8vP9vbZL4VqDx98e7Qfdu5KJdmuMso4FSpkVrbMCEzvV7p): piecestore: rpc: tcp connector failed: rpc: dial tcp 37.220.82.246:28967: i/o timeout; ecclient: failed to dial (node:182WzkWv4xAb9grXVXDAfTwpHopk2cYZxZHQWqLXeYTPYZV3gJ): piecestore: rpc: tcp connector failed: rpc: dial tcp 185.117.154.118:28978: i/o timeout; ecclient: failed to dial (node:1DqhJBvU4WgYJgRyd5BXBrBY8oc9tk1gTqoB6PRHFRdfVYADfS): piecestore: rpc: tcp connector failed: rpc: dial tcp 45.8.98.152:29003: i/o timeout; ecclient: failed to dial (node:158kyhGAeic1szq5cWfeGDdtGScpzqGMPkrZTxmVJNJqHX7z5t): piecestore: rpc: tcp connector failed: rpc: dial tcp 193.109.79.135:28976: i/o timeout; ecclient: failed to dial (node:1cgYyDQ98ssRCRF8UJp1pvzghUZvV9JZZqjkKPYxfugVtCQxJp): piecestore: rpc: tcp connector failed: rpc: dial tcp 80.85.158.88:28978: i/o timeout; ecclient: failed to dial (node:1mT6ENWRZWbuYDLQrW5LfQqfiMf8AdjnwQVzA94diK8XyVigsX): piecestore: rpc: tcp connector failed: rpc: dial tcp 91.210.169.205:29106: i/o timeout; ecclient: failed to dial (node:129Hd51wiK3hDAF73tbqdV8gX7SsUWBr6hmUhzsUgUAZWeh8PUw): piecestore: rpc: tcp connector failed: rpc: dial tcp 185.31.163.23:40024: i/o timeout; ecclient: failed to dial (node:1kjQBzqfBm9dTui18LYm2tKBzZXhmDMqezvrqT1mSnJ7ENF9HU): piecestore: rpc: tcp connector failed: rpc: dial tcp 176.114.226.178:28967: i/o timeout; ecclient: failed to dial (node:12HYeHdE1K7UyoHNybBi3aV9Xyedyd5P5MXjFm1RWynQfVGY4eB): piecestore: rpc: tcp connector failed: rpc: dial tcp 87.237.47.211:28999: i/o timeout; ecclient: failed to dial (node:18A6EpBwJV2caLH7Z9QQCXgfizj3JFtvNEck6a5QNSho1EVEeJ): piecestore: rpc: tcp connector failed: rpc: dial tcp 178.250.157.154:40013: i/o timeout; ecclient: failed to dial (node:1FFFX4MHQKCUNaBuuEVc5Fyhe9qz2urcf8JzzrTan1VGCK2GbZ): piecestore: rpc: tcp connector failed: rpc: context deadline exceeded; ecclient: failed to dial (node:12iAtWvEZu1hMxRNcZaRYyqa4DrPTkQM34QtNzdYTKThbHNcM8A): piecestore: rpc: tcp connector failed: rpc: dial tcp 83.146.80.235:28967: i/o timeout; ecclient: failed to dial (node:122d78cfjZi6FoGwc2F9e4gcHYEHYMadtqYVmiX8TewLwTndCXJ): piecestore: rpc: tcp connector failed: rpc: dial tcp 62.109.26.14:28933: i/o timeout; ecclient: failed to dial (node:1ZqXsX4sfHHvaTxVyMHQcNwxi53erMBc6AThjtkMeA1UcnqSqd): piecestore: rpc: tcp connector failed: rpc: dial tcp 194.67.112.241:28936: i/o timeout; ecclient: failed to dial (node:12NVf9AvqBgDeKxSyJsoCpVKJrB5RYSg9NaVF9YAymkHumYe35q): piecestore: rpc: tcp connector failed: rpc: dial tcp 185.231.204.16:10141: i/o timeout; ecclient: failed to dial (node:1B24qCgo1TnMcwemqLgfJzQL7htKra2ZuQss6wXYgNGMdH69KL): piecestore: rpc: tcp connector failed: rpc: dial tcp 193.124.118.14:29132: i/o timeout; ecclient: failed to dial (node:12rfnjtzu4opGcrh85fb1nk36ff2yqFv9CpT4vxUxvf7ZpT4VAz): piecestore: rpc: tcp connector failed: rpc: dial tcp 81.200.144.227:29098: i/o timeout; ecclient: failed to dial (node:1kJK3vr1zjPCG7R6KyGimD3tb1DpdMzqXruCvYQotdfBU6Reb6): piecestore: rpc: tcp connector failed: rpc: dial tcp 194.87.210.83:29145: i/o timeout; ecclient: failed to dial (node:12MkEbqLJLpAMesAYmxtvic2WGzBR9niP5PuX6A2pVfC6t1SJeL): piecestore: rpc: tcp connector failed: rpc: dial tcp 95.165.14.7:28968: i/o timeout; ecclient: failed to dial (node:136eoyJWgDe1zkCT9TAzJiM4XyDg3C3ftiVKXrsR8c5PwCSo8k): piecestore: rpc: tcp connector failed: rpc: dial tcp 46.173.219.61:29118: i/o timeout; ecclient: failed to dial (node:1AVWugA48fnSnpLbEFRV5VPdEqZ7AaRvuPbszP3uTweuSqS1ST): piecestore: rpc: tcp connector failed: rpc: dial tcp 89.207.223.226:29245: i/o timeout; ecclient: failed to dial (node:12hNxck1huvWwg6SF6XJzq9KMp9zSWzButxTBz4pXRJeUQqdPBq): piecestore: rpc: tcp connector failed: rpc: dial tcp 83.217.5.100:29109: i/o timeout; ecclient: failed to dial (node:1AeqdQz11juwvKevB4BDpt4vLqMETY6ee9L7oR3edDkzYBgSbP): piecestore: rpc: tcp connector failed: rpc: dial tcp 94.142.143.113:28161: i/o timeout; ecclient: upload failed (node:1jm2eEmECZi5rbTdtmH2vUBxWPZr9sienRpwKZCH8KASRGGP9j, address:5.196.246.191:3051): protocol: expected piece hash; context canceled; EOF; ecclient: upload failed (node:12dn9bfb782GQZ4bQ45v19PHpfbo2aYssYAFD4vVNZWivaGyks3, address:15.235.105.121:28967): protocol: expected piece hash; message timeout; EOF

I’m running the job with the following flags, from a local, copy-compatible storage that I also use to copy up to B2:

-threads 2 -upload-limit-rate 2560 -key /config/duplicacy-priv.pem -key-passphrase xxxxxxxx

This is from the :mini docker container provided by saspus on the latest version available.

Thanks for any insight. This is a repeatable issue as it happened on schedule last night and on demand today during testing.

snellgrove · 4 April 2023 06:38

Hi,

I assume Storj is using “s3 compatible” or something and that’s what you’ve told Duplicacy the backend is?

Can you get some logs from Storj from the same time, I think it’d help figure out what’s going on - these logs are mostly moaning about timeouts.

I assume you’re using the Storj cloud gateway (or whatever it’s called) to ingest and spread the data out to storage - I wonder if its massively oversubscribed/too busy… ?

I don’t know a huge amount about Storj, looked into using it myself - I like the idea of it, at least in theory but I went with Google cloud storage for the time being…

Regards

saspus · 4 April 2023 16:03

If this occurs consistently, it could be your router getting overwhelmed with a number of connection storj native client creates. It’s very effective and performant but not a workload many home routers expect. It’s peer to peer, your client connects directly to the storage nodes to upload each piece.

What happens to the rest of the internet connectivity when this occurs? Can you glean anything from the router logs?

You may have to switch to using the storj hosted gateway. This will diminish certain storj benefits, but those don’t matter in the backup workflow. It will, however save you bandwidth. Alternatively, you can host your own gateway on a VPS with sufficient bandwidth.

By the way, no need to specify 2 threads, the upload is already massively parallel.

Edit: the error message “storage node overloaded” is likely a red herring: the pieces are uploaded to multitude of nodes, some of them failing upload is expected and harmless. However in your case it failed to upload way too many pieces, to fall under 80 threshold, and therefore it’s likely an issue on your end, that looks like node refused connection, when in reality likely your router is having a seizure.

dwtp · 4 April 2023 16:50

@snellgrove It’s actually using the native Storj storage that was available as of version 1.7.

@saspus I’m seeing a massive latency spike on my UDMP at the time indicated for the copy job. If you’re saying for the Duplicacy workflow there is no discernible downside to swapping to an S3 configuration, I can do that.

I had set threads to 2 since I was seeing reduced upload speeds (400Kb/s versus over 1.2Mb/s to B2) with both on a single thread, and that seemed to help a bit (700Kb/s), but good to know.

If there is any specific tuning I can do with the UDMP to support the native protocol, I can look into that. I imagine it would be easier if I were still running pfSense?

Thanks.

saspus · 4 April 2023 17:10

Interesting, the plot thickens. I’m using UDMP as well, v2.4.27, and not only use storj as a client, but also host storj storage node. No weird latency spikes, it’s consistently under 15 ms. Unless they broke something in the new version (I see it offers me to update to 2.5.17) I doubt the UDMP is culprit here. I by default assumed its some dlink/tplink type of deal.

Since you are saying it also happens when ran on-demand, it rules out scheduled provider maintenance at night (e.g. I have internet hiccup every night at 3AM for a minute)

And your machine connected wired, right? And what OS is there? Could it be some local “max number of connection” limit type of deal?

Edit: never mind last paragraph, this would not explain upstream latency spike.

What is UDMP connected to? Cable modem in bridge mode?