From 442a3bafa4f11fee189a8fcb094c18987bd8678c Mon Sep 17 00:00:00 2001 From: "Evgeny @ SimpleX Chat" <259188159+evgeny-simplex@users.noreply.github.com> Date: Wed, 11 Feb 2026 00:07:42 +0000 Subject: [PATCH] debug logging in web page and server --- src/Simplex/FileTransfer/Server.hs | 12 +++++++++--- xftp-web/src/client.ts | 28 +++++++++++++++++++++++++-- xftp-web/src/protocol/handshake.ts | 16 +++++++++++++++ xftp-web/src/protocol/transmission.ts | 13 ++++++++++++- 4 files changed, 63 insertions(+), 6 deletions(-) diff --git a/src/Simplex/FileTransfer/Server.hs b/src/Simplex/FileTransfer/Server.hs index 0c75daee5..7845af026 100644 --- a/src/Simplex/FileTransfer/Server.hs +++ b/src/Simplex/FileTransfer/Server.hs @@ -75,7 +75,7 @@ import Simplex.Messaging.Version import System.Environment (lookupEnv) import System.Exit (exitFailure) import System.FilePath (()) -import System.IO (hPrint, hPutStrLn, universalNewlineMode) +import System.IO (hPrint, hPutStrLn, stderr, universalNewlineMode) #ifdef slow_servers import System.Random (getStdRandom, randomR) #endif @@ -179,12 +179,18 @@ xftpServer cfg@XFTPServerConfig {xftpPort, transportConfig, inactiveClientExpira webHello = sniUsed && any (\(t, _) -> tokenKey t == "xftp-web-hello") (fst $ H.requestHeaders request) webHandshake = sniUsed && any (\(t, _) -> tokenKey t == "xftp-handshake") (fst $ H.requestHeaders request) processHello pk_ = do + liftIO $ hPutStrLn stderr $ "DEBUG processHello: bodyHead.len=" <> show (B.length bodyHead) <> " sniUsed=" <> show sniUsed <> " webHello=" <> show webHello + liftIO $ hPutStrLn stderr $ "DEBUG processHello: bodyHead first20=" <> show (B.take 20 bodyHead) challenge_ <- if | B.null bodyHead -> pure Nothing | sniUsed -> do - body <- liftHS $ C.unPad bodyHead - XFTPClientHello {webChallenge} <- liftHS $ smpDecode body + let unpadResult = C.unPad bodyHead + liftIO $ hPutStrLn stderr $ "DEBUG processHello: unPad result=" <> show (either show (\b -> "OK len=" <> show (B.length b) <> " bytes=" <> show (B.take 20 b)) unpadResult) + body <- liftHS unpadResult + let decodeResult = smpDecode body :: Either String XFTPClientHello + liftIO $ hPutStrLn stderr $ "DEBUG processHello: smpDecode result=" <> show (either id (\(XFTPClientHello wc) -> "OK challenge=" <> show (fmap B.length wc)) decodeResult) + XFTPClientHello {webChallenge} <- liftHS $ first show decodeResult pure webChallenge | otherwise -> throwE HANDSHAKE rng <- asks random diff --git a/xftp-web/src/client.ts b/xftp-web/src/client.ts index f3424b935..358c2b6de 100644 --- a/xftp-web/src/client.ts +++ b/xftp-web/src/client.ts @@ -79,15 +79,21 @@ function createBrowserTransport(baseUrl: string): Transport { const effectiveUrl = typeof __XFTP_PROXY_PORT__ !== 'undefined' && __XFTP_PROXY_PORT__ ? '/xftp-proxy' : baseUrl + console.log('[DEBUG transport] baseUrl=%s effectiveUrl=%s proxy=%s', baseUrl, effectiveUrl, __XFTP_PROXY_PORT__) return { async post(body: Uint8Array, headers?: Record): Promise { + console.log('[DEBUG transport.post] url=%s bodyLen=%d headers=%o', effectiveUrl, body.length, headers) const resp = await fetch(effectiveUrl, { method: "POST", headers, body, }) + console.log('[DEBUG transport.post] status=%d statusText=%s', resp.status, resp.statusText) + console.log('[DEBUG transport.post] response headers:', Object.fromEntries(resp.headers.entries())) if (!resp.ok) throw new Error(`fetch failed: ${resp.status}`) - return new Uint8Array(await resp.arrayBuffer()) + const buf = new Uint8Array(await resp.arrayBuffer()) + console.log('[DEBUG transport.post] responseLen=%d first16=%s', buf.length, Array.from(buf.subarray(0, 16)).map(b => b.toString(16).padStart(2,'0')).join(' ')) + return buf }, close() {} } @@ -135,13 +141,19 @@ export async function connectXFTP(server: XFTPServer): Promise { try { // Step 1: send client hello with web challenge + console.log('[DEBUG connectXFTP] Step 1: sending client hello') const challenge = new Uint8Array(32) crypto.getRandomValues(challenge) const clientHelloBytes = encodeClientHello({webChallenge: challenge}) + console.log('[DEBUG connectXFTP] clientHelloBytes.length=%d', clientHelloBytes.length) const shsBody = await transport.post(clientHelloBytes, {"xftp-web-hello": "1"}) + console.log('[DEBUG connectXFTP] Step 1 done: shsBody.length=%d', shsBody.length) // Step 2: decode + verify server handshake + console.log('[DEBUG connectXFTP] Step 2: decoding server handshake') const hs = decodeServerHandshake(shsBody) + console.log('[DEBUG connectXFTP] Step 2 decoded: sessionId.length=%d certChain.length=%d signedKey.length=%d webProof=%s', + hs.sessionId.length, hs.certChainDer.length, hs.signedKeyDer.length, hs.webIdentityProof ? hs.webIdentityProof.length : 'null') if (!hs.webIdentityProof) throw new Error("connectXFTP: no web identity proof") const idOk = verifyIdentityProof({ certChainDer: hs.certChainDer, @@ -151,17 +163,22 @@ export async function connectXFTP(server: XFTPServer): Promise { sessionId: hs.sessionId, keyHash: server.keyHash }) + console.log('[DEBUG connectXFTP] Step 2 identity verified=%s', idOk) if (!idOk) throw new Error("connectXFTP: identity verification failed") // Step 3: version negotiation const vr = compatibleVRange(hs.xftpVersionRange, {minVersion: initialXFTPVersion, maxVersion: currentXFTPVersion}) + console.log('[DEBUG connectXFTP] Step 3: version range=%o negotiated=%o', hs.xftpVersionRange, vr) if (!vr) throw new Error("connectXFTP: incompatible version") const xftpVersion = vr.maxVersion // Step 4: send client handshake + console.log('[DEBUG connectXFTP] Step 4: sending client handshake v=%d', xftpVersion) const ack = await transport.post(encodeClientHandshake({xftpVersion, keyHash: server.keyHash}), {"xftp-handshake": "1"}) + console.log('[DEBUG connectXFTP] Step 4 done: ack.length=%d', ack.length) if (ack.length !== 0) throw new Error("connectXFTP: non-empty handshake ack") + console.log('[DEBUG connectXFTP] handshake complete, sessionId=%s', Array.from(hs.sessionId.subarray(0, 8)).map(b => b.toString(16).padStart(2,'0')).join('')) return {baseUrl, sessionId: hs.sessionId, xftpVersion, transport} } catch (e) { transport.close() @@ -178,15 +195,22 @@ async function sendXFTPCommand( cmdBytes: Uint8Array, chunkData?: Uint8Array ): Promise<{response: FileResponse, body: Uint8Array}> { + const cmdTag = String.fromCharCode(...cmdBytes.subarray(0, 4)) + console.log('[DEBUG sendXFTPCommand] cmd=%s entityId.len=%d chunkData=%s', cmdTag, entityId.length, chunkData ? chunkData.length : 'none') const corrId = new Uint8Array(0) const block = encodeAuthTransmission(client.sessionId, corrId, entityId, cmdBytes, privateKey) const reqBody = chunkData ? concatBytes(block, chunkData) : block + console.log('[DEBUG sendXFTPCommand] reqBody.length=%d (block=%d + chunk=%d)', reqBody.length, block.length, chunkData?.length ?? 0) const fullResp = await client.transport.post(reqBody) - if (fullResp.length < XFTP_BLOCK_SIZE) throw new Error("sendXFTPCommand: response too short") + console.log('[DEBUG sendXFTPCommand] fullResp.length=%d', fullResp.length) + if (fullResp.length < XFTP_BLOCK_SIZE) throw new Error("sendXFTPCommand: response too short (" + fullResp.length + " < " + XFTP_BLOCK_SIZE + ")") const respBlock = fullResp.subarray(0, XFTP_BLOCK_SIZE) const body = fullResp.subarray(XFTP_BLOCK_SIZE) + console.log('[DEBUG sendXFTPCommand] respBlock first4: %s', Array.from(respBlock.subarray(0, 4)).map(b => b.toString(16).padStart(2,'0')).join(' ')) const {command} = decodeTransmission(client.sessionId, respBlock) + console.log('[DEBUG sendXFTPCommand] decoded command=%s', String.fromCharCode(...command.subarray(0, Math.min(20, command.length)))) const response = decodeResponse(command) + console.log('[DEBUG sendXFTPCommand] response.type=%s', response.type) if (response.type === "FRErr") throw new Error("XFTP error: " + response.err.type) return {response, body} } diff --git a/xftp-web/src/protocol/handshake.ts b/xftp-web/src/protocol/handshake.ts index 84f936c56..b0ac19792 100644 --- a/xftp-web/src/protocol/handshake.ts +++ b/xftp-web/src/protocol/handshake.ts @@ -85,18 +85,34 @@ export interface XFTPServerHandshake { // sigBytes = ByteString (1-byte len prefix, empty for Nothing) // Trailing bytes (Tail) are ignored for forward compatibility. export function decodeServerHandshake(block: Uint8Array): XFTPServerHandshake { + console.log('[DEBUG decodeServerHandshake] block.length=%d', block.length) const raw = blockUnpad(block) + console.log('[DEBUG decodeServerHandshake] unpadded.length=%d content=%s', raw.length, String.fromCharCode(...raw.subarray(0, Math.min(40, raw.length)))) + // Detect error responses (server sends padded error string like "HANDSHAKE") + if (raw.length < 20) { + const text = String.fromCharCode(...raw) + if (/^[A-Z_]+$/.test(text)) { + throw new Error("server handshake error: " + text) + } + } const d = new Decoder(raw) const xftpVersionRange = decodeVersionRange(d) + console.log('[DEBUG decodeServerHandshake] versionRange=%o offset=%d', xftpVersionRange, d.offset()) const sessionId = decodeBytes(d) + console.log('[DEBUG decodeServerHandshake] sessionId.length=%d offset=%d', sessionId.length, d.offset()) // CertChainPubKey: smpEncode (encodeCertChain certChain, SignedObject signedPubKey) const certChainDer = decodeNonEmpty(decodeLarge, d) + console.log('[DEBUG decodeServerHandshake] certChain.length=%d offset=%d', certChainDer.length, d.offset()) const signedKeyDer = decodeLarge(d) + console.log('[DEBUG decodeServerHandshake] signedKey.length=%d offset=%d remaining=%d', signedKeyDer.length, d.offset(), d.remaining()) // webIdentityProof: 1-byte length-prefixed ByteString (empty = Nothing) let webIdentityProof: Uint8Array | null = null if (d.remaining() > 0) { const sigBytes = decodeBytes(d) + console.log('[DEBUG decodeServerHandshake] webProof.length=%d', sigBytes.length) webIdentityProof = sigBytes.length === 0 ? null : sigBytes + } else { + console.log('[DEBUG decodeServerHandshake] no webIdentityProof (remaining=0)') } // Remaining bytes are Tail (ignored for forward compatibility) return {xftpVersionRange, sessionId, certChainDer, signedKeyDer, webIdentityProof} diff --git a/xftp-web/src/protocol/transmission.ts b/xftp-web/src/protocol/transmission.ts index 8fd06e52a..6ec26c919 100644 --- a/xftp-web/src/protocol/transmission.ts +++ b/xftp-web/src/protocol/transmission.ts @@ -92,21 +92,32 @@ export interface DecodedTransmission { // Call decodeResponse(command) from commands.ts to parse the response. // Matches xftpDecodeTClient with implySessId = False: reads and verifies sessionId from wire. export function decodeTransmission(sessionId: Uint8Array, block: Uint8Array): DecodedTransmission { + console.log('[DEBUG decodeTransmission] block.length=%d', block.length) const raw = blockUnpad(block) + console.log('[DEBUG decodeTransmission] unpadded.length=%d first8=%s', raw.length, Array.from(raw.subarray(0, 8)).map(b => b.toString(16).padStart(2,'0')).join(' ')) const d = new Decoder(raw) const count = d.anyByte() + console.log('[DEBUG decodeTransmission] batch count=%d', count) if (count !== 1) throw new Error("decodeTransmission: expected batch count 1, got " + count) const transmission = decodeLarge(d) + console.log('[DEBUG decodeTransmission] transmission.length=%d', transmission.length) const td = new Decoder(transmission) // Skip authenticator (server responses have empty auth) - decodeBytes(td) + const auth = decodeBytes(td) + console.log('[DEBUG decodeTransmission] auth.length=%d', auth.length) // implySessId = False: read sessionId from wire and verify const sessId = decodeBytes(td) + console.log('[DEBUG decodeTransmission] sessId.length=%d', sessId.length) if (sessId.length !== sessionId.length || !sessId.every((b, i) => b === sessionId[i])) { + console.log('[DEBUG decodeTransmission] SESSION MISMATCH expected=%s got=%s', + Array.from(sessionId.subarray(0, 8)).map(b => b.toString(16).padStart(2,'0')).join(''), + Array.from(sessId.subarray(0, 8)).map(b => b.toString(16).padStart(2,'0')).join('')) throw new Error("decodeTransmission: session ID mismatch") } const corrId = decodeBytes(td) const entityId = decodeBytes(td) const command = td.takeAll() + console.log('[DEBUG decodeTransmission] corrId.len=%d entityId.len=%d command.len=%d cmd=%s', + corrId.length, entityId.length, command.length, String.fromCharCode(...command.subarray(0, Math.min(10, command.length)))) return {corrId, entityId, command} }