From 2ccee7bd7c4899130883de3150ad46131b1347a2 Mon Sep 17 00:00:00 2001 From: Kieran Date: Thu, 25 May 2023 00:03:54 +0100 Subject: [PATCH] Use debug logger package Fix profile loading loop for expired profile same result --- packages/app/package.json | 2 + packages/app/src/Cache/FeedCache.ts | 25 +++++++------ packages/app/src/Pages/Layout.tsx | 2 - packages/app/src/System/GossipModel.ts | 3 +- packages/app/src/System/NoteCollection.ts | 4 +- packages/app/src/System/ProfileCache.ts | 37 +++++++++++++------ packages/app/src/System/Query.ts | 36 ++++++------------ packages/app/src/System/index.ts | 16 ++++---- packages/app/src/Wallet/LNCWallet.ts | 10 +++-- packages/app/src/Wallet/LNDHub.ts | 1 - packages/app/src/Wallet/NostrWalletConnect.ts | 3 +- packages/nostr/src/legacy/Connection.ts | 6 +-- yarn.lock | 14 ++++++- 13 files changed, 89 insertions(+), 70 deletions(-) diff --git a/packages/app/package.json b/packages/app/package.json index a28acdba..1d68eff0 100644 --- a/packages/app/package.json +++ b/packages/app/package.json @@ -17,6 +17,7 @@ "@void-cat/api": "^1.0.4", "base32-decode": "^1.0.0", "bech32": "^2.0.0", + "debug": "^4.3.4", "dexie": "^3.2.2", "dexie-react-hooks": "^1.1.1", "dns-over-http-resolver": "^2.1.1", @@ -80,6 +81,7 @@ "@babel/preset-react": "^7.18.6", "@formatjs/cli": "^6.0.1", "@formatjs/ts-transformer": "^3.13.1", + "@types/debug": "^4.1.8", "@types/jest": "^29.5.1", "@types/node": "^18.11.18", "@types/react": "^18.0.26", diff --git a/packages/app/src/Cache/FeedCache.ts b/packages/app/src/Cache/FeedCache.ts index 4a24f541..ccd91667 100644 --- a/packages/app/src/Cache/FeedCache.ts +++ b/packages/app/src/Cache/FeedCache.ts @@ -1,4 +1,5 @@ import { db } from "Db"; +import debug from "debug"; import { Table } from "dexie"; import { unixNowMs, unwrap } from "SnortUtils"; @@ -24,13 +25,14 @@ export default abstract class FeedCache { this.#name = name; this.#table = table; setInterval(() => { - console.debug( - `[${this.#name}] ${this.cache.size} loaded, ${this.onTable.size} on-disk, ${this.#hooks.length} hooks, ${( - (this.#hits / (this.#hits + this.#miss)) * - 100 - ).toFixed(1)} % hit` + debug(this.#name)( + "%d loaded, %d on-disk, %d hooks, %d% hit", + this.cache.size, + this.onTable.size, + this.#hooks.length, + ((this.#hits / (this.#hits + this.#miss)) * 100).toFixed(1) ); - }, 5_000); + }, 30_000); } async preload() { @@ -138,7 +140,7 @@ export default abstract class FeedCache { } return "no_change"; })(); - console.debug(`Updating ${k} ${updateType}`, m); + debug(this.#name)("Updating %s %s %o", k, updateType, m); if (updateType !== "no_change") { const updated = { ...existing, @@ -168,10 +170,11 @@ export default abstract class FeedCache { this.cache.set(this.key(a), a); }); this.notifyChange(fromCacheFiltered.map(a => this.key(a))); - console.debug( - `[${this.#name}] Loaded ${fromCacheFiltered.length}/${keys.length} in ${( - unixNowMs() - start - ).toLocaleString()} ms` + debug(this.#name)( + `Loaded %d/%d in %d ms`, + fromCacheFiltered.length, + keys.length, + (unixNowMs() - start).toLocaleString() ); return mapped.filter(a => !a.has).map(a => a.key); } diff --git a/packages/app/src/Pages/Layout.tsx b/packages/app/src/Pages/Layout.tsx index f57d9c51..9c538dd2 100644 --- a/packages/app/src/Pages/Layout.tsx +++ b/packages/app/src/Pages/Layout.tsx @@ -16,7 +16,6 @@ import useModeration from "Hooks/useModeration"; import { NoteCreator } from "Element/NoteCreator"; import { db } from "Db"; import useEventPublisher from "Feed/EventPublisher"; -import SubDebug from "Element/SubDebug"; import { preload } from "Cache"; import { useDmCache } from "Hooks/useDmsCache"; import { mapPlanName } from "./subscribe"; @@ -170,7 +169,6 @@ export default function Layout() { )} - {window.localStorage.getItem("debug") && } ); diff --git a/packages/app/src/System/GossipModel.ts b/packages/app/src/System/GossipModel.ts index 596473c8..06c359f4 100644 --- a/packages/app/src/System/GossipModel.ts +++ b/packages/app/src/System/GossipModel.ts @@ -1,6 +1,7 @@ import { RawReqFilter } from "@snort/nostr"; import { UserRelays } from "Cache/UserRelayCache"; import { unwrap } from "SnortUtils"; +import debug from "debug"; const PickNRelays = 2; @@ -106,6 +107,6 @@ export function splitByWriteRelays(filter: RawReqFilter): Array i } onEvent(cb: OnEventCallback): OnEventCallbackRelease { - const existing = this.#eventHooks.findIndex(a => a === cb); - if (existing === -1) { + const existing = this.#eventHooks.find(a => a === cb); + if (!existing) { this.#eventHooks.push(cb); return () => { const idx = this.#eventHooks.findIndex(a => a === cb); diff --git a/packages/app/src/System/ProfileCache.ts b/packages/app/src/System/ProfileCache.ts index 12bc12b0..00a6fb55 100644 --- a/packages/app/src/System/ProfileCache.ts +++ b/packages/app/src/System/ProfileCache.ts @@ -4,6 +4,7 @@ import { mapEventToProfile, MetadataCache } from "Cache"; import { UserCache } from "Cache/UserCache"; import { PubkeyReplaceableNoteStore, RequestBuilder, System } from "System"; import { unixNowMs } from "SnortUtils"; +import debug from "debug"; class ProfileLoaderService { /** @@ -11,6 +12,8 @@ class ProfileLoaderService { */ WantsMetadata: Set = new Set(); + readonly #log = debug("ProfileCache"); + constructor() { this.#FetchMetadata(); } @@ -39,12 +42,10 @@ class ProfileLoaderService { } } - async onProfileEvent(ev: Readonly>) { - for (const e of ev) { - const profile = mapEventToProfile(e); - if (profile) { - await UserCache.update(profile); - } + async onProfileEvent(e: Readonly) { + const profile = mapEventToProfile(e); + if (profile) { + await UserCache.update(profile); } } @@ -57,18 +58,25 @@ class ProfileLoaderService { .filter(a => (UserCache.getFromCache(a)?.loaded ?? 0) < expire); const missing = new Set([...missingFromCache, ...expired]); if (missing.size > 0) { - console.debug(`[UserCache] Wants profiles: ${missingFromCache.length} missing, ${expired.length} expired`); + this.#log("Wants profiles: %d missing, %d expired", missingFromCache.length, expired.length); - const sub = new RequestBuilder(`profiles`); + const sub = new RequestBuilder("profiles"); sub + .withOptions({ + skipDiff: true, + }) .withFilter() .kinds([EventKind.SetMetadata]) .authors([...missing]); + const newProfiles = new Set(); const q = System.Query(PubkeyReplaceableNoteStore, sub); // never release this callback, it will stop firing anyway after eose const releaseOnEvent = q.onEvent(async e => { - await this.onProfileEvent(e); + for (const pe of e) { + newProfiles.add(pe.id); + await this.onProfileEvent(pe); + } }); const results = await new Promise>>(resolve => { let timeout: ReturnType | undefined = undefined; @@ -76,21 +84,21 @@ class ProfileLoaderService { if (!q.loading) { clearTimeout(timeout); resolve(q.getSnapshotData() ?? []); - console.debug("Profiles finished: ", sub.id); + this.#log("Profiles finished: %s", sub.id); release(); } }); timeout = setTimeout(() => { release(); resolve(q.getSnapshotData() ?? []); - console.debug("Profiles timeout: ", sub.id); + this.#log("Profiles timeout: %s", sub.id); }, 5_000); }); releaseOnEvent(); const couldNotFetch = [...missing].filter(a => !results.some(b => b.pubkey === a)); if (couldNotFetch.length > 0) { - console.debug("No profiles: ", couldNotFetch); + this.#log("No profiles: %o", couldNotFetch); const empty = couldNotFetch.map(a => UserCache.update({ pubkey: a, @@ -100,6 +108,11 @@ class ProfileLoaderService { ); await Promise.all(empty); } + + // When we fetch an expired profile and its the same as what we already have + // onEvent is not fired and the loaded timestamp never gets updated + const expiredSame = results.filter(a => !newProfiles.has(a.id) && expired.includes(a.pubkey)); + await Promise.all(expiredSame.map(v => this.onProfileEvent(v))); } setTimeout(() => this.#FetchMetadata(), 500); diff --git a/packages/app/src/System/Query.ts b/packages/app/src/System/Query.ts index 01b45c5d..d877f3ab 100644 --- a/packages/app/src/System/Query.ts +++ b/packages/app/src/System/Query.ts @@ -1,7 +1,9 @@ import { v4 as uuid } from "uuid"; +import debug from "debug"; import { Connection, RawReqFilter, Nips } from "@snort/nostr"; import { unixNowMs, unwrap } from "SnortUtils"; import { NoteStore } from "./NoteCollection"; + /** * Tracing for relay query status */ @@ -17,6 +19,7 @@ class QueryTrace { #wasForceClosed = false; readonly #fnClose: (id: string) => void; readonly #fnProgress: () => void; + readonly #log = debug("QueryTrace"); constructor(sub: string, relay: string, connId: string, fnClose: (id: string) => void, fnProgress: () => void) { this.id = uuid(); @@ -35,18 +38,15 @@ class QueryTrace { gotEose() { this.eose = unixNowMs(); - if (this.responseTime > 5_000) { - console.debug(`Slow query ${this.subId} on ${this.relay} took ${this.responseTime.toLocaleString()}ms`); - } this.#fnProgress(); - console.debug(`[EOSE][${this.subId}] ${this.relay}`); + //this.#log("[EOSE] %s %s", this.subId, this.relay); } forceEose() { this.eose = unixNowMs(); this.#wasForceClosed = true; this.#fnProgress(); - console.debug(`[F-EOSE][${this.subId}] ${this.relay}`); + //this.#log("[F-EOSE] %s %s", this.subId, this.relay); } sendClose() { @@ -55,14 +55,6 @@ class QueryTrace { this.#fnProgress(); } - log() { - console.debug( - `QT:${this.id}, ${this.subId}, finished=${ - this.finished - }, queued=${this.queued.toLocaleString()}ms, runtime=${this.runtime?.toLocaleString()}ms, ${this.relay}` - ); - } - /** * Time spent in queue */ @@ -143,6 +135,7 @@ export class Query implements QueryBase { #feed: NoteStore; subQueryCounter = 0; + #log = debug("Query"); constructor(id: string, filters: Array, feed: NoteStore) { this.id = id; @@ -189,15 +182,8 @@ export class Query implements QueryBase { this.#sendQueryInternal(c, subq); } - connectionLost(c: Connection, active: Array, pending: Array) { - const allQueriesLost = [...active, ...pending].filter(a => this.id === a || this.#tracing.some(b => b.subId === a)); - if (allQueriesLost.length > 0) { - console.debug("Lost", allQueriesLost, c.Address, c.Id); - } - for (const qLost of allQueriesLost) { - const qt = this.#tracing.find(a => a.subId === qLost && a.connId == c.Id); - qt?.forceEose(); - } + connectionLost(id: string) { + this.#tracing.filter(a => a.connId == id).forEach(a => a.forceEose()); } sendClose() { @@ -234,7 +220,7 @@ export class Query implements QueryBase { #onProgress() { const isFinished = this.progress === 1; if (this.feed.loading !== isFinished) { - console.debug(`[QT] ${this.id}, loading=${this.feed.loading}, progress=${this.progress}`); + this.#log("%s loading=%s, progress=%d", this.id, this.feed.loading, this.progress); this.feed.loading = isFinished; } } @@ -261,11 +247,11 @@ export class Query implements QueryBase { return false; } if ((q.relays?.length ?? 0) === 0 && c.Ephemeral) { - console.debug("Cant send non-specific REQ to ephemeral connection"); + this.#log("Cant send non-specific REQ to ephemeral connection"); return false; } if (q.filters.some(a => a.search) && !c.SupportsNip(Nips.Search)) { - console.debug("Cant send REQ to non-search relay", c.Address); + this.#log("Cant send REQ to non-search relay", c.Address); return false; } return true; diff --git a/packages/app/src/System/index.ts b/packages/app/src/System/index.ts index 13304c26..5c8a1e49 100644 --- a/packages/app/src/System/index.ts +++ b/packages/app/src/System/index.ts @@ -74,7 +74,7 @@ export class NostrSystem extends ExternalStore { this.Sockets.set(addr, c); c.OnEvent = (s, e) => this.OnEvent(s, e); c.OnEose = s => this.OnEndOfStoredEvents(c, s); - c.OnDisconnect = (a, p) => this.OnRelayDisconnect(c, a, p); + c.OnDisconnect = id => this.OnRelayDisconnect(id); c.OnConnected = () => { for (const [, q] of this.Queries) { q.sendToRelay(c); @@ -90,9 +90,9 @@ export class NostrSystem extends ExternalStore { } } - OnRelayDisconnect(c: Connection, active: Array, pending: Array) { + OnRelayDisconnect(id: string) { for (const [, q] of this.Queries) { - q.connectionLost(c, active, pending); + q.connectionLost(id); } } @@ -131,10 +131,12 @@ export class NostrSystem extends ExternalStore { this.Sockets.set(addr, c); c.OnEvent = (s, e) => this.OnEvent(s, e); c.OnEose = s => this.OnEndOfStoredEvents(c, s); - c.OnDisconnect = (a, p) => this.OnRelayDisconnect(c, a, p); + c.OnDisconnect = id => this.OnRelayDisconnect(id); c.OnConnected = () => { for (const [, q] of this.Queries) { - q.sendToRelay(c); + if (q.progress !== 1) { + q.sendToRelay(c); + } } }; await c.Connect(); @@ -198,7 +200,7 @@ export class NostrSystem extends ExternalStore { const subQ = { id: `${q.id}-${q.subQueryCounter++}`, filters: sf.filters, - relays: sf.relay ? [sf.relay] : [], + relays: sf.relay ? [sf.relay] : undefined, } as QueryBase; this.SendSubQuery(q, subQ); } @@ -230,7 +232,7 @@ export class NostrSystem extends ExternalStore { const subQ = { id: `${q.id}-${q.subQueryCounter++}`, filters: sf.filters, - relays: sf.relay ? [sf.relay] : [], + relays: sf.relay ? [sf.relay] : undefined, } as QueryBase; this.SendSubQuery(q, subQ); } diff --git a/packages/app/src/Wallet/LNCWallet.ts b/packages/app/src/Wallet/LNCWallet.ts index fa861c44..342dfec8 100644 --- a/packages/app/src/Wallet/LNCWallet.ts +++ b/packages/app/src/Wallet/LNCWallet.ts @@ -11,6 +11,7 @@ import { WalletInvoice, WalletInvoiceState, } from "Wallet"; +import debug from "debug"; enum Payment_PaymentStatus { UNKNOWN = "UNKNOWN", @@ -22,6 +23,7 @@ enum Payment_PaymentStatus { export class LNCWallet implements LNWallet { #lnc: LNC; + readonly #log = debug("LNC"); private constructor(pairingPhrase?: string, password?: string) { this.#lnc = new LNC({ @@ -90,7 +92,7 @@ export class LNCWallet implements LNWallet { async getBalance(): Promise { const rsp = await this.#lnc.lnd.lightning.channelBalance(); - console.debug(rsp); + this.#log(rsp); return parseInt(rsp.localBalance?.sat ?? "0"); } @@ -112,7 +114,7 @@ export class LNCWallet implements LNWallet { feeLimitSat: "100", }, msg => { - console.debug(msg); + this.#log(msg); if (msg.status === Payment_PaymentStatus.SUCCEEDED) { resolve({ preimage: msg.paymentPreimage, @@ -122,7 +124,7 @@ export class LNCWallet implements LNWallet { } }, err => { - console.debug(err); + this.#log(err); reject(err); } ); @@ -135,7 +137,7 @@ export class LNCWallet implements LNWallet { reversed: true, }); - console.debug(invoices); + this.#log(invoices); return invoices.payments.map(a => { const parsedInvoice = prToWalletInvoice(a.paymentRequest); if (!parsedInvoice) { diff --git a/packages/app/src/Wallet/LNDHub.ts b/packages/app/src/Wallet/LNDHub.ts index 83cb6519..738dfeb9 100644 --- a/packages/app/src/Wallet/LNDHub.ts +++ b/packages/app/src/Wallet/LNDHub.ts @@ -26,7 +26,6 @@ export default class LNDHubWallet implements LNWallet { if (url.startsWith("lndhub://")) { const regex = /^lndhub:\/\/([\S-]+):([\S-]+)@(.*)$/i; const parsedUrl = url.match(regex); - console.debug(parsedUrl); if (!parsedUrl || parsedUrl.length !== 4) { throw new Error("Invalid LNDHUB config"); } diff --git a/packages/app/src/Wallet/NostrWalletConnect.ts b/packages/app/src/Wallet/NostrWalletConnect.ts index 1fd6d70d..5979b957 100644 --- a/packages/app/src/Wallet/NostrWalletConnect.ts +++ b/packages/app/src/Wallet/NostrWalletConnect.ts @@ -2,6 +2,7 @@ import { Connection, EventKind, RawEvent } from "@snort/nostr"; import { EventBuilder } from "System"; import { EventExt } from "System/EventExt"; import { LNWallet, WalletError, WalletErrorCode, WalletInfo, WalletInvoice, WalletInvoiceState } from "Wallet"; +import debug from "debug"; interface WalletConnectConfig { relayUrl: string; @@ -184,7 +185,7 @@ export class NostrConnectWallet implements LNWallet { this.#commandQueue.set(evCommand.id, { resolve: async (o: string) => { const reply = JSON.parse(await EventExt.decryptData(o, this.#config.secret, this.#config.walletPubkey)); - console.debug("NWC", reply); + debug("NWC")("%o", reply); resolve(reply); }, reject, diff --git a/packages/nostr/src/legacy/Connection.ts b/packages/nostr/src/legacy/Connection.ts index 452f2ac8..36ed4c4d 100644 --- a/packages/nostr/src/legacy/Connection.ts +++ b/packages/nostr/src/legacy/Connection.ts @@ -47,7 +47,7 @@ export class Connection { cmd: ReqCommand, cb: () => void }> = []; - ActiveRequests: Set = new Set(); + ActiveRequests = new Set(); Settings: RelaySettings; Info?: RelayInfo; @@ -63,7 +63,7 @@ export class Connection { OnConnected?: () => void; OnEvent?: (sub: string, e: TaggedRawEvent) => void; OnEose?: (sub: string) => void; - OnDisconnect?: (active: Array, pending: Array) => void; + OnDisconnect?: (id: string) => void; Auth?: AuthHandler; AwaitingAuth: Map; Authed = false; @@ -190,7 +190,7 @@ export class Connection { this.ReconnectTimer = null; } - this.OnDisconnect?.([...this.ActiveRequests], this.PendingRequests.map(a => a.cmd[1])) + this.OnDisconnect?.(this.Id); this.#ResetQueues(); // reset connection Id on disconnect, for query-tracking this.Id = uuid(); diff --git a/yarn.lock b/yarn.lock index f69433cc..100b9383 100644 --- a/yarn.lock +++ b/yarn.lock @@ -2357,6 +2357,13 @@ dependencies: "@types/node" "*" +"@types/debug@^4.1.8": + version "4.1.8" + resolved "https://registry.yarnpkg.com/@types/debug/-/debug-4.1.8.tgz#cef723a5d0a90990313faec2d1e22aee5eecb317" + integrity sha512-/vPO1EPOs306Cvhwv7KfVfYvOJqA/S/AXjaHQiJboCZzcNDb+TIJFN9/2C9DZ//ijSKWioNyUxD792QmDJ+HKQ== + dependencies: + "@types/ms" "*" + "@types/eslint-scope@^3.7.3": version "3.7.4" resolved "https://registry.npmjs.org/@types/eslint-scope/-/eslint-scope-3.7.4.tgz" @@ -2529,6 +2536,11 @@ resolved "https://registry.npmjs.org/@types/mocha/-/mocha-10.0.1.tgz" integrity sha512-/fvYntiO1GeICvqbQ3doGDIP97vWmvFt83GKguJ6prmQM2iXZfFcq6YE8KteFyRtX2/h5Hf91BYvPodJKFYv5Q== +"@types/ms@*": + version "0.7.31" + resolved "https://registry.yarnpkg.com/@types/ms/-/ms-0.7.31.tgz#31b7ca6407128a3d2bbc27fe2d21b345397f6197" + integrity sha512-iiUgKzV9AuaEkZqkOLDIvlQiL6ltuZd9tGcW3gwpnX8JbuiuhFlEGmmFXEXkN50Cvq7Os88IY2v0dkDqXYWVgA== + "@types/node@*", "@types/node@^18.11.18": version "18.15.11" resolved "https://registry.npmjs.org/@types/node/-/node-18.15.11.tgz" @@ -4448,7 +4460,7 @@ debug@2.6.9: debug@4, debug@4.3.4, debug@^4.1.0, debug@^4.1.1, debug@^4.3.1, debug@^4.3.2, debug@^4.3.3, debug@^4.3.4: version "4.3.4" - resolved "https://registry.npmjs.org/debug/-/debug-4.3.4.tgz" + resolved "https://registry.yarnpkg.com/debug/-/debug-4.3.4.tgz#1319f6579357f2338d3337d2cdd4914bb5dcc865" integrity sha512-PRWFHuSU3eDtQJPvnNY7Jcket1j0t5OuOsFzPPzsekD52Zl8qUfFIPEiswXqIvHWGVHOgX+7G/vCNNhehwxfkQ== dependencies: ms "2.1.2"