Skip to content

Commit

Permalink
chore: introduce a pattern to help standardize log tag names (#2371)
Browse files Browse the repository at this point in the history
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.

<!-- start pr-codex -->

---

## 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}`

<!-- end pr-codex -->
  • Loading branch information
aditiharini authored Oct 28, 2024
1 parent 8c13640 commit 5080bbb
Show file tree
Hide file tree
Showing 5 changed files with 65 additions and 47 deletions.
5 changes: 5 additions & 0 deletions .changeset/nice-lions-tickle.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,5 @@
---
"@farcaster/hubble": patch
---

chore: introduce a pattern to help standardize log tag names
3 changes: 2 additions & 1 deletion apps/hubble/src/hubble.ts
Original file line number Diff line number Diff line change
Expand Up @@ -51,6 +51,7 @@ import {
onChainEventToLog,
SubmitMessageSuccessLogCache,
usernameProofToLog,
Tags,
} from "./utils/logger.js";
import {
addressInfoFromGossip,
Expand Down Expand Up @@ -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`);
Expand Down
18 changes: 9 additions & 9 deletions apps/hubble/src/network/p2p/gossipNode.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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";
Expand Down Expand Up @@ -267,7 +267,7 @@ export class GossipNode extends TypedEmitter<NodeEvents> {
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");
}
}

Expand Down Expand Up @@ -302,9 +302,9 @@ export class GossipNode extends TypedEmitter<NodeEvents> {
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
Expand Down Expand Up @@ -546,11 +546,11 @@ export class GossipNode extends TypedEmitter<NodeEvents> {
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);
Expand All @@ -561,12 +561,12 @@ export class GossipNode extends TypedEmitter<NodeEvents> {
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({
Expand Down
46 changes: 9 additions & 37 deletions apps/hubble/src/network/sync/syncHealthJob.ts
Original file line number Diff line number Diff line change
@@ -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";
Expand Down Expand Up @@ -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.
Expand All @@ -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;
}

Expand Down Expand Up @@ -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;
}

Expand All @@ -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;
Expand Down
40 changes: 40 additions & 0 deletions apps/hubble/src/utils/logger.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand Down

0 comments on commit 5080bbb

Please sign in to comment.