Missed Block help with troubleshooting v8.0.0

Staking & Delegation Operate a Stake Pool
1

Hello community,

After a few epochs and some trouble with upgrades I seemed to be going ok. [CTL] pool was supposed to be leader on this epoch 415 but the node did not adopt a block. From the log I search for ‘error’ and found the following using:

grep "error" node0-20230603082843.json


grep "error" node0-20230603082843.json
{"app":[],"at":"2023-06-03T09:51:35.57Z","data":{"address":"161.97.108.250:6000","event":"ErrorPolicySuspendPeer (Just (ApplicationExceptionTrace (MuxError (MuxIOException Network.Socket.recvBuf: resource vanished (Connection reset by peer)) \"(recv errored)\"))) 1s 20s","kind":"ErrorPolicyTrace"},"env":"8.0.0:00000","host":"x9x","loc":null,"msg":"","ns":["cardano.node.ErrorPolicy"],"pid":"3245403","sev":"Warning","thread":"539"}
{"app":[],"at":"2023-06-03T23:13:06.52Z","data":{"domain":"\"relay1.cointradeledger.com\"","event":"Application Exception: 80.208.230.113:3001 MuxError (MuxIOException Network.Socket.recvBuf: resource vanished (Connection reset by peer)) \"(recv errored)\"","kind":"SubscriptionTrace"},"env":"8.0.0:00000","host":"x9x","loc":null,"msg":"","ns":["cardano.node.DnsSubscription"],"pid":"3245403","sev":"Error","thread":"336761"}
{"app":[],"at":"2023-06-03T23:13:06.52Z","data":{"address":"80.208.230.113:3001","event":"ErrorPolicySuspendPeer (Just (ApplicationExceptionTrace (MuxError (MuxIOException Network.Socket.recvBuf: resource vanished (Connection reset by peer)) \"(recv errored)\"))) 1s 20s","kind":"ErrorPolicyTrace"},"env":"8.0.0:00000","host":"x9x","loc":null,"msg":"","ns":["cardano.node.ErrorPolicy"],"pid":"3245403","sev":"Warning","thread":"542"}
{"app":[],"at":"2023-06-03T23:13:06.52Z","data":{"address":"80.208.230.113:37591","event":"ErrorPolicySuspendPeer (Just (ApplicationExceptionTrace (MuxError (MuxIOException Network.Socket.recvBuf: resource vanished (Connection reset by peer)) \"(recv errored)\"))) 1s 20s","kind":"ErrorPolicyTrace"},"env":"8.0.0:00000","host":"x9x","loc":null,"msg":"","ns":["cardano.node.ErrorPolicy"],"pid":"3245403","sev":"Warning","thread":"552"}

My node gLiveView looks like the following which shows zero transactions (not sure if this is normal, the relay is showing 1262 for Total Tx):

image

1 Like
2

It looks like you made a block 6 hours ago. Is that the block you mean?
In terms of logs, you need to look at the logs at the time of the block. See what they say at the allocated slot.

Screenshot_20230604_130721_Chrome
Screenshot_20230604_130721_Chrome1080×2340 137 KB

1 Like
3

You know your leadership schedule details for when you were supposed to mint your block. So you already know the exact timestamp to look in your logs.

I will use some of my data as an example. Say your leader schedule was:

94210034 2023-06-03T17:12:05+1000

Note that I converted my leader schedule data to my local timezone rather than it being left as UTC. Eg:

date -d “2023-06-04 00:41:02.00 UTC” “+%Y-%m-%dT%H:%M:%S%z”
2023-06-04T10:41:02+1000

Now look in your logs at this time:

journalctl --since "2023-06-03 17:12:05"

You should see logs like:

