[PLT-87] marconi: Log progress of synced blocks

[andreabedini]

This PR implements the story PLT-87.

As an [internal developer (Marlowe, Mamba, etc.)] running the chain-index
I want to be informed about the syncing rate of the chain-index
So that:
I can know the syncing progress
I can know if the process is stuck
I can generally monitor the performance

Example usage:

$ cabal run --  marconi --mainnet --socket-path ~/work/cardano-mainnet/socket/node.socket --database-path marconi.sqlite3 
Up to date
[2022-05-31 05:10:12.06987873 UTC] Processed 0 blocks. Last rollback was on 2022-05-31 05:10:12.069877487 UTC. Synchornising (68.73%). Current point is ChainPoint (SlotNo 39795032) (HeaderHash ">odP\248Yb\214QeN\230`\145\152\v#2\SYNoU\ENQ\253\DLE\185{\ENQ \201\239\172\144").
[2022-05-31 05:10:22.070659624 UTC] Processed 10064 blocks. Current rate: 357.28 blocks/s. Last rollback was on 2022-05-31 05:10:12.069877487 UTC. Synchornising (69.08%). Current point is ChainPoint (SlotNo 39999246) (HeaderHash "\162>H)\191[,&.\STXG\US7\231\146\252\210(4\193\229z\186\DC4\156\181\180\185y\177&\203").
[2022-05-31 05:10:32.070854717 UTC] Processed 18627 blocks. Current rate: 890.83 blocks/s. Last rollback was on 2022-05-31 05:10:12.069877487 UTC. Synchornising (69.38%). Current point is ChainPoint (SlotNo 40172636) (HeaderHash "\196y\DLE\178\US\242\149(9\220o8\199\253\136\205*\227I\172;\141R\254\141\STX\164\ACK\175\212\202\176").

Implementation notes:

• I have basically reworked the code written by @koslambrou in SCP-3431: Better syncing logging in the chain-index. #309.
• The messages are printed on screen on every block processed (streams are pull based) but no more than once every 10 seconds.
• "Last rollback" might be a bit misleading as the first event is always a rollback.

[raduom]

I think it still misses logging levels and tests. I also don't know why you moved Datum.hs into the app folder.

[andreabedini]

I think it still misses logging levels

The story doesn't mention logging levels.

The logging should have an appropriate min logging level, from which we can specify from the CLI.

my bad. But is it really relevant? There's only one thing we are logging now.

and tests

What kind of tests would you like to see?

I also don't know why you moved Datum.hs into the app folder.

To separate marconi from the other plutus-chain-index. Otherwise dependencies of marconi get mixed up with dependencies of plutus-chain-index.

[koslambrou]

The printed header hash prints something like "\180W\245E\161\231\171\247\225\227\212\US\179\r3B\RS\199\210\255\245qK\231\&3\214\180\219\168\246q". However, shouldn't be something like b457f56045a1e7abf7e1e3d41fb30d33421ec7d2fff5714be733d6b4dba8f671?

It would be better to use the Pretty typeclass of these datatypes instead of Show.

[koslambrou]

Putting a from block hash in the CLI gives:

marconi: ExceptionInLinkedThread (ThreadId 12) Maybe.fromJust: Nothing
CallStack (from HasCallStack):
  error, called at libraries/base/Data/Maybe.hs:148:21 in base:Data.Maybe
  fromJust, called at app/Marconi.hs:142:16 in main:Main

A better error message should be printed.

[koslambrou]

Tried running cabal run plutus-chain-index:exe:marconi -- --socket-path ~/.local/share/Daedalus/mainnet/cardano-node.socket --mainnet --database-path /tmp/marconi.db --slot-no 62449666 --block-hash 2777227cb7f229fe710be5e078b805b60f7d1e6f20cde0ef0c49e30f160f4a14.

However, there's nothing stored in the database even though I've started the indexer more than 2k blocks deep.

[koslambrou]

When not setting the correct block hash and slotno in the CLI, I'm getting the error:

marconi: ExceptionInLinkedThread (ThreadId 12) NoIntersectionFound

Maybe a prettier error message with Pretty typeclass?

[andreabedini]

@koslambrou I think I addressed all your feedback. There's no pretty instance for chain points (AFAIK) so I just implemented a function.

