besu icon indicating copy to clipboard operation
besu copied to clipboard

Published 20 hours ago • verified publisher icon hyperledger

Duplicate log lines while syncing

Open benjaminion opened this issue 2 years ago • 11 comments

Description

As a node operator, I want to see clean logs so that I can sort signal from noise more easily.

Acceptance Criteria

  • Besu does not output multiple identical consecutive console log entries

Steps to Reproduce (Bug)

  1. Start a sync.
  2. Watch the console.

Expected behavior: [What you expect to happen]

Logs look like

Aug 28 20:44:46 metalalbert besu[17025]: 2022-08-28 20:44:46.156+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
Aug 28 20:44:51 metalalbert besu[17025]: 2022-08-28 20:44:51.156+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
Aug 28 20:44:54 metalalbert besu[17025]: 2022-08-28 20:44:54.778+00:00 | nioEventLoopGroup-3-1 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
Aug 28 20:44:59 metalalbert besu[17025]: 2022-08-28 20:44:59.778+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
Aug 28 20:45:04 metalalbert besu[17025]: 2022-08-28 20:45:04.778+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.

Actual behavior: [What actually happens]

Logs look as follows. Note that each line appears three times with identical timestamps.

Aug 28 20:44:46 metalalbert besu[17025]: 2022-08-28 20:44:46.156+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
Aug 28 20:44:46 metalalbert besu[17025]: 2022-08-28 20:44:46.156+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
Aug 28 20:44:46 metalalbert besu[17025]: 2022-08-28 20:44:46.156+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
Aug 28 20:44:51 metalalbert besu[17025]: 2022-08-28 20:44:51.156+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
Aug 28 20:44:51 metalalbert besu[17025]: 2022-08-28 20:44:51.156+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
Aug 28 20:44:51 metalalbert besu[17025]: 2022-08-28 20:44:51.156+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
Aug 28 20:44:54 metalalbert besu[17025]: 2022-08-28 20:44:54.778+00:00 | nioEventLoopGroup-3-1 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
Aug 28 20:44:54 metalalbert besu[17025]: 2022-08-28 20:44:54.778+00:00 | nioEventLoopGroup-3-1 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
Aug 28 20:44:54 metalalbert besu[17025]: 2022-08-28 20:44:54.778+00:00 | nioEventLoopGroup-3-1 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
Aug 28 20:44:59 metalalbert besu[17025]: 2022-08-28 20:44:59.778+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
Aug 28 20:44:59 metalalbert besu[17025]: 2022-08-28 20:44:59.778+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
Aug 28 20:44:59 metalalbert besu[17025]: 2022-08-28 20:44:59.778+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
Aug 28 20:45:04 metalalbert besu[17025]: 2022-08-28 20:45:04.778+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
Aug 28 20:45:04 metalalbert besu[17025]: 2022-08-28 20:45:04.778+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
Aug 28 20:45:04 metalalbert besu[17025]: 2022-08-28 20:45:04.778+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.

Frequency: [What percentage of the time does it occur?]

Frequently when printing a message relating to waiting for peers is printed (every few minutes). Identical lines are printed between one and five times each.

Versions (Add all that apply)

  • Software version: 22.7.1

benjaminion avatar Aug 28 '22 20:08 benjaminion

I was not able to reproduce this. Are you running in a docker container or using the distro startup script? I am assuming that you are not configuring any custom logging such as https://besu.hyperledger.org/en/stable/public-networks/how-to/monitor/logging/#advanced-logging

This seems to me like a case of multiple additive log4j categories or appenders are at work here.

jflo avatar Aug 31 '22 16:08 jflo

Not running in docker - just running the besu distribution directly via systemctl. No custom logging settings at all.

I can supply multiple thousands of examples from my logs if you like :-) It only seems to occur for variants of the waiting for peers messages, all other log messages only appeared a single time as far as I saw.

benjaminion avatar Aug 31 '22 17:08 benjaminion 

$ journalctl -u besu.service --since "2022-08-27 00:00" | wc -l
67509
$ journalctl -u besu.service --since "2022-08-27 00:00" | uniq | wc -l
45206