Jun 03 17:12:05 bprod1 cardano-node[471016]: [bprod1:cardano.node.LeadershipCheck:Info:263] [2023-06-03 07:12:05.00 UTC] {"chainDensity":4.704831e-2,"credentials":"Cardano","delegMapSize":1282316,"kind":"TraceStartLeadershipCheck","slot":94210034,"utxoSize":9996774}
Jun 03 17:12:05 bprod1 cardano-node[471016]: [bprod1:cardano.node.Forge:Info:263] [2023-06-03 07:12:05.04 UTC] fromList [("credentials",String "Cardano"),("val",Object (fromList [("kind",String "TraceNodeIsLeader"),("slot",Number 9.4210034e7)]))]
Jun 03 17:12:05 bprod1 cardano-node[471016]: [bprod1:cardano.node.Forge:Info:263] [2023-06-03 07:12:05.10 UTC] fromList [("credentials",String "Cardano"),("val",Object (fromList [("block",String "ba34d876d44afc824162fbe04b95fcf186cc28516e3be0e4f2fb39d029704346"),("blockNo",Number 8855882.0),("blockPrev",String "617c7c24da10f6dac74c98ba28573165eaba532c18cc3e73b3b38c73605c5376"),("kind",String "TraceForgedBlock"),("slot",Number 9.4210034e7)]))]

The first line says the node is starting a check to see if it is a leader.
The next line says it determined that it was a leader.
The 3rd line says that it forged (minted) a block.

If all this happened similarly in your node then at least you know you minted the block. Then you can analyse the logs further to try to identify what happened next. Did your relays pull the block from your block producer? You might need to look at the logs in your relays just after this time to find out.

gLiveView is nice eye-candy, but don’t rely on it as a tool for analysis. It wasn’t designed for that purpose.

1 Like
4

Many thanks jeremy and Terminada,

That’s super helpful and I really appreciate it.

I need to start from the beginning. I was able to get the leader slot using:

cncli.sh init

Which shows:

Validating epoch 415
CONFIRMED: Leader for slot ‘94253339’ and match found in CNCLI DB for this slot with pool’s VRF public key

So I can get the slot but now I need to get the date of the stot for the log search.

It seems from this that I did indeed mint a block but that is now showing on gLiveView, perhaps there’s an issue there with compatibility with v8.

In cardano BP I have my logging set to file, do you guys use file or the output window:

"defaultScribes": [
    [
      "FileSK",
      "/opt/cardano/cnode/logs/node0.json"
    ]
  ],
1 Like
5

So now you need a function to convert a slot number into a date time value for your timezone.

See: And so it begins: reflections on this first Shelley epoch

Shelley first slot: “2020-07-29 21:44:51 UTC”, epoch 208, slot 4492800

echo $(date -d"2020-07-29 21:44:51 UTC" "+%s") - 4492800 | bc # == 1591566291

slot0sec=1591566291

This is a magic number representing the unix time stamp (seconds since 1970-01-01 00:00:00 UTC) for an imaginary slot 0 which assumes that every slot in the past was 1 second in duration. This allows us to calculate the timestamp of any slot since the Shelley era began when slots have all been 1 second duration.

Thanks goes to @HeptaSean for helping me work out that magic number some time ago.

So here is how you can use it to calculate your date time value:

slot=94253339; slot0sec=1591566291;  date --date=@$(("$slot0sec + $slot"))

Sun 04 Jun 2023 05:13:50 AEST

When you run the above on your machine you will see the output for your timezone. (AEST is Australian eastern standard time).

1 Like
6

Ok, so I can now get the exact time using your command, excellent.

The next step is perusing and understanding the logs. My BP and Relay nodes are setup to use logs outputting to a json file (node0.json) in the /opt/cardano/cnode/logs/ directory. I have been using commands like less node0.json to view contents of the log file.

The journalctl (as I understand it) is a system wide logging output which captures logs by various services, the output is as follows running the

sudo journalctl --since "2023-06-03 22:13:50"

