Skip to content

One-line contextual logging of Kore actions #3837

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 49 commits into from
May 7, 2024

Conversation

geo2a
Copy link
Contributor

@geo2a geo2a commented Apr 30, 2024

Combines #3833 and #3831

  • in Kore, implement rendering of oneline logs prefixed with the context stack, in the spirit of Implement better booster logging #3826

  • add --log-format <standard|oneline|json> (default:oneline) to kore-rpc-booster.

    • to recover the old behaviour of -l Rewrite and friends, use --log-format standard, i.e. kore-rpc-booster --log-format standard -l Rewrite
    • if any --log-context is passed, the log format is effectively override to be oneline
  • in booster/tools/booster/Server.hs, construct a log action to be passed to Kore. If no --log-context options are passed, then the old -l RewriteKore and fields levels still work with --log-format standard. If --log-context is passed, then the complete set of proxy-compatible Kore log entries is enabled, and the filtering is done using the glob context filter late in the colog pipeline.

Things to do in a follow-up:

  • json logging is inconsistent, both the interface and the implementation:
    • to get simplification JSON logs from both Booster and Kore, we currently need to give two options: kore-rpc-booster --log-format json -l SimplifyJson, which is not ideal. We need to remove -l SimplifyJson and forward the log format to Booster instead.
    • To implement the previous item in a clean way, we actually need to stop emitting the logs at SimplifyJson level and instead render the regular log items as json.
  • file logging is inconsistent. It is currently not possible to redirect Booster's contextual logs into a file.
  • the performance of context filtering in Kore is likely terrible, since we match the while log message, as a string, against the glob pattern. There is not penalty if the contextual logging is off however.

@geo2a geo2a force-pushed the georgy/better-kore-logging branch from 98d840f to 5f25cf0 Compare April 30, 2024 09:31
@geo2a geo2a marked this pull request as ready for review May 2, 2024 10:39
Copy link
Member

@jberthold jberthold left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Left some comments, maybe for the next iteration

Copy link
Contributor

@goodlyrottenapple goodlyrottenapple left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, left one comment about making a single copy of showHashHex. If the timings look ok with contextual logs turned off, I'm happy to merge

@geo2a geo2a force-pushed the georgy/better-kore-logging branch from a3c06ca to bce8a4f Compare May 6, 2024 12:22
@geo2a
Copy link
Contributor Author

geo2a commented May 6, 2024

Kontrol performance with 10 workers. No visible performance degradation. Will re-run with 1 worker overnight to hopefully get an empty table.

| Test                                                     | georgy-better-kore-loggin time | master-88ef647ec time | (georgy-better-kore-loggin/master-88ef647ec) time
|----------------------------------------------------------|--------------------------------|-----------------------|---------------------------------------------------
| ExpectRevertTest.testFail_expectRevert_false()           | 140.52                         | 175.61                | 0.8001822219691361
| EmitContractTest.testExpectEmitDoNotCheckData()          | 105.32                         | 130.5                 | 0.8070498084291188
| ExpectRevertTest.test_expectRevert_bytes4()              | 148.92                         | 177.83                | 0.8374290052297136
| MockCallTestFoundry.testMockCalldata()                   | 232.69                         | 258.98                | 0.8984863696038303
| StructTypeTest.test_vars((uint8,uint32,bytes32))         | 75.51                          | 80.78                 | 0.9347610794751177
| MockCallTestFoundry.testMockNested()                     | 448.67                         | 479.79                | 0.9351382896683966
| UintTypeTest.test_uint256(uint256)                       | 61.87                          | 64.33                 | 0.9617596766671848
| StoreTest.testStoreLoadNonExistent()                     | 91.5                           | 88.27                 | 1.0365922737056759
| MockCallTestFoundry.testMockSelector()                   | 137.7                          | 132.59                | 1.0385398597179274
| MockCallTest.testSelectorMockCall()                      | 105.1                          | 101.19                | 1.0386401818361497
| AssumeTest.test_multi_assume(address,address)            | 229.78                         | 220.88                | 1.0402933719666787
| ExpectRevertTest.test_ExpectRevert_increasedDepth()      | 283.95                         | 272.76                | 1.0410250769907612
| PrankTestMsgSender.test_msgsender_setup()                | 205.76                         | 197.54                | 1.0416118254530728
| BytesTypeTest.test_bytes32(bytes32)                      | 50.49                          | 48.45                 | 1.0421052631578946
| ExpectRevertTest.testFail_expectRevert_empty()           | 79.96                          | 76.63                 | 1.0434555657053373
| FreshBytesTest.test_symbolic_bytes_length                | 205.72                         | 196.67                | 1.046016169217471
| FreshBytesTest.test_symbolic_bytes_3                     | 288.81                         | 275.7                 | 1.047551686615887
| LabelTest.testLabel()                                    | 61.18                          | 58.3                  | 1.049399656946827
| LoopsTest.test_sum_10()                                  | 130.54                         | 124.39                | 1.0494412734142615
| PlainPrankTest.test_startPrank_true()                    | 235.19                         | 224.08                | 1.0495805069617994
| GasTest.testSetGas()                                     | 67.74                          | 64.43                 | 1.051373583734285
| AccountParamsTest.testFail_GetNonce_true()               | 110.8                          | 105.21                | 1.0531318315749454
| SymbolicStorageTest.testEmptyInitialStorage(uint256)     | 81.88                          | 77.74                 | 1.0532544378698225
| PlainPrankTest.testFail_startPrank_internalCall()        | 91.1                           | 86.22                 | 1.0565993968916725
| MockCallTestFoundry.testMockCallEmptyAccount()           | 168.53                         | 159.48                | 1.056746927514422
| BytesTypeTest.test_bytes4(bytes4)                        | 59.97                          | 56.74                 | 1.0569263306309482
| AccountParamsTest.test_Nonce_ExistentAddress()           | 98.63                          | 93.24                 | 1.057807807807808
| ArithmeticTest.test_max2(uint256,uint256)                | 125.01                         | 118.14                | 1.0581513458608431
| ConstructorTest.run_constructor()                        | 136.95                         | 127.02                | 1.0781766650921114
| FreshCheatcodes.test_bool()                              | 83.98                          | 77.32                 | 1.0861355406104503
| StoreTest.testLoadNonExistent()                          | 79.34                          | 72.12                 | 1.1001109262340543
| EmitContractTest.testExpectEmitLessTopics()              | 145.43                         | 131.91                | 1.1024941247820486
| ExpectRevertTest.testFail_expectRevert_multipleReverts() | 190.31                         | 163.95                | 1.160780725831046
| TOTAL                                                    | 4758.849999999999              | 4718.789999999999     | 1.008489464460169

@geo2a
Copy link
Contributor Author

geo2a commented May 7, 2024

Kontrol performance with 1 worker:

Test georgy-better-kore-loggin time master-88ef647ec time (georgy-better-kore-loggin/master-88ef647ec) time
BlockParamsTest.testCoinBase() 39.25 41.39 0.9482966900217443
CoinBaseTest.test_coinbase_setup() 69.0 72.68 0.9493670886075949
BytesTypeTest.test_bytes4(bytes4) 36.89 38.51 0.9579330044144378
FreshCheatcodes.test_address() 69.19 66.27 1.0440621699109702
MethodDisambiguateTest.test_method_call() 34.94 31.32 1.115581098339719
TOTAL 249.26999999999998 250.17000000000002 0.996402446336491

@geo2a geo2a added the automerge label May 7, 2024
@rv-jenkins rv-jenkins merged commit fcaae28 into master May 7, 2024
@rv-jenkins rv-jenkins deleted the georgy/better-kore-logging branch May 7, 2024 08:02
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants