search

codius / old-codius-cli

Codius Client Command Line Interface (CLI)
https://codius.org
Apache License 2.0
110 stars 13 forks source link

Maiden upload to host always fails. Subsequent are fine. #43

Open retryW opened 6 years ago

retryW commented 6 years ago

I've seen this issue on about 10 different codius hosts (unsure if to post issue here as I was using CLI, or on codiusd repo as it's when I'm connecting to a codiusd host).

The very first time uploading to a codius host after it has gone live returns a invalid json body error. Any subsequent attempt to upload works flawlessly.

[root@host1 ~]# codius upload /tmp/example-manifest.json --host https://codius-1.logancodius.xyz --duration 300
Failed To Upload Pods to:
[ { error:
     'invalid json response body at https://codius-1.logancodius.xyz/pods?duration=300 reason: Unexpected token < in JSON at position 0',
    host: 'https://codius-1.logancodius.xyz',
    status: 504,
    statusText: 'Gateway Time-out' } ]
[root@host1 ~]# codius upload /tmp/example-manifest.json --host https://codius-1.logancodius.xyz --duration 300

[root@host1 ~]# codius upload /tmp/example-manifest.json --host https://codius-1.logancodius.xyz --duration 300
Successfully Uploaded Pods to:
[ { url:
     'https://lg6gjhhh2b3if2tzpbms6cr3hdmh7dixa2v4an6pz4tdxdmqtjpa.codius-1.logancodius.xyz/',
    manifestHash: 'lg6gjhhh2b3if2tzpbms6cr3hdmh7dixa2v4an6pz4tdxdmqtjpa',
    host: 'https://codius-1.logancodius.xyz',
    expiry: '2018-06-18T06:00:34.171Z',
    expirationDate: '06-18-2018 6:00:34 +0000',
    expires: 'in 10 minutes',
    pricePaid: '1141' } ]
spearl commented 6 years ago

This is a two part bug. Codiusd is hanging for some reason, or the timeouts just aren't high enough and nginx is timing out and severing the connection so that needs to be fixed. But also, the codius CLI is not interpreting the status code of the response, since it shouldn't be trying to read JSON from a 504 error in the first place

sharafian commented 6 years ago

Maybe it's that most of the images we're uploading use similar base docker images, so the first upload of one contract will time out, but then will finish downloading the dependency images in the background making all future image downloads (even different images with a common dependency) faster

cvanolm commented 6 years ago

I have gotten this error numerous times. Reuploading after the first attempt/error does not fix. I did fix it once however, but I can't be quite sure how I did it as I forgot.

traviscrist commented 6 years ago

@cvanolm do you by chance have the error output you received when getting the similar error that you could post?

jonaagenilsen commented 6 years ago

Some debug-info on

invalid json response body at https://hodl-xrp.net/pods?duration=300 reason: Unexpected token < in JSON at position 0

Note: contract gets uploaded even with this error. Used https://upload.host1.codius.live/ for testing.

Running Codiusd with: Environment="DEBUG=codiusd*,ilp*,-*Peer*,-*trace*"

in /etc/systemd/system/codiusd.service using command journalctl -f -u codiusd:

