Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logging improvements #63

Merged
merged 5 commits into from
Jun 28, 2024
Merged

Logging improvements #63

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
d882ac8
serialize logged output to JSON
eriktaubeneck Jun 26, 2024
789c877
add timestamp to log object, sort the array by it
eriktaubeneck Jun 27, 2024
1b10465
add ability to download logs
eriktaubeneck Jun 27, 2024
b69b1ad
fix sorting bug
eriktaubeneck Jun 27, 2024
376cef4
add ability to filter by server
eriktaubeneck Jun 27, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
51 changes: 44 additions & 7 deletions server/app/query/servers.tsx
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@ export enum RemoteServerNames {
export interface ServerLog {
remoteServer: RemoteServer;
logLine: string;
timestamp: number;
}

export enum Status {
Expand Down Expand Up @@ -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";
Expand Down Expand Up @@ -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) => {
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@akoshelev this is where the ordering happens. if the new log is already the last, it is just appended. if not, it uses lastIndexOf to find the right spot. this should be O(n) and I would imagine starts from the end of the list, where it will most likely find the right position.

the other performance knob here is the max lines kept. I upped it to 10k, but we could lower that now that the download option is available.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

is it server side or client side?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

client side. client connects directly via websocket to logs from every helper.

I don't think it would be possible to do server side while they query is running, because a stale log from one helper could always arrive after other logs have reached the client.

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(
Expand Down
44 changes: 29 additions & 15 deletions server/app/query/view/[id]/components.tsx
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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>
);
Expand Down
89 changes: 88 additions & 1 deletion server/app/query/view/[id]/page.tsx
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@ import {
Status,
ServerLog,
RemoteServer,
RemoteServerNames,
RemoteServersType,
IPARemoteServers, //hack until the queryId is stored in a DB
StatusByRemoteServer,
Expand All @@ -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] =
Expand All @@ -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);

Expand All @@ -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(
Expand Down Expand Up @@ -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>
</>
);
Expand Down
2 changes: 1 addition & 1 deletion sidecar/app/query/base.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
)
Expand Down
37 changes: 36 additions & 1 deletion sidecar/app/routes/start.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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
Expand Down Expand Up @@ -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(
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would recommend to guarantee ordering on the server side. JS operates in my browser and it is busy with other things, so we should delegate hard work to server side. Besides that, it also makes API consistent

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

btw can you point me to the file where traces are written out of order? I'd like to take a look and see if we may have an issue on the MPC side

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

oh I don't think they should ever be out of order on the server side. they are only out of order when merging the 4 files together. for example a log from Helper 1 might arrive after a log from Helper 2, but have an earlier timestamp.

this is particularly true when we're refreshing later and just consuming the file in it's entirety.

let me point you to where the ordering happens. It should be pretty efficient.

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,
Expand Down
Loading