This suggests that ~22 thousand lines are redundant (1/3 of the total) down to duplicating the exact timestamp to the millisecond.

benjaminion avatar Aug 31 '22 18:08 benjaminion

The first column in the below is the number of times the identical line (including timestamp) was printed consecutively - apparently up to 32 times. I didn't see these particularly large numbers at the time as they occurred in a spate in the early morning.

All of the instances are to do with waiting for peers.

$ journalctl -u besu.service --since "2022-08-27 00:00" | uniq -c | sort -brn | head -n 100
     32 Aug 29 04:25:01 metalalbert besu[17025]: 2022-08-29 04:25:01.557+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     32 Aug 29 04:24:56 metalalbert besu[17025]: 2022-08-29 04:24:56.557+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
     32 Aug 29 04:24:33 metalalbert besu[17025]: 2022-08-29 04:24:33.767+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
     32 Aug 29 04:24:28 metalalbert besu[17025]: 2022-08-29 04:24:28.767+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
     32 Aug 29 04:23:59 metalalbert besu[17025]: 2022-08-29 04:23:59.937+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     32 Aug 29 04:23:54 metalalbert besu[17025]: 2022-08-29 04:23:54.937+00:00 | nioEventLoopGroup-3-7 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
     32 Aug 29 04:23:54 metalalbert besu[17025]: 2022-08-29 04:23:54.458+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     32 Aug 29 04:23:49 metalalbert besu[17025]: 2022-08-29 04:23:49.458+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
     32 Aug 29 04:22:53 metalalbert besu[17025]: 2022-08-29 04:22:53.254+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     32 Aug 29 04:22:48 metalalbert besu[17025]: 2022-08-29 04:22:48.254+00:00 | nioEventLoopGroup-3-7 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
     32 Aug 29 04:21:45 metalalbert besu[17025]: 2022-08-29 04:21:45.569+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     32 Aug 29 04:21:40 metalalbert besu[17025]: 2022-08-29 04:21:40.569+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
     32 Aug 29 04:21:35 metalalbert besu[17025]: 2022-08-29 04:21:35.569+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
     31 Aug 29 04:24:23 metalalbert besu[17025]: 2022-08-29 04:24:23.767+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
     31 Aug 29 04:21:30 metalalbert besu[17025]: 2022-08-29 04:21:30.569+00:00 | nioEventLoopGroup-3-5 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
     31 Aug 29 04:21:10 metalalbert besu[17025]: 2022-08-29 04:21:10.742+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     31 Aug 29 04:21:05 metalalbert besu[17025]: 2022-08-29 04:21:05.742+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     31 Aug 29 04:21:00 metalalbert besu[17025]: 2022-08-29 04:21:00.742+00:00 | nioEventLoopGroup-3-10 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     31 Aug 29 04:20:18 metalalbert besu[17025]: 2022-08-29 04:20:18.094+00:00 | nioEventLoopGroup-3-5 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     31 Aug 29 04:20:05 metalalbert besu[17025]: 2022-08-29 04:20:05.717+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     31 Aug 29 04:20:00 metalalbert besu[17025]: 2022-08-29 04:20:00.717+00:00 | nioEventLoopGroup-3-1 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     31 Aug 29 04:19:50 metalalbert besu[17025]: 2022-08-29 04:19:50.054+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     31 Aug 29 04:19:45 metalalbert besu[17025]: 2022-08-29 04:19:45.054+00:00 | nioEventLoopGroup-3-1 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     31 Aug 29 04:19:15 metalalbert besu[17025]: 2022-08-29 04:19:15.383+00:00 | nioEventLoopGroup-3-7 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     31 Aug 29 04:19:12 metalalbert besu[17025]: 2022-08-29 04:19:12.585+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     31 Aug 29 04:19:07 metalalbert besu[17025]: 2022-08-29 04:19:07.585+00:00 | nioEventLoopGroup-3-3 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     31 Aug 29 04:19:02 metalalbert besu[17025]: 2022-08-29 04:19:02.392+00:00 | nioEventLoopGroup-3-5 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     31 Aug 29 04:18:47 metalalbert besu[17025]: 2022-08-29 04:18:47.370+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     31 Aug 29 04:18:42 metalalbert besu[17025]: 2022-08-29 04:18:42.370+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     31 Aug 29 04:18:32 metalalbert besu[17025]: 2022-08-29 04:18:32.369+00:00 | nioEventLoopGroup-3-1 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     31 Aug 29 04:18:23 metalalbert besu[17025]: 2022-08-29 04:18:23.086+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 1 peers currently connected.
     30 Aug 29 04:18:18 metalalbert besu[17025]: 2022-08-29 04:18:18.086+00:00 | nioEventLoopGroup-3-5 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     30 Aug 29 04:15:15 metalalbert besu[17025]: 2022-08-29 04:15:15.112+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     30 Aug 29 04:13:27 metalalbert besu[17025]: 2022-08-29 04:13:27.543+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     30 Aug 29 04:12:11 metalalbert besu[17025]: 2022-08-29 04:12:11.633+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 1 peers currently connected.
     30 Aug 29 04:11:48 metalalbert besu[17025]: 2022-08-29 04:11:48.333+00:00 | nioEventLoopGroup-3-2 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     30 Aug 29 04:11:27 metalalbert besu[17025]: 2022-08-29 04:11:27.432+00:00 | nioEventLoopGroup-3-3 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
     30 Aug 29 04:10:39 metalalbert besu[17025]: 2022-08-29 04:10:39.419+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 1 peers currently connected.
     29 Aug 29 04:24:38 metalalbert besu[17025]: 2022-08-29 04:24:38.767+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     29 Aug 29 04:23:44 metalalbert besu[17025]: 2022-08-29 04:23:44.458+00:00 | nioEventLoopGroup-3-2 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
     29 Aug 29 04:21:53 metalalbert besu[17025]: 2022-08-29 04:21:53.270+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     28 Aug 29 04:21:48 metalalbert besu[17025]: 2022-08-29 04:21:48.270+00:00 | nioEventLoopGroup-3-8 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
     28 Aug 29 04:17:23 metalalbert besu[17025]: 2022-08-29 04:17:23.631+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     28 Aug 29 04:16:58 metalalbert besu[17025]: 2022-08-29 04:16:58.013+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     28 Aug 29 04:16:14 metalalbert besu[17025]: 2022-08-29 04:16:14.531+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     28 Aug 29 04:10:12 metalalbert besu[17025]: 2022-08-29 04:10:12.837+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     28 Aug 29 04:00:43 metalalbert besu[17025]: 2022-08-29 04:00:43.177+00:00 | nioEventLoopGroup-3-8 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     28 Aug 29 03:59:52 metalalbert besu[17025]: 2022-08-29 03:59:52.016+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 0 peers currently connected.
     27 Aug 29 04:16:40 metalalbert besu[17025]: 2022-08-29 04:16:40.773+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     27 Aug 29 04:14:22 metalalbert besu[17025]: 2022-08-29 04:14:22.354+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     27 Aug 29 04:03:32 metalalbert besu[17025]: 2022-08-29 04:03:32.274+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     27 Aug 29 04:00:12 metalalbert besu[17025]: 2022-08-29 04:00:12.328+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     27 Aug 29 03:55:51 metalalbert besu[17025]: 2022-08-29 03:55:51.583+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 1 peers currently connected.
     27 Aug 29 03:55:10 metalalbert besu[17025]: 2022-08-29 03:55:10.062+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     26 Aug 29 04:07:52 metalalbert besu[17025]: 2022-08-29 04:07:52.483+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     26 Aug 29 04:06:44 metalalbert besu[17025]: 2022-08-29 04:06:44.896+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     26 Aug 29 04:03:58 metalalbert besu[17025]: 2022-08-29 04:03:58.774+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 0 peers currently connected.
     26 Aug 29 04:02:52 metalalbert besu[17025]: 2022-08-29 04:02:52.549+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 0 peers currently connected.
     26 Aug 29 03:56:21 metalalbert besu[17025]: 2022-08-29 03:56:21.626+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 1 peers currently connected.
     26 Aug 29 03:53:19 metalalbert besu[17025]: 2022-08-29 03:53:19.879+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     26 Aug 29 03:53:14 metalalbert besu[17025]: 2022-08-29 03:53:14.879+00:00 | nioEventLoopGroup-3-3 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     26 Aug 29 03:52:14 metalalbert besu[17025]: 2022-08-29 03:52:14.434+00:00 | nioEventLoopGroup-3-1 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     26 Aug 29 03:50:55 metalalbert besu[17025]: 2022-08-29 03:50:55.571+00:00 | nioEventLoopGroup-3-7 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     26 Aug 29 03:50:51 metalalbert besu[17025]: 2022-08-29 03:50:51.324+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 1 peers currently connected.
     26 Aug 29 03:50:46 metalalbert besu[17025]: 2022-08-29 03:50:46.324+00:00 | nioEventLoopGroup-3-6 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     26 Aug 29 03:50:38 metalalbert besu[17025]: 2022-08-29 03:50:38.284+00:00 | nioEventLoopGroup-3-5 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     26 Aug 29 03:50:16 metalalbert besu[17025]: 2022-08-29 03:50:16.265+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 1 peers currently connected.
     26 Aug 29 03:50:11 metalalbert besu[17025]: 2022-08-29 03:50:11.265+00:00 | nioEventLoopGroup-3-6 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     26 Aug 29 03:49:21 metalalbert besu[17025]: 2022-08-29 03:49:21.818+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     26 Aug 29 03:49:16 metalalbert besu[17025]: 2022-08-29 03:49:16.818+00:00 | nioEventLoopGroup-3-4 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     25 Aug 29 04:26:18 metalalbert besu[17025]: 2022-08-29 04:26:18.378+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
     25 Aug 29 04:24:51 metalalbert besu[17025]: 2022-08-29 04:24:51.557+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
     25 Aug 29 04:19:07 metalalbert besu[17025]: 2022-08-29 04:19:07.393+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 1 peers currently connected.
     25 Aug 29 04:14:05 metalalbert besu[17025]: 2022-08-29 04:14:05.690+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     25 Aug 29 04:08:57 metalalbert besu[17025]: 2022-08-29 04:08:57.158+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 1 peers currently connected.
     25 Aug 29 04:05:50 metalalbert besu[17025]: 2022-08-29 04:05:50.990+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 1 peers currently connected.
     25 Aug 29 04:04:10 metalalbert besu[17025]: 2022-08-29 04:04:10.057+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     25 Aug 29 04:03:12 metalalbert besu[17025]: 2022-08-29 04:03:12.154+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     25 Aug 29 03:58:05 metalalbert besu[17025]: 2022-08-29 03:58:05.687+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     25 Aug 29 03:52:19 metalalbert besu[17025]: 2022-08-29 03:52:19.434+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     25 Aug 29 03:48:26 metalalbert besu[17025]: 2022-08-29 03:48:26.227+00:00 | nioEventLoopGroup-3-9 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     25 Aug 29 03:47:21 metalalbert besu[17025]: 2022-08-29 03:47:21.563+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     25 Aug 29 03:47:16 metalalbert besu[17025]: 2022-08-29 03:47:16.563+00:00 | nioEventLoopGroup-3-7 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     25 Aug 29 03:45:46 metalalbert besu[17025]: 2022-08-29 03:45:46.155+00:00 | nioEventLoopGroup-3-1 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     25 Aug 29 03:45:33 metalalbert besu[17025]: 2022-08-29 03:45:33.000+00:00 | nioEventLoopGroup-3-1 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     25 Aug 29 03:43:45 metalalbert besu[17025]: 2022-08-29 03:43:45.945+00:00 | nioEventLoopGroup-3-10 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     24 Aug 29 04:26:13 metalalbert besu[17025]: 2022-08-29 04:26:13.378+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  2 / 3 required peers currently available.
     24 Aug 29 04:24:16 metalalbert besu[17025]: 2022-08-29 04:24:16.495+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     24 Aug 29 04:19:55 metalalbert besu[17025]: 2022-08-29 04:19:55.054+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     24 Aug 29 04:16:21 metalalbert besu[17025]: 2022-08-29 04:16:21.303+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 1 peers currently connected.
     24 Aug 29 04:15:50 metalalbert besu[17025]: 2022-08-29 04:15:50.290+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     24 Aug 29 04:12:29 metalalbert besu[17025]: 2022-08-29 04:12:29.261+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 1 peers currently connected.
     24 Aug 29 04:07:06 metalalbert besu[17025]: 2022-08-29 04:07:06.090+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 0 peers currently connected.
     24 Aug 29 04:00:36 metalalbert besu[17025]: 2022-08-29 04:00:36.819+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     24 Aug 29 03:59:21 metalalbert besu[17025]: 2022-08-29 03:59:21.982+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     24 Aug 29 03:53:25 metalalbert besu[17025]: 2022-08-29 03:53:25.925+00:00 | EthScheduler-Timer-0 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     24 Aug 29 03:51:34 metalalbert besu[17025]: 2022-08-29 03:51:34.995+00:00 | nioEventLoopGroup-3-9 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     24 Aug 29 03:50:16 metalalbert besu[17025]: 2022-08-29 03:50:16.682+00:00 | nioEventLoopGroup-3-7 | INFO  | FastSyncActions | Waiting for valid peers with chain height information.  1 / 3 required peers currently available.
     24 Aug 29 03:48:56 metalalbert besu[17025]: 2022-08-29 03:48:56.072+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.
     24 Aug 29 03:46:31 metalalbert besu[17025]: 2022-08-29 03:46:31.158+00:00 | EthScheduler-Timer-0 | INFO  | WaitForPeersTask | Waiting for 3 total peers to connect. 2 peers currently connected.

