916234 - Code Review for node.js server

Status: RESOLVED FIXED

(Webtools Graveyard :: Telemetry Server, defect)

Description

[Mark Reid [:mreid]]

I would appreciate a general review of server.js:
https://github.com/mreid-moz/telemetry-server/blob/master/server/server.js

In particular, please focus on
- the efficiency of dumping incoming requests to disk
- the safety / efficiency of synchronously writing to the stats log file (appendFileSync) in multiple child processes
- general node.js noob mistakes

Comment 1

[Fred Wenzel [:wenzel]]

CCing Edna, James, Matt. Can any of you help out Mark and take a look?

Comment 2

[Fred Wenzel [:wenzel]]

Mark: It's helpful if there's a way to add comments. If you can issue a pull request for this file against... really anywhere, that lends itself best for code reviews.

Comment 3

[Jen Fong-Adwent [:ednapiranha]]

Mark, any reason why you aren't using an existing module like winston https://npmjs.org/package/winston for logging functionality?

Comment 4

[Mark Reid [:mreid]]

(In reply to Jen Fong-Adwent [:ednapiranha] from comment #3)
> Mark, any reason why you aren't using an existing module like winston
> https://npmjs.org/package/winston for logging functionality?

I actually did use winston initially, but its log rotation scheme was not playing nicely with heka (which we use to analyze the server stats), so I dropped it.

Comment 5

[Jen Fong-Adwent [:ednapiranha]]

Mark, can you use winston to handle the fs write part and handle the rotation separately? In that situation it would be easier to compartmentalize parts in case there are issues you need to debug - otherwise if this solution isn't possible, can you send a pull request on Github with all the changes from this code so we can comment inline? Thanks!

Comment 6

[Mark Reid [:mreid]]

(In reply to Jen Fong-Adwent [:ednapiranha] from comment #5)
> Mark, can you use winston to handle the fs write part and handle the
> rotation separately? In that situation it would be easier to
> compartmentalize parts in case there are issues you need to debug -
> otherwise if this solution isn't possible, can you send a pull request on
> Github with all the changes from this code so we can comment inline? Thanks!

I'd like to keep things simple and avoid dependencies if possible.  If winston buys us a lot of value, I can definitely look ad putting it back.

I made a couple of dummy commits so you can comment on github. The main server:
https://github.com/mreid-moz/telemetry-server/commit/d681b98c3406556052eadcdc4765524d48701526

And the "relay" server:
https://github.com/mreid-moz/telemetry-server/commit/ab370226ffad59cb973810b2925a048a3f671ee0

Comment 7

[tofumatt [:tofumatt]]

A friendly NIH-reminder: it's often more simple to include code that already works than to write your own. Dependencies exist to make things more simple, not less.

Comment 8

[Jen Fong-Adwent [:ednapiranha]]

Mark, what were the problems that you had with winston and heka specifically? Your current code will be blocking io and without tests on the node portion, we can't see how it will behave on heavy loads. Also, the identity team uses winston for their logging so I believe working on integrating that module will be very helpful.

Comment 9

[Mark Reid [:mreid]]

(In reply to Jen Fong-Adwent [:ednapiranha] from comment #8)
> Mark, what were the problems that you had with winston and heka
> specifically? Your current code will be blocking io and without tests on the
> node portion, we can't see how it will behave on heavy loads. Also, the
> identity team uses winston for their logging so I believe working on
> integrating that module will be very helpful.

The main problem was with winston's log rotation behaviour. I had configured it to rotate at 200MB, but was seeing wildly fluctuating actual log sizes (anywhere from just over 200MB as expected up to >800MB).

Winston's method of naming logs (which admittedly can probably be customized) also didn't directly work with heka's log ingestion semantics.

I also didn't see any guarantees that it is safe to write data to the same log file from multiple concurrent processes, and since I am using cluster mode in the server, that's a concern. I thought about having only the master process write log data, but I didn't have time to fully investigate the overhead of sending all those messages from the children back to the master.

Lastly, when I considered keeping winston to do the log writes and allowing logrotate to handle the rotation aspect, I would have needed to implement code to force-close the underlying log file on SIGHUP, and wasn't sure how that all works in winston.

Overall, since my needs are so basic, it seemed easier just to do the file writes directly.  The blocking IO is definitely not ideal, but I wanted to get feedback from folks in the know before going much further.

Comment 10

[Mark Reid [:mreid]]

(In reply to tofumatt [:tofumatt] from comment #7)
> A friendly NIH-reminder: it's often more simple to include code that already
> works than to write your own. Dependencies exist to make things more simple,
> not less.

+1, that's why I initially went with winston, until things started getting less simple instead of more.

Comment 11

[Jen Fong-Adwent [:ednapiranha]]

Mark:

Okay I've talked to one of the contributors of winston and this is probably your best course of action:

- use winston and use logrotate that comes with *nix 
OR
- if winston is too bulky for your needs, do the above (logrotate) but use bunyan https://npmjs.org/package/bunyan#stream-type-rotating-file or minilog https://npmjs.org/package/minilog

Main reason is that they are focused on logging and it looks as though the latter modules support streams or variants thereof.

Comment 12

[Mark Reid [:mreid]]

(In reply to Jen Fong-Adwent [:ednapiranha] from comment #11)
> - if winston is too bulky for your needs, do the above (logrotate) but use
> bunyan https://npmjs.org/package/bunyan#stream-type-rotating-file or minilog
> https://npmjs.org/package/minilog

Bunyan looks good to me, but can you confirm if it can safely write to a single log file from multiple processes?

Comment 13

[Jen Fong-Adwent [:ednapiranha]]

Mark, afaik you can't write asynchronously to a single file on disk - you can only write to it through a queue (if that is what you are asking). Joyent uses bunyan so I'm assuming it is designed to handle heavy logging scenarios. You could write a test to see what it does from multiple processes and see if there are lock errors - which then you will need to add your own queue.