Freshness check triggers 1 audit transaction per ledger

[c2bo]

Plenum uses a freshness check to make sure the current state of the system has a certain freshness in the audit ledger with default values of

UPDATE_STATE_FRESHNESS = True
STATE_FRESHNESS_UPDATE_INTERVAL = 300  # in secs

If I understand the audit ledger and expected behavior for this correctly, we would like to make sure that at any point in time there is an audit transaction reflecting the current state of the system that is <300s old. What seems to happen is that this is checked per ledger (config, domain, pool) and we create 3 transactions (amount of ledgers) per defined freshness interval instead of the one that should be sufficient?
This causes a lot of additional transactions / uses a lot of storage in the audit ledger.

To check the behavior, i created a local network with 4 nodes and did not post any transactions (and did not start a ledger browser to not cause any traffic at all). The logs resulting showed:
[node1 - master]:

node1  | 2022-11-09 09:01:58,015|INFO|ordering_service.py|Ledger 0 is not updated for 301 seconds, so its freshness state is going to be updated now
node1  | 2022-11-09 09:01:58,035|INFO|ordering_service.py|Ledger 1 is not updated for 301 seconds, so its freshness state is going to be updated now
node1  | 2022-11-09 09:01:58,044|INFO|ordering_service.py|Ledger 2 is not updated for 301 seconds, so its freshness state is going to be updated now
node1  | 2022-11-09 09:06:59,003|INFO|ordering_service.py|Ledger 0 is not updated for 301 seconds, so its freshness state is going to be updated now
node1  | 2022-11-09 09:06:59,009|INFO|ordering_service.py|Ledger 1 is not updated for 301 seconds, so its freshness state is going to be updated now
node1  | 2022-11-09 09:06:59,013|INFO|ordering_service.py|Ledger 2 is not updated for 301 seconds, so its freshness state is going to be updated now
node1  | 2022-11-09 09:12:00,003|INFO|ordering_service.py|Ledger 0 is not updated for 301 seconds, so its freshness state is going to be updated now
node1  | 2022-11-09 09:12:00,013|INFO|ordering_service.py|Ledger 1 is not updated for 301 seconds, so its freshness state is going to be updated now
node1  | 2022-11-09 09:12:00,020|INFO|ordering_service.py|Ledger 2 is not updated for 301 seconds, so its freshness state is going to be updated now

[node2]:

node2  | 2022-11-09 09:01:58,332|DEBUG|audit_batch_handler.py|committed 1 audit txns; uncommitted root hash is b'\xa6\x92Bl\xb6*\x06\xc7\r\x17u\x1d\xa9s:-\xce\xbd\x14\xa3\xbe\xda\xfb\xd2\xe6\xd2\xa9\xd5Q\xb5"\x11'; uncommitted size is 3
node2  | 2022-11-09 09:01:58,400|DEBUG|audit_batch_handler.py|committed 1 audit txns; uncommitted root hash is b'\xa6\x92Bl\xb6*\x06\xc7\r\x17u\x1d\xa9s:-\xce\xbd\x14\xa3\xbe\xda\xfb\xd2\xe6\xd2\xa9\xd5Q\xb5"\x11'; uncommitted size is 3
node2  | 2022-11-09 09:01:58,444|DEBUG|audit_batch_handler.py|committed 1 audit txns; uncommitted root hash is b'\xa6\x92Bl\xb6*\x06\xc7\r\x17u\x1d\xa9s:-\xce\xbd\x14\xa3\xbe\xda\xfb\xd2\xe6\xd2\xa9\xd5Q\xb5"\x11'; uncommitted size is 3
node2  | 2022-11-09 09:06:59,169|DEBUG|audit_batch_handler.py|committed 1 audit txns; uncommitted root hash is b"\xc2\xab\xe3\t\xff\xefdx\xd8\xaa\x89\xed\x97f\x805'\x08K\xba\xd6I \xb9\x83[V\xd6Z]m\x1d"; uncommitted size is 6
node2  | 2022-11-09 09:06:59,202|DEBUG|audit_batch_handler.py|committed 1 audit txns; uncommitted root hash is b"\xc2\xab\xe3\t\xff\xefdx\xd8\xaa\x89\xed\x97f\x805'\x08K\xba\xd6I \xb9\x83[V\xd6Z]m\x1d"; uncommitted size is 6
node2  | 2022-11-09 09:06:59,220|DEBUG|audit_batch_handler.py|committed 1 audit txns; uncommitted root hash is b"\xc2\xab\xe3\t\xff\xefdx\xd8\xaa\x89\xed\x97f\x805'\x08K\xba\xd6I \xb9\x83[V\xd6Z]m\x1d"; uncommitted size is 6
node2  | 2022-11-09 09:12:00,215|DEBUG|audit_batch_handler.py|committed 1 audit txns; uncommitted root hash is b'\xbaq4u(\xe0oG\xe56\xcbf\xf6<O\x92>>?\xb5\x87q>\x884\x8dj\xcc\x959\xfed'; uncommitted size is 9
node2  | 2022-11-09 09:12:00,254|DEBUG|audit_batch_handler.py|committed 1 audit txns; uncommitted root hash is b'\xbaq4u(\xe0oG\xe56\xcbf\xf6<O\x92>>?\xb5\x87q>\x884\x8dj\xcc\x959\xfed'; uncommitted size is 9
node2  | 2022-11-09 09:12:00,295|DEBUG|audit_batch_handler.py|committed 1 audit txns; uncommitted root hash is b'\xbaq4u(\xe0oG\xe56\xcbf\xf6<O\x92>>?\xb5\x87q>\x884\x8dj\xcc\x959\xfed'; uncommitted size is 9

If you search for committed 1 audit txns; uncommitted root hash is in logs from productive networks (with level debug), you should be able to find something similar - 3 transactions per 5 minutes during idle time.

Can someone with more knowledge about plenum and the audit ledger verify if my assumption is correct that one audit transaction would be enough or comment on the implications if this was changed?

[c2bo]

This would be the relevant code:
https://github.com/hyperledger/indy-plenum/blob/ubuntu-20.04-upgrade/plenum/server/consensus/ordering_service.py#L1998-L2010

[WadeBarnes]

@esplinr, @Toktar, Would either of you be ale to provide some insight or background on this behavior?