benjaminion avatar Aug 31 '22 18:08 benjaminion

Confirmed with @benjaminion that this was happening during an X-CHECKPOINT sync.

jflo avatar Sep 01 '22 18:09 jflo

Would you mind posting the systemctl startup settings? Still unable to reproduce.

jflo avatar Sep 01 '22 18:09 jflo

Here's the service file:

[Unit]
Description=Besu Client
Wants=network-online.target
After=network-online.target

[Service]
Type=simple
User=besu
Group=besu
Restart=always
RestartSec=5
SuccessExitStatus=143
WorkingDirectory=/data/besu
Environment=JAVA_OPTS=-Xmx4g
ExecStart=/usr/local/besu/bin/besu --config-file /etc/besu/besu.toml

[Install]
WantedBy=multi-user.target

And here's the config file.

network="mainnet"
engine-jwt-secret="/var/lib/teku/jwt.hex"
data-storage-format="BONSAI"
data-path="/data/besu"
p2p-host=<redacted>
host-allowlist=["127.0.0.1","192.168.1.203","localhost","albert"]
metrics-enabled=true
metrics-host="0.0.0.0"
rpc-http-enabled=true
rpc-http-host="0.0.0.0"
rpc-http-api=["ETH","NET","WEB3","DEBUG","ADMIN"]
rpc-http-cors-origins=["*"]
sync-mode="X_CHECKPOINT"
Xsynchronizer-downloader-chain-segment-size=100
Xsynchronizer-downloader-header-request-size=100
Xsynchronizer-fast-sync-full-validation-rate="0.0001"
fast-sync-min-peers=2

The Xsynchronizer options were courtesy of Adrian.

benjaminion avatar Sep 01 '22 18:09 benjaminion

Do you have a custom log4j config set up or custom ELK ingestion set up? the Aug 28 20:44:46 metalalbert besu[17025]: part of the log lines are not part of the standard log4j config and may come from a custom config or the particular way the log files are being injested.

Are these how the raw logs look coming out of the besu process?

shemnon avatar Sep 01 '22 19:09 shemnon

I believe that is being pre-pended by systemctl or journalctl

jflo avatar Sep 01 '22 21:09 jflo

Yes, prepended to each line automatically by journalctl.

benjaminion avatar Sep 01 '22 21:09 benjaminion

Confirmed with @benjaminion that this was happening during an X-CHECKPOINT sync.

Can add that I see 1000s of these too, using --sync-mode=X_SNAP

cfelde avatar Sep 16 '22 06:09 cfelde

Closing for sync logging changes in latest.

non-fungible-nelson avatar Jan 26 '23 12:01 non-fungible-nelson