feat(csms): 增强 OCPP 操作的日志记录，添加请求和响应的详细信息

2026-04-20 14:28:27 +08:00
parent d688a8497d
commit 073bae726a
9 changed files with 207 additions and 18 deletions
--- 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) => {
--- 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<AuthorizeResponse> {
+  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 };
 }
--- 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<BootNotificationResponse> {
+  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(),
--- 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<HeartbeatResponse> {
+  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(),
  }
 }
--- 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<MeterValuesResponse> {
+  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 {};
 }
--- 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<StartTransactionResponse> {
+  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 };
--- 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<StatusNotificationResponse> {
+  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 {}
 }
--- 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<StopTransactionResponse> {
+  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 ?? "-"})`,
  );
--- 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<string, unknown> {
+  const p = payload as Record<string, unknown>
+  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<TPayload extends Record<string, unknown>, 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<TResult>((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<TPayload extends Record<string, unknown>, 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<TPayload extends Record<string, unknown>, 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<unknown>
        )(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'}`,
+      )
    },
  }
 }