Logging improvements (#63)

* serialize logged output to JSON

* add timestamp to log object, sort the array by it

* add ability to download logs

* fix sorting bug

* add ability to filter by server

server/app/query/servers.tsx

@@ -10,6 +10,7 @@ export enum RemoteServerNames {
 export interface ServerLog {
   remoteServer: RemoteServer;
   logLine: string;
+  timestamp: number;
 }
 
 export enum Status {
@@ -86,6 +87,10 @@ export class RemoteServer {
     throw new Error("Not Implemented");
   }
 
+  logURL(id: string): URL {
+    return new URL(`/start/${id}/log-file`, this.baseURL);
+  }
+
   logsWebSocketURL(id: string): URL {
     const webSocketURL = new URL(`/ws/logs/${id}`, this.baseURL);
     webSocketURL.protocol = "wss";
@@ -122,13 +127,45 @@ export class RemoteServer {
   ): WebSocket {
     const ws = this.logsSocket(id);
     ws.onmessage = (event) => {
-      const newLog: ServerLog = {
-        remoteServer: this,
-        logLine: event.data,
-      };
-
-      // only retain last 1000 logs
-      setLogs((prevLogs) => [...prevLogs.slice(-1000), newLog]);
+      let newLog: ServerLog;
+      try {
+        const logValue = JSON.parse(event.data);
+        newLog = {
+          remoteServer: this,
+          logLine: logValue.record.message,
+          timestamp: logValue.record.time.timestamp,
+        };
+      } catch (e) {
+        newLog = {
+          remoteServer: this,
+          logLine: event.data,
+          timestamp: Date.now(),
+        };
+      }
+
+      // only retain last 10,000 logs
+      const maxNumLogs = 10000;
+      setLogs((prevLogs) => {
+        if (
+          prevLogs.length === 0 ||
+          newLog.timestamp >= prevLogs[prevLogs.length - 1].timestamp
+        ) {
+          // most the time, we put the new log at the end of the array
+          return [...prevLogs.slice(-maxNumLogs), newLog];
+        } else {
+          // if the timestamp is out of order, e.g., less than the
+          // end of the array, we put it in the right location
+          const lastPreviousLogIndex = prevLogs.findLastIndex(
+            (log) => log.timestamp < newLog.timestamp,
+          );
+
+          return [
+            ...prevLogs.slice(-maxNumLogs, lastPreviousLogIndex + 1),
+            newLog,
+            ...prevLogs.slice(lastPreviousLogIndex - 1),
+          ];
+        }
+      });
     };
     ws.onclose = (event) => {
       console.log(

server/app/query/view/[id]/components.tsx

@@ -88,31 +88,45 @@ export function LogViewer({
   return (
     <div
       className={clsx(
-        "w-full bg-white dark:bg-slate-950 overflow-y-scroll max-h-96 text-start indent-[-128px] pl-32 text-wrap",
+        "w-full bg-white dark:bg-slate-950 overflow-y-scroll max-h-96 text-start text-wrap",
         className,
       )}
     >
       <div className="px-4 py-5 sm:p-6">
-        {logs.map((log, index) => (
+        <dl>
+          {logs.map((log, index) => {
+            const date = new Date(log.timestamp * 1000);
+            return (
+              <div className="flex" key={index}>
+                <dt
+                  className={clsx(
+                    "flex-none w-80 text-slate-900 dark:text-slate-100 text-xs",
+                    sourceCodePro.className,
+                  )}
+                >
+                  {date.toISOString()} | {log.remoteServer.remoteServerNameStr}:
+                </dt>
+                <dd
+                  className={clsx(
+                    "text-slate-900 dark:text-slate-100 text-xs",
+                    sourceCodePro.className,
+                  )}
+                >
+                  {log.logLine}
+                </dd>
+              </div>
+            );
+          })}
           <div
-            key={index}
+            key="last"
             className={clsx(
-              "text-slate-900 dark:text-slate-100 text-xs whitespace-pre-line",
+              "text-slate-900 dark:text-slate-100 text-xs whitespace-pre-line animate-pulse",
               sourceCodePro.className,
             )}
           >
-            {log.logLine}
+            {">_"}
           </div>
-        ))}
-        <div
-          key="last"
-          className={clsx(
-            "text-slate-900 dark:text-slate-100 text-xs whitespace-pre-line animate-pulse",
-            sourceCodePro.className,
-          )}
-        >
-          {">_"}
-        </div>
+        </dl>
       </div>
     </div>
   );

server/app/query/view/[id]/page.tsx

@@ -11,6 +11,7 @@ import {
   Status,
   ServerLog,
   RemoteServer,
+  RemoteServerNames,
   RemoteServersType,
   IPARemoteServers, //hack until the queryId is stored in a DB
   StatusByRemoteServer,
@@ -27,8 +28,21 @@ export default function QueryPage({ params }: { params: { id: string } }) {
   // display controls
   const [logsHidden, setLogsHidden] = useState<boolean>(true);
   const [statsHidden, setStatsHidden] = useState<boolean>(true);
+  const [query, setQuery] = useState<Query | null>(null);
 
   const [logs, setLogs] = useState<ServerLog[]>([]);
+  const [selectedRemoteServerLogs, setSelectedRemoteServerLogs] = useState<
+    string[]
+  >(
+    Object.keys(RemoteServerNames).filter((item) => {
+      return isNaN(Number(item));
+    }),
+  );
+
+  const displayedLogs = logs.filter((item) =>
+    selectedRemoteServerLogs.includes(item.remoteServer.remoteServerNameStr),
+  );
+
   const [statusByRemoteServer, setStatusByRemoteServer] =
     useState<StatusByRemoteServer>(initialStatusByRemoteServer);
   const [statsByRemoteServer, setStatsByRemoteServer] =
@@ -44,6 +58,24 @@ export default function QueryPage({ params }: { params: { id: string } }) {
     setStatsHidden(!statsHidden);
   }
 
+  function handleCheckbox(e: React.ChangeEvent<HTMLInputElement>) {
+    const remoteServer = e.target.id;
+
+    if (e.target.checked) {
+      setSelectedRemoteServerLogs((prevSelectedRemoteServers) => [
+        ...prevSelectedRemoteServers,
+        remoteServer,
+      ]);
+    } else {
+      setSelectedRemoteServerLogs((prevSelectedRemoteServers) =>
+        prevSelectedRemoteServers.filter(
+          (prevSelectedRemoteServer) =>
+            prevSelectedRemoteServer !== remoteServer,
+        ),
+      );
+    }
+  }
+
   const kill = async (remoteServers: RemoteServersType) => {
     const query: Query = await getQuery(params.id);
 
@@ -61,7 +93,11 @@ export default function QueryPage({ params }: { params: { id: string } }) {
   useEffect(() => {
     (async () => {
       const query: Query = await getQuery(params.id);
+      setQuery(query);
       let webSockets: WebSocket[] = [];
+      // useEffect() gets called twice locally
+      // so this prevents the logs from being shown twice
+      setLogs([]);
       for (const remoteServer of Object.values(IPARemoteServers)) {
         const loggingWs = remoteServer.openLogSocket(query.uuid, setLogs);
         const statusWs = remoteServer.openStatusSocket(
@@ -185,7 +221,58 @@ export default function QueryPage({ params }: { params: { id: string } }) {
             </dl>
           </div>
         </button>
-        {!logsHidden && <LogViewer logs={logs} />}
+        {!logsHidden && (
+          <>
+            <form>
+              <div>
+                <ul
+                  role="list"
+                  className="divide-y divide-gray-100 dark:divide-gray-900 border-b border-gray-200 dark:border-gray-800"
+                >
+                  {Object.values(IPARemoteServers).map(
+                    (remoteServer: RemoteServer) => {
+                      return (
+                        <>
+                          <li className="flex items-center justify-between py-2 pl-4 pr-5 text-sm leading-6">
+                            <input
+                              id={remoteServer.remoteServerNameStr}
+                              type="checkbox"
+                              defaultChecked={true}
+                              onChange={handleCheckbox}
+                              className="h-4 w-4 rounded border-gray-300 text-indigo-600 focus:ring-indigo-500"
+                            />
+                            <div className="flex w-0 flex-1 items-center">
+                              <div className="ml-4 flex min-w-0 flex-1 gap-2">
+                                <span className="truncate font-medium">
+                                  {remoteServer.remoteServerNameStr}-
+                                  {query?.uuid}
+                                  .log
+                                </span>
+                              </div>
+                            </div>
+                            {query && (
+                              <div className="ml-4 flex-shrink-0">
+                                <a
+                                  href={remoteServer
+                                    .logURL(query.uuid)
+                                    .toString()}
+                                  className="font-medium text-indigo-600 hover:text-indigo-500"
+                                >
+                                  Download
+                                </a>
+                              </div>
+                            )}
+                          </li>
+                        </>
+                      );
+                    },
+                  )}
+                </ul>
+              </div>
+            </form>
+            <LogViewer logs={displayedLogs} />
+          </>
+        )}
       </div>
     </>
   );

sidecar/app/query/base.py

@@ -43,7 +43,7 @@ def __post_init__(self):
         self._status_dir.mkdir(exist_ok=True)
         self._logger_id = logger.add(
             self.log_file_path,
-            format="{extra[role]}: {message}",
+            serialize=True,
             filter=lambda record: record["extra"].get("task") == self.query_id,
             enqueue=True,
         )

sidecar/app/routes/start.py

@@ -1,7 +1,10 @@
+import json
+from datetime import datetime
 from pathlib import Path
 from typing import Annotated
 
-from fastapi import APIRouter, BackgroundTasks, Form
+from fastapi import APIRouter, BackgroundTasks, Form, HTTPException
+from fastapi.responses import StreamingResponse
 
 from ..local_paths import Paths
 from ..query.base import Query
@@ -87,6 +90,38 @@ def get_ipa_helper_status(
     return {"status": query.status.name}
 
 
+@router.get("/{query_id}/log-file")
+def get_ipa_helper_log_file(
+    query_id: str,
+):
+    query = Query.get_from_query_id(query_id)
+    if query is None:
+        return HTTPException(status_code=404, detail="Query not found")
+
+    def iterfile():
+        with open(query.log_file_path, "rb") as f:
+            for line in f:
+                try:
+                    data = json.loads(line)
+                    d = datetime.fromtimestamp(
+                        float(data["record"]["time"]["timestamp"])
+                    )
+                    message = data["record"]["message"]
+                    yield f"{d.isoformat()} - {message}\n"
+                except (json.JSONDecodeError, KeyError):
+                    yield line
+
+    return StreamingResponse(
+        iterfile(),
+        headers={
+            "Content-Disposition": (
+                f'attachment; filename="{query_id}-{settings.role.name.title()}.log"'
+            )
+        },
+        media_type="text/plain",
+    )
+
+
 @router.post("/ipa-query/{query_id}")
 def start_ipa_test_query(
     query_id: str,