search

paritytech / substrate

Substrate: The platform for blockchain innovators
Apache License 2.0
8.39k stars 2.65k forks source link

Node sync frozen on HTTP error #3131

Open drewstone opened 5 years ago

drewstone commented 5 years ago

Another odd behavior of a node pegged against master from July 14th. In the middle of syncing, the following error finally drops syncing and drops the node from telemetry. The program doesn't crash but instead begins eating up most of the CPU power as well.

Encountered an error: Unable to parse HTTP: Invalid byte where token is required.
Enable a logger to see more information.
2019-07-16 22:22:25 Imported #28631 (0xe34b…160c)
2019-07-16 22:22:26 Idle (18 peers), best: #28631 (0xe34b…160c), finalized #6819 (0x937e…4184), ⬇ 10.8kiB/s ⬆ 10.6kiB/s
2019-07-16 22:22:31 Imported #28632 (0xa72f…a816)
2019-07-16 22:22:31 Idle (18 peers), best: #28632 (0xa72f…a816), finalized #6819 (0x937e…4184), ⬇ 8.5kiB/s ⬆ 7.4kiB/s
2019-07-16 22:22:36 Idle (18 peers), best: #28632 (0xa72f…a816), finalized #6819 (0x937e…4184), ⬇ 16.9kiB/s ⬆ 11.9kiB/s
2019-07-16 22:22:37 Imported #28633 (0xe986…3ce7)
2019-07-16 22:22:41 Idle (18 peers), best: #28633 (0xe986…3ce7), finalized #6819 (0x937e…4184), ⬇ 14.5kiB/s ⬆ 10.5kiB/s
2019-07-16 22:22:43 Imported #28634 (0x5013…5196)
2019-07-16 22:22:46 Idle (18 peers), best: #28634 (0x5013…5196), finalized #6819 (0x937e…4184), ⬇ 7.3kiB/s ⬆ 6.5kiB/s
2019-07-16 22:22:49 Imported #28635 (0xb492…e348)
2019-07-16 22:22:51 Idle (18 peers), best: #28635 (0xb492…e348), finalized #6819 (0x937e…4184), ⬇ 10.3kiB/s ⬆ 9.7kiB/s
2019-07-16 22:22:55 Imported #28636 (0x8bce…29b0)
2019-07-16 22:22:56 Idle (18 peers), best: #28636 (0x8bce…29b0), finalized #6819 (0x937e…4184), ⬇ 10.9kiB/s ⬆ 11.4kiB/s
2019-07-16 22:23:01 Idle (18 peers), best: #28636 (0x8bce…29b0), finalized #6819 (0x937e…4184), ⬇ 8.4kiB/s ⬆ 8.5kiB/s
2019-07-16 22:23:01 Imported #28637 (0x2c60…d243)
2019-07-16 22:23:06 Idle (18 peers), best: #28637 (0x2c60…d243), finalized #6819 (0x937e…4184), ⬇ 10.2kiB/s ⬆ 9.0kiB/s
2019-07-16 22:23:07 Imported #28638 (0x412b…5ada)
2019-07-16 22:23:11 Idle (18 peers), best: #28638 (0x412b…5ada), finalized #6819 (0x937e…4184), ⬇ 11.1kiB/s ⬆ 10.8kiB/s
2019-07-16 22:23:13 Imported #28639 (0xbd93…2be4)
2019-07-16 22:23:16 Idle (18 peers), best: #28639 (0xbd93…2be4), finalized #6819 (0x937e…4184), ⬇ 8.4kiB/s ⬆ 8.5kiB/s
2019-07-16 22:23:19 Imported #28640 (0xe621…720d)
2019-07-16 22:23:21 Idle (18 peers), best: #28640 (0xe621…720d), finalized #6819 (0x937e…4184), ⬇ 11.2kiB/s ⬆ 10.8kiB/s
2019-07-16 22:53:14 Idle (9 peers), best: #28640 (0xe621…720d), finalized #6819 (0x937e…4184), ⬇ 8.3kiB/s ⬆ 7.8kiB/s
2019-07-16 22:53:19 Idle (6 peers), best: #28640 (0xe621…720d), finalized #6819 (0x937e…4184), ⬇ 11.1kiB/s ⬆ 21.4kiB/s
2019-07-16 22:53:24 Idle (3 peers), best: #28640 (0xe621…720d), finalized #6819 (0x937e…4184), ⬇ 23.3kiB/s ⬆ 35.1kiB/s
2019-07-16 22:53:26 Discovered new external address for our node: /ip4/10.12.4.223/tcp/30333/p2p/QmecTMkota1mMo3G1kcxmLXPUS5kYhom4gf61eswbmfu6t
2019-07-16 22:53:50 Discovered new external address for our node: /ip4/10.12.4.223/tcp/30333/p2p/QmecTMkota1mMo3G1kcxmLXPUS5kYhom4gf61eswbmfu6t
2019-07-16 22:54:13 Discovered new external address for our node: /ip4/10.12.4.223/tcp/30333/p2p/QmecTMkota1mMo3G1kcxmLXPUS5kYhom4gf61eswbmfu6t
Encountered an error: Unable to parse HTTP: Invalid byte where token is required.
Enable a logger to see more information.
bkchr commented 5 years ago

