File descriptors not closed properly on OSX

[giacomodabisias]

Node 7.9
Osx Sierra 10.12.4

Node installed through Brew

Hello everyone.
I am using node to process several files and I noticed at some point that node was breaking due to to having too many file descriptors in use. I was quite sure that I was correctly handling the files so I started investigating removing code and checking the number of open file descriptors. At the end my code consisted just in a for loop printing a message.

I had a look with lsof node to the open file descriptors and I noticed that every time I invoke console.log() a new file descriptor is created using /dev/ttys001 which is the current shell if I am not wrong.
These file descriptors continue to accumulate until I reach the maximum and then the code brakes.
If I remove the console.log() everything works fine. I tested the same problem on ubuntu 16.04 and there I have no issues. The number of file descriptors is almost constant.

Any idea about this issue?

Thanks a lot

[addaleax]

Can somebody from @nodejs/platform-macos confirm this?

Also, it might help us if you could provide some kind of minimal reproduction for this issue.

[Fishrock123]

I have not run into this. Running macOS 10.12 for about 2 weeks now.

I'll try some sample code if some is provided.

[Fishrock123]

I had a look with lsof node to the open file descriptors and I noticed that every time I invoke console.log() a new file descriptor is created using /dev/ttys001 which is the current shell if I am not wrong.

Hmm, @giacomodabisias what Terminal are you using?

[giacomodabisias]

Hi, I will try to produce some code. I am using iterm2; actually it could be that there is an issue with that. just to be sure I will try it with the system terminal

[giacomodabisias]

OK I tried and also terminal has the same issue.

[Fishrock123]

@galambalazs Do you have a rough estimate on how many console calls it takes to notice anything, and/or how fast those are done?

[gblazex]

@Fishrock123 was i CC'd by mistake?

[sambthompson]

I'm using node 7.9 on OS X 10.11.6 (term is zsh). I have an application with extensive logging but haven't noticed issue with FDs as reported by OP. However, I tried a simple loop with console log and it does seem to have a memory growth issue (rapidly rises to about 1.6 GB in process size), as well as getting slower and slower, (and makes the rest of the OS unresponsive), once over 8 million or so messages are logged.

The sample code:

"use strict";
// Copyright (c) 2017, Sam Thompson (under ISC license).

try {
	var num = 1;
	while (1) {
		console.log('Log: ' + num);
		num++; 
	}
}
catch (err) {
	console.error('FATAL ERROR: ' + err.message);
	throw (err); // For stack trace.
}

However, lsof only shows about a dozen FD's in use, and this number doesn't grow. I assume I'm using lsof correctly. I haven't managed to get it to crash or bail with any error though, so I can't be certain this reproduces the OP's issue, or if it's even the same problem, but it does make my Mac sad.

> lsof -c node -r 5
COMMAND   PID USER   FD     TYPE             DEVICE  SIZE/OFF     NODE NAME
node    92543  sam  cwd      DIR                1,4      1088  1287414 /Users/sam/Developer
node    92543  sam  txt      REG                1,4  20721204 18657939 /opt/local/bin/node
node    92543  sam  txt      REG                1,4   2061992 15621392 /opt/local/lib/libcrypto.1.0.0.dylib
node    92543  sam  txt      REG                1,4    393280 15621395 /opt/local/lib/libssl.1.0.0.dylib
node    92543  sam  txt      REG                1,4   2325092 18576710 /opt/local/lib/libicui18n.58.2.dylib
node    92543  sam  txt      REG                1,4   1480004 18576726 /opt/local/lib/libicuuc.58.2.dylib
node    92543  sam  txt      REG                1,4  26214496 18576706 /opt/local/lib/libicudata.58.2.dylib
node    92543  sam  txt      REG                1,4    162292 14242599 /opt/local/lib/libz.1.2.11.dylib
node    92543  sam  txt      REG                1,4    646624 14319023 /usr/lib/dyld
node    92543  sam  txt      REG                1,4 560059400 14320339 /private/var/db/dyld/dyld_shared_cache_x86_64
node    92543  sam    0u     CHR               16,1      0t69    11853 /dev/ttys001
node    92543  sam    1u     CHR               16,1 0x757c97e    11853 /dev/ttys001
node    92543  sam    2u     CHR               16,1       0t0    11853 /dev/ttys001
node    92543  sam    3     PIPE 0x10b1564c2a1c54c5     16384          ->0x10b1564c0512cd85
node    92543  sam    4     PIPE 0x10b1564c0512cd85     16384          ->0x10b1564c2a1c54c5
node    92543  sam    5u  KQUEUE                                       count=0, state=0
node    92543  sam    6     PIPE 0x10b1564c0512d5c5     16384          ->0x10b1564c0512d445
node    92543  sam    7     PIPE 0x10b1564c0512d445     16384          ->0x10b1564c0512d5c5
node    92543  sam    8     PIPE 0x10b1564c0512aa45     16384          ->0x10b1564c0c4b0d45
node    92543  sam    9     PIPE 0x10b1564c0c4b0d45     16384          ->0x10b1564c0512aa45
node    92543  sam   10u     CHR               16,1 0x757c97e    11853 /dev/ttys001
node    92543  sam   11r     CHR                3,2       0t0      307 /dev/null
node    92543  sam   12u     CHR               16,1       0t0    11853 /dev/ttys001
=======

I thought it might be related to unlimited scroll-back setting, but changing this to 10k makes no difference to the memory effects.

HTH; happy to run other tests on Mac; especially if OP can provide sample code.

[bnoordhuis]

@sambthompson console.log() is asynchronous, your example is stacking up an unbounded number of work items.

@giacomodabisias Can you reproduce the issue with the official binaries from https://nodejs.org/?

[sambthompson]

Sorry for muddying the waters here; I must have misread the docs. I understood this was async on Mac. I know there have been some changes around this (e.g. #6816). But according to https://nodejs.org/dist/latest-v7.x/docs/api/process.html#process_a_note_on_process_i_o, it's sync (i.e. isn't Mac OS considered a Unix)?

[bnoordhuis]

@sambthompson The documentation is right that the operation itself is synchronous (the write system call blocks) but node's internal bookkeeping may not be released until the next tick of the event loop.

If you replace console.log() with process._rawDebug() it should keep on running forever.

[giacomodabisias]

So I think I noticed that it was actually my fault. I will investigate more and let you know soon