Sep 30 14:36:44 hodl-xrp.net codiusd[30746]: 2018-09-30T12:36:44.690Z codiusd:pods debug got post pod request. duration=300 price=1142
Sep 30 14:36:44 hodl-xrp.net codiusd[30746]: 2018-09-30T12:36:44.691Z ilp-cog-hapi debug generating stream params. id=81774e903aa579a0bc8feeb3a91b017b
Sep 30 14:36:44 hodl-xrp.net codiusd[30746]: 2018-09-30T12:36:44.890Z ilp-protocol-stream:Server:debug debug got incoming packet for new connection: _qhCJw59cxeZyz2qNz7mCGls~81774e903aa579a0bc8feeb3a91b017b (connectionTag: 81774e903aa579a0bc8feeb3a91b017b)
Sep 30 14:36:44 hodl-xrp.net codiusd[30746]: 2018-09-30T12:36:44.891Z ilp-protocol-stream:Server:Connection:info debug connected
Sep 30 14:36:44 hodl-xrp.net codiusd[30746]: 2018-09-30T12:36:44.891Z ilp-protocol-stream:Server:Connection:debug debug got unfulfillable prepare for amount: 1000. generated condition: bdcd74c5595141678d51ff01de44effa42af58bfeba04131698b74e296cc9b50, prepare condition: 5e3b2c5c7ee97b6f284cfd5d9912a9a89e9d8527badbee61bc722586c23ab2d8
Sep 30 14:36:45 hodl-xrp.net codiusd[30746]: 2018-09-30T12:36:45.277Z ilp-protocol-stream:Server:Connection:info debug got new stream: 1
Sep 30 14:36:45 hodl-xrp.net codiusd[30746]: 2018-09-30T12:36:45.278Z ilp-protocol-stream:Server:Stream:1:info debug new stream created
Sep 30 14:36:45 hodl-xrp.net codiusd[30746]: 2018-09-30T12:36:45.278Z ilp-protocol-stream:Server:Connection:debug debug starting send loop
Sep 30 14:36:45 hodl-xrp.net codiusd[30746]: 2018-09-30T12:36:45.283Z ilp-protocol-stream:Server:Connection:debug debug peer sent too much for stream: 1. got: 1000, max receivable: 0
Sep 30 14:36:45 hodl-xrp.net codiusd[30746]: 2018-09-30T12:36:45.612Z ilp-protocol-stream:Server:Connection:debug debug peer told us that they want to send more money on stream 1 but we are blocking them. they have sent: 0 so far and want to send: 1900
Sep 30 14:36:57 hodl-xrp.net codiusd[30746]: 2018-09-30T12:36:57.028Z ilp-protocol-stream:Server:Connection:debug debug test packet 3 was rejected with a T04 triggered by g.nl-mlab2.ilsp. error with the message: "Insufficient bandwidth, used: 981001 max: 0"
Sep 30 14:36:57 hodl-xrp.net codiusd[30746]: 2018-09-30T12:36:57.028Z ilp-protocol-stream:Server:Connection:debug debug got T04 error, waiting 100ms before sending another test packet
Sep 30 14:36:57 hodl-xrp.net codiusd[30746]: 2018-09-30T12:36:57.028Z ilp-protocol-stream:Server:Connection:debug debug test packet 4 was rejected with a T04 triggered by g.nl-mlab2.ilsp. error with the message: "Insufficient bandwidth, used: 999981001 max: 0"
Sep 30 14:36:57 hodl-xrp.net codiusd[30746]: 2018-09-30T12:36:57.029Z ilp-protocol-stream:Server:Connection:debug debug got T04 error, waiting 100ms before sending another test packet
Sep 30 14:37:12 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:12.112Z ilp-protocol-stream:Server:Connection:debug debug test packet 5 was rejected with a T04 triggered by g.nl-mlab2.ilsp. error with the message: "Insufficient bandwidth, used: 980000 max: 0"
Sep 30 14:37:12 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:12.112Z ilp-protocol-stream:Server:Connection:debug debug got T04 error, waiting 150ms before sending another test packet
Sep 30 14:37:12 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:12.112Z ilp-protocol-stream:Server:Connection:debug debug test packet 6 was rejected with a T04 triggered by g.nl-mlab2.ilsp. error with the message: "Insufficient bandwidth, used: 999980000 max: 0"
Sep 30 14:37:12 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:12.112Z ilp-protocol-stream:Server:Connection:debug debug got T04 error, waiting 150ms before sending another test packet
Sep 30 14:37:15 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:15.281Z ilp-protocol-stream:Server:Connection:error debug test packet 7 timed out before we got a response
Sep 30 14:37:15 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:15.286Z ilp-protocol-stream:Server:Connection:error debug test packet 8 timed out before we got a response
Sep 30 14:37:15 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:15.286Z ilp-protocol-stream:Server:Connection:debug debug sending test packet of 1 delivered 1 (exchange rate: 1)
Sep 30 14:37:15 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:15.286Z ilp-protocol-stream:Server:Connection:debug debug sending test packet of 1000 delivered 1000 (exchange rate: 1)
Sep 30 14:37:15 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:15.286Z ilp-protocol-stream:Server:Connection:debug debug determined exchange rate to be 1
Sep 30 14:37:37 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:37.155Z ilp-protocol-stream:Server:Connection:debug debug got response to packet: 9: {"sequence":"9","ilpPacketType":13,"prepareAmount":"0","frames":[{"type":3,"name":"ConnectionMaxData","maxOffset":"65534"},{"type":18,"name":"StreamMaxMoney","streamId":"1","receiveMax":"0","totalReceived":"0"},{"type":21,"name":"StreamMaxData","streamId":"1","maxOffset":"16385"}]}
Sep 30 14:37:37 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:37.365Z codiusd:pods debug got post pod request. duration=300 price=1142
Sep 30 14:37:37 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:37.365Z ilp-cog-hapi debug got stream. id= 81774e903aa579a0bc8feeb3a91b017b
Sep 30 14:37:37 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:37.365Z ilp-protocol-stream:Server:Stream:1:debug debug setting receiveMax to 1142
Sep 30 14:37:37 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:37.365Z ilp-protocol-stream:Server:Connection:debug debug starting send loop
Sep 30 14:37:50 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:50.968Z ilp-protocol-stream:Server:Connection:debug debug got response to packet: 10: {"sequence":"10","ilpPacketType":13,"prepareAmount":"0","frames":[{"type":3,"name":"ConnectionMaxData","maxOffset":"65535"},{"type":18,"name":"StreamMaxMoney","streamId":"1","receiveMax":"0","totalReceived":"0"},{"type":21,"name":"StreamMaxData","streamId":"1","maxOffset":"16385"}]}
Sep 30 14:37:50 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:50.969Z ilp-protocol-stream:Server:Connection:debug debug finished sending
Sep 30 14:37:51 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:51.028Z ilp-protocol-stream:Server:Connection:debug debug got response to packet: 11: {"sequence":"11","ilpPacketType":13,"prepareAmount":"0","frames":[{"type":3,"name":"ConnectionMaxData","maxOffset":"65535"},{"type":18,"name":"StreamMaxMoney","streamId":"1","receiveMax":"0","totalReceived":"0"},{"type":21,"name":"StreamMaxData","streamId":"1","maxOffset":"16385"}]}
Sep 30 14:37:51 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:51.028Z ilp-protocol-stream:Server:Connection:debug debug finished sending
Sep 30 14:37:52 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:52.379Z ilp-protocol-stream:Server:Connection:debug debug peer told us that they want to send more money on stream 1 but we are blocking them. they have sent: 1000 so far and want to send: 1900
Sep 30 14:37:52 hodl-xrp.net codiusd[30746]: 2018-09-30T12:37:52.733Z ilp-protocol-stream:Server:Connection:debug debug peer told us that they want to send more money on stream 1 but we are blocking them. they have sent: 1142 so far and want to send: 1900
Sep 30 14:38:43 hodl-xrp.net codiusd[30746]: 2018-09-30T12:38:43.839Z codiusd:PodDatabase debug added pod. id=keyzb3mqgtwua5ahzuggtnhpswqef7gm7hrxxwb3f62cljxvrzsa running=true duration=300 expiry=2018-09-30T12:42:52.382Z memory=512
Sep 30 14:39:07 hodl-xrp.net codiusd[30746]: 2018-09-30T12:39:07.586Z ilp-protocol-stream:Server:Connection:debug debug peer told us that they want to send more money on stream 1 but we are blocking them. they have sent: 1142 so far and want to send: 1900
Sep 30 14:39:14 hodl-xrp.net codiusd[30746]: 2018-09-30T12:39:14.785Z codiusd:HyperClient info creating pod. id=keyzb3mqgtwua5ahzuggtnhpswqef7gm7hrxxwb3f62cljxvrzsa
Sep 30 14:39:20 hodl-xrp.net codiusd[30746]: 2018-09-30T12:39:20.226Z codiusd:HyperClient info starting pod. id=keyzb3mqgtwua5ahzuggtnhpswqef7gm7hrxxwb3f62cljxvrzsa
Sep 30 14:39:21 hodl-xrp.net codiusd[30746]: 2018-09-30T12:39:21.150Z codiusd:HyperClient debug fetching pod info. id=keyzb3mqgtwua5ahzuggtnhpswqef7gm7hrxxwb3f62cljxvrzsa
Sep 30 14:39:48 hodl-xrp.net codiusd[30746]: 2018-09-30T12:39:48.902Z codiusd:PodManager debug dbPods=keyzb3mqgtwua5ahzuggtnhpswqef7gm7hrxxwb3f62cljxvrzsa
Sep 30 14:39:48 hodl-xrp.net codiusd[30746]: 2018-09-30T12:39:48.905Z codiusd:HyperClient debug running pod list=keyzb3mqgtwua5ahzuggtnhpswqef7gm7hrxxwb3f62cljxvrzsa
Sep 30 14:39:48 hodl-xrp.net codiusd[30746]: 2018-09-30T12:39:48.905Z codiusd:PodManager debug delete pods=
Sep 30 14:39:48 hodl-xrp.net codiusd[30746]: 2018-09-30T12:39:48.905Z codiusd:PodDatabase debug saved manifest. hash="keyzb3mqgtwua5ahzuggtnhpswqef7gm7hrxxwb3f62cljxvrzsa"