search

keep-network / keep-core

The smart contracts and reference client behind the Keep network
https://keep.network
MIT License
122 stars 75 forks source link

Verify logs severity #3636

Open thevops opened 1 year ago

thevops commented 1 year ago

Version: keep-client version v2.0.0-m3 (revision cdddee4b0)

Keep-client sometimes logs several error logs, which does not seem to have much impact. Could you verify if they have proper severity? Many of them occur just once, which looks to me like there is a retry mechanism. If so, then maybe it'd be worth logging an error message only when all retries fail. This is just my guess.

A few examples

ERROR keep-contract-WalletCoordinator contract/WalletCoordinator.go:3499 subscription failed to pull events: [error retrieving past HeartbeatRequestSubmitted events: [Internal server error]]

context

2023-06-14T23:39:03.481Z    INFO    dht/RtRefreshManager    rtrefresh/rt_refresh_manager.go:286 finished refreshing cpl 4, routing table size is now 70
2023-06-14T23:39:03.482Z    INFO    dht/RtRefreshManager    rtrefresh/rt_refresh_manager.go:279 starting refreshing cpl 5 with key CIQAAAGAXYAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA (routing table size was 70)
2023-06-14T23:39:03.540Z    INFO    keep-contract-WalletRegistry    contract/WalletRegistry.go:7760 subscription monitoring fetching past DkgStarted events starting from block [17481388]
2023-06-14T23:39:03.540Z    INFO    keep-contract-WalletRegistry    contract/WalletRegistry.go:7389 subscription monitoring fetching past DkgResultSubmitted events starting from block [17481388]
2023-06-14T23:39:03.540Z    INFO    keep-contract-WalletCoordinator contract/WalletCoordinator.go:3115  subscription monitoring fetching past DepositSweepProposalSubmitted events starting from block [17481388]
2023-06-14T23:39:03.540Z    INFO    keep-contract-WalletCoordinator contract/WalletCoordinator.go:3488  subscription monitoring fetching past HeartbeatRequestSubmitted events starting from block [17481388]
2023-06-14T23:39:03.663Z    INFO    keep-contract-WalletRegistry    contract/WalletRegistry.go:7777 subscription monitoring fetched [0] past DkgStarted events
2023-06-14T23:39:03.670Z    INFO    keep-contract-WalletRegistry    contract/WalletRegistry.go:7407 subscription monitoring fetched [0] past DkgResultSubmitted events
2023-06-14T23:39:03.681Z    INFO    keep-contract-WalletCoordinator contract/WalletCoordinator.go:3132  subscription monitoring fetched [0] past DepositSweepProposalSubmitted events
2023-06-14T23:39:03.784Z    INFO    dht/RtRefreshManager    rtrefresh/rt_refresh_manager.go:286 finished refreshing cpl 5, routing table size is now 70
2023-06-14T23:40:01.646Z    ERROR   keep-contract-WalletCoordinator contract/WalletCoordinator.go:3499  subscription failed to pull events: [error retrieving past HeartbeatRequestSubmitted events: [Internal server error]]
2023-06-14T23:40:02.380Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]
2023-06-14T23:41:02.380Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]
2023-06-14T23:42:02.380Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]
2023-06-14T23:43:02.380Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]
2023-06-14T23:44:02.380Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]
2023-06-14T23:45:02.380Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]
2023-06-14T23:46:02.380Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]
2023-06-14T23:47:02.380Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]
2023-06-14T23:48:02.380Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]
2023-06-14T23:49:02.380Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]

ERROR keep-contract-WalletRegistry contract/WalletRegistry.go:7401 subscription failed to pull events: [error retrieving past DkgResultSubmitted events: [Internal server error]]

context

