Log noise to do with websockets #36

New Issue

dboreham · 2022-09-27T13:42:39Z

dboreham commented

2022-09-27 13:42:39 +00:00

We see constant log output like this, under normal operating conditions:

Sep 27 13:37:44 vaasl-cerc-1 chibaclonkd[418747]: 1:37PM ERR Failed to read request err="websocket: close 1006 (abnormal closure): unexpected EOF" module=rpc-server protocol=websocket remote={"IP":"127.0.0.1","Port":39564,"Zone":""}
Sep 27 13:37:44 vaasl-cerc-1 chibaclonkd[418747]: 1:37PM ERR not stopping client; it is already stopped client=wsConnection module=rpc-server protocol=websocket remote={"IP":"127.0.0.1","Port":39564,"Zone":""}
Sep 27 13:37:44 vaasl-cerc-1 chibaclonkd[418747]: 1:37PM ERR error while stopping connection error="client is not running" module=rpc-server protocol=websocket

This output is not useful and clutters the log making it hard to determine if the service is operating correctly.

Task is to stop this log output from appearing, one way or another.

We see constant log output like this, under normal operating conditions: ``` Sep 27 13:37:44 vaasl-cerc-1 chibaclonkd[418747]: 1:37PM ERR Failed to read request err="websocket: close 1006 (abnormal closure): unexpected EOF" module=rpc-server protocol=websocket remote={"IP":"127.0.0.1","Port":39564,"Zone":""} Sep 27 13:37:44 vaasl-cerc-1 chibaclonkd[418747]: 1:37PM ERR not stopping client; it is already stopped client=wsConnection module=rpc-server protocol=websocket remote={"IP":"127.0.0.1","Port":39564,"Zone":""} Sep 27 13:37:44 vaasl-cerc-1 chibaclonkd[418747]: 1:37PM ERR error while stopping connection error="client is not running" module=rpc-server protocol=websocket ``` This output is not useful and clutters the log making it hard to determine if the service is operating correctly. Task is to stop this log output from appearing, one way or another.

dboreham commented

2022-09-27 13:43:44 +00:00

Quick search of the laconicd source code shows that these messages are not coming from our code. Probably originate in a dependency. Checking...

dboreham commented

2022-09-27 13:45:34 +00:00

Found it here:

https://github.com/tendermint/tendermint/blob/main/rpc/jsonrpc/server/ws_handler.go#L97

Found it here: https://github.com/tendermint/tendermint/blob/main/rpc/jsonrpc/server/ws_handler.go#L97

dboreham commented

2022-09-27 14:13:45 +00:00

Code where the messages are generated:

https://github.com/tendermint/tendermint/blob/main/rpc/jsonrpc/server/ws_handler.go#L327
https://github.com/tendermint/tendermint/blob/main/rpc/jsonrpc/server/ws_handler.go#L97

