tmp: query tracing

packages/app/src/System/Query.ts

@@ -1,10 +1,77 @@
+import { v4 as uuid } from "uuid";
 import { Connection, RawReqFilter, Nips } from "@snort/nostr";
 import { unixNowMs } from "Util";
+import { NoteStore } from "./NoteCollection";
+/**
+ * Tracing for relay query status
+ */
+class QueryTrace {
+  readonly id: string;
+  readonly subId: string;
+  readonly relay: string;
+  readonly connId: string;
+  readonly start: number;
+  sent?: number;
+  eose?: number;
+  close?: number;
+  #wasForceClosed = false;
+  readonly #fnClose: (id: string) => void;
 
-export interface QueryRequest {
-  filters: Array<RawReqFilter>;
-  started: number;
-  finished?: number;
+  constructor(sub: string, relay: string, connId: string, fnClose: (id: string) => void) {
+    this.id = uuid();
+    this.subId = sub;
+    this.relay = relay;
+    this.connId = connId;
+    this.start = unixNowMs();
+    this.#fnClose = fnClose;
+  }
+
+  sentToRelay() {
+    this.sent = unixNowMs();
+  }
+
+  gotEose() {
+    this.eose = unixNowMs();
+  }
+
+  forceEose() {
+    this.eose = unixNowMs();
+    this.#wasForceClosed = true;
+  }
+
+  sendClose() {
+    this.close = unixNowMs();
+    this.#fnClose(this.subId);
+  }
+
+  log() {
+    console.debug(
+      `QT:${this.id}, ${this.relay}, ${this.subId}, finished=${
+        this.finished
+      }, queued=${this.queued.toLocaleString()}ms, runtime=${this.runtime?.toLocaleString()}ms`
+    );
+  }
+
+  /**
+   * Time spent in queue
+   */
+  get queued() {
+    return (this.sent === undefined ? unixNowMs() : this.sent) - this.start;
+  }
+
+  /**
+   * Total query runtime
+   */
+  get runtime() {
+    return (this.eose === undefined ? unixNowMs() : this.eose) - this.start;
+  }
+
+  /**
+   * If tracing is finished, we got EOSE or timeout
+   */
+  get finished() {
+    return this.eose !== undefined;
+  }
 }
 
 /**
@@ -19,7 +86,7 @@ export class Query {
   /**
    * The query payload (REQ filters)
    */
-  request: QueryRequest;
+  filters: Array<RawReqFilter>;
 
   /**
    * Sub-Queries which are connected to this subscription
@@ -29,12 +96,7 @@ export class Query {
   /**
    * Which relays this query has already been executed on
    */
-  #sentToRelays: Array<Readonly<Connection>> = [];
-
-  /**
-   * When each relay returned EOSE
-   */
-  #eoseRelays: Map<string, number> = new Map();
+  #tracing: Array<QueryTrace> = [];
 
   /**
    * Leave the query open until its removed
@@ -51,9 +113,21 @@ export class Query {
    */
   #cancelTimeout?: number;
 
-  constructor(id: string, request: QueryRequest) {
+  /**
+   * Timer used to track tracing status
+   */
+  #checkTrace?: ReturnType<typeof setInterval>;
+
+  /**
+   * Feed object which collects events
+   */
+  #feed?: NoteStore;
+
+  constructor(id: string, filters: Array<RawReqFilter>, feed?: NoteStore) {
     this.id = id;
-    this.request = request;
+    this.filters = filters;
+    this.#feed = feed;
+    this.#checkTraces();
   }
 
   get closing() {
@@ -64,6 +138,10 @@ export class Query {
     return this.#cancelTimeout;
   }
 
+  get feed() {
+    return this.#feed;
+  }
+
   cancel() {
     this.#cancelTimeout = unixNowMs() + 5_000;
   }
@@ -72,6 +150,11 @@ export class Query {
     this.#cancelTimeout = undefined;
   }
 
+  cleanup() {
+    console.debug("Cleanup", this.id);
+    this.#stopCheckTraces();
+  }
+
   sendToRelay(c: Connection) {
     if (this.relays.length > 0 && !this.relays.includes(c.Address)) {
       return;
@@ -80,31 +163,47 @@ export class Query {
       console.debug("Cant send non-specific REQ to ephemeral connection");
       return;
     }
-    if (this.request.filters.some(a => a.search) && !c.SupportsNip(Nips.Search)) {
+    if (this.filters.some(a => a.search) && !c.SupportsNip(Nips.Search)) {
       console.debug("Cant send REQ to non-search relay", c.Address);
       return;
     }
-    c.QueueReq(["REQ", this.id, ...this.request.filters]);
-    this.#sentToRelays.push(c);
+    const qt = new QueryTrace(this.id, c.Address, c.Id, x => c.CloseReq(x));
+    this.#tracing.push(qt);
+    c.QueueReq(["REQ", this.id, ...this.filters], () => qt.sentToRelay());
+  }
+
+  connectionLost(c: Connection, active: Array<string>, pending: Array<string>) {
+    const allQueriesLost = [...active, ...pending].filter(a => this.id === a || this.subQueries.some(b => b.id === a));
+    if (allQueriesLost.length > 0) {
+      console.debug("Lost", allQueriesLost, c.Address, c.Id);
+    }
   }
 
   sendClose() {
-    for (const c of this.#sentToRelays) {
-      c.CloseReq(this.id);
+    for (const qt of this.#tracing) {
+      qt.sendClose();
     }
     for (const sq of this.subQueries) {
       sq.sendClose();
     }
+    this.cleanup();
   }
 
-  eose(sub: string, relay: string) {
+  eose(sub: string, conn: Readonly<Connection>) {
+    const qt = this.#tracing.filter(a => a.subId === sub && a.connId === conn.Id);
     if (sub === this.id) {
-      console.debug(`[EOSE][${sub}] ${relay}`);
-      this.#eoseRelays.set(relay, unixNowMs());
+      console.debug(`[EOSE][${sub}] ${conn.Address}`);
+      qt.forEach(a => a.gotEose());
+      if (this.#feed) {
+        this.#feed.loading = this.progress < 1;
+      }
+      if (!this.leaveOpen) {
+        this.sendClose();
+      }
     } else {
       const subQ = this.subQueries.find(a => a.id === sub);
       if (subQ) {
-        subQ.eose(sub, relay);
+        subQ.eose(sub, conn);
       } else {
         throw new Error("No query found");
       }
@@ -115,7 +214,7 @@ export class Query {
    * Get the progress to EOSE, can be used to determine when we should load more content
    */
   get progress() {
-    let thisProgress = this.#eoseRelays.size / this.#sentToRelays.reduce((acc, v) => (acc += v.Down ? 0 : 1), 0);
+    let thisProgress = this.#tracing.reduce((acc, v) => (acc += v.finished ? 1 : 0), 0) / this.#tracing.length;
     if (isNaN(thisProgress)) {
       thisProgress = 0;
     }
@@ -129,4 +228,22 @@ export class Query {
     }
     return totalProgress / (this.subQueries.length + 1);
   }
+
+  #stopCheckTraces() {
+    if (this.#checkTrace) {
+      clearInterval(this.#checkTrace);
+    }
+  }
+
+  #checkTraces() {
+    this.#stopCheckTraces();
+    this.#checkTrace = setInterval(() => {
+      for (const v of this.#tracing) {
+        //v.log();
+        if (v.runtime > 5_000 && !v.finished) {
+          v.forceEose();
+        }
+      }
+    }, 2_000);
+  }
 }