diff --git a/server/routers/olm/handleOlmRegisterMessage.ts b/server/routers/olm/handleOlmRegisterMessage.ts index a4a62973d..aaaf81c41 100644 --- a/server/routers/olm/handleOlmRegisterMessage.ts +++ b/server/routers/olm/handleOlmRegisterMessage.ts @@ -22,14 +22,14 @@ import { canCompress } from "@server/lib/clientVersionChecks"; import config from "@server/lib/config"; export const handleOlmRegisterMessage: MessageHandler = async (context) => { - logger.info("Handling register olm message!"); + logger.info("[handleOlmRegisterMessage] Handling register olm message"); const { message, client: c, sendToClient } = context; const olm = c as Olm; const now = Math.floor(Date.now() / 1000); if (!olm) { - logger.warn("Olm not found"); + logger.warn("[handleOlmRegisterMessage] Olm not found"); return; } @@ -46,16 +46,19 @@ export const handleOlmRegisterMessage: MessageHandler = async (context) => { } = message.data; if (!olm.clientId) { - logger.warn("Olm client ID not found"); + logger.warn("[handleOlmRegisterMessage] Olm client ID not found"); sendOlmError(OlmErrorCodes.CLIENT_ID_NOT_FOUND, olm.olmId); return; } - logger.debug("Handling fingerprint insertion for olm register...", { - olmId: olm.olmId, - fingerprint, - postures - }); + logger.debug( + "[handleOlmRegisterMessage] Handling fingerprint insertion for olm register...", + { + olmId: olm.olmId, + fingerprint, + postures + } + ); const isUserDevice = olm.userId !== null && olm.userId !== undefined; @@ -85,14 +88,17 @@ export const handleOlmRegisterMessage: MessageHandler = async (context) => { .limit(1); if (!client) { - logger.warn("Client ID not found"); + logger.warn("[handleOlmRegisterMessage] Client not found", { + clientId: olm.clientId + }); sendOlmError(OlmErrorCodes.CLIENT_NOT_FOUND, olm.olmId); return; } if (client.blocked) { logger.debug( - `Client ${client.clientId} is blocked. Ignoring register.` + `[handleOlmRegisterMessage] Client ${client.clientId} is blocked. Ignoring register.`, + { orgId: client.orgId } ); sendOlmError(OlmErrorCodes.CLIENT_BLOCKED, olm.olmId); return; @@ -100,7 +106,8 @@ export const handleOlmRegisterMessage: MessageHandler = async (context) => { if (client.approvalState == "pending") { logger.debug( - `Client ${client.clientId} approval is pending. Ignoring register.` + `[handleOlmRegisterMessage] Client ${client.clientId} approval is pending. Ignoring register.`, + { orgId: client.orgId } ); sendOlmError(OlmErrorCodes.CLIENT_PENDING, olm.olmId); return; @@ -128,14 +135,18 @@ export const handleOlmRegisterMessage: MessageHandler = async (context) => { .limit(1); if (!org) { - logger.warn("Org not found"); + logger.warn("[handleOlmRegisterMessage] Org not found", { + orgId: client.orgId + }); sendOlmError(OlmErrorCodes.ORG_NOT_FOUND, olm.olmId); return; } if (orgId) { if (!olm.userId) { - logger.warn("Olm has no user ID"); + logger.warn("[handleOlmRegisterMessage] Olm has no user ID", { + orgId: client.orgId + }); sendOlmError(OlmErrorCodes.USER_ID_NOT_FOUND, olm.olmId); return; } @@ -143,12 +154,18 @@ export const handleOlmRegisterMessage: MessageHandler = async (context) => { const { session: userSession, user } = await validateSessionToken(userToken); if (!userSession || !user) { - logger.warn("Invalid user session for olm register"); + logger.warn( + "[handleOlmRegisterMessage] Invalid user session for olm register", + { orgId: client.orgId } + ); sendOlmError(OlmErrorCodes.INVALID_USER_SESSION, olm.olmId); return; } if (user.userId !== olm.userId) { - logger.warn("User ID mismatch for olm register"); + logger.warn( + "[handleOlmRegisterMessage] User ID mismatch for olm register", + { orgId: client.orgId } + ); sendOlmError(OlmErrorCodes.USER_ID_MISMATCH, olm.olmId); return; } @@ -163,11 +180,15 @@ export const handleOlmRegisterMessage: MessageHandler = async (context) => { sessionId // this is the user token passed in the message }); - logger.debug("Policy check result:", policyCheck); + logger.debug("[handleOlmRegisterMessage] Policy check result", { + orgId: client.orgId, + policyCheck + }); if (policyCheck?.error) { logger.error( - `Error checking access policies for olm user ${olm.userId} in org ${orgId}: ${policyCheck?.error}` + `[handleOlmRegisterMessage] Error checking access policies for olm user ${olm.userId} in org ${orgId}: ${policyCheck?.error}`, + { orgId: client.orgId } ); sendOlmError(OlmErrorCodes.ORG_ACCESS_POLICY_DENIED, olm.olmId); return; @@ -175,7 +196,8 @@ export const handleOlmRegisterMessage: MessageHandler = async (context) => { if (policyCheck.policies?.passwordAge?.compliant === false) { logger.warn( - `Olm user ${olm.userId} has non-compliant password age for org ${orgId}` + `[handleOlmRegisterMessage] Olm user ${olm.userId} has non-compliant password age for org ${orgId}`, + { orgId: client.orgId } ); sendOlmError( OlmErrorCodes.ORG_ACCESS_POLICY_PASSWORD_EXPIRED, @@ -186,7 +208,8 @@ export const handleOlmRegisterMessage: MessageHandler = async (context) => { policyCheck.policies?.maxSessionLength?.compliant === false ) { logger.warn( - `Olm user ${olm.userId} has non-compliant session length for org ${orgId}` + `[handleOlmRegisterMessage] Olm user ${olm.userId} has non-compliant session length for org ${orgId}`, + { orgId: client.orgId } ); sendOlmError( OlmErrorCodes.ORG_ACCESS_POLICY_SESSION_EXPIRED, @@ -195,7 +218,8 @@ export const handleOlmRegisterMessage: MessageHandler = async (context) => { return; } else if (policyCheck.policies?.requiredTwoFactor === false) { logger.warn( - `Olm user ${olm.userId} does not have 2FA enabled for org ${orgId}` + `[handleOlmRegisterMessage] Olm user ${olm.userId} does not have 2FA enabled for org ${orgId}`, + { orgId: client.orgId } ); sendOlmError( OlmErrorCodes.ORG_ACCESS_POLICY_2FA_REQUIRED, @@ -204,7 +228,8 @@ export const handleOlmRegisterMessage: MessageHandler = async (context) => { return; } else if (!policyCheck.allowed) { logger.warn( - `Olm user ${olm.userId} does not pass access policies for org ${orgId}: ${policyCheck.error}` + `[handleOlmRegisterMessage] Olm user ${olm.userId} does not pass access policies for org ${orgId}: ${policyCheck.error}`, + { orgId: client.orgId } ); sendOlmError(OlmErrorCodes.ORG_ACCESS_POLICY_DENIED, olm.olmId); return; @@ -226,29 +251,39 @@ export const handleOlmRegisterMessage: MessageHandler = async (context) => { sitesCountResult.length > 0 ? sitesCountResult[0].count : 0; // Prepare an array to store site configurations - logger.debug(`Found ${sitesCount} sites for client ${client.clientId}`); + logger.debug( + `[handleOlmRegisterMessage] Found ${sitesCount} sites for client ${client.clientId}`, + { orgId: client.orgId } + ); let jitMode = false; if (sitesCount > 250 && build == "saas") { // THIS IS THE MAX ON THE BUSINESS TIER // we have too many sites // If we have too many sites we need to drop into fully JIT mode by not sending any of the sites - logger.info("Too many sites (%d), dropping into JIT mode", sitesCount); + logger.info( + `[handleOlmRegisterMessage] Too many sites (${sitesCount}), dropping into JIT mode`, + { orgId: client.orgId } + ); jitMode = true; } logger.debug( - `Olm client ID: ${client.clientId}, Public Key: ${publicKey}, Relay: ${relay}` + `[handleOlmRegisterMessage] Olm client ID: ${client.clientId}, Public Key: ${publicKey}, Relay: ${relay}`, + { orgId: client.orgId } ); if (!publicKey) { - logger.warn("Public key not provided"); + logger.warn("[handleOlmRegisterMessage] Public key not provided", { + orgId: client.orgId + }); return; } if (client.pubKey !== publicKey || client.archived) { logger.info( - "Public key mismatch. Updating public key and clearing session info..." + "[handleOlmRegisterMessage] Public key mismatch. Updating public key and clearing session info...", + { orgId: client.orgId } ); // Update the client's public key await db @@ -274,12 +309,13 @@ export const handleOlmRegisterMessage: MessageHandler = async (context) => { // TODO: I still think there is a better way to do this rather than locking it out here but ??? if (now - (client.lastHolePunch || 0) > 5 && sitesCount > 0) { logger.warn( - `Client last hole punch is too old and we have sites to send; skipping this register. The client is failing to hole punch and identify its network address with the server. Can the client reach the server on UDP port ${config.getRawConfig().gerbil.clients_start_port}?` + `[handleOlmRegisterMessage] Client last hole punch is too old and we have sites to send; skipping this register. The client is failing to hole punch and identify its network address with the server. Can the client reach the server on UDP port ${config.getRawConfig().gerbil.clients_start_port}?`, + { orgId: client.orgId } ); return; } - // NOTE: its important that the client here is the old client and the public key is the new key + // NOTE: its important that the client here is the old client and the public key is the new key const siteConfigurations = await buildSiteConfigurationForOlmClient( client, publicKey,