search

expressjs / morgan

HTTP request logger middleware for node.js
MIT License
7.95k stars 536 forks source link

Not logging correct statusCode and endTime #242

Closed Kiranbhat2005 closed 4 years ago

Kiranbhat2005 commented 4 years ago

Hi, I have implemented Morgan in Express application with custom formatting using tokens. It fails to send correct statusCode and endTime when the request takes more than 20 seconds. It logs status as 200 even when the application has sent 4xx or 5xx to client. Even the endTime is not recorded ( am setting endTime = res.res._startTime and status=res.statusCode).

Looks like Morgan does not wait for the request to complete beyond certain time if it is long running process? Can you please fix the issue or suggest a workaround?

ghinks commented 4 years ago

@Kiranbhat2005 could you provide a small but working example of your issue? So we can run and address this issue.

Kiranbhat2005 commented 4 years ago

Thanks for the quick reply @ghinks. Please find the attached API and Client files. Steps to reproduce the issue:

  1. install express & morgan and run it. 2 Hit http://localhost:8080/?delay=10 using postman ( delay denotes the number of seconds after which you get response.)
  2. In ideal case program always logs 400 which is purposefully coded.
  3. If client (postman or another client program) disconnects, morgan logs status 200 instead of intended 400 with empty endTime.
  4. The attached client.js file can be run to call the api to reproduce timeout issue. Here also morgan prints 200 without endTime.

Can you please suggest how to overcome this problem?

client.js.zip

index.js.zip

dougwilson commented 4 years ago

The issue is that your client is disconnecting, terminating the TCP connection. When that happens, your server cannot write a status back to the client. A logger like Morgan is here to log what actually happens, and will log out once the request/response has completed, which in your example, happens when the client disconnects (as at that point, the server can no longer talk to the client in order to do anything further at the HTTP level).

The reason why your code is logging a status of 200 is because that is, by default, the status code of a Node.js HTTP response until you change it. If you use our :status token instead of your custom implementation, it will log as a - for the client disconnect instead of the 200 (https://github.com/expressjs/morgan#status). You can of course change your implementation to do the same if you don't want to use the one we provide.

Kiranbhat2005 commented 4 years ago

Thank you