2023-06-14T19:38:55.387Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [146]
2023-06-14T19:39:55.387Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [146]
2023-06-14T19:40:55.386Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [146]
2023-06-14T19:40:56.496Z    INFO    keep-contract-WalletCoordinator contract/WalletCoordinator.go:3488  subscription monitoring fetching past HeartbeatRequestSubmitted events starting from block [17480215]
2023-06-14T19:40:56.496Z    INFO    keep-contract-WalletRegistry    contract/WalletRegistry.go:7760 subscription monitoring fetching past DkgStarted events starting from block [17480215]
2023-06-14T19:40:56.496Z    INFO    keep-contract-WalletCoordinator contract/WalletCoordinator.go:3115  subscription monitoring fetching past DepositSweepProposalSubmitted events starting from block [17480215]
2023-06-14T19:40:56.496Z    INFO    keep-contract-WalletRegistry    contract/WalletRegistry.go:7389 subscription monitoring fetching past DkgResultSubmitted events starting from block [17480215]
2023-06-14T19:40:56.626Z    INFO    keep-contract-WalletCoordinator contract/WalletCoordinator.go:3505  subscription monitoring fetched [0] past HeartbeatRequestSubmitted events
2023-06-14T19:40:56.627Z    INFO    keep-contract-WalletCoordinator contract/WalletCoordinator.go:3132  subscription monitoring fetched [0] past DepositSweepProposalSubmitted events
2023-06-14T19:40:56.638Z    INFO    keep-contract-WalletRegistry    contract/WalletRegistry.go:7777 subscription monitoring fetched [0] past DkgStarted events
2023-06-14T19:41:54.608Z    ERROR   keep-contract-WalletRegistry    contract/WalletRegistry.go:7401 subscription failed to pull events: [error retrieving past DkgResultSubmitted events: [Internal server error]]
2023-06-14T19:41:55.386Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [146]
2023-06-14T19:42:55.387Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [146]
2023-06-14T19:43:55.386Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [146]
2023-06-14T19:44:55.387Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [146]
2023-06-14T19:45:55.387Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [146]
2023-06-14T19:46:55.386Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [146]
2023-06-14T19:47:55.387Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [146]
2023-06-14T19:48:55.387Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [146]
2023-06-14T19:49:55.386Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [146]
2023-06-14T19:50:55.387Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [146]

ERROR keep-contract-WalletCoordinator contract/WalletCoordinator.go:3550 subscription to event HeartbeatRequestSubmitted failed with error: [read tcp IP_ADDRESS:38014->IP_ADDRESS:443: i/o timeout]; resubscription attempt will be performed and ERROR keep-contract-WalletRegistry contract/WalletRegistry.go:7455 subscription to event DkgResultSubmitted failed with error: [read tcp IP_ADDRESS:33310->IP_ADDRESS:443: i/o timeout]; resubscription attempt will be performed

context