However, there's nothing stored in the database even though I've started the indexer more than 2k blocks deep.

I am going to try the same.

@raduom On my computer, next to a running node, I am doing ~500-1000 block/s does it sound ok to you? I don't want the logging to slow things down.

[raduom]

@raduom On my computer, next to a running node, I am doing ~500-1000 block/s does it sound ok to you? I don't want the logging to slow things down.

I think we are fine. Good job!

[andreabedini]

However, there's nothing stored in the database even though I've started the indexer more than 2k blocks deep.

@koslambrou I cannot reproduce. My node is stuck at slot 57901784 hash 470eb682589f65aacac4c5f5e8eaa3348ebb63475d35528ec7822cc7a3dfca2f, if I start from the begingging of the same epoch it works ok:

❯ cabal run plutus-chain-index:exe:marconi -- --socket-path $CARDANO_NODE_SOCKET_PATH --mainnet --database-path /tmp/marconi.db --slot-no 57628811 --block-hash 1566984742669a4d858f8e56580294a5b426611dbc0e7a73987fefcdc138c104
Up to date
[2022-06-01 14:06:52] Last rollback was on 2022-06-01 14:06:52. Synchronising (99.53%). Current point is slotNo 57628811 hash 1566984742669a4d858f8e56580294a5b426611dbc0e7a73987fefcdc138c104.
[2022-06-01 14:07:02] Processed 3770 blocks in the last 10 seconds. Last rollback was on 2022-06-01 14:06:52. Synchronising (99.66%). Current point is slotNo 57706993 hash f745d16419980521f6acb17a4a4ecd4a675ccee555280e098d519e76f90e57ca.
[2022-06-01 14:07:12] Processed 4403 blocks in the last 10 seconds. Last rollback was on 2022-06-01 14:06:52. Synchronising (99.82%). Current point is slotNo 57799414 hash 09e5a2e6900f54858720d117bc15ca44f20dbe775953f726e08c1f82c83dc58a.
[2022-06-01 14:07:22] Processed 4843 blocks in the last 10 seconds. Last rollback was on 2022-06-01 14:06:52. Synchronising (100.00%). Current point is slotNo 57899290 hash 7a151f89e832bf648628fa7cd7cd8706a13cda750a3f0500801a98c633a05ca3.

[koslambrou]

@koslambrou I think I addressed all your feedback. There's no pretty instance for chain points (AFAIK) so I just implemented a function.

Two options here: Either create an orphan instance for Pretty ChainPoint (which I'm not a fan of), or create your own Point datatype which has this instance. We do that in plutus-chain-index-core in Plutus.ChainIndex.Types.Point. We have Tip, BlockId, Point, BlockNumber datatypes which are isomorphic representations of types in cardano-api (we have conversion functions in Plutus.ChainIndex.Compatibility. I think it's a good idea to use them because we have add whatever instances we want without requiring to do a PR in cardano-node.

@koslambrou I cannot reproduce. My node is stuck at slot 57901784 hash 470eb682589f65aacac4c5f5e8eaa3348ebb63475d35528ec7822cc7a3dfca2f, if I start from the begingging of the same epoch it works ok:

Mmm... Does that mean there's no datums after slot 62449666? Weird...

BTW, by running the command abal run plutus-chain-index:exe:marconi -- --socket-path ~/.local/share/Daedalus/mainnet/cardano-node.socket --mainnet --database-path /tmp/marconi.db --slot-no 62449666 --block-hash 2777227cb7f229fe710be5e078b805b60f7d1e6f20cde0ef0c49e30f160f4a14 it seems stuck here:

[2022-06-01 09:31:56] Last rollback was on 2022-06-01 09:31:56. Synchronising (99.96%). Current point is slotNo 62449666 hash 2777227cb7f229fe710be5e078b805b60f7d1e6f20cde0ef0c49e30f160f4a14.

I would expect a Synchronized log message.

[andreabedini]

I would expect a Synchronized log message.

Oh, that's weird. That would be starting exactly at the chain tip right? perhaps there's an edge case that I missed. It should say Synchronised as soon as slotNo are close enough.

[andreabedini]

Two options here: Either create an orphan instance for Pretty ChainPoint (which I'm not a fan of), or create your own Point datatype which has this instance.

I used a third option. No polymorphism :)

prettyChainPoint :: ChainPoint -> String
prettyChainPoint ChainPointAtGenesis = "genesis"
prettyChainPoint (ChainPoint (SlotNo wo) hash) = "slotNo " <> show wo <> " hash " <> T.unpack (serialiseToRawBytesHexText hash)

edit: after the chat, ok I will implement Pretty

[andreabedini]

@koslambrou when you have time I have implemented your last suggestions 🤗

[koslambrou]

For iohk-monitoring, reuse what we're doing in Plutus.ChainIndex.App. Most notably, we can specify a logging configuration (from which you can specify the severity). Also you can reuse the PrettyObject which pretty prints the logs in text (not in JSON). Ex. (trace :: Trace IO (PrettyObject SyncLog), _) <- setupTrace_ logConfig "chain-index". Also, instead of doing logInfo tracer ..., I would suggest to use the LogMsg effect so that you can simply do logInfo syncMsg. Look at how we're using trace in Plutus.ChainIndex.Events.

Concerning the actual output, multiple things:

• I would keep the blocks/s log. As you don't always print every 10s, it is very useful information.
• I would still show the current point (slot number and block hash)
• I would put the number of rollbacks handled instead of the last rollback date

Example of expected output:

Processed 930 blocks and 1 rollback in the last 15 seconds (5.1 blocks/s). Synchronising. Current tip is Point(Slot 62581757, BlockHash ...). Node tip is 62607694 (99.96%)
Processed 1218 blocks and 0 rollbacks in the last 31 seconds (6.1 blocks/s). Synchronised. Chain tip is Point(Slot 62607738,  BlockHash 229d0c0fa7ff880cd7a300fd7a29205341b95db91695b84f1a4c6c488dd29bd1, BlockNo(7324319)"

[koslambrou]

I don't think that's a good idea. We should create our own types isomorphic to Cardano.Api. The reason is because if you define an instance of Pretty for Cardano.Api.SlotNo, and another library you depend on does the same, you'll get an error. I've always read "Don't declare orphan instances unless you can make sure they won't come back to bite you".

@sjoerdvisscher @raduom @ak3n What are your thoughts?

[sjoerdvisscher]

I agree in principle, but then the original simple function that @andreabedini had starts to sound quite appealing.

[andreabedini]

I agree in principle too. I think a monomorphic function prettyChainPoint :: ChainPoint -> Doc ann would be the best trade off because we are not really using the polymorphism anywhere (i.e. we are not passing a ChainPoint to anything that is Pretty a => a).
Also this is not a library but an executable, nobody can import this.

[koslambrou]

We actually use the Pretty instance with PrettyObject to nicely integrate the LogMsg with Pretty, so Pretty actually simplifies things a bit.

@andreabedini This is actually a library, not an executable. I would expect a new package like marconi-pab which imports marconi and indexes stuff specific for the Contract API. Also, with the query interface, someone actually needs to import marconi if he wants to query the information that's stored in memory.

[andreabedini]

following up in private

[raduom]

I prefer the way it is written right now, to be honest.

[andreabedini]

@koslambrou

Also, instead of doing logInfo tracer ..., I would suggest to use the LogMsg effect so that you can simply do logInfo syncMsg.

I am not going to bring in effects for this.

I would keep the blocks/s log. As you don't always print every 10s, it is very useful information.
I would still show the current point (slot number and block hash)
I would put the number of rollbacks handled instead of the last rollback date

I will do these things.

[koslambrou]

I am not going to bring in effects for this.

Why not? It's not so hard to use it and bringing LogMsg will bring a lot of utility for simplifying the writing of logging. For example, instead of writing

        logInfo tracer $
          renderStrict $
            layoutPretty defaultLayoutOptions $
              syncMsg <+> (blocksMsg $ rollbackMsg $ "Chain tip is" <+> pretty ct <> "."

You can just do: logInfo $ SyncMessage ... which is much more informative, less boilerplate, is consistent with the rest of the codebase and will integrate neatly with Pretty instance of logging message types (but yeah, this is a bit out of scope of this already long PR).

[koslambrou]

We want to know the chain tip of the synced block, not the tip of the node. So it should be pretty cp.