From 073bae726a636ab009965f05d3072050b72cc1ef Mon Sep 17 00:00:00 2001 From: Timothy Yin Date: Mon, 20 Apr 2026 14:28:27 +0800 Subject: [PATCH] =?UTF-8?q?feat(csms):=20=E5=A2=9E=E5=BC=BA=20OCPP=20?= =?UTF-8?q?=E6=93=8D=E4=BD=9C=E7=9A=84=E6=97=A5=E5=BF=97=E8=AE=B0=E5=BD=95?= =?UTF-8?q?=EF=BC=8C=E6=B7=BB=E5=8A=A0=E8=AF=B7=E6=B1=82=E5=92=8C=E5=93=8D?= =?UTF-8?q?=E5=BA=94=E7=9A=84=E8=AF=A6=E7=BB=86=E4=BF=A1=E6=81=AF?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- apps/csms/src/index.ts | 20 +++ apps/csms/src/ocpp/actions/authorize.ts | 14 +- .../src/ocpp/actions/boot-notification.ts | 8 +- apps/csms/src/ocpp/actions/heartbeat.ts | 13 +- apps/csms/src/ocpp/actions/meter-values.ts | 8 ++ .../src/ocpp/actions/start-transaction.ts | 13 +- .../src/ocpp/actions/status-notification.ts | 11 ++ .../csms/src/ocpp/actions/stop-transaction.ts | 12 +- apps/csms/src/ocpp/handler.ts | 126 +++++++++++++++++- 9 files changed, 207 insertions(+), 18 deletions(-) diff --git a/apps/csms/src/index.ts b/apps/csms/src/index.ts index c33f0e6..ece93c4 100644 --- a/apps/csms/src/index.ts +++ b/apps/csms/src/index.ts @@ -91,9 +91,18 @@ app.get( '/ocpp/:chargePointId', async (c, next) => { const chargePointId = c.req.param('chargePointId') + const connInfo = getConnInfo(c) + const remoteAddr = connInfo.remote.address const authHeader = c.req.header('Authorization') + console.info( + `[OCPP][AUTH][BEGIN] cp=${chargePointId} remote=${remoteAddr} hasAuthHeader=${Boolean(authHeader)}`, + ) + if (!authHeader?.startsWith('Basic ')) { + console.warn( + `[OCPP][AUTH][REJECT] cp=${chargePointId} remote=${remoteAddr} reason=missing_or_invalid_scheme`, + ) c.header('WWW-Authenticate', 'Basic realm="OCPP"') return c.json({ error: 'Unauthorized' }, 401) } @@ -106,10 +115,16 @@ app.get( id = decoded.slice(0, colonIdx) password = decoded.slice(colonIdx + 1) } catch { + console.warn( + `[OCPP][AUTH][REJECT] cp=${chargePointId} remote=${remoteAddr} reason=invalid_authorization_header`, + ) return c.json({ error: 'Invalid Authorization header' }, 400) } if (id !== chargePointId) { + console.warn( + `[OCPP][AUTH][REJECT] cp=${chargePointId} remote=${remoteAddr} reason=identity_mismatch authId=${id}`, + ) return c.json({ error: 'Unauthorized' }, 401) } @@ -121,9 +136,14 @@ app.get( .limit(1) if (!cp?.passwordHash || !(await verifyOcppPassword(password, cp.passwordHash))) { + console.warn( + `[OCPP][AUTH][REJECT] cp=${chargePointId} remote=${remoteAddr} reason=bad_credentials_or_missing_cp`, + ) return c.json({ error: 'Unauthorized' }, 401) } + console.info(`[OCPP][AUTH][PASS] cp=${chargePointId} remote=${remoteAddr}`) + await next() }, upgradeWebSocket((c) => { diff --git a/apps/csms/src/ocpp/actions/authorize.ts b/apps/csms/src/ocpp/actions/authorize.ts index 2bc9ec0..fbbaa56 100644 --- a/apps/csms/src/ocpp/actions/authorize.ts +++ b/apps/csms/src/ocpp/actions/authorize.ts @@ -9,6 +9,11 @@ import type { OcppConnectionContext, } from "../types.ts"; +function shortIdTag(idTagValue: string): string { + if (idTagValue.length <= 8) return idTagValue; + return `${idTagValue.slice(0, 4)}...${idTagValue.slice(-4)}`; +} + /** * Shared helper — resolves idTagInfo from the database. * Used by Authorize, StartTransaction, and StopTransaction. @@ -56,9 +61,14 @@ export async function resolveIdTagInfo( export async function handleAuthorize( payload: AuthorizeRequest, - _ctx: OcppConnectionContext, + ctx: OcppConnectionContext, ): Promise { + console.info( + `[OCPP][ACTION][Authorize][BEGIN] cp=${ctx.chargePointIdentifier} idTag=${shortIdTag(payload.idTag)}`, + ); const idTagInfo = await resolveIdTagInfo(payload.idTag); - console.log(`[OCPP] Authorize idTag=${payload.idTag} -> ${idTagInfo.status}`); + console.info( + `[OCPP][ACTION][Authorize][END] cp=${ctx.chargePointIdentifier} idTag=${shortIdTag(payload.idTag)} status=${idTagInfo.status}`, + ); return { idTagInfo }; } diff --git a/apps/csms/src/ocpp/actions/boot-notification.ts b/apps/csms/src/ocpp/actions/boot-notification.ts index 967327d..310c764 100644 --- a/apps/csms/src/ocpp/actions/boot-notification.ts +++ b/apps/csms/src/ocpp/actions/boot-notification.ts @@ -12,6 +12,10 @@ export async function handleBootNotification( payload: BootNotificationRequest, ctx: OcppConnectionContext, ): Promise { + console.info( + `[OCPP][ACTION][BootNotification][BEGIN] cp=${ctx.chargePointIdentifier} vendor=${payload.chargePointVendor} model=${payload.chargePointModel} fw=${payload.firmwareVersion ?? 'n/a'}`, + ) + const db = useDrizzle() const { heartbeatInterval } = await getOcpp16jSettings() @@ -57,7 +61,9 @@ export async function handleBootNotification( const status = cp.registrationStatus ctx.isRegistered = status === 'Accepted' - console.log(`[OCPP] BootNotification ${ctx.chargePointIdentifier} status=${status}`) + console.info( + `[OCPP][ACTION][BootNotification][END] cp=${ctx.chargePointIdentifier} status=${status} heartbeatInterval=${heartbeatInterval}`, + ) return { currentTime: dayjs().toISOString(), diff --git a/apps/csms/src/ocpp/actions/heartbeat.ts b/apps/csms/src/ocpp/actions/heartbeat.ts index 16fba39..2ce747c 100644 --- a/apps/csms/src/ocpp/actions/heartbeat.ts +++ b/apps/csms/src/ocpp/actions/heartbeat.ts @@ -12,18 +12,25 @@ export async function handleHeartbeat( _payload: HeartbeatRequest, ctx: OcppConnectionContext, ): Promise { + const now = dayjs() + console.info(`[OCPP][ACTION][Heartbeat][BEGIN] cp=${ctx.chargePointIdentifier}`) + const db = useDrizzle() await db .update(chargePoint) .set({ - lastHeartbeatAt: dayjs().toDate(), + lastHeartbeatAt: now.toDate(), transportStatus: 'online', - updatedAt: dayjs().toDate(), + updatedAt: now.toDate(), }) .where(eq(chargePoint.chargePointIdentifier, ctx.chargePointIdentifier)) + console.info( + `[OCPP][ACTION][Heartbeat][END] cp=${ctx.chargePointIdentifier} currentTime=${now.toISOString()}`, + ) + return { - currentTime: dayjs().toISOString(), + currentTime: now.toISOString(), } } diff --git a/apps/csms/src/ocpp/actions/meter-values.ts b/apps/csms/src/ocpp/actions/meter-values.ts index fd44d7b..ff9f8b3 100644 --- a/apps/csms/src/ocpp/actions/meter-values.ts +++ b/apps/csms/src/ocpp/actions/meter-values.ts @@ -8,6 +8,10 @@ export async function handleMeterValues( payload: MeterValuesRequest, ctx: OcppConnectionContext, ): Promise { + console.info( + `[OCPP][ACTION][MeterValues][BEGIN] cp=${ctx.chargePointIdentifier} connector=${payload.connectorId} txId=${payload.transactionId ?? 'n/a'} meterValueCount=${payload.meterValue.length}`, + ); + const db = useDrizzle(); const [cp] = await db @@ -48,5 +52,9 @@ export async function handleMeterValues( await db.insert(meterValue).values(records); } + console.info( + `[OCPP][ACTION][MeterValues][END] cp=${ctx.chargePointIdentifier} connector=${payload.connectorId} txId=${payload.transactionId ?? 'n/a'} inserted=${records.length}`, + ); + return {}; } diff --git a/apps/csms/src/ocpp/actions/start-transaction.ts b/apps/csms/src/ocpp/actions/start-transaction.ts index c19e50b..6efee25 100644 --- a/apps/csms/src/ocpp/actions/start-transaction.ts +++ b/apps/csms/src/ocpp/actions/start-transaction.ts @@ -9,10 +9,19 @@ import type { } from "../types.ts"; import { resolveIdTagInfo } from "./authorize.ts"; +function shortIdTag(idTagValue: string): string { + if (idTagValue.length <= 8) return idTagValue; + return `${idTagValue.slice(0, 4)}...${idTagValue.slice(-4)}`; +} + export async function handleStartTransaction( payload: StartTransactionRequest, ctx: OcppConnectionContext, ): Promise { + console.info( + `[OCPP][ACTION][StartTransaction][BEGIN] cp=${ctx.chargePointIdentifier} connector=${payload.connectorId} idTag=${shortIdTag(payload.idTag)} meterStart=${payload.meterStart} timestamp=${payload.timestamp}`, + ); + const db = useDrizzle(); // Resolve idTag authorization @@ -78,8 +87,8 @@ export async function handleStartTransaction( } console.log( - `[OCPP] StartTransaction cp=${ctx.chargePointIdentifier} connector=${payload.connectorId} ` + - `idTag=${payload.idTag} status=${idTagInfo.status} txId=${tx.id}`, + `[OCPP][ACTION][StartTransaction][END] cp=${ctx.chargePointIdentifier} connector=${payload.connectorId} ` + + `idTag=${shortIdTag(payload.idTag)} status=${idTagInfo.status} txId=${tx.id} rejected=${rejected}`, ); return { transactionId: tx.id, idTagInfo }; diff --git a/apps/csms/src/ocpp/actions/status-notification.ts b/apps/csms/src/ocpp/actions/status-notification.ts index 8f6e3a9..da03b68 100644 --- a/apps/csms/src/ocpp/actions/status-notification.ts +++ b/apps/csms/src/ocpp/actions/status-notification.ts @@ -42,6 +42,10 @@ export async function handleStatusNotification( payload: StatusNotificationRequest, ctx: OcppConnectionContext, ): Promise { + console.info( + `[OCPP][ACTION][StatusNotification][BEGIN] cp=${ctx.chargePointIdentifier} connector=${payload.connectorId} status=${payload.status} errorCode=${payload.errorCode}`, + ) + const db = useDrizzle() // Retrieve the internal charge point id @@ -52,6 +56,9 @@ export async function handleStatusNotification( .limit(1) if (!cp) { + console.error( + `[OCPP][ACTION][StatusNotification][ERROR] cp=${ctx.chargePointIdentifier} reason=charge_point_not_found`, + ) throw new Error(`ChargePoint not found: ${ctx.chargePointIdentifier}`) } @@ -101,5 +108,9 @@ export async function handleStatusNotification( }) } + console.info( + `[OCPP][ACTION][StatusNotification][END] cp=${ctx.chargePointIdentifier} connector=${payload.connectorId} status=${connStatus} errorCode=${connErrorCode} historySaved=${Boolean(upsertedConnector)}`, + ) + return {} } diff --git a/apps/csms/src/ocpp/actions/stop-transaction.ts b/apps/csms/src/ocpp/actions/stop-transaction.ts index 728d038..29bec3b 100644 --- a/apps/csms/src/ocpp/actions/stop-transaction.ts +++ b/apps/csms/src/ocpp/actions/stop-transaction.ts @@ -14,8 +14,12 @@ import { resolveIdTagInfo } from "./authorize.ts"; export async function handleStopTransaction( payload: StopTransactionRequest, - _ctx: OcppConnectionContext, + ctx: OcppConnectionContext, ): Promise { + console.info( + `[OCPP][ACTION][StopTransaction][BEGIN] cp=${ctx.chargePointIdentifier} txId=${payload.transactionId} meterStop=${payload.meterStop} reason=${payload.reason ?? 'none'} timestamp=${payload.timestamp}`, + ); + const db = useDrizzle(); // Update the transaction record @@ -37,7 +41,9 @@ export async function handleStopTransaction( .returning(); if (!tx) { - console.warn(`[OCPP] StopTransaction: transaction ${payload.transactionId} not found`); + console.warn( + `[OCPP][ACTION][StopTransaction][MISS] cp=${ctx.chargePointIdentifier} txId=${payload.transactionId} reason=transaction_not_found`, + ); return {}; } @@ -182,7 +188,7 @@ export async function handleStopTransaction( } console.log( - `[OCPP] StopTransaction txId=${payload.transactionId} ` + + `[OCPP][ACTION][StopTransaction][END] cp=${ctx.chargePointIdentifier} txId=${payload.transactionId} ` + `reason=${payload.reason ?? "none"} energyWh=${energyWh} ` + `feeFen=${feeFen} (elec=${electricityFen ?? "flat"} svc=${serviceFeeFen ?? "-"})`, ); diff --git a/apps/csms/src/ocpp/handler.ts b/apps/csms/src/ocpp/handler.ts index 012c896..4654d1c 100644 --- a/apps/csms/src/ocpp/handler.ts +++ b/apps/csms/src/ocpp/handler.ts @@ -101,6 +101,59 @@ const actionHandlers: ActionHandlerMap = { StopTransaction: handleStopTransaction, } +function shortId(value: string): string { + return value.length <= 12 ? value : `${value.slice(0, 8)}...${value.slice(-4)}` +} + +function summarizeCallPayload(action: string, payload: unknown): Record { + const p = payload as Record + switch (action) { + case 'BootNotification': + return { + chargePointVendor: p.chargePointVendor, + chargePointModel: p.chargePointModel, + firmwareVersion: p.firmwareVersion ?? null, + } + case 'Authorize': + return { + idTag: typeof p.idTag === 'string' ? shortId(p.idTag) : undefined, + } + case 'Heartbeat': + return {} + case 'StatusNotification': + return { + connectorId: p.connectorId, + status: p.status, + errorCode: p.errorCode, + timestamp: p.timestamp ?? null, + } + case 'StartTransaction': + return { + connectorId: p.connectorId, + idTag: typeof p.idTag === 'string' ? shortId(p.idTag) : undefined, + meterStart: p.meterStart, + timestamp: p.timestamp, + } + case 'StopTransaction': + return { + transactionId: p.transactionId, + meterStop: p.meterStop, + reason: p.reason ?? null, + timestamp: p.timestamp, + } + case 'MeterValues': + return { + connectorId: p.connectorId, + transactionId: p.transactionId ?? null, + meterValueCount: Array.isArray(p.meterValue) ? p.meterValue.length : 0, + } + default: + return { + keys: p && typeof p === 'object' ? Object.keys(p).slice(0, 20) : [], + } + } +} + function sendCallResult(ws: WSContext, uniqueId: string, payload: unknown): void { ws.send(JSON.stringify([OCPP_MESSAGE_TYPE.CALLRESULT, uniqueId, payload])) } @@ -162,9 +215,17 @@ export async function sendOcppCall, TRe const uniqueId = typeof timeoutOrOptions === 'number' ? crypto.randomUUID() : (timeoutOrOptions.uniqueId ?? crypto.randomUUID()) + console.info( + `[OCPP][TX][CALL] cp=${chargePointIdentifier} action=${action} uniqueId=${uniqueId} timeoutMs=${timeoutMs}`, + summarizeCallPayload(action, payload), + ) + const resultPromise = new Promise((resolve, reject) => { const timeout = setTimeout(async () => { pendingCalls.delete(uniqueId) + console.warn( + `[OCPP][TX][TIMEOUT] cp=${chargePointIdentifier} action=${action} uniqueId=${uniqueId} timeoutMs=${timeoutMs}`, + ) await updateTransportState(chargePointIdentifier, { transportStatus: getCommandChannelStatus(chargePointIdentifier), lastCommandStatus: 'Timeout', @@ -176,7 +237,12 @@ export async function sendOcppCall, TRe pendingCalls.set(uniqueId, { chargePointIdentifier, action, - resolve: (response) => resolve(response as TResult), + resolve: (response) => { + console.info( + `[OCPP][TX][CALLRESULT] cp=${chargePointIdentifier} action=${action} uniqueId=${uniqueId}`, + ) + resolve(response as TResult) + }, reject, timeout, }) @@ -195,6 +261,10 @@ export async function sendOcppCall, TRe lastCommandStatus: 'Error', lastCommandAt: dayjs().toDate(), }) + console.error( + `[OCPP][TX][SEND_ERROR] cp=${chargePointIdentifier} action=${action} uniqueId=${uniqueId}`, + error, + ) throw error instanceof Error ? error : new Error('CommandSendFailed') } @@ -219,6 +289,9 @@ export function createOcppHandler(chargePointIdentifier: string, remoteAddr?: st async onOpen(_evt: Event, ws: WSContext) { const subProtocol = ws.protocol ?? 'unknown' if (!isSupportedOCPP(subProtocol)) { + console.warn( + `[OCPP][WS][OPEN_REJECT] cp=${chargePointIdentifier} session=${sessionId} subProtocol=${subProtocol} reason=unsupported_subprotocol`, + ) ws.close(1002, 'Unsupported subprotocol') return } @@ -246,12 +319,14 @@ export function createOcppHandler(chargePointIdentifier: string, remoteAddr?: st connectionSessionId: sessionId, lastWsConnectedAt: dayjs().toDate(), }) - console.log( - `[OCPP] ${chargePointIdentifier} connected` + - (remoteAddr ? ` from ${remoteAddr}` : ''), + console.info( + `[OCPP][WS][OPEN] cp=${chargePointIdentifier} session=${sessionId} subProtocol=${subProtocol} registered=${ctx.isRegistered}` + + (remoteAddr ? ` remote=${remoteAddr}` : ''), ) if (previous && previous.sessionId !== sessionId) { - console.log(`[OCPP] ${chargePointIdentifier} replaced previous connection`) + console.info( + `[OCPP][WS][REPLACE] cp=${chargePointIdentifier} oldSession=${previous.sessionId} newSession=${sessionId}`, + ) } }, @@ -260,6 +335,9 @@ export function createOcppHandler(chargePointIdentifier: string, remoteAddr?: st try { const current = ocppConnections.get(chargePointIdentifier) if (!current || current.sessionId !== sessionId) { + console.warn( + `[OCPP][WS][STALE] cp=${chargePointIdentifier} session=${sessionId} activeSession=${current?.sessionId ?? 'none'}`, + ) try { ws.close(1008, 'Stale connection') } catch { @@ -288,6 +366,23 @@ export function createOcppHandler(chargePointIdentifier: string, remoteAddr?: st const [messageType, msgUniqueId] = message uniqueId = String(msgUniqueId) + if (messageType === OCPP_MESSAGE_TYPE.CALL) { + const [, , action, payload] = message as OcppCall + console.info( + `[OCPP][RX][CALL] cp=${chargePointIdentifier} session=${sessionId} action=${action} uniqueId=${uniqueId}`, + summarizeCallPayload(action, payload), + ) + } else if (messageType === OCPP_MESSAGE_TYPE.CALLRESULT) { + console.info( + `[OCPP][RX][CALLRESULT] cp=${chargePointIdentifier} session=${sessionId} uniqueId=${uniqueId}`, + ) + } else if (messageType === OCPP_MESSAGE_TYPE.CALLERROR) { + const [, , errorCode, errorDescription] = message as OcppCallErrorMessage + console.warn( + `[OCPP][RX][CALLERROR] cp=${chargePointIdentifier} session=${sessionId} uniqueId=${uniqueId} code=${errorCode} desc=${errorDescription}`, + ) + } + if (messageType === OCPP_MESSAGE_TYPE.CALLRESULT) { const [, responseUniqueId, payload] = message as OcppCallResultMessage const pending = pendingCalls.get(responseUniqueId) @@ -314,6 +409,9 @@ export function createOcppHandler(chargePointIdentifier: string, remoteAddr?: st lastCommandStatus: errorCode === 'InternalError' ? 'Error' : 'Rejected', lastCommandAt: dayjs().toDate(), }) + console.warn( + `[OCPP][TX][REJECTED] cp=${pending.chargePointIdentifier} action=${pending.action} uniqueId=${responseUniqueId} code=${errorCode} desc=${errorDescription}`, + ) pending.reject(new Error(`${errorCode}:${errorDescription}`)) return } @@ -324,6 +422,9 @@ export function createOcppHandler(chargePointIdentifier: string, remoteAddr?: st // Enforce BootNotification before any other action if (!ctx.isRegistered && action !== 'BootNotification') { + console.warn( + `[OCPP][RX][REJECT] cp=${chargePointIdentifier} session=${sessionId} action=${action} uniqueId=${uniqueId} reason=boot_notification_required`, + ) sendCallError( ws, uniqueId, @@ -335,6 +436,9 @@ export function createOcppHandler(chargePointIdentifier: string, remoteAddr?: st const handler = actionHandlers[action as keyof ActionHandlerMap] if (!handler) { + console.warn( + `[OCPP][RX][NOT_IMPLEMENTED] cp=${chargePointIdentifier} session=${sessionId} action=${action} uniqueId=${uniqueId}`, + ) sendCallError(ws, uniqueId, 'NotImplemented', `Action '${action}' is not implemented`) return } @@ -343,9 +447,15 @@ export function createOcppHandler(chargePointIdentifier: string, remoteAddr?: st handler as (payload: unknown, ctx: OcppConnectionContext) => Promise )(payload, ctx) + console.info( + `[OCPP][TX][CALLRESULT] cp=${chargePointIdentifier} session=${sessionId} action=${action} uniqueId=${uniqueId}`, + ) sendCallResult(ws, uniqueId, response) } catch (err) { - console.error(`[OCPP] Error handling message from ${chargePointIdentifier} (uniqueId=${uniqueId}):`, err) + console.error( + `[OCPP][RX][ERROR] cp=${chargePointIdentifier} session=${sessionId} uniqueId=${uniqueId}`, + err, + ) sendCallError(ws, uniqueId, 'InternalError', 'Internal server error') } }, @@ -359,7 +469,9 @@ export function createOcppHandler(chargePointIdentifier: string, remoteAddr?: st lastWsDisconnectedAt: dayjs().toDate(), }) } - console.log(`[OCPP] ${chargePointIdentifier} disconnected (code=${evt.code})`) + console.info( + `[OCPP][WS][CLOSE] cp=${chargePointIdentifier} session=${sessionId} code=${evt.code} activeSession=${current?.sessionId ?? 'none'}`, + ) }, } }