Did you do any offchain http requests?

tomusdrw commented 5 years ago

The error comes from ws-rs crate, so it's also related to the weboscket server as #3124. I'd be in favour of merging the two issues. Is:

Encountered an error: Unable to parse HTTP: Invalid byte where token is required.
Enable a logger to see more information.

the last log line that was printed? It seems that it was printed earlier as well and it didn't really cause any issues.

Again to fully analyze what's going on having a full log running with -lws=trace,rpc=trace would be really helpful.

soc1c commented 5 years ago

Getting the same by trying to connect a the polkadot UI to a remote subtrate node

2019-09-19 09:47:02.964 tokio-runtime-worker-2 INFO substrate  Idle (1 peers), best: #0 (0x6963…8cb9), finalized #0 (0x6963…8cb9), ⬇ 0 ⬆ 0
2019-09-19 09:47:03.763  TRACE ws::io  Processing 1 events
2019-09-19 09:47:03.764  INFO ws::io  Accepted a new tcp connection from 87.xxx.xxx.30:35412.
2019-09-19 09:47:03.765  TRACE ws::io  Active connections 1
2019-09-19 09:47:03.765  TRACE ws::io  Waiting for event
2019-09-19 09:47:03.765  TRACE ws::io  Processing 1 events
2019-09-19 09:47:03.765  TRACE ws::connection  Ready to read handshake from 87.xxx.xxx.30:35412.
2019-09-19 09:47:03.765  TRACE ws::io  Encountered error while reading: Unable to parse HTTP: Invalid byte where token is required.
2019-09-19 09:47:03.765  ERROR ws::handler  WS Error <Http(Token)>: Invalid byte where token is required.
2019-09-19 09:47:03.765  TRACE ws::io  Scheduling connection to 87.xxx.xxx.30:35412 as Writable
2019-09-19 09:47:03.765  TRACE ws::io  Active connections 1
2019-09-19 09:47:03.765  TRACE ws::io  Waiting for event
2019-09-19 09:47:03.765  TRACE ws::io  Processing 1 events
2019-09-19 09:47:03.765  TRACE ws::connection  Ready to write handshake to 87.xxx.xxx.30:35412.
2019-09-19 09:47:03.766  TRACE ws::connection  Finished writing handshake response to 87.xxx.xxx.30:35412
2019-09-19 09:47:03.766  DEBUG ws::io  WebSocket connection to 87.xxx.xxx.30:35412 disconnected.
2019-09-19 09:47:03.766  TRACE ws::io  Active connections 0
2019-09-19 09:47:03.766  TRACE ws::io  Waiting for event

can't comment on the node sync part. I'm running with --ws-external what kind of token is required?

edit: it's also not working with a local node, setting https://polkadot.js.org/apps/#/settings to

wss://127.0.0.1:9944/

Tested with https://github.com/dothereum/dothereum @ 35138d4

Based on Substrate master @ 5a2be8bd56ed5d9dc787fb3b9a76ce10ced4704b

tomusdrw commented 5 years ago

@soc1c What do you mean by "the same"? Does the node crash, stop operating, etc? Is the Waiting for event the last line that ever get's printed?

The errors in logs just indicate that an invalid http request has been send to the server, as you can see it just disconnected the client that sent this and it should be operating normally. --ws-external maybe the reason why you get such invalid http request - most likely just some automated scanner.

soc1c commented 5 years ago

@soc1c What do you mean by "the same"? Does the node crash, stop operating, etc? Is the Waiting for event the last line that ever get's printed?

No, the node is not crashing or freezing. The Waiting for event line gets printed.

Does this mean I misconfigured the node? Sorry, I just jumped on this ticket because the first error message is the same...

The errors in logs just indicate that an invalid http request has been send to the server, as you can see it just disconnected the client that sent this and it should be operating normally. --ws-external maybe the reason why you get such invalid http request - most likely just some automated scanner.

Ok, the message coincides with starting the polkadot ui connection to the node in question and stops when I shut down polkadot ui. As I mentioned, this also happens on a local node without exposing websockets to external addresses.

Maybe this is a polkadot-js/apps issue? @jacogr

jacogr commented 5 years ago

Your issue for local is here - wss://127.0.0.1:9944/ - local is certainly not a secure connection. The node has no certificates.

If you want certs, put it behind an nginx proxy.

tomusdrw commented 5 years ago

@soc1c Does the node continue to operate (i.e. import blocks, etc) or is the waiting thing the last thing you ever see. Since indeed the wss is not supported, but it shouldn't break node operations under any circumstances.

soc1c commented 5 years ago

Ah, perfect! So my comments are off-topic. Thanks