Jun 03 22:13:51 x9x.l.hostens.cloud cnode-cncli-ptsendtip[1648332]: 'POOL_ID' and/or 'POOL_TICKER' and/or 'PT_API_KEY' not set in cncli.sh, >
Jun 03 22:13:51 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Main process exited, code=exited, status=1/FAILURE
Jun 03 22:13:51 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Failed with result 'exit-code'.
Jun 03 22:13:51 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Consumed 1.642s CPU time.
Jun 03 22:14:11 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Scheduled restart job, restart counter is at 18918.
Jun 03 22:14:11 x9x.l.hostens.cloud systemd[1]: Stopped Cardano Node - CNCLI PoolTool SendTip.
Jun 03 22:14:11 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Consumed 1.642s CPU time.
Jun 03 22:14:11 x9x.l.hostens.cloud systemd[1]: Started Cardano Node - CNCLI PoolTool SendTip.
Jun 03 22:14:11 x9x.l.hostens.cloud cnode-cncli-ptsendtip[1648646]: TERM environment variable not set.
Jun 03 22:14:11 x9x.l.hostens.cloud cnode-cncli-ptsendtip[1648572]: Checking for script updates...
Jun 03 22:14:13 x9x.l.hostens.cloud cnode-cncli-ptsendtip[1648572]: 'POOL_ID' and/or 'POOL_TICKER' and/or 'PT_API_KEY' not set in cncli.sh, >
Jun 03 22:14:13 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Main process exited, code=exited, status=1/FAILURE
Jun 03 22:14:13 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Failed with result 'exit-code'.
Jun 03 22:14:13 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Consumed 1.742s CPU time.
Jun 03 22:14:13 x9x.l.hostens.cloud kernel: [UFW BLOCK] IN=ens3 OUT= MAC=00:00:50:d0:e1:8c:fe:00:50:d0:e1:8c:08:00 SRC=184.105.247.239 DST=8>
Jun 03 22:14:21 x9x.l.hostens.cloud kernel: [UFW BLOCK] IN=ens3 OUT= MAC=00:00:50:d0:e1:8c:fe:00:50:d0:e1:8c:08:00 SRC=45.134.144.212 DST=80>
Jun 03 22:14:33 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Scheduled restart job, restart counter is at 18919.
Jun 03 22:14:33 x9x.l.hostens.cloud systemd[1]: Stopped Cardano Node - CNCLI PoolTool SendTip.
Jun 03 22:14:33 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Consumed 1.742s CPU time.
Jun 03 22:14:33 x9x.l.hostens.cloud systemd[1]: Started Cardano Node - CNCLI PoolTool SendTip.
Jun 03 22:14:33 x9x.l.hostens.cloud cnode-cncli-ptsendtip[1648886]: TERM environment variable not set.
Jun 03 22:14:33 x9x.l.hostens.cloud cnode-cncli-ptsendtip[1648812]: Checking for script updates...
Jun 03 22:14:35 x9x.l.hostens.cloud cnode-cncli-ptsendtip[1648812]: 'POOL_ID' and/or 'POOL_TICKER' and/or 'PT_API_KEY' not set in cncli.sh, >
Jun 03 22:14:35 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Main process exited, code=exited, status=1/FAILURE
Jun 03 22:14:35 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Failed with result 'exit-code'.
Jun 03 22:14:35 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Consumed 1.904s CPU time.
Jun 03 22:14:48 x9x.l.hostens.cloud kernel: [UFW BLOCK] IN=ens3 OUT= MAC=00:00:50:d0:e1:8c:fe:00:50:d0:e1:8c:08:00 SRC=89.248.162.161 DST=80>
Jun 03 22:14:51 x9x.l.hostens.cloud kernel: [UFW BLOCK] IN=ens3 OUT= MAC=00:00:50:d0:e1:8c:fe:00:50:d0:e1:8c:08:00 SRC=162.142.125.249 DST=8>
Jun 03 22:14:55 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Scheduled restart job, restart counter is at 18920.
Jun 03 22:14:55 x9x.l.hostens.cloud systemd[1]: Stopped Cardano Node - CNCLI PoolTool SendTip.
Jun 03 22:14:55 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Consumed 1.904s CPU time.
Jun 03 22:14:55 x9x.l.hostens.cloud systemd[1]: Started Cardano Node - CNCLI PoolTool SendTip.
Jun 03 22:14:55 x9x.l.hostens.cloud cnode-cncli-ptsendtip[1649126]: TERM environment variable not set.
Jun 03 22:14:56 x9x.l.hostens.cloud cnode-cncli-ptsendtip[1649052]: Checking for script updates...
Jun 03 22:14:57 x9x.l.hostens.cloud cnode-cncli-ptsendtip[1649052]: 'POOL_ID' and/or 'POOL_TICKER' and/or 'PT_API_KEY' not set in cncli.sh, >
Jun 03 22:14:57 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Main process exited, code=exited, status=1/FAILURE
Jun 03 22:14:57 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Failed with result 'exit-code'.
Jun 03 22:14:57 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Consumed 1.712s CPU time.
Jun 03 22:15:00 x9x.l.hostens.cloud kernel: [UFW BLOCK] IN=ens3 OUT= MAC=00:00:50:d0:e1:8c:fe:00:50:d0:e1:8c:08:00 SRC=116.209.208.118 DST=8>
Jun 03 22:15:17 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Scheduled restart job, restart counter is at 18921.
Jun 03 22:15:17 x9x.l.hostens.cloud systemd[1]: Stopped Cardano Node - CNCLI PoolTool SendTip.
Jun 03 22:15:17 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Consumed 1.712s CPU time.
Jun 03 22:15:17 x9x.l.hostens.cloud systemd[1]: Started Cardano Node - CNCLI PoolTool SendTip.
Jun 03 22:15:17 x9x.l.hostens.cloud cnode-cncli-ptsendtip[1649366]: TERM environment variable not set.
Jun 03 22:15:18 x9x.l.hostens.cloud cnode-cncli-ptsendtip[1649292]: Checking for script updates...
Jun 03 22:15:19 x9x.l.hostens.cloud cnode-cncli-ptsendtip[1649292]: 'POOL_ID' and/or 'POOL_TICKER' and/or 'PT_API_KEY' not set in cncli.sh, >
Jun 03 22:15:19 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Main process exited, code=exited, status=1/FAILURE
Jun 03 22:15:19 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Failed with result 'exit-code'.
Jun 03 22:15:19 x9x.l.hostens.cloud systemd[1]: cnode-cncli-ptsendtip.service: Consumed 1.791s CPU time.
Jun 03 22:15:19 x9x.l.hostens.cloud kernel: [UFW BLOCK] IN=ens3 OUT= MAC=00:00:50:d0:e1:8c:fe:00:50:d0:e1:8c:86:dd SRC=2001:41d0:0403:1f43:0>