2023-06-14T19:24:52.504Z    INFO    keep-contract-WalletRegistry    contract/WalletRegistry.go:7389 subscription monitoring fetching past DkgResultSubmitted events starting from block [17480135]
2023-06-14T19:24:52.631Z    INFO    keep-contract-WalletCoordinator contract/WalletCoordinator.go:3132  subscription monitoring fetched [0] past DepositSweepProposalSubmitted events
2023-06-14T19:24:52.631Z    INFO    keep-contract-WalletCoordinator contract/WalletCoordinator.go:3505  subscription monitoring fetched [0] past HeartbeatRequestSubmitted events
2023-06-14T19:24:52.643Z    INFO    keep-contract-WalletRegistry    contract/WalletRegistry.go:7777 subscription monitoring fetched [0] past DkgStarted events
2023-06-14T19:24:52.651Z    INFO    keep-contract-WalletRegistry    contract/WalletRegistry.go:7407 subscription monitoring fetched [0] past DkgResultSubmitted events
2023-06-14T19:25:51.388Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [144]
2023-06-14T19:26:51.388Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [144]
2023-06-14T19:27:51.388Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [144]
2023-06-14T19:28:22.528Z    WARN    keep-ethereum   go-log@v1.0.5/log.go:180    subscription to new blocks interrupted: [read tcp IP_ADDRESS:49418->IP_ADDRESS:443: i/o timeout]
2023-06-14T19:28:28.540Z    INFO    keep-libp2p libp2p/libp2p.go:526    established connection to [/ip4/137.184.124.182/tcp/34540/ipfs/16Uiu2HAmFq9yrhX83xDGCtyHVHRJvMCiBwxwnuLNGJXs24HcRFSC]
2023-06-14T19:28:32.528Z    ERROR   keep-contract-WalletCoordinator contract/WalletCoordinator.go:3550  subscription to event HeartbeatRequestSubmitted failed with error: [read tcp IP_ADDRESS:38014->IP_ADDRESS:443: i/o timeout]; resubscription attempt will be performed
2023-06-14T19:28:37.529Z    WARN    keep-ethereum   go-log@v1.0.5/log.go:180    could not create subscription to new blocks: [context deadline exceeded]
2023-06-14T19:28:42.529Z    ERROR   keep-contract-WalletRegistry    contract/WalletRegistry.go:7455 subscription to event DkgResultSubmitted failed with error: [read tcp IP_ADDRESS:33310->IP_ADDRESS:443: i/o timeout]; resubscription attempt will be performed
2023-06-14T19:28:51.388Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]
2023-06-14T19:28:56.529Z    WARN    keep-contract-WalletCoordinator contract/WalletCoordinator.go:3541  subscription to event HeartbeatRequestSubmitted had to be retried [34.001044274s] since the last attempt; please inspect host chain connectivity
2023-06-14T19:29:30.530Z    WARN    keep-contract-WalletRegistry    contract/WalletRegistry.go:7446 subscription to event DkgResultSubmitted had to be retried [1m8.002470717s] since the last attempt; please inspect host chain connectivity
2023-06-14T19:29:51.388Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]
2023-06-14T19:30:51.388Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]
2023-06-14T19:31:51.388Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]
2023-06-14T19:32:51.388Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]
2023-06-14T19:33:51.388Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]
2023-06-14T19:34:51.388Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]
2023-06-14T19:35:51.388Z    INFO    keep-libp2p libp2p/libp2p.go:242    number of connected peers: [145]

These are all error logs since 2023-05-15

