Avalanchego producing enormous amount of P chain logs

[metmirr]

Describe the bug
Avalanchego is producing an enormous amount of logs for the P chain. It's like there is an infinite loop that prints the same log over and over again.

To Reproduce
I am running a custom local network with 3 validator nodes(each node is on a different physical machine) and my genesis file is a modified version of genesis_local.json.

Expected behavior
Normal logs.

Logs

[01-26|11:07:45.210] INFO <P Chain> proposervm/pre_fork_block.go:223 built block {"blkID": "Hf3JzFPKeHpnFzZjowb7Lk6RcMBVKEpdJv2SesbBCUbnKdhdm", "innerBlkID": "g6JoMbFdqEBnVN8vjG9pzsq59Vxtk8j8UyUykLZooFfyquANX", "height": 1, "parentTimestamp": "[01-24|10:06:51.000]", "blockTimestamp": "[01-26|11:07:45.000]"}
[01-26|11:07:45.210] INFO <P Chain> proposervm/pre_fork_block.go:223 built block {"blkID": "Hf3JzFPKeHpnFzZjowb7Lk6RcMBVKEpdJv2SesbBCUbnKdhdm", "innerBlkID": "g6JoMbFdqEBnVN8vjG9pzsq59Vxtk8j8UyUykLZooFfyquANX", "height": 1, "parentTimestamp": "[01-24|10:06:51.000]", "blockTimestamp": "[01-26|11:07:45.000]"}
[01-26|11:07:45.210] INFO <P Chain> proposervm/pre_fork_block.go:223 built block {"blkID": "Hf3JzFPKeHpnFzZjowb7Lk6RcMBVKEpdJv2SesbBCUbnKdhdm", "innerBlkID": "g6JoMbFdqEBnVN8vjG9pzsq59Vxtk8j8UyUykLZooFfyquANX", "height": 1, "parentTimestamp": "[01-24|10:06:51.000]", "blockTimestamp": "[01-26|11:07:45.000]"}
[01-26|11:07:45.210] INFO <P Chain> proposervm/pre_fork_block.go:223 built block {"blkID": "Hf3JzFPKeHpnFzZjowb7Lk6RcMBVKEpdJv2SesbBCUbnKdhdm", "innerBlkID": "g6JoMbFdqEBnVN8vjG9pzsq59Vxtk8j8UyUykLZooFfyquANX", "height": 1, "parentTimestamp": "[01-24|10:06:51.000]", "blockTimestamp": "[01-26|11:07:45.000]"}

And logs directory overview:

root@node01:~/.avalanchego/logs# ls -l
total 60260
-rw-r--r-- 1 root root   13128 Jan 26 14:53 C.log
-rw-r--r-- 1 root root 8388354 Jan 26 15:06 P-2023-01-26T15-06-55.090.log
-rw-r--r-- 1 root root 8388358 Jan 26 15:06 P-2023-01-26T15-06-58.577.log
-rw-r--r-- 1 root root 8388536 Jan 26 15:07 P-2023-01-26T15-07-02.289.log
-rw-r--r-- 1 root root 8388388 Jan 26 15:07 P-2023-01-26T15-07-06.065.log
-rw-r--r-- 1 root root 8388595 Jan 26 15:07 P-2023-01-26T15-07-09.908.log
-rw-r--r-- 1 root root 8388503 Jan 26 15:07 P-2023-01-26T15-07-13.478.log
-rw-r--r-- 1 root root 8388397 Jan 26 15:07 P-2023-01-26T15-07-17.380.log
-rw-r--r-- 1 root root 2946858 Jan 26 15:07 P.log
-rw-r--r-- 1 root root    1281 Jan 26 14:53 X.log
-rw-r--r-- 1 root root   12694 Jan 26 14:53 main.log

Metrics

Operating System
Ubuntu 22.04 LTS

[ceyonur]

It seems to me that your network was never able to reach a consensus.
1- Check health API to see what's wrong with your network
2- Try to run minimum 5 validators
3- Your genesis file might also lead network to a wrong state, plus that file must be available and identical for all your nodes

[metmirr]

Thanks for the comment.
I have done a similar setup(3 nodes) with version avalanchegov1.7.7 it was working fine.

1- Health API response

{
  "jsonrpc": "2.0",
  "result": {
    "checks": {
      "C": {
        "message": {
          "consensus": {
            "longestRunningBlock": "0s",
            "outstandingBlocks": 0
          },
          "vm": null
        },
        "timestamp": "2023-01-26T15:51:14.669736062Z",
        "duration": 12480
      },
      "P": {
        "message": {
          "consensus": {
            "longestRunningBlock": "0s",
            "outstandingBlocks": 0
          },
          "vm": {
            "primary-percentConnected": 1
          }
        },
        "timestamp": "2023-01-26T15:51:14.669771312Z",
        "duration": 86589
      },
      "X": {
        "message": {
          "consensus": {
            "outstandingVertices": 0,
            "snowstorm": {
              "outstandingTransactions": 0
            }
          },
          "vm": null
        },
        "timestamp": "2023-01-26T15:51:14.669720982Z",
        "duration": 27799
      },
      "bootstrapped": {
        "message": [],
        "timestamp": "2023-01-26T15:51:14.669741642Z",
        "duration": 5320
      },
      "database": {
        "timestamp": "2023-01-26T15:51:14.669725582Z",
        "duration": 610
      },
      "diskspace": {
        "message": {
          "availableDiskBytes": 322995503104
        },
        "timestamp": "2023-01-26T15:51:14.669731392Z",
        "duration": 5090
      },
      "network": {
        "message": {
          "connectedPeers": 2,
          "sendFailRate": 0,
          "timeSinceLastMsgReceived": "2.669708593s",
          "timeSinceLastMsgSent": "4.669708593s"
        },
        "timestamp": "2023-01-26T15:51:14.669712153Z",
        "duration": 26100
      },
      "router": {
        "message": {
          "longestRunningRequest": "0s",
          "outstandingRequests": 0
        },
        "timestamp": "2023-01-26T15:51:14.669724092Z",
        "duration": 9719
      }
    },
    "healthy": true
  },
  "id": 1
}

3- Genesis file identical across the network, and info API response for bootstrapping:

{"jsonrpc":"2.0","result":{"isBootstrapped":true},"id":1}

[ceyonur]

could you provide your genesis, log files?

[metmirr]

Genesis file (github doesn't allow JSON files so I changed the ext to txt) genesis_custom.txt
Logs: logs.zip

[abi87]

Hello @metmirr;
I believe the issue is with initialStakeDuration.
The value you specified is so large that causes an overflow in the calculation of validator's staking period.
This in turns makes the P-chain attempt to remove and reward the validators as soon as it starts.
The blocks you see repeatedly created contain a RewardTx transactions for the validators.
You could avoid the issue by reducing staking period to, e.g., 31536000, which is the value we use in genesis_local.json.
Please make this change and confirm things are fine on your side.

[metmirr]

Thank you @abi87 I will try it out and let you know.

[metmirr]

@abi87 @ceyonur thank you guys for helping with the issue.

I can confirm that changing initialStakeDuration to a lower value fixed the issue. I will leave it to you to close the issue or not.

[ceyonur]

Closing this as lowering the value fixed the issue
cc @abi87