It’s interesting to note the firewall blocks but there doesn’t seem to be logging from cnode. I assume because it is outputting to the node0.json file and not the system.

So using the following command to peruse the json file with (note, only gets 9 seconds of logs):

less node0-20230603082843.json | jq --arg date "2023-06-03T22:13:5" 'select(.at | startswith($date))'

I get (applogies for the large amount of data):

{
  "app": [],
  "at": "2023-06-03T22:13:50.00Z",
  "data": {
    "chainDensity": 0.04651614,
    "credentials": "Cardano",
    "delegMapSize": 1282460,
    "kind": "TraceStartLeadershipCheck",
    "slot": 94264139,
    "utxoSize": 10000910
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.LeadershipCheck"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:50.05Z",
  "data": {
    "credentials": "Cardano",
    "val": {
      "kind": "TraceNodeNotLeader",
      "slot": 94264139
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.Forge"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:50.70Z",
  "data": {
    "kind": "PeersFetch",
    "peers": [
      {
        "declined": "FetchDeclineChainNotPlausible",
        "kind": "FetchDecision declined",
        "peer": {
          "local": {
            "addr": "80.208.225.140",
            "port": "42397"
          },
          "remote": {
            "addr": "161.97.108.250",
            "port": "6000"
          }
        }
      },
      {
        "kind": "FetchDecision results",
        "length": "1",
        "peer": {
          "local": {
            "addr": "80.208.225.140",
            "port": "43799"
          },
          "remote": {
            "addr": "80.208.230.113",
            "port": "3001"
          }
        }
      }
    ]
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.BlockFetchDecision"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "531"
}
{
  "app": [],
  "at": "2023-06-03T22:13:50.70Z",
  "data": {
    "kind": "AcknowledgedFetchRequest",
    "peer": {
      "local": {
        "addr": "80.208.225.140",
        "port": "43799"
      },
      "remote": {
        "addr": "80.208.230.113",
        "port": "3001"
      }
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.BlockFetchClient"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "336772"
}
{
  "app": [],
  "at": "2023-06-03T22:13:50.70Z",
  "data": {
    "kind": "AddedFetchRequest",
    "peer": {
      "local": {
        "addr": "80.208.225.140",
        "port": "43799"
      },
      "remote": {
        "addr": "80.208.230.113",
        "port": "3001"
      }
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.BlockFetchClient"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "531"
}
{
  "app": [],
  "at": "2023-06-03T22:13:50.70Z",
  "data": {
    "head": "120a24990e4e5e6bb556a7c24a748f19da6cdb6bea26bba172f786f7d23fb118",
    "kind": "SendFetchRequest",
    "length": 1,
    "peer": {
      "local": {
        "addr": "80.208.225.140",
        "port": "43799"
      },
      "remote": {
        "addr": "80.208.230.113",
        "port": "3001"
      }
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.BlockFetchClient"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "336772"
}
{
  "app": [],
  "at": "2023-06-03T22:13:50.70Z",
  "data": {
    "kind": "StartedFetchBatch",
    "peer": {
      "local": {
        "addr": "80.208.225.140",
        "port": "43799"
      },
      "remote": {
        "addr": "80.208.230.113",
        "port": "3001"
      }
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.BlockFetchClient"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "336771"
}
{
  "app": [],
  "at": "2023-06-03T22:13:50.71Z",
  "data": {
    "block": "120a24990e4e5e6bb556a7c24a748f19da6cdb6bea26bba172f786f7d23fb118",
    "delay": 0.709108642,
    "kind": "CompletedBlockFetch",
    "peer": {
      "local": {
        "addr": "80.208.225.140",
        "port": "43799"
      },
      "remote": {
        "addr": "80.208.230.113",
        "port": "3001"
      }
    },
    "size": 74181
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.BlockFetchClient"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "336771"
}
{
  "app": [],
  "at": "2023-06-03T22:13:50.71Z",
  "data": {
    "kind": "CompletedFetchBatch",
    "peer": {
      "local": {
        "addr": "80.208.225.140",
        "port": "43799"
      },
      "remote": {
        "addr": "80.208.230.113",
        "port": "3001"
      }
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.BlockFetchClient"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "336771"
}
{
  "app": [],
  "at": "2023-06-03T22:13:50.75Z",
  "data": {
    "chainLengthDelta": 1,
    "kind": "TraceAddBlockEvent.AddedToCurrentChain",
    "newtip": "120a24990e4e5e6bb556a7c24a748f19da6cdb6bea26bba172f786f7d23fb118@94264139"
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.ChainDB"
  ],
  "pid": "3245403",
  "sev": "Notice",
  "thread": "519"
}
{
  "app": [],
  "at": "2023-06-03T22:13:51.00Z",
  "data": {
    "chainDensity": 0.046513133,
    "credentials": "Cardano",
    "delegMapSize": 1282459,
    "kind": "TraceStartLeadershipCheck",
    "slot": 94264140,
    "utxoSize": 10000903
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.LeadershipCheck"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:51.05Z",
  "data": {
    "credentials": "Cardano",
    "val": {
      "kind": "TraceNodeNotLeader",
      "slot": 94264140
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.Forge"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:52.00Z",
  "data": {
    "chainDensity": 0.046513133,
    "credentials": "Cardano",
    "delegMapSize": 1282459,
    "kind": "TraceStartLeadershipCheck",
    "slot": 94264141,
    "utxoSize": 10000903
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.LeadershipCheck"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:52.04Z",
  "data": {
    "credentials": "Cardano",
    "val": {
      "kind": "TraceNodeNotLeader",
      "slot": 94264141
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.Forge"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:53.00Z",
  "data": {
    "chainDensity": 0.046513133,
    "credentials": "Cardano",
    "delegMapSize": 1282459,
    "kind": "TraceStartLeadershipCheck",
    "slot": 94264142,
    "utxoSize": 10000903
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.LeadershipCheck"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:53.05Z",
  "data": {
    "credentials": "Cardano",
    "val": {
      "kind": "TraceNodeNotLeader",
      "slot": 94264142
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.Forge"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:54.00Z",
  "data": {
    "chainDensity": 0.046513133,
    "credentials": "Cardano",
    "delegMapSize": 1282459,
    "kind": "TraceStartLeadershipCheck",
    "slot": 94264143,
    "utxoSize": 10000903
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.LeadershipCheck"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:54.07Z",
  "data": {
    "credentials": "Cardano",
    "val": {
      "kind": "TraceNodeNotLeader",
      "slot": 94264143
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.Forge"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:55.00Z",
  "data": {
    "chainDensity": 0.046513133,
    "credentials": "Cardano",
    "delegMapSize": 1282459,
    "kind": "TraceStartLeadershipCheck",
    "slot": 94264144,
    "utxoSize": 10000903
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.LeadershipCheck"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:55.05Z",
  "data": {
    "credentials": "Cardano",
    "val": {
      "kind": "TraceNodeNotLeader",
      "slot": 94264144
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.Forge"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:56.00Z",
  "data": {
    "chainDensity": 0.046513133,
    "credentials": "Cardano",
    "delegMapSize": 1282459,
    "kind": "TraceStartLeadershipCheck",
    "slot": 94264145,
    "utxoSize": 10000903
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.LeadershipCheck"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:56.04Z",
  "data": {
    "credentials": "Cardano",
    "val": {
      "kind": "TraceNodeNotLeader",
      "slot": 94264145
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.Forge"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:57.00Z",
  "data": {
    "chainDensity": 0.046513133,
    "credentials": "Cardano",
    "delegMapSize": 1282459,
    "kind": "TraceStartLeadershipCheck",
    "slot": 94264146,
    "utxoSize": 10000903
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.LeadershipCheck"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:57.04Z",
  "data": {
    "credentials": "Cardano",
    "val": {
      "kind": "TraceNodeNotLeader",
      "slot": 94264146
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.Forge"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:58.00Z",
  "data": {
    "chainDensity": 0.046513133,
    "credentials": "Cardano",
    "delegMapSize": 1282459,
    "kind": "TraceStartLeadershipCheck",
    "slot": 94264147,
    "utxoSize": 10000903
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.LeadershipCheck"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:58.05Z",
  "data": {
    "credentials": "Cardano",
    "val": {
      "kind": "TraceNodeNotLeader",
      "slot": 94264147
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.Forge"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:59.00Z",
  "data": {
    "chainDensity": 0.046513133,
    "credentials": "Cardano",
    "delegMapSize": 1282459,
    "kind": "TraceStartLeadershipCheck",
    "slot": 94264148,
    "utxoSize": 10000903
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.LeadershipCheck"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T22:13:59.04Z",
  "data": {
    "credentials": "Cardano",
    "val": {
      "kind": "TraceNodeNotLeader",
      "slot": 94264148
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.Forge"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}

So what am i looking at here to confirm I have added a block or whether there was a problem with block creation.

1 Like
7

Looking at your node0-20230603082843.json file contents:
The first entry shows your node doing a leadership check at “2023-06-03T22:13:50.00Z”
The second entry shows that it determined that it was not a leader:

{
  "app": [],
  "at": "2023-06-03T22:13:50.05Z",
  "data": {
    "credentials": "Cardano",
    "val": {
      "kind": "TraceNodeNotLeader",
      "slot": 94264139
    }

Ahhh. See the problem. Slot number is not the same as the slot number you listed above. This is because your node0 json “at”: timestamps are in UTC time whereas your syslog will log things with timestamps in your localtime.

So now you need to convert your slot number to UTC time but adding a -u switch to the date command I provided above. Here is how you can do that:

slot=94253339; slot0sec=1591566291;  date -u --date=@$(("$slot0sec + $slot"))

Sat 03 Jun 2023 19:13:50 UTC

Now you can look in your node0 json file with those “at” timestamps.

If you just leave everything logged to your standard journal you should get logs like this:

Jun 05 17:56:29 relay2 cardano-node[2791572]: [relay2:cardano.node.ChainDB:Info:195] [2023-06-05 07:56:29.78 UTC] Valid candidate f81a179eb4bf135cf01cd03f9d80d914545bb4b2849916e0c31e3992e92be22c at slot 94385498

Note that my syslog timestamp is in my local time (AEST) but the cardano-node also includes the UTC time in square brackets.

If you separate your logs like you are doing then when looking at other events happening on your system around the same time you will need to keep in mind that your standard journal has timestamps in localtime whereas your cardano-node node0 json files has it’s at: timestamps in UTC.

You still don’t know yet. You need to change your json viewing command to:

less node0-20230603082843.json | jq --arg date "2023-06-03T19:13:5" 'select(.at | startswith($date))'

You can also use your cncli database to look at the blocks around your slot number:

sqlite3 /var/lib/cardano/cncli.db '.headers on' '.mode column' "select id, block_number, slot_number, pool_id, substr(hash,1,8), substr(prev_hash,1,8), substr(block_vrf_0,1,8), orphaned from chain where slot_number between 94253310 and 94253359;"
id       block_number  slot_number  pool_id                                                   substr(hash,1,8)  substr(prev_hash,1,8)  substr(block_vrf_0,1,8)  orphaned
-------  ------------  -----------  --------------------------------------------------------  ----------------  ---------------------  -----------------------  --------
4392453  8857914       94253338     dc508ac7975e573adf6ef17873c74d200e0cd71931c139eb76853281  88bb6053          0f84fcff               5f4b8fba                 0       
4392454  8857915       94253339     8c35ca0a53467e3a71adb8088001345e3817a23d9667beebbb2145ce  78bc6b5d          88bb6053               f9b8bddc                 0       
4392455  8857916       94253358     d785ff6a030ae9d521770c00f264a2aa423e928c85fc620b13d46eda  4e3dc998          78bc6b5d               042759fe                 0

Is your pool ID “8c35ca0a53467e3a71adb8088001345e3817a23d9667beebbb2145ce”? Because if that is your poolID then your block is on chain.

8

I thing we are making progress here, this is super helpful and hopefully helps others in the same situation. Thank you so much for your help on this.

Querying the logs at the correct UTC time (I should have known better) I am seeing more information that I think looks like the block was minted. I see below a log with the ‘kind’ of ‘TraceBlockAdopted’ which i think is the indication that the block was minted (as well as another log, TraceAddBlockEvent.AddedToCurrentChain)?

{
  "app": [],
  "at": "2023-06-03T19:13:50.00Z",
  "data": {
    "chainDensity": 0.04667099,
    "credentials": "Cardano",
    "delegMapSize": 1282420,
    "kind": "TraceStartLeadershipCheck",
    "slot": 94253339,
    "utxoSize": 10000004
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.LeadershipCheck"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T19:13:50.03Z",
  "data": {
    "credentials": "Cardano",
    "val": {
      "kind": "TraceNodeIsLeader",
      "slot": 94253339
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.Forge"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T19:13:50.03Z",
  "data": {
    "credentials": "Cardano",
    "val": {
      "block": "78bc6b5d1ff4ccdfcac0170f88f29cbf5813c2a2b1e551b840564752a87bda1f",
      "blockNo": 8857915,
      "blockPrev": "88bb6053f015f279560d0278a36b0d08c5f48394c9c6993431888afdaeb48ecb",
      "kind": "TraceForgedBlock",
      "slot": 94253339
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.Forge"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T19:13:50.09Z",
  "data": {
    "block": "78bc6b5d1ff4ccdfcac0170f88f29cbf5813c2a2b1e551b840564752a87bda1f@94253339",
    "kind": "TraceAddBlockEvent.AddBlockValidation.ValidCandidate"
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.ChainDB"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "519"
}
{
  "app": [],
  "at": "2023-06-03T19:13:50.09Z",
  "data": {
    "chainLengthDelta": 1,
    "kind": "TraceAddBlockEvent.AddedToCurrentChain",
    "newtip": "78bc6b5d1ff4ccdfcac0170f88f29cbf5813c2a2b1e551b840564752a87bda1f@94253339"
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.ChainDB"
  ],
  "pid": "3245403",
  "sev": "Notice",
  "thread": "519"
}
{
  "app": [],
  "at": "2023-06-03T19:13:50.09Z",
  "data": {
    "credentials": "Cardano",
    "val": {
      "blockHash": "78bc6b5d1ff4ccdfcac0170f88f29cbf5813c2a2b1e551b840564752a87bda1f",
      "blockSize": 87466,
      "kind": "TraceAdoptedBlock",
      "slot": 94253339
    }
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.Forge"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}
{
  "app": [],
  "at": "2023-06-03T19:13:51.00Z",
  "data": {
    "chainDensity": 0.046694204,
    "credentials": "Cardano",
    "delegMapSize": 1282419,
    "kind": "TraceStartLeadershipCheck",
    "slot": 94253340,
    "utxoSize": 9999995
  },
  "env": "8.0.0:00000",
  "host": "x9x",
  "loc": null,
  "msg": "",
  "ns": [
    "cardano.node.LeadershipCheck"
  ],
  "pid": "3245403",
  "sev": "Info",
  "thread": "529"
}

Yes, that is the correct pool id (8c35ca0a53467e3a71adb8088001345e3817a23d9667beebbb2145ce), did you find that on pooltool.io?

1 Like
9

Yes. Your block is on chain.

This is the process I go through when checking each block for my pool:

  1. Run leadership schedule for next epoch 1 day before epoch end so I know when my blocks are due.
  2. After each block should have been produced, check to see if pooltool.io has the block on chain. For your pool ID this would be this page:
    Cardano PoolTool - The most comprehensive staking statistics for Cardano on the web.

If the block is not on-chain according to pooltool.io then you need to find out what went wrong:

  1. First look in your log files for the time your block was minted and make sure that it was actually minted. IE: TraceNodeIsLeader, TraceForgedBlock, TraceAddBlockEvent, TraceAdoptedBlock, etc.
  2. If you block was minted but is no longer on-chain then it may be because you lost a “fork battle”. So I look in my cncli database to check for that. Just modify the sqlite3 query I used to show all the blocks around the time of your slot. For your block we have been investigating this query is:
sqlite3 /var/lib/cardano/cncli.db '.headers on' '.mode column' "select id, block_number, slot_number, pool_id, substr(hash,1,8), substr(prev_hash,1,8), substr(block_vrf_0,1,8), orphaned  from chain where slot_number between 94253310 and 94253359;"

Your cncli database should already store all this information. Although your logs from your journalctl --since command above showed that there could be a problem with cncli on your machine. Note the following error message in your logs:

cnode-cncli-ptsendtip[1648572]: 'POOL_ID' and/or 'POOL_TICKER' and/or 'PT_API_KEY' not set in cncli.sh

If cncli-sync is running properly on your machine then you should have an sqlite database you can directly query. Just modify my sqlite3 command above to direct it at the location of your own cncli database. Mine is at /var/lib/cardano/cncli.db but yours is probably in your user home directory somewhere if you have followed one of the more common guides (which I don’t agree with). The substr functions in the sqlite3 command just shorten the hash and VRF values for ease of viewing.

If your block has a 1 in the orphaned column then you need to understand why it was “orphaned”. Often it is orphaned because you lost a “fork battle”. This happens when the other pool’s competing block had a lower block VRF value. That is why my query includes information about each block’s VRF value. The VRF (Verifiable random function) value is used to settle “fork battles” which are equal in length. (If forks differ in length then longest chain wins.) Most forks in Cardano don’t get longer than a single block long before they are settled. The block(s) in the losing fork get “orphaned” which means they are dropped from the chain. Furthermore, those orphaned blocks are not rewarded for staking rewards. So if your block gets “orphaned” you don’t get any staking rewards for that block. Bummer!

See also: troublshooting why my block got orphaned.

10

@Terminada, very helpful;

I was able to correctly query the db and found my block:

image
image1667×187 61.5 KB

For cntools users the path to my db was:

/opt/cardano/cnode/guild-db/cncli/cncli.db

I see the errors with ptsendtip service, I have set the pool_id and ticker but it still generates an error. I think I will just disable the service.

1 Like
11

The send tip service is not essential. On the margin, one argument for doing it could have been that operators who send info about their block receipt delays could be seen as “more proactive”, and as such, maybe some astute users might prefer to delegate to these pools. But that is a pretty flimsy argument in my mind and most delegators wouldn’t even know about it. Another argument for sending your tip info might have been that other pool operators might prefer to add your relays to their topology files. But this argument is also largely out the window since the majority of relays seem to be running P2P mode now.

So I agree. If the service is going to be a pain to fix then just disable it.

12

Thanks so much for your help on this issue. It’s great that the community steps in to help other stake pool operators