Use debug logger package

Fix profile loading loop for expired profile same result

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",

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<TCached> {
     this.#name = name;
     this.#table = table;
     setInterval(() => {
-      console.debug(
+      debug(this.#name)(
-        `[${this.#name}] ${this.cache.size} loaded, ${this.onTable.size} on-disk, ${this.#hooks.length} hooks, ${(
+        "%d loaded, %d on-disk, %d hooks, %d% hit",
-          (this.#hits / (this.#hits + this.#miss)) *
+        this.cache.size,
-          100
+        this.onTable.size,
-        ).toFixed(1)} % hit`
+        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<TCached> {
       }
       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<TCached> {
         this.cache.set(this.key(a), a);
       });
       this.notifyChange(fromCacheFiltered.map(a => this.key(a)));
-      console.debug(
+      debug(this.#name)(
-        `[${this.#name}] Loaded ${fromCacheFiltered.length}/${keys.length} in ${(
+        `Loaded %d/%d in %d ms`,
-          unixNowMs() - start
+        fromCacheFiltered.length,
-        ).toLocaleString()} ms`
+        keys.length,
+        (unixNowMs() - start).toLocaleString()
       );
       return mapped.filter(a => !a.has).map(a => a.key);
     }

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() {
           <NoteCreator />
         </>
       )}
-      {window.localStorage.getItem("debug") && <SubDebug />}
       <Toaster />
     </div>
   );

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<RelayTaggedFilte
       },
     });
   }
-  console.debug("GOSSIP", picked);
+  debug("GOSSIP")("Picked %o", picked);
   return picked;
 }

packages/app/src/System/NoteCollection.ts

@@ -89,8 +89,8 @@ export abstract class HookedNoteStore<TSnapshot extends NoteStoreSnapshotData> i
   }
 
   onEvent(cb: OnEventCallback): OnEventCallbackRelease {
-    const existing = this.#eventHooks.findIndex(a => a === cb);
+    const existing = this.#eventHooks.find(a => a === cb);
-    if (existing === -1) {
+    if (!existing) {
       this.#eventHooks.push(cb);
       return () => {
         const idx = this.#eventHooks.findIndex(a => a === cb);

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<HexKey> = new Set();
 
+  readonly #log = debug("ProfileCache");
+
   constructor() {
     this.#FetchMetadata();
   }
@@ -39,14 +42,12 @@ class ProfileLoaderService {
     }
   }
 
-  async onProfileEvent(ev: Readonly<Array<TaggedRawEvent>>) {
+  async onProfileEvent(e: Readonly<TaggedRawEvent>) {
-    for (const e of ev) {
     const profile = mapEventToProfile(e);
     if (profile) {
       await UserCache.update(profile);
     }
   }
-  }
 
   async #FetchMetadata() {
     const missingFromCache = await UserCache.buffer([...this.WantsMetadata]);
@@ -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<string>();
       const q = System.Query<PubkeyReplaceableNoteStore>(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<Readonly<Array<TaggedRawEvent>>>(resolve => {
         let timeout: ReturnType<typeof setTimeout> | 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);

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<RawReqFilter>, feed: NoteStore) {
     this.id = id;
@@ -189,15 +182,8 @@ export class Query implements QueryBase {
     this.#sendQueryInternal(c, subq);
   }
 
-  connectionLost(c: Connection, active: Array<string>, pending: Array<string>) {
+  connectionLost(id: string) {
-    const allQueriesLost = [...active, ...pending].filter(a => this.id === a || this.#tracing.some(b => b.subId === a));
+    this.#tracing.filter(a => a.connId == id).forEach(a => a.forceEose());
-    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();
-    }
   }
 
   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;

packages/app/src/System/index.ts

@@ -74,7 +74,7 @@ export class NostrSystem extends ExternalStore<SystemSnapshot> {
         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<SystemSnapshot> {
     }
   }
 
-  OnRelayDisconnect(c: Connection, active: Array<string>, pending: Array<string>) {
+  OnRelayDisconnect(id: string) {
     for (const [, q] of this.Queries) {
-      q.connectionLost(c, active, pending);
+      q.connectionLost(id);
     }
   }
 
@@ -131,11 +131,13 @@ export class NostrSystem extends ExternalStore<SystemSnapshot> {
         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) {
+            if (q.progress !== 1) {
               q.sendToRelay(c);
             }
+          }
         };
         await c.Connect();
         return c;
@@ -198,7 +200,7 @@ export class NostrSystem extends ExternalStore<SystemSnapshot> {
           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<SystemSnapshot> {
         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);
       }

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<number> {
     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) {

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");
       }

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,

packages/nostr/src/legacy/Connection.ts

@@ -47,7 +47,7 @@ export class Connection {
     cmd: ReqCommand,
     cb: () => void
   }> = [];
-  ActiveRequests: Set<string> = new Set();
+  ActiveRequests = new Set<string>();
 
   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<string>, pending: Array<string>) => void;
+  OnDisconnect?: (id: string) => void;
   Auth?: AuthHandler;
   AwaitingAuth: Map<string, boolean>;
   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();

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"