Skip to content

chore(host-papp): add console.info diagnostics for SSO request flow #156

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

Open
duewarn wants to merge 1 commit into
base: main
Choose a base branch
from
Open

chore(host-papp): add console.info diagnostics for SSO request flow #156

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
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
6 changes: 6 additions & 0 deletions packages/host-papp/src/sso/auth/impl.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,10 @@ import { createAttestationService, createSudoAliceVerifier } from './attestation
import { HandshakeData, HandshakeResponsePayload, HandshakeResponseSensitiveData } from './scale/handshake.js';
import type { AttestationStatus, PairingStatus } from './types.js';

declare global {
var __registerStatementStoreTopicLabel: ((topic: unknown, label: string) => void) | undefined;
}

export type AuthComponent = ReturnType<typeof createAuth>;

export type HostMetadata = {
Expand Down Expand Up @@ -100,6 +104,8 @@ export function createAuth({
);

return dataPrepared.asyncAndThen(([, handshakeTopic, encrKeys]) => {
// Optional consumer-side hook — see statement-store/session.ts.
globalThis.__registerStatementStoreTopicLabel?.(handshakeTopic, 'handshake');
const pappResponse = waitForStatements<StoredUserSession>(
callback =>
statementStore.subscribeStatements({ matchAll: [handshakeTopic] }, page => callback(page.statements)),
Expand Down
101 changes: 97 additions & 4 deletions packages/host-papp/src/sso/sessionManager/userSession.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -29,11 +29,24 @@ const QUEUE_TASK_TIMEOUT_MS = 180_000;

function withQueueTimeout<T>(resultAsync: ResultAsync<T, Error>, label: string): ResultAsync<T, Error> {
const timeoutPromise = new Promise<Result<T, Error>>(resolve =>
setTimeout(() => resolve(err(new Error(`${label} timed out — queue freed`))), QUEUE_TASK_TIMEOUT_MS),
setTimeout(() => {
console.warn(`[host-papp][${label}] inner queue task TIMED OUT after ${QUEUE_TASK_TIMEOUT_MS}ms — freeing pool`);
resolve(err(new Error(`${label} timed out — queue freed`)));
}, QUEUE_TASK_TIMEOUT_MS),
);
return ResultAsync.fromPromise(Promise.race([resultAsync, timeoutPromise]), toError).andThen(r => r);
}

// Set of remote-message ids we are currently awaiting a response for. Used to
// classify incoming SignResponse / RingVrfAliasResponse messages in the
// `[sso-incoming]` log: messages whose `respondingTo` matches an id in this
// set are "relevant" (we have a pending wait), everything else is "stale"
// (typically a leftover from a previous session, since bulletin paseo retains
// statements for ~7 days). On a fresh session start we end up receiving every
// stale response from prior runs in one go; this set lets us bulk-count them
// instead of dumping a wall of detail per message.
const pendingExpectedMessageIds = new Set<string>();

type ProcessedMessage =
| {
processed: true;
Expand Down Expand Up @@ -106,8 +119,11 @@ export function createUserSession({
remoteAccount: userSession.remoteAccount,

signPayload(payload) {
console.info('[host-papp][signPayload] queueing in requestQueue');
return requestQueue.call(() => {
const messageId = nanoid();
pendingExpectedMessageIds.add(messageId);
console.info(`[host-papp][signPayload] task RUNNING — messageId=${messageId}`);
const request = session.request(RemoteMessageCodec, {
messageId,
data: enumValue(
Expand All @@ -128,12 +144,19 @@ export function createUserSession({
message.data.value.tag === 'SignResponse' &&
message.data.value.value.respondingTo === messageId
) {
console.info(
`[host-papp][signPayload filter] MATCH expected=${messageId.slice(0, 12)} respondingTo=${message.data.value.value.respondingTo.slice(0, 12)}`,
);
return message.data.value.value.payload;
}
};

const inner = request
.andTee(() =>
console.info(`[host-papp][signPayload] request submitted — waiting for response messageId=${messageId}`),
)
.andThen(() => session.waitForRequestMessage(RemoteMessageCodec, responseFilter))
.andTee(() => console.info(`[host-papp][signPayload] response RECEIVED — messageId=${messageId}`))
.andThen(message => {
if (message.success) {
return ok(message.value);
Expand All @@ -142,13 +165,17 @@ export function createUserSession({
}
});

return withQueueTimeout(inner, 'signPayload');
const cleanup = () => pendingExpectedMessageIds.delete(messageId);
return withQueueTimeout(inner, 'signPayload').andTee(cleanup).orTee(cleanup);
});
},

signRaw(payload) {
console.info('[host-papp][signRaw] queueing in requestQueue');
return requestQueue.call(() => {
const messageId = nanoid();
pendingExpectedMessageIds.add(messageId);
console.info(`[host-papp][signRaw] task RUNNING — messageId=${messageId}`);
const request = session.request(RemoteMessageCodec, {
messageId,
data: enumValue(
Expand All @@ -169,12 +196,19 @@ export function createUserSession({
message.data.value.tag === 'SignResponse' &&
message.data.value.value.respondingTo === messageId
) {
console.info(
`[host-papp][signRaw filter] MATCH expected=${messageId.slice(0, 12)} respondingTo=${message.data.value.value.respondingTo.slice(0, 12)}`,
);
return message.data.value.value.payload;
}
};

const inner = request
.andTee(() =>
console.info(`[host-papp][signRaw] request submitted — waiting for response messageId=${messageId}`),
)
.andThen(() => session.waitForRequestMessage(RemoteMessageCodec, responseFilter))
.andTee(() => console.info(`[host-papp][signRaw] response RECEIVED — messageId=${messageId}`))
.andThen(message => {
if (message.success) {
return ok(message.value);
Expand All @@ -183,7 +217,8 @@ export function createUserSession({
}
});

return withQueueTimeout(inner, 'signRaw');
const cleanup = () => pendingExpectedMessageIds.delete(messageId);
return withQueueTimeout(inner, 'signRaw').andTee(cleanup).orTee(cleanup);
});
},

Expand All @@ -199,8 +234,11 @@ export function createUserSession({
},

getRingVrfAlias(productAccountId, productId) {
console.info('[host-papp][getRingVrfAlias] queueing in requestQueue');
return requestQueue.call(() => {
const messageId = nanoid();
pendingExpectedMessageIds.add(messageId);
console.info(`[host-papp][getRingVrfAlias] task RUNNING — messageId=${messageId}`);
const request = session.request(RemoteMessageCodec, {
messageId,
data: enumValue(
Expand All @@ -218,18 +256,73 @@ export function createUserSession({
message.data.value.tag === 'RingVrfAliasResponse' &&
message.data.value.value.respondingTo === messageId
) {
console.info(
`[host-papp][getRingVrfAlias filter] MATCH expected=${messageId.slice(0, 12)} respondingTo=${message.data.value.value.respondingTo.slice(0, 12)}`,
);
return message.data.value.value.payload;
}
};

return request
const inner = request
.andTee(() =>
console.info(
`[host-papp][getRingVrfAlias] request submitted — waiting for response messageId=${messageId}`,
),
)
.andThen(() => session.waitForRequestMessage(RemoteMessageCodec, responseFilter))
.andTee(() => console.info(`[host-papp][getRingVrfAlias] response RECEIVED — messageId=${messageId}`))
.andThen(result => (result.success ? ok(result.value) : err(new Error(result.value))));

const cleanup = () => pendingExpectedMessageIds.delete(messageId);
return inner.andTee(cleanup).orTee(cleanup);
});
},

subscribe(callback: Callback<CodecType<typeof RemoteMessageCodec>, ResultAsync<boolean, Error>>) {
return session.subscribe(RemoteMessageCodec, messages => {
let stale = 0;
const relevant: typeof messages = [];
for (const m of messages) {
// Stale = a SignResponse / RingVrfAliasResponse for a request we are no
// longer waiting on (typically left over on the bulletin chain from
// earlier sessions). Bulk-count them; only print details for messages
// we actively care about.
const respondingTo =
m?.type === 'request' && m.payload.status === 'parsed'
? // eslint-disable-next-line @typescript-eslint/no-explicit-any
((m.payload.value.data.value as any)?.value?.respondingTo as string | undefined)
: undefined;
if (respondingTo && !pendingExpectedMessageIds.has(respondingTo)) {
stale++;
} else {
relevant.push(m);
}
}
console.info(
`[sso-incoming] sess=${userSession.id?.slice?.(0, 8) ?? '?'} got ${messages.length} message(s) — ${relevant.length} relevant, ${stale} stale (pending=${pendingExpectedMessageIds.size})`,
);
for (const m of relevant) {
if (m.type !== 'request') {
console.info(`[sso-incoming] type=${m.type}`);
continue;
}
const status = m.payload.status;
const messageId = status === 'parsed' ? m.payload.value.messageId : undefined;
const dataTag = status === 'parsed' ? m.payload.value.data.tag : undefined;
const subTag =
status === 'parsed'
? // eslint-disable-next-line @typescript-eslint/no-explicit-any
((m.payload.value.data.value as any)?.tag as string | undefined)
: undefined;
const respondingTo =
status === 'parsed'
? // eslint-disable-next-line @typescript-eslint/no-explicit-any
((m.payload.value.data.value as any)?.value?.respondingTo as string | undefined)
: undefined;
console.info(
`[sso-incoming] type=request status=${status} msgId=${messageId?.slice?.(0, 12) ?? '-'} tag=${dataTag}/${subTag} respondingTo=${respondingTo?.slice?.(0, 12) ?? '-'}`,
);
}
processedMessages.read().andThen(processed => {
const results = messages.map<ResultAsync<ProcessedMessage, Error>>(message => {
if (message.type === 'request' && message.payload.status === 'parsed') {
Expand Down