From 5080bbb7cf3c69660b4506dd50f6955d3530c5ee Mon Sep 17 00:00:00 2001 From: Aditi Srinivasan Date: Mon, 28 Oct 2024 15:22:28 -0400 Subject: [PATCH] chore: introduce a pattern to help standardize log tag names (#2371) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit It's hard to filter logs by tag if we name the same tag different things in different places. Introduce a pattern for constructing logs that pushes us toward standardizing log tag names. ## Merge Checklist _Choose all relevant options below by adding an `x` now or at any time before submitting for review_ - [x] PR title adheres to the [conventional commits](https://www.conventionalcommits.org/en/v1.0.0/) standard - [x] PR has a [changeset](https://github.com/farcasterxyz/hub-monorepo/blob/main/CONTRIBUTING.md#35-adding-changesets) - [x] PR has been tagged with a change label(s) (i.e. documentation, feature, bugfix, or chore) - [ ] PR includes [documentation](https://github.com/farcasterxyz/hub-monorepo/blob/main/CONTRIBUTING.md#32-writing-docs) if necessary. --- ## PR-Codex overview This PR focuses on standardizing log tag names by introducing a `Tags` class, which is used throughout the codebase to create consistent log entries. ### Detailed summary - Introduced `Tags` class in `apps/hubble/src/utils/logger.ts` for standardized log tags. - Updated logging in `apps/hubble/src/hubble.ts`, `apps/hubble/src/network/p2p/gossipNode.ts`, and `apps/hubble/src/network/sync/syncHealthJob.ts` to use `Tags`. - Added `TagFields` type definition for better structure of log fields. > ✨ Ask PR-Codex anything about this PR by commenting with `/codex {your question}` --- .changeset/nice-lions-tickle.md | 5 ++ apps/hubble/src/hubble.ts | 3 +- apps/hubble/src/network/p2p/gossipNode.ts | 18 ++++---- apps/hubble/src/network/sync/syncHealthJob.ts | 46 ++++--------------- apps/hubble/src/utils/logger.ts | 40 ++++++++++++++++ 5 files changed, 65 insertions(+), 47 deletions(-) create mode 100644 .changeset/nice-lions-tickle.md diff --git a/.changeset/nice-lions-tickle.md b/.changeset/nice-lions-tickle.md new file mode 100644 index 0000000000..bb88e1bf30 --- /dev/null +++ b/.changeset/nice-lions-tickle.md @@ -0,0 +1,5 @@ +--- +"@farcaster/hubble": patch +--- + +chore: introduce a pattern to help standardize log tag names diff --git a/apps/hubble/src/hubble.ts b/apps/hubble/src/hubble.ts index 2e2dabdef6..322324790a 100644 --- a/apps/hubble/src/hubble.ts +++ b/apps/hubble/src/hubble.ts @@ -51,6 +51,7 @@ import { onChainEventToLog, SubmitMessageSuccessLogCache, usernameProofToLog, + Tags, } from "./utils/logger.js"; import { addressInfoFromGossip, @@ -1757,7 +1758,7 @@ export class Hub implements HubInterface { } } - log.info({ peerId }, "falling back to addressbook lookup for peer"); + log.info(new Tags({ peerId: peerId.toString() }), "falling back to addressbook lookup for peer"); const peerAddresses = await this.gossipNode.getPeerAddresses(peerId); if (!peerAddresses) { log.info({ function: "getRPCClientForPeer", peer }, `failed to find peer's address to request simple sync`); diff --git a/apps/hubble/src/network/p2p/gossipNode.ts b/apps/hubble/src/network/p2p/gossipNode.ts index bd886df060..44fe28c57d 100644 --- a/apps/hubble/src/network/p2p/gossipNode.ts +++ b/apps/hubble/src/network/p2p/gossipNode.ts @@ -25,7 +25,7 @@ import { peerIdFromBytes, peerIdFromString } from "@libp2p/peer-id"; import { multiaddr, Multiaddr } from "@multiformats/multiaddr"; import { err, ok, Result } from "neverthrow"; import { TypedEmitter } from "tiny-typed-emitter"; -import { logger, messageTypeToName } from "../../utils/logger.js"; +import { logger, messageTypeToName, Tags } from "../../utils/logger.js"; import { PeriodicPeerCheckScheduler } from "./periodicPeerCheck.js"; import { GOSSIP_PROTOCOL_VERSION } from "./protocol.js"; import { AddrInfo } from "@chainsafe/libp2p-gossipsub/types"; @@ -267,7 +267,7 @@ export class GossipNode extends TypedEmitter { async putPeerAddrToDB(peerIdStr: string, addr: string) { if (this._db) { await this._db.put(this.makePeerKey(peerIdStr), Buffer.from(addr)); - log.info({ peerId: peerIdStr, addr }, "Added peer to DB"); + log.info(new Tags({ addr, peerId: peerIdStr }), "Added peer to DB"); } } @@ -302,9 +302,9 @@ export class GossipNode extends TypedEmitter { const peerAddr = multiaddr(addr); const result = await this.connectAddress(peerAddr); if (result.isOk()) { - log.info({ peerIdStr, addr }, "Connected to peer from DB"); + log.info(new Tags({ addr, peerId: peerIdStr }), "Connected to peer from DB"); } else { - log.debug({ peerIdStr, addr, error: result.error }, "Failed to connect to peer from DB"); + log.debug(new Tags({ addr, error: result.error, peerId: peerIdStr }), "Failed to connect to peer from DB"); } // Sleep for a bit to avoid overwhelming the network @@ -546,11 +546,11 @@ export class GossipNode extends TypedEmitter { this._nodeEvents?.addListener("connection:open", (detail: Connection) => { // console.log("Peer Connected", JSON.stringify(detail, null, 2)); log.info( - { - peer: detail.remotePeer, + new Tags({ addrs: detail.remoteAddr, type: detail.direction, - }, + peerId: detail.remotePeer.toString(), + }), "P2P Connection established", ); this.emit("peerConnect", detail); @@ -561,12 +561,12 @@ export class GossipNode extends TypedEmitter { this.putPeerAddrToDB(detail.remotePeer.toString(), detail.remoteAddr.toString()); }); this._nodeEvents?.addListener("connection:close", (detail: Connection) => { - log.info({ peer: detail.remotePeer }, "P2P Connection disconnected"); + log.info(new Tags({ peerId: detail.remotePeer.toString() }), "P2P Connection disconnected"); this.emit("peerDisconnect", detail); this.updateStatsdPeerGauges(); }); this._nodeEvents?.addListener("peer:discovery", (detail) => { - log.info({ peer: detail }, "Discovered peer"); + log.info(new Tags({ peerId: detail.remotePeer?.toString() }), "Discovered peer"); }); this._nodeEvents?.addListener("gossipsub:message", (detail: GossipsubMessage) => { log.debug({ diff --git a/apps/hubble/src/network/sync/syncHealthJob.ts b/apps/hubble/src/network/sync/syncHealthJob.ts index dcde887333..fe03b777d6 100644 --- a/apps/hubble/src/network/sync/syncHealthJob.ts +++ b/apps/hubble/src/network/sync/syncHealthJob.ts @@ -1,5 +1,5 @@ import cron from "node-cron"; -import { logger } from "../../utils/logger.js"; +import { logger, Tags } from "../../utils/logger.js"; import SyncEngine from "./syncEngine.js"; import { RpcMetadataRetriever, SyncEngineMetadataRetriever, SyncHealthProbe } from "../../utils/syncHealth.js"; import { HubInterface } from "hubble.js"; @@ -109,43 +109,15 @@ export class MeasureSyncHealthJobScheduler { let numAlreadyMerged = 0; for (const result of results) { if (result.isOk()) { - const hashString = bytesToHexString(result.value.hash); - const hash = hashString.isOk() ? hashString.value : "unable to show hash"; - - const typeValue = result.value.data?.type; - const type = typeValue ? UserDataType[typeValue] : "unknown type"; - log.info( - { - msgDetails: { - type, - fid: result.value.data?.fid, - timestamp: this.unixTimestampFromMessage(result.value), - hash, - peerId, - }, - startTime, - stopTime, - }, + new Tags({ peerId, message: result.value, startTime, stopTime }), "Successfully submitted message via SyncHealth", ); numSuccesses += 1; } else { - const hashString = bytesToHexString(result.error.originalMessage.hash); - const hash = hashString.isOk() ? hashString.value : "unable to show hash"; - - const logTags = { - errMessage: result.error.hubError.message, - peerId, - startTime, - stopTime, - msgDetails: { - fid: result.error.originalMessage.data?.fid, - timestamp: this.unixTimestampFromMessage(result.error.originalMessage), - hash, - }, - }; + const logTags = new Tags({ errMessage: result.error.hubError.message, startTime, stopTime }); + if (result.error.hubError.errCode === "bad_request.duplicate") { // This message has already been merged into the DB, but for some reason is not in the Trie. // Just update the trie. @@ -166,7 +138,7 @@ export class MeasureSyncHealthJobScheduler { const contactInfo = this._metadataRetriever._syncEngine.getContactInfoForPeerId(peer.identifier); if (!contactInfo) { - log.info({ peerId: peer.identifier }, "Couldn't get contact info for peer"); + log.info(new Tags({ peerId: peer.identifier }), "Couldn't get contact info for peer"); return undefined; } @@ -205,7 +177,7 @@ export class MeasureSyncHealthJobScheduler { const rpcClient = await this.getRpcClient(peer); if (rpcClient === undefined) { - log.info({ peerId: peer.identifier }, "Couldn't get rpc client, skipping peer"); + log.info(new Tags({ peerId: peer.identifier }), "Couldn't get rpc client, skipping peer"); continue; } @@ -225,11 +197,11 @@ export class MeasureSyncHealthJobScheduler { if (syncHealthMessageStats.isErr()) { const contactInfo = this.contactInfoForLogs(peer); log.info( - { - peerId: peer.identifier, + new Tags({ err: syncHealthMessageStats.error, contactInfo, - }, + peerId: peer.identifier, + }), `Error computing SyncHealth: ${syncHealthMessageStats.error}.`, ); continue; diff --git a/apps/hubble/src/utils/logger.ts b/apps/hubble/src/utils/logger.ts index ec7c3385d4..051cfc0e96 100644 --- a/apps/hubble/src/utils/logger.ts +++ b/apps/hubble/src/utils/logger.ts @@ -134,6 +134,46 @@ class BufferedLogger { } } +export type TagFields = { + fid?: number; + timestamp?: number; + peerId?: string; + messageType?: MessageType; + message?: Message; + // biome-ignore lint/suspicious/noExplicitAny: justified use case + [key: string]: any; +}; + +// Always go through this class to construct log tags so that tag names are standardized. +export class Tags { + private fields: TagFields; + + constructor(fields: TagFields) { + this.fields = fields; + } + + toString() { + const extraFields = Object.fromEntries( + Object.entries(this.fields).filter(([key, value]) => { + return !["fid", "timestamp", "peerId", "messageType", "message"].includes(key); + }), + ); + JSON.stringify({ + fid: this.fields.fid, + timestamp: this.fields.timestamp, + peerId: this.fields.peerId, + messageType: this.fields.messageType, + messageFields: { + timestamp: fromFarcasterTime(this.fields.message?.data?.timestamp || 0)._unsafeUnwrap(), + hash: this.fields.message ? bytesToHexString(this.fields.message.hash)._unsafeUnwrap() : undefined, + fid: this.fields.message?.data?.fid, + type: this.fields.message?.data?.type, + }, + ...extraFields, + }); + } +} + export const logger = new BufferedLogger().createProxy(); export type Logger = pino.Logger;