keep-contract-WalletCoordinator contract/WalletCoordinator.go:3177  subscription to event DepositSweepProposalSubmitted failed with error: [read tcp IP_ADDRESS:38192->IP_ADDRESS:443: i/o timeout]; resubscription attempt will be performed
keep-contract-WalletCoordinator contract/WalletCoordinator.go:3499  subscription failed to pull events: [error retrieving past HeartbeatRequestSubmitted events: [Internal server error]]
keep-contract-WalletCoordinator contract/WalletCoordinator.go:3550  subscription to event HeartbeatRequestSubmitted failed with error: [read tcp IP_ADDRESS:38014->IP_ADDRESS:443: i/o timeout]; resubscription attempt will be performed
keep-contract-WalletCoordinator contract/WalletCoordinator.go:3550  subscription to event HeartbeatRequestSubmitted failed with error: [read tcp IP_ADDRESS:55050->IP_ADDRESS:443: i/o timeout]; resubscription attempt will be performed
keep-contract-WalletRegistry    contract/WalletRegistry.go:7401 subscription failed to pull events: [error retrieving past DkgResultSubmitted events: [Internal server error]]
keep-contract-WalletRegistry    contract/WalletRegistry.go:7401 subscription failed to pull events: [error retrieving past DkgResultSubmitted events: [read tcp IP_ADDRESS:51966->IP_ADDRESS:443: i/o timeout]]
keep-contract-WalletRegistry    contract/WalletRegistry.go:7401 subscription failed to pull events: [error retrieving past DkgResultSubmitted events: [websocket: close 1006 (abnormal closure): unexpected EOF]]
keep-contract-WalletRegistry    contract/WalletRegistry.go:7455 subscription to event DkgResultSubmitted failed with error: [dial tcp IP_ADDRESS:443: i/o timeout]; resubscription attempt will be performed
keep-contract-WalletRegistry    contract/WalletRegistry.go:7455 subscription to event DkgResultSubmitted failed with error: [read tcp IP_ADDRESS:33310->IP_ADDRESS:443: i/o timeout]; resubscription attempt will be performed
keep-contract-WalletRegistry    contract/WalletRegistry.go:7455 subscription to event DkgResultSubmitted failed with error: [websocket: bad handshake (HTTP status 502 Bad Gateway)]; resubscription attempt will be performed
keep-contract-WalletRegistry    contract/WalletRegistry.go:7771 subscription failed to pull events: [error retrieving past DkgStarted events: [read tcp IP_ADDRESS:51966->IP_ADDRESS:443: i/o timeout]]
keep-contract-WalletRegistry    contract/WalletRegistry.go:7771 subscription failed to pull events: [error retrieving past DkgStarted events: [websocket: close 1006 (abnormal closure): unexpected EOF]]
keep-contract-WalletRegistry    contract/WalletRegistry.go:7822 subscription to event DkgStarted failed with error: [websocket: bad handshake (HTTP status 502 Bad Gateway)]; resubscription attempt will be performed
keep-electrum   electrum/electrum.go:713    failed to ping the electrum server; please verify health of the electrum server: [retry timeout [2m0s] exceeded; most recent error: [request failed: [request timeout]]]
keep-libp2p libp2p/channel.go:286   couldn't find unmarshaler for type [protocol_announcer/announcement_message]
keep-libp2p libp2p/channel.go:286   couldn't find unmarshaler for type [tbtc/signing_done_message]
keep-tbtc   tbtc/wallet.go:116  action execution terminated with error: [error while ensuring wallet state is synced between BTC and host chain: [cannot get mempool: [cannot get P2PKH mempool items for public key hash [0x...]: [failed to get mempool for script [0x...]: [retry timeout [2m0s] exceeded; most recent error: [request failed: [request timeout]]]]]]]   {"wallet": "0x...", "action": "DepositSweep"}
keep-tbtc   tbtc/wallet.go:116  action execution terminated with error: [error while ensuring wallet state is synced between BTC and host chain: [cannot get mempool: [cannot get P2PKH mempool items for public key hash [0x...]: [failed to get mempool for script [0x...]: [retry timeout [2m0s] exceeded; most recent error: [request failed: [use of closed network connection]]]]]]]  {"wallet": "0x...", "action": "DepositSweep"}

These can be skipped, because they are related to the poor blockstream server issue:

keep-libp2p libp2p/channel.go:286   couldn't find unmarshaler for type [protocol_announcer/announcement_message]
keep-libp2p libp2p/channel.go:286   couldn't find unmarshaler for type [tbtc/signing_done_message]

I replaced IP addresses and all 0xaaaa strings from the logs. If you need them, let me know.

thevops commented 1 year ago

Similar situation with log: WARN keep-electrum electrum/electrum.go:795 connection to electrum server is down; reconnecting... It happens from time to time, but regularly, and after it occurs immediately occurs also: INFO keep-electrum electrum/electrum.go:800 reconnected to electrum server I think, that the first log should also have INFO severity.

nkuba commented 1 year ago

Thank you for the report! We will take a closer look at the log messages you mentioned.

For the couldn't find unmarshaler for type logs we have a separate issue https://github.com/keep-network/keep-core/issues/3611.

thevops commented 1 year ago

Another log that probably can be decreased to warning:

{"level":"error","ts":"2023-08-30T11:33:26.063Z","logger":"keep-clientinfo","caller":"clientinfo/clientinfo.go:62","msg":"could not write response: [write tcp 10.35.0.99:9614->10.35.0.1:35976: write: broken pipe]"}

or with slightly different message

could not write response: [write tcp 10.35.0.103:9608->10.35.0.1:34080: write: connection reset by peer]