(Can't find the code for "not stopping client; it is already stopped" yet)

Code where the messages are generated: https://github.com/tendermint/tendermint/blob/main/rpc/jsonrpc/server/ws_handler.go#L327 https://github.com/tendermint/tendermint/blob/main/rpc/jsonrpc/server/ws_handler.go#L97 (Can't find the code for "not stopping client; it is already stopped" yet)

dboreham commented

2022-09-27 15:02:30 +00:00

Possibly here? https://github.com/tendermint/tendermint/blob/main/libs/service/service.go#L174

dboreham commented

2022-09-27 15:19:38 +00:00

See also: https://github.com/evmos/ethermint/issues/1253

dboreham commented

2022-11-23 20:20:56 +00:00

Resolved by rebasing to older CosmosSDK

dboreham commented

2022-11-29 18:33:54 +00:00

Reports are the message persists in the latest release, re-opening.

dboreham commented

2022-11-30 13:18:11 +00:00

Sample log output:

6:43AM INF executed block height=115260 module=state num_invalid_txs=0 num_valid_txs=0 server=node
6:43AM INF commit synced commit=436F6D6D697449447B5B353620313635203134332031393720393020323035203137362032313620313237203233302031203630203235302031303320313339203131342031393020313735203138332032323620313431203738203131312031373920313237203137342038312032343620363720313739203839203131335D3A31433233437D
6:43AM INF committed state app_hash=38A58FC55ACDB0D87FE6013CFA678B72BEAFB7E28D4E6FB37FAE51F643B35971 height=115260 module=state num_txs=0 server=node
6:43AM INF indexed block height=115260 module=txindex server=node
6:43AM ERR Failed to read request err="websocket: close 1006 (abnormal closure): unexpected EOF" module=rpc-server protocol=websocket remote={"IP":"127.0.0.1","Port":56880,"Zone":""} server=node
6:43AM INF service stop impl={"Logger":{}} module=rpc-server msg={} protocol=websocket remote={"IP":"127.0.0.1","Port":56880,"Zone":""} server=node
6:43AM ERR error while stopping connection error="already stopped" module=rpc-server protocol=websocket server=node
6:43AM INF Timed out dur=4951.497901 height=115261 module=consensus round=0 server=node step=1
6:43AM INF received proposal module=consensus proposal={"Type":32,"block_id":{"hash":"C7A902FDDDB1002AD199E0EB47ADCB83F433008F486ADCFA8311CA77EE60284A","parts":{"hash":"818CB3B392BF317DE9D4F619F72DD7BF087F5D93810F64BB589425310AFAEA49","total":1}},"height":115261,"pol_round":-1,"round":0,"signature":"6cCWcllSd1Vd2Z6F6iA6oL0Z6RENmgb31IC7voNKhApzRDb0qaEi7aYOthm4yqhwgckeWbsh8opvkNPtyXtRCA==","timestamp":"2022-11-30T06:43:50.351283628Z"} server=node
6:43AM INF received complete proposal block hash=C7A902FDDDB1002AD199E0EB47ADCB83F433008F486ADCFA8311CA77EE60284A height=115261 module=consensus server=node
6:43AM INF finalizing commit of block hash={} height=115261 module=consensus num_txs=0 root=38A58FC55ACDB0D87FE6013CFA678B72BEAFB7E28D4E6FB37FAE51F643B35971 server=node
6:43AM INF minted coins from module account amount=2654112105175373achk from=mint module=x/bank
6:43AM INF executed block height=115261 module=state num_invalid_txs=0 num_valid_txs=0 server=node

Sample log output: ``` 6:43AM INF executed block height=115260 module=state num_invalid_txs=0 num_valid_txs=0 server=node 6:43AM INF commit synced commit=436F6D6D697449447B5B353620313635203134332031393720393020323035203137362032313620313237203233302031203630203235302031303320313339203131342031393020313735203138332032323620313431203738203131312031373920313237203137342038312032343620363720313739203839203131335D3A31433233437D 6:43AM INF committed state app_hash=38A58FC55ACDB0D87FE6013CFA678B72BEAFB7E28D4E6FB37FAE51F643B35971 height=115260 module=state num_txs=0 server=node 6:43AM INF indexed block height=115260 module=txindex server=node 6:43AM ERR Failed to read request err="websocket: close 1006 (abnormal closure): unexpected EOF" module=rpc-server protocol=websocket remote={"IP":"127.0.0.1","Port":56880,"Zone":""} server=node 6:43AM INF service stop impl={"Logger":{}} module=rpc-server msg={} protocol=websocket remote={"IP":"127.0.0.1","Port":56880,"Zone":""} server=node 6:43AM ERR error while stopping connection error="already stopped" module=rpc-server protocol=websocket server=node 6:43AM INF Timed out dur=4951.497901 height=115261 module=consensus round=0 server=node step=1 6:43AM INF received proposal module=consensus proposal={"Type":32,"block_id":{"hash":"C7A902FDDDB1002AD199E0EB47ADCB83F433008F486ADCFA8311CA77EE60284A","parts":{"hash":"818CB3B392BF317DE9D4F619F72DD7BF087F5D93810F64BB589425310AFAEA49","total":1}},"height":115261,"pol_round":-1,"round":0,"signature":"6cCWcllSd1Vd2Z6F6iA6oL0Z6RENmgb31IC7voNKhApzRDb0qaEi7aYOthm4yqhwgckeWbsh8opvkNPtyXtRCA==","timestamp":"2022-11-30T06:43:50.351283628Z"} server=node 6:43AM INF received complete proposal block hash=C7A902FDDDB1002AD199E0EB47ADCB83F433008F486ADCFA8311CA77EE60284A height=115261 module=consensus server=node 6:43AM INF finalizing commit of block hash={} height=115261 module=consensus num_txs=0 root=38A58FC55ACDB0D87FE6013CFA678B72BEAFB7E28D4E6FB37FAE51F643B35971 server=node 6:43AM INF minted coins from module account amount=2654112105175373achk from=mint module=x/bank 6:43AM INF executed block height=115261 module=state num_invalid_txs=0 num_valid_txs=0 server=node ```

Sign in to join this conversation.