Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Verify logs severity #3636

Open
thevops opened this issue Jun 15, 2023 · 3 comments
Open

Verify logs severity #3636

thevops opened this issue Jun 15, 2023 · 3 comments

Comments

@thevops
Copy link
Contributor

thevops commented Jun 15, 2023

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 thevops changed the title Verify log severity Verify logs severity Jun 15, 2023
@thevops
Copy link
Contributor Author

thevops commented Jul 4, 2023

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
Copy link
Member

nkuba commented Jul 25, 2023

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 #3611.

@thevops
Copy link
Contributor Author

thevops commented Aug 31, 2023 •
edited

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]

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@nkuba @thevops