search

f-o-a-m / kepler

A Haskell framework that facilitates writing ABCI applications
https://kepler.dev
Apache License 2.0
34 stars 10 forks source link

logger seems to be duplicating logs / missing context #44

Closed martyall closed 5 years ago

martyall commented 5 years ago

If you run a tendermint server and turn on the example app, you might see logs such as this:

[2019-08-06 03:21:08][ABCI.Server][Info][Martins-MacBook-Pro.local][28658][ThreadId 6] Request Received
[2019-08-06 03:21:08][ABCI.Server][Info][Martins-MacBook-Pro.local][28658][ThreadId 5] Request Received
[2019-08-06 03:21:08][ABCI.Server][Info][Martins-MacBook-Pro.local][28658][ThreadId 6] Request Received
[2019-08-06 03:21:08][ABCI.Server][Info][Martins-MacBook-Pro.local][28658][ThreadId 6] Request Received
[2019-08-06 03:21:09][ABCI.Server][Info][Martins-MacBook-Pro.local][28658][ThreadId 6][message_type:begin_block][hash:0x82799495fa53a682e50f958546ec58d1f9ff24041f9027b550863358068e6e0f][last_commit_info.round:0][header.app_hash:0x][header.chain_id:test-chain-qFW9Ac][header.proposer_address:0xf5fa01b64b1ba1e54ee6d7b640dd4328db9ff7d8][header.height:126][header.consensus_hash:0x048091bc7ddc283f77bfbf91d73c44da58c3df8a9cbc867405d8b7f3daada22f][header.total_txs:0][header.time:1.565061668067311e9][header.validators_hash:0x6b0f6ee69f6c7d6c34b7bc403cd266d9676663c4c193dcda14760ae608d0fb46][header.next_validators_hash:0x6b0f6ee69f6c7d6c34b7bc403cd266d9676663c4c193dcda14760ae608d0fb46][header.last_block_id.parts_header.hash:0x25a3642e99cbed7a8fb3ecd077753714108d82f95c20b2f6da822427c09bcc46][header.last_block_id.parts_header.total:1][header.last_block_id.hash:0x3a216ef41e834094447a6d5b59f90e7fb66c62b6a194f0ba10ce51cfef115393][header.evidence_hash:0x][header.last_commit_hash:0x720ecfa2b29be954e5ed69ff0a942b9f7890a53fc7f2b1de93b43fff4f6aa258][header.version.app:0][header.version.block:10][header.last_results_hash:0x][header.data_hash:0x][header.num_txs:0] Request Received
[2019-08-06 03:21:09][ABCI.Server][Info][Martins-MacBook-Pro.local][28658][ThreadId 6] Request Received
[2019-08-06 03:21:09][ABCI.Server][Info][Martins-MacBook-Pro.local][28658][ThreadId 6][message_type:end_block][height:126] Request Received
[2019-08-06 03:21:09][ABCI.Server][Info][Martins-MacBook-Pro.local][28658][ThreadId 6] Request Received
[2019-08-06 03:21:09][ABCI.Server][Info][Martins-MacBook-Pro.local][28658][ThreadId 5] Request Received
[2019-08-06 03:21:09][ABCI.Server][Info][Martins-MacBook-Pro.local][28658][ThreadId 6] Request Received
[2019-08-06 03:21:09][ABCI.Server][Info][Martins-MacBook-Pro.local][28658][ThreadId 6] Request Received

It seems like there is some dulplicates / missing context?

for example:

[2019-08-06 03:21:08][ABCI.Server][Info][Martins-MacBook-Pro.local][28658][ThreadId 6] Request Received
[2019-08-06 03:21:08][ABCI.Server][Info][Martins-MacBook-Pro.local][28658][ThreadId 5] Request Received
[2019-08-06 03:21:08][ABCI.Server][Info][Martins-MacBook-Pro.local][28658][ThreadId 6] Request Received
[2019-08-06 03:21:08][ABCI.Server][Info][Martins-MacBook-Pro.local][28658][ThreadId 6] Request Received
martyall commented 5 years ago

For the time being (before we do #41) you can start tindermint core if you have a tendermint binary in your path (v0.32.2)

> tendermint init
> tendermint node

then you can start the example app with 

> make run-simple-storage
charlescrain commented 5 years ago

Seems the extra logs come from empty requests:

I changed ToObject instance to the following.

instance ToObject (Loggable (Request (t :: MessageType))) where
  toObject (Loggable v) = case A.toJSON v of
    A.Object o -> addMessageType v o
    -- unreachable case
    a          ->  at "showing_request" ?~ A.String (pack $ show a) $ mempty
   where -- everything else the same
      .
      .

Then running the both tendermint and the server I got the following:

[2019-08-08 04:31:10][ABCI.Server][Info][Charless-MacBook-Pro.local][42308][ThreadId 6][showing_request:Array []] Request Received
[2019-08-08 04:31:10][ABCI.Server][Info][Charless-MacBook-Pro.local][42308][ThreadId 6][message_type:end_block][height:33] Request Received
[2019-08-08 04:31:10][ABCI.Server][Info][Charless-MacBook-Pro.local][42308][ThreadId 6][showing_request:Array []] Request Received
[2019-08-08 04:31:10][ABCI.Server][Info][Charless-MacBook-Pro.local][42308][ThreadId 5][showing_request:Array []] Request Received
[2019-08-08 04:31:10][ABCI.Server][Info][Charless-MacBook-Pro.local][42308][ThreadId 6][showing_request:Array []] Request Received
[2019-08-08 04:31:10][ABCI.Server][Info][Charless-MacBook-Pro.local][42308][ThreadId 6][showing_request:Array []] Request Received

Strange that empty requests are passed in since they don't seem to be of the MessageType.

We could have the logger do [message_type: empty] in this case as a possible solution.

safareli commented 5 years ago

After seeing Charle's comment, I looked into it as it seamed too strange and here is "fix" https://github.com/f-o-a-m/hs-abci/pull/55

it's "fix" and not fix because after that pr is merged we would see nice logs but, underling issue is different.

We have https://github.com/f-o-a-m/hs-abci/blob/bf9df3ec3d05c1e8e92f2f7a667b2458912be234/hs-abci-types/src/Network/ABCI/Types/Messages/Request.hs#L67-L74

and

https://github.com/f-o-a-m/hs-abci/blob/bf9df3ec3d05c1e8e92f2f7a667b2458912be234/hs-abci-types/src/Network/ABCI/Types/Messages/Request.hs#L392-L402

Looks like generic deriving of in ToJSON instances for these result in empty json array and as Request GADT defferes to ToJSON instance of underlying type as a result you wouldn't be able distinguish toJSON $ RequestCommit Commit and toJSON $ RequestFlush Flush from each other.

i.e. issue is that ToJSON/FromJSON instances of Request and Responce are incorrect. instead they should have repesentation like this:

{ type: "flush", message: []}
{ type: "begin_block", message: {...}}

i.e. https://github.com/f-o-a-m/hs-abci/blob/aaccc11f4963449cd84793608dadbeb0a1556459/hs-abci-extra/src/Network/ABCI/Server/Middleware/RequestLogger.hs#L23-L24

I've created issue for it https://github.com/f-o-a-m/hs-abci/issues/56

Besides this, I would recommend to use something like unsafeCrashWith "error message here" from PureScript, for cases where we can't guaranty something by type system and we think is unreachable/impossible and explaine why it's like that as the error message, so if in future some of the assumptions change and impossible becomes possible, we get error message instead of incorrect behavior/silence.

charlescrain commented 5 years ago

Ahh got it, that's my bad didn't realize types without any records were treated that way.