socketio / socket.io

Realtime application framework (Node.JS server)
https://socket.io
MIT License
61.02k stars 10.11k forks source link

Log with pino-http middleware raises TypeError: res.on is not a function #5072

Open kohtala opened 1 year ago

kohtala commented 1 year ago

Describe the bug Other app requests get logged with pino-http. Since the express middleware support was added in commit 24786e77c5403b1c4b5a2bc84e2af06f9187f74a, I expected to be able to log using the pino-http. But it crashes on upgrade.

To Reproduce

Engine.IO server version: 6.4.2 pino-http 8.3.3

Server

const engine = require("engine.io");
const logger = require("pino-http")();
const server = engine.listen(3000, {});

server.use(logger);
server.on("connection", (socket) => {
  console.log("connection");

  socket.on("message", (data) => {
    console.log("data", data);
  });

  socket.on("close", () => {
    console.log("close");
  });
});

Engine.IO client version: 6.2.2

Client

const { Socket } = require('engine.io-client');
const socket = new Socket('ws://localhost:3000');

socket.on("open", () => {
  console.log("open");

  socket.on("message", (data) => {
    console.log("data", data);
  });

  socket.on("close", () => {
    console.log("close");
  });
});

Expected behavior I expected the upgrade request to be logged at upgrade time.

Platform: Ubuntu 20.04.6, node v18.16.0.

Additional context

$ node server.js
connection
{"level":30,"time":1683554062833,"pid":2257406,"hostname":"ubuntu.mshome.net","req":{"id":1,"method":"GET","url":"/engine.io/?EIO=4&transport=polling&t=OVxf57J&b64=1","headers":{"user-agent":"node-XMLHttpRequest","accept":"*/*","host":"localhost:3000","connection":"close"},"remoteAddress":"::ffff:127.0.0.1","remotePort":36144},"res":{"statusCode":200,"headers":{}},"responseTime":6,"msg":"request completed"}
/home/kohtala/andritz/ava/js/node_modules/pino-http/logger.js:193
        res.on('close', onResponseComplete)
            ^

TypeError: res.on is not a function
    at loggingMiddleware (/home/kohtala/andritz/ava/js/node_modules/pino-http/logger.js:193:13)
    at Array.result (/home/kohtala/andritz/ava/js/node_modules/pino-http/logger.js:89:12)
    at apply (/home/kohtala/andritz/ava/js/node_modules/engine.io/build/server.js:182:32)
    at Server._applyMiddlewares (/home/kohtala/andritz/ava/js/node_modules/engine.io/build/server.js:194:9)
    at Server.handleUpgrade (/home/kohtala/andritz/ava/js/node_modules/engine.io/build/server.js:497:14)
    at Server.<anonymous> (/home/kohtala/andritz/ava/js/node_modules/engine.io/build/server.js:598:26)
    at Server.emit (node:events:513:28)
    at onParserExecuteCommon (node:_http_server:903:14)
    at onParserExecute (node:_http_server:797:3)

Node.js v18.16.0

I can see there is a small WebSocketResponse instead of a real ServerResponse. It does not implement events.

pino-http uses events to postpone the logging until request is complete.

kohtala commented 1 year ago

I have worked around this by testing for req.on to be undefined and logging the upgrade in another way.