Skip to content
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

Move winston NodeJS transports to cli package #4509

Merged
merged 13 commits into from Sep 6, 2022

Conversation

dapplion
Copy link
Contributor

@dapplion dapplion commented Sep 3, 2022

Motivation

@lodestar/utils package is meant to contain misc utilities re-used across multiple packages that is platform agnostic, and compatible in the browser.

Defining a common logger for all packages makes sense, but including a NodeJS only transport (FileRotate) breaks the above invariant.

Flags of type --logger.chain.level debug have been broken for a long time. This is due to the way winston handles log level at the transport level and doesn't allow customization on child logger.

Description

  • Move winston NodeJS transports to cli package
  • Keep generic platform agnostic logger code in utils
  • Re-enable per-module log level setting

Also, testing this change found out why file rotate does not clean old files. The library https://www.npmjs.com/package/winston-daily-rotate-file can only delete files that it know of if they are present in the audit file. The audit file location is by default the process cwd, which is not persisted if dockerized. Forcing the audit file to be in the same directory as the log file fixes the issue

auditFile: path.join(path.dirname(transportOpts.filename), ".log_rotate_audit.json"),

closes #2381

@@ -113,7 +113,7 @@ describe("chain / lightclient", function () {
});
}).then(async (head) => {
// Initialize lightclient
loggerLC.important("Initializing lightclient", {slot: head.slot});
loggerLC.info("Initializing lightclient", {slot: head.slot});
Copy link
Contributor Author

Choose a reason for hiding this comment

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

.important API is not used anymore in production and forces creators of custom loggers to add it

@@ -70,49 +69,4 @@ describe("BlockArchiveRepository", function () {
savedBlock2.message.slot = sampleBlock.message.slot;
expect(ssz.phase0.SignedBeaconBlock.equals(savedBlock1, savedBlock2)).to.equal(true);
});

it("batchPutBinary should be faster than batchPut", async () => {
Copy link
Contributor Author

Choose a reason for hiding this comment

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

This is not a test but a very old performance test with winston profiler. Removed as it's not even tracked

description: "Set log level for a specific module by name: 'chain=debug' or 'network=debug,chain=debug'",
type: "array",
string: true,
coerce: (args: string[]) => args.map((item) => item.split(",")).flat(1),
Copy link
Contributor Author

Choose a reason for hiding this comment

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

New option that allows to customize arbitrary modules without dedicated flags per module

datePattern: "YYYY-MM-DD",
handleExceptions: true,
maxFiles: args.logFileDailyRotate ?? defaultLogMaxFiles,
auditFile: path.join(path.dirname(filename), ".log_rotate_audit.json"),
Copy link
Contributor Author

Choose a reason for hiding this comment

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

For dockerized setups the audit file was placed in the process root and lost on restart. So DailyRotateFile could not clean the log files.

return this.levelByModule.delete(module);
}

_write(info: LogInfo, enc: BufferEncoding, callback: (error?: Error | null | undefined) => void): void {
Copy link
Contributor Author

Choose a reason for hiding this comment

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

A bit intrusive into Winston mechanics but this is the easiest solution to have custom module levels by far from the few options I've tried

@@ -60,7 +60,7 @@ describe("cmds / beacon / args handler", () => {
fs.writeFileSync(peerIdFile, JSON.stringify(prevPeerId.toJSON()));

const {peerId} = await runBeaconHandlerInit({
peerIdFile,
// peerIdFile,
Copy link
Contributor Author

Choose a reason for hiding this comment

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

This test is skipped, not sure why Typescript didn't complain about this one before

@@ -85,7 +85,7 @@ function humanReadableTemplateFn(_info: {[key: string]: any; level: string; mess

if (info.timestamp) str += info.timestamp;

str += `[${infoString.toUpperCase()}] ${info.level.padStart(infoPad)}: ${info.message}`;
str += `[${infoString}] ${info.level.padStart(infoPad)}: ${info.message}`;
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Do not mutate module field to keep it equal to what's there in the code

@github-actions
Copy link
Contributor

github-actions bot commented Sep 6, 2022

Performance Report

✔️ no performance regression detected

Full benchmark results
Benchmark suite Current: bb8eb8a Previous: 8806ed2 Ratio
getPubkeys - index2pubkey - req 1000 vs - 250000 vc 2.2160 ms/op 2.0881 ms/op 1.06
getPubkeys - validatorsArr - req 1000 vs - 250000 vc 76.133 us/op 71.740 us/op 1.06
BLS verify - blst-native 2.3677 ms/op 1.8569 ms/op 1.28
BLS verifyMultipleSignatures 3 - blst-native 4.8904 ms/op 3.8027 ms/op 1.29
BLS verifyMultipleSignatures 8 - blst-native 10.820 ms/op 8.1905 ms/op 1.32
BLS verifyMultipleSignatures 32 - blst-native 38.853 ms/op 29.755 ms/op 1.31
BLS aggregatePubkeys 32 - blst-native 53.023 us/op 39.612 us/op 1.34
BLS aggregatePubkeys 128 - blst-native 207.52 us/op 152.82 us/op 1.36
getAttestationsForBlock 177.03 ms/op 163.53 ms/op 1.08
isKnown best case - 1 super set check 454.00 ns/op 468.00 ns/op 0.97
isKnown normal case - 2 super set checks 465.00 ns/op 461.00 ns/op 1.01
isKnown worse case - 16 super set checks 443.00 ns/op 457.00 ns/op 0.97
CheckpointStateCache - add get delete 10.487 us/op 8.7670 us/op 1.20
validate gossip signedAggregateAndProof - struct 5.7161 ms/op 4.2826 ms/op 1.33
validate gossip attestation - struct 2.7525 ms/op 2.0293 ms/op 1.36
pickEth1Vote - no votes 2.3696 ms/op 2.2555 ms/op 1.05
pickEth1Vote - max votes 20.428 ms/op 18.556 ms/op 1.10
pickEth1Vote - Eth1Data hashTreeRoot value x2048 13.426 ms/op 10.959 ms/op 1.23
pickEth1Vote - Eth1Data hashTreeRoot tree x2048 22.212 ms/op 20.788 ms/op 1.07
pickEth1Vote - Eth1Data fastSerialize value x2048 1.7482 ms/op 1.5808 ms/op 1.11
pickEth1Vote - Eth1Data fastSerialize tree x2048 13.107 ms/op 12.096 ms/op 1.08
bytes32 toHexString 1.1320 us/op 1.0160 us/op 1.11
bytes32 Buffer.toString(hex) 736.00 ns/op 711.00 ns/op 1.04
bytes32 Buffer.toString(hex) from Uint8Array 1.0250 us/op 954.00 ns/op 1.07
bytes32 Buffer.toString(hex) + 0x 747.00 ns/op 718.00 ns/op 1.04
Object access 1 prop 0.41500 ns/op 0.34900 ns/op 1.19
Map access 1 prop 0.30500 ns/op 0.29800 ns/op 1.02
Object get x1000 15.111 ns/op 18.335 ns/op 0.82
Map get x1000 0.84600 ns/op 0.99000 ns/op 0.85
Object set x1000 107.64 ns/op 115.32 ns/op 0.93
Map set x1000 75.231 ns/op 70.237 ns/op 1.07
Return object 10000 times 0.37820 ns/op 0.37360 ns/op 1.01
Throw Error 10000 times 7.3832 us/op 6.1021 us/op 1.21
enrSubnets - fastDeserialize 64 bits 2.9360 us/op 2.6320 us/op 1.12
enrSubnets - ssz BitVector 64 bits 784.00 ns/op 726.00 ns/op 1.08
enrSubnets - fastDeserialize 4 bits 405.00 ns/op 365.00 ns/op 1.11
enrSubnets - ssz BitVector 4 bits 761.00 ns/op 754.00 ns/op 1.01
prioritizePeers score -10:0 att 32-0.1 sync 2-0 100.29 us/op 94.167 us/op 1.07
prioritizePeers score 0:0 att 32-0.25 sync 2-0.25 141.43 us/op 135.13 us/op 1.05
prioritizePeers score 0:0 att 32-0.5 sync 2-0.5 250.02 us/op 220.84 us/op 1.13
prioritizePeers score 0:0 att 64-0.75 sync 4-0.75 512.86 us/op 388.86 us/op 1.32
prioritizePeers score 0:0 att 64-1 sync 4-1 557.95 us/op 460.38 us/op 1.21
RateTracker 1000000 limit, 1 obj count per request 187.63 ns/op 186.59 ns/op 1.01
RateTracker 1000000 limit, 2 obj count per request 143.65 ns/op 139.88 ns/op 1.03
RateTracker 1000000 limit, 4 obj count per request 118.30 ns/op 119.01 ns/op 0.99
RateTracker 1000000 limit, 8 obj count per request 110.80 ns/op 104.46 ns/op 1.06
RateTracker with prune 4.9320 us/op 4.3350 us/op 1.14
array of 16000 items push then shift 4.6645 us/op 3.1810 us/op 1.47
LinkedList of 16000 items push then shift 18.090 ns/op 18.090 ns/op 1.00
array of 16000 items push then pop 250.58 ns/op 231.77 ns/op 1.08
LinkedList of 16000 items push then pop 17.036 ns/op 17.349 ns/op 0.98
array of 24000 items push then shift 6.9648 us/op 4.5621 us/op 1.53
LinkedList of 24000 items push then shift 18.771 ns/op 21.644 ns/op 0.87
array of 24000 items push then pop 222.67 ns/op 214.90 ns/op 1.04
LinkedList of 24000 items push then pop 17.148 ns/op 19.408 ns/op 0.88
intersect bitArray bitLen 8 11.673 ns/op 11.558 ns/op 1.01
intersect array and set length 8 190.29 ns/op 164.24 ns/op 1.16
intersect bitArray bitLen 128 66.136 ns/op 72.017 ns/op 0.92
intersect array and set length 128 2.3519 us/op 2.1845 us/op 1.08
Buffer.concat 32 items 2.4050 ns/op 2.2390 ns/op 1.07
pass gossip attestations to forkchoice per slot 4.4855 ms/op 7.1422 ms/op 0.63
computeDeltas 3.7118 ms/op 3.3664 ms/op 1.10
computeProposerBoostScoreFromBalances 786.68 us/op 908.41 us/op 0.87
altair processAttestation - 250000 vs - 7PWei normalcase 4.5655 ms/op 3.5737 ms/op 1.28
altair processAttestation - 250000 vs - 7PWei worstcase 7.2817 ms/op 6.6303 ms/op 1.10
altair processAttestation - setStatus - 1/6 committees join 229.24 us/op 208.85 us/op 1.10
altair processAttestation - setStatus - 1/3 committees join 432.83 us/op 400.66 us/op 1.08
altair processAttestation - setStatus - 1/2 committees join 624.07 us/op 558.96 us/op 1.12
altair processAttestation - setStatus - 2/3 committees join 827.42 us/op 717.28 us/op 1.15
altair processAttestation - setStatus - 4/5 committees join 1.1543 ms/op 995.46 us/op 1.16
altair processAttestation - setStatus - 100% committees join 1.3322 ms/op 1.1764 ms/op 1.13
altair processBlock - 250000 vs - 7PWei normalcase 30.857 ms/op 27.039 ms/op 1.14
altair processBlock - 250000 vs - 7PWei normalcase hashState 43.690 ms/op 41.597 ms/op 1.05
altair processBlock - 250000 vs - 7PWei worstcase 109.77 ms/op 82.228 ms/op 1.33
altair processBlock - 250000 vs - 7PWei worstcase hashState 115.41 ms/op 99.815 ms/op 1.16
phase0 processBlock - 250000 vs - 7PWei normalcase 4.0917 ms/op 3.7271 ms/op 1.10
phase0 processBlock - 250000 vs - 7PWei worstcase 56.137 ms/op 46.834 ms/op 1.20
altair processEth1Data - 250000 vs - 7PWei normalcase 1.0217 ms/op 719.33 us/op 1.42
Tree 40 250000 create 970.46 ms/op 822.99 ms/op 1.18
Tree 40 250000 get(125000) 310.52 ns/op 285.75 ns/op 1.09
Tree 40 250000 set(125000) 3.2563 us/op 2.3289 us/op 1.40
Tree 40 250000 toArray() 33.893 ms/op 36.987 ms/op 0.92
Tree 40 250000 iterate all - toArray() + loop 34.476 ms/op 37.342 ms/op 0.92
Tree 40 250000 iterate all - get(i) 122.32 ms/op 116.09 ms/op 1.05
MutableVector 250000 create 19.057 ms/op 15.071 ms/op 1.26
MutableVector 250000 get(125000) 13.620 ns/op 14.947 ns/op 0.91
MutableVector 250000 set(125000) 829.97 ns/op 609.96 ns/op 1.36
MutableVector 250000 toArray() 7.3778 ms/op 7.2875 ms/op 1.01
MutableVector 250000 iterate all - toArray() + loop 7.3553 ms/op 7.4903 ms/op 0.98
MutableVector 250000 iterate all - get(i) 3.1019 ms/op 3.2827 ms/op 0.94
Array 250000 create 6.9530 ms/op 6.8677 ms/op 1.01
Array 250000 clone - spread 5.4376 ms/op 3.4339 ms/op 1.58
Array 250000 get(125000) 2.1040 ns/op 1.4110 ns/op 1.49
Array 250000 set(125000) 2.1500 ns/op 1.3990 ns/op 1.54
Array 250000 iterate all - loop 134.08 us/op 167.82 us/op 0.80
effectiveBalanceIncrements clone Uint8Array 300000 113.54 us/op 78.840 us/op 1.44
effectiveBalanceIncrements clone MutableVector 300000 1.6570 us/op 1.0240 us/op 1.62
effectiveBalanceIncrements rw all Uint8Array 300000 273.92 us/op 252.54 us/op 1.08
effectiveBalanceIncrements rw all MutableVector 300000 287.08 ms/op 199.87 ms/op 1.44
phase0 afterProcessEpoch - 250000 vs - 7PWei 207.69 ms/op 205.80 ms/op 1.01
phase0 beforeProcessEpoch - 250000 vs - 7PWei 70.090 ms/op 72.997 ms/op 0.96
altair processEpoch - mainnet_e81889 622.63 ms/op 586.78 ms/op 1.06
mainnet_e81889 - altair beforeProcessEpoch 176.44 ms/op 158.40 ms/op 1.11
mainnet_e81889 - altair processJustificationAndFinalization 90.165 us/op 22.098 us/op 4.08
mainnet_e81889 - altair processInactivityUpdates 11.158 ms/op 10.702 ms/op 1.04
mainnet_e81889 - altair processRewardsAndPenalties 97.486 ms/op 91.719 ms/op 1.06
mainnet_e81889 - altair processRegistryUpdates 19.087 us/op 3.6020 us/op 5.30
mainnet_e81889 - altair processSlashings 7.4520 us/op 1.1670 us/op 6.39
mainnet_e81889 - altair processEth1DataReset 6.6470 us/op 1.1770 us/op 5.65
mainnet_e81889 - altair processEffectiveBalanceUpdates 2.2565 ms/op 2.2403 ms/op 1.01
mainnet_e81889 - altair processSlashingsReset 44.579 us/op 7.9260 us/op 5.62
mainnet_e81889 - altair processRandaoMixesReset 43.045 us/op 8.0700 us/op 5.33
mainnet_e81889 - altair processHistoricalRootsUpdate 7.4420 us/op 1.0630 us/op 7.00
mainnet_e81889 - altair processParticipationFlagUpdates 30.450 us/op 2.9180 us/op 10.44
mainnet_e81889 - altair processSyncCommitteeUpdates 6.3620 us/op 698.00 ns/op 9.11
mainnet_e81889 - altair afterProcessEpoch 197.71 ms/op 197.24 ms/op 1.00
phase0 processEpoch - mainnet_e58758 601.02 ms/op 533.42 ms/op 1.13
mainnet_e58758 - phase0 beforeProcessEpoch 282.49 ms/op 235.40 ms/op 1.20
mainnet_e58758 - phase0 processJustificationAndFinalization 86.769 us/op 19.888 us/op 4.36
mainnet_e58758 - phase0 processRewardsAndPenalties 151.01 ms/op 138.08 ms/op 1.09
mainnet_e58758 - phase0 processRegistryUpdates 50.990 us/op 11.396 us/op 4.47
mainnet_e58758 - phase0 processSlashings 5.7970 us/op 1.0040 us/op 5.77
mainnet_e58758 - phase0 processEth1DataReset 6.3740 us/op 1.2500 us/op 5.10
mainnet_e58758 - phase0 processEffectiveBalanceUpdates 2.3007 ms/op 2.3230 ms/op 0.99
mainnet_e58758 - phase0 processSlashingsReset 24.303 us/op 5.9280 us/op 4.10
mainnet_e58758 - phase0 processRandaoMixesReset 32.259 us/op 8.9390 us/op 3.61
mainnet_e58758 - phase0 processHistoricalRootsUpdate 7.3140 us/op 1.1610 us/op 6.30
mainnet_e58758 - phase0 processParticipationRecordUpdates 40.438 us/op 6.4240 us/op 6.29
mainnet_e58758 - phase0 afterProcessEpoch 159.73 ms/op 161.34 ms/op 0.99
phase0 processEffectiveBalanceUpdates - 250000 normalcase 2.2076 ms/op 2.6572 ms/op 0.83
phase0 processEffectiveBalanceUpdates - 250000 worstcase 0.5 2.5786 ms/op 3.4970 ms/op 0.74
altair processInactivityUpdates - 250000 normalcase 46.092 ms/op 41.898 ms/op 1.10
altair processInactivityUpdates - 250000 worstcase 55.685 ms/op 52.007 ms/op 1.07
phase0 processRegistryUpdates - 250000 normalcase 27.649 us/op 12.574 us/op 2.20
phase0 processRegistryUpdates - 250000 badcase_full_deposits 459.59 us/op 531.04 us/op 0.87
phase0 processRegistryUpdates - 250000 worstcase 0.5 240.84 ms/op 218.68 ms/op 1.10
altair processRewardsAndPenalties - 250000 normalcase 132.28 ms/op 129.82 ms/op 1.02
altair processRewardsAndPenalties - 250000 worstcase 91.211 ms/op 86.417 ms/op 1.06
phase0 getAttestationDeltas - 250000 normalcase 14.668 ms/op 13.809 ms/op 1.06
phase0 getAttestationDeltas - 250000 worstcase 15.117 ms/op 13.794 ms/op 1.10
phase0 processSlashings - 250000 worstcase 5.8465 ms/op 5.4327 ms/op 1.08
altair processSyncCommitteeUpdates - 250000 321.13 ms/op 288.96 ms/op 1.11
BeaconState.hashTreeRoot - No change 575.00 ns/op 501.00 ns/op 1.15
BeaconState.hashTreeRoot - 1 full validator 77.498 us/op 54.961 us/op 1.41
BeaconState.hashTreeRoot - 32 full validator 807.24 us/op 637.01 us/op 1.27
BeaconState.hashTreeRoot - 512 full validator 9.7085 ms/op 8.2015 ms/op 1.18
BeaconState.hashTreeRoot - 1 validator.effectiveBalance 101.28 us/op 77.190 us/op 1.31
BeaconState.hashTreeRoot - 32 validator.effectiveBalance 1.4946 ms/op 1.1445 ms/op 1.31
BeaconState.hashTreeRoot - 512 validator.effectiveBalance 18.268 ms/op 15.684 ms/op 1.16
BeaconState.hashTreeRoot - 1 balances 76.001 us/op 61.267 us/op 1.24
BeaconState.hashTreeRoot - 32 balances 779.60 us/op 575.49 us/op 1.35
BeaconState.hashTreeRoot - 512 balances 6.8343 ms/op 5.6703 ms/op 1.21
BeaconState.hashTreeRoot - 250000 balances 115.05 ms/op 94.866 ms/op 1.21
aggregationBits - 2048 els - zipIndexesInBitList 39.550 us/op 35.772 us/op 1.11
regular array get 100000 times 51.976 us/op 67.372 us/op 0.77
wrappedArray get 100000 times 51.838 us/op 67.412 us/op 0.77
arrayWithProxy get 100000 times 31.947 ms/op 28.743 ms/op 1.11
ssz.Root.equals 590.00 ns/op 497.00 ns/op 1.19
byteArrayEquals 546.00 ns/op 489.00 ns/op 1.12
shuffle list - 16384 els 11.508 ms/op 12.633 ms/op 0.91
shuffle list - 250000 els 172.80 ms/op 164.68 ms/op 1.05
processSlot - 1 slots 15.305 us/op 11.742 us/op 1.30
processSlot - 32 slots 2.2096 ms/op 1.6854 ms/op 1.31
getEffectiveBalanceIncrementsZeroInactive - 250000 vs - 7PWei 676.60 us/op 392.50 us/op 1.72
getCommitteeAssignments - req 1 vs - 250000 vc 4.9319 ms/op 5.2711 ms/op 0.94
getCommitteeAssignments - req 100 vs - 250000 vc 6.8950 ms/op 7.2967 ms/op 0.94
getCommitteeAssignments - req 1000 vs - 250000 vc 7.4950 ms/op 7.7748 ms/op 0.96
RootCache.getBlockRootAtSlot - 250000 vs - 7PWei 8.2200 ns/op 8.5800 ns/op 0.96
state getBlockRootAtSlot - 250000 vs - 7PWei 1.1541 us/op 1.1374 us/op 1.01
computeProposers - vc 250000 18.656 ms/op 17.028 ms/op 1.10
computeEpochShuffling - vc 250000 167.87 ms/op 170.19 ms/op 0.99
getNextSyncCommittee - vc 250000 310.93 ms/op 280.15 ms/op 1.11

by benchmarkbot/action

@dapplion dapplion marked this pull request as ready for review September 6, 2022 13:22
@dapplion dapplion requested a review from a team as a code owner September 6, 2022 13:22
@dapplion
Copy link
Contributor Author

dapplion commented Sep 6, 2022

Tested locally with dev command and works well 👍

lodestar$ ./packages/cli/bin/lodestar.js dev --startValidators 0..7 --logLevelModule chain=debug

....
Eph 0/1 3.002[]                 info: Synced - slot: 1 - head: 1 0x2144…5eb4 - finalized: 0x0000…0000:0 - peers: 0
Eph 0/1 4.135[]                 info: Published aggregateAndProofs slot=1, index=0, count=1
Eph 0/2 0.009[chain]         verbose: Clock slot slot=2
Eph 0/2 0.026[]                 warn: Proposer duties re-org. This may happen from time to time priorDependentRoot=0xbda398f7e6216544a3d42e8b26ef79d31022585485e0cd6dafca5f16cdf5cd6c, dependentRoot=0x730702253512af6fd7bbd286acc2fa0e32c9b13e8f588100a3d38e02cc7a4fc9
Eph 0/2 0.047[chain]         verbose: New chain head headSlot=2, headRoot=0xfaaa45b02594122096125e5e7ecc95d34691a518d79c5fc3eec843a456d112d2, delaySec=0.04699993133544922

@wemeetagain wemeetagain merged commit 91a5a06 into unstable Sep 6, 2022
@wemeetagain wemeetagain deleted the dapplion/winston-node-transports branch September 6, 2022 14:59
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Not able to turn on debug for a specific module
2 participants