socket logger tests

src/socket/messages/socketLogger.ts

@@ -1,4 +1,3 @@
-import { RawData } from 'ws'
 import SocketConnection from '../socketConnection'
 import { SocketMessageResponse } from './socketMessage'
 import { IncomingMessage } from 'http'
@@ -14,14 +13,13 @@ function getSize(message: string): string {
   return `${Buffer.byteLength(message)}b`
 }
 
-export function logRequest(conn: SocketConnection, rawData: RawData) {
-  const message = rawData.toString()
+export function logRequest(conn: SocketConnection, message: string) {
   const req = JSON.parse(message)?.req
-  console.log(`  <-- ${getSocketUrl(conn)}{${req}} ${conn.ip} ${getSize(message)}`)
+  console.log(`  <-- ${getSocketUrl(conn)}{${req}} ${conn.getRemoteAddress()} ${getSize(message)}`)
 }
 
 export function logResponse(conn: SocketConnection, res: SocketMessageResponse, message: string) {
-  console.log(`  --> ${getSocketUrl(conn)}{${res}} ${conn.ip} ${getSize(message)}`)
+  console.log(`  --> ${getSocketUrl(conn)}{${res}} ${conn.getRemoteAddress()} ${getSize(message)}`)
 }
 
 export function logConnection(req: IncomingMessage) {
@@ -30,8 +28,8 @@ export function logConnection(req: IncomingMessage) {
 
 export function logConnectionClosed(conn: SocketConnection | undefined, preclosed: boolean, code: number, reason?: string) {
   const direction = preclosed ? '<--' : '-->'
-  const ip = conn?.ip ?? 'unknown'
+  const ip = conn?.getRemoteAddress() ?? 'unknown'
   const displayCode = preclosed ? '' : code
   const displayReason = reason ?? ''
-  console.log(`  ${direction} ${getSocketUrl(conn)}close ${ip} ${displayCode} ${displayReason}`)
+  console.log(`  ${direction} ${getSocketUrl(conn)}close ${ip} ${displayCode} ${displayReason}`.trimEnd())
 }

src/socket/router/socketRouter.ts

@@ -27,7 +27,7 @@ export default class SocketRouter {
   constructor(readonly socket: Socket) {}
 
   async handleMessage(conn: SocketConnection, rawData: RawData): Promise<void> {
-    logRequest(conn, rawData)
+    logRequest(conn, rawData.toString())
 
     addBreadcrumb({
       category: 'message',

src/socket/socketConnection.ts

@@ -16,7 +16,7 @@ export default class SocketConnection {
   game: Game | null = null
   scopes: APIKeyScope[] = []
   private headers: IncomingHttpHeaders = {}
-  ip: string = ''
+  private remoteAddress: string = 'unknown'
 
   rateLimitKey: string = v4()
   rateLimitWarnings: number = 0
@@ -25,7 +25,7 @@ export default class SocketConnection {
     this.game = apiKey.game
     this.scopes = apiKey.scopes
     this.headers = req.headers
-    this.ip = req.socket.remoteAddress
+    this.remoteAddress = req.socket.remoteAddress
   }
 
   async getPlayerAlias(): Promise<PlayerAlias | null> {
@@ -69,4 +69,8 @@ export default class SocketConnection {
 
     return rateLimitExceeded
   }
+
+  getRemoteAddress(): string {
+    return this.remoteAddress
+  }
 }

tests/socket/messages/socketLogger.test.ts

@@ -0,0 +1,126 @@
+import { WebSocket } from 'ws'
+import TaloSocket from '../../../src/socket'
+import SocketConnection from '../../../src/socket/socketConnection'
+import createAPIKeyAndToken from '../../utils/createAPIKeyAndToken'
+import { IncomingMessage } from 'http'
+import { Socket } from 'net'
+import { logConnection, logConnectionClosed, logRequest, logResponse } from '../../../src/socket/messages/socketLogger'
+import { EntityManager } from '@mikro-orm/mysql'
+
+describe('Socket logger', () => {
+  const consoleMock = vi.spyOn(console, 'log').mockImplementation(() => undefined)
+
+  afterEach(() => {
+    consoleMock.mockReset()
+  })
+
+  async function createSocketConnection(): Promise<[TaloSocket, SocketConnection, () => void]>{
+    const [apiKey] = await createAPIKeyAndToken([])
+    await (<EntityManager>global.em).persistAndFlush(apiKey)
+
+    const socket = new TaloSocket(global.server, global.em)
+    const conn = new SocketConnection(new WebSocket(null, [], {}), apiKey, new IncomingMessage(new Socket()))
+    vi.spyOn(conn, 'getRemoteAddress').mockReturnValue('0.0.0.0')
+
+    return [
+      socket,
+      conn,
+      () => {
+        socket.getServer().close()
+      }
+    ]
+  }
+
+  it('should log requests', async () => {
+    const [, conn, cleanup] = await createSocketConnection()
+
+    logRequest(conn, JSON.stringify({ req: 'v1.fake', data: {} }))
+
+    expect(consoleMock).toHaveBeenCalledOnce()
+    expect(consoleMock).toHaveBeenLastCalledWith(`  <-- WSS /games/${conn.game.id}/{v1.fake} 0.0.0.0 27b`)
+
+    cleanup()
+  })
+
+  it('should log requests with aliases', async () => {
+    const [, conn, cleanup] = await createSocketConnection()
+    conn.playerAliasId = 2
+
+    logRequest(conn, JSON.stringify({ req: 'v1.fake', data: {} }))
+
+    expect(consoleMock).toHaveBeenCalledOnce()
+    expect(consoleMock).toHaveBeenLastCalledWith(`  <-- WSS /games/${conn.game.id}/aliases/2/{v1.fake} 0.0.0.0 27b`)
+
+    cleanup()
+  })
+
+  it('should log responses', async () => {
+    const [, conn, cleanup] = await createSocketConnection()
+
+    logResponse(conn, 'v1.players.identify.success', JSON.stringify({ res: 'v1.players.identify.success', data: {} }))
+
+    expect(consoleMock).toHaveBeenCalledOnce()
+    expect(consoleMock).toHaveBeenLastCalledWith(`  --> WSS /games/${conn.game.id}/{v1.players.identify.success} 0.0.0.0 47b`)
+
+    cleanup()
+  })
+
+  it('should log connections', async () => {
+    logConnection(new IncomingMessage(new Socket()))
+
+    expect(consoleMock).toHaveBeenCalledOnce()
+    expect(consoleMock).toHaveBeenLastCalledWith('  <-- WSS /open undefined')
+  })
+
+  it('should log pre-closed connections', async () => {
+    const [, conn, cleanup] = await createSocketConnection()
+
+    logConnectionClosed(conn, true, 3000)
+
+    expect(consoleMock).toHaveBeenCalledOnce()
+    expect(consoleMock).toHaveBeenLastCalledWith(`  <-- WSS /games/${conn.game.id}/close 0.0.0.0`)
+
+    cleanup()
+  })
+
+  it('should log manually-closed connections', async () => {
+    const [, conn, cleanup] = await createSocketConnection()
+
+    logConnectionClosed(conn, false, 3000, 'Unauthorised')
+
+    expect(consoleMock).toHaveBeenCalledOnce()
+    expect(consoleMock).toHaveBeenLastCalledWith(`  --> WSS /games/${conn.game.id}/close 0.0.0.0 3000 Unauthorised`)
+
+    cleanup()
+  })
+
+  it('should log manually-closed connections without a reason', async () => {
+    const [, conn, cleanup] = await createSocketConnection()
+
+    logConnectionClosed(conn, false, 3000)
+
+    expect(consoleMock).toHaveBeenCalledOnce()
+    expect(consoleMock).toHaveBeenLastCalledWith(`  --> WSS /games/${conn.game.id}/close 0.0.0.0 3000`)
+
+    cleanup()
+  })
+
+  it('should log manually-closed connections without a SocketConnection', async () => {
+    logConnectionClosed(undefined, false, 3000)
+
+    expect(consoleMock).toHaveBeenCalledOnce()
+    expect(consoleMock).toHaveBeenLastCalledWith('  --> WSS /close unknown 3000')
+  })
+
+  it('should log pre-closed connection with aliases', async () => {
+    const [, conn, cleanup] = await createSocketConnection()
+    conn.playerAliasId = 2
+
+    logConnectionClosed(conn, true, 3000)
+
+    expect(consoleMock).toHaveBeenCalledOnce()
+    expect(consoleMock).toHaveBeenLastCalledWith(`  <-- WSS /games/${conn.game.id}/aliases/2/close 0.0.0.0`)
+
+    cleanup()
+  })
+})