Skip to content

File descriptors not closed properly on OSX #12776

Closed
Closed
File descriptors not closed properly on OSX#12776
Labels
consoleIssues and PRs related to the console subsystem.macosIssues and PRs related to the macOS platform.

Description

@giacomodabisias
giacomodabisias
opened on May 1, 2017

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

Activity

  1. addaleax
    added
    consoleIssues and PRs related to the console subsystem.
    macosIssues and PRs related to the macOS platform.
    on May 1, 2017

  2. addaleax commented on May 1, 2017

    @addaleax
    addaleax
    on May 1, 2017
    Member

    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.

  3. Fishrock123 commented on May 1, 2017

    @Fishrock123
    Fishrock123
    on May 1, 2017
    Contributor

    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.

  4. Fishrock123 commented on May 1, 2017

    @Fishrock123
    Fishrock123
    on May 1, 2017
    Contributor

    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?

  5. giacomodabisias commented on May 1, 2017

    @giacomodabisias
    giacomodabisias
    on May 1, 2017
    Author

    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

  6. giacomodabisias commented on May 1, 2017

    @giacomodabisias
    giacomodabisias
    on May 1, 2017
    Author

    OK I tried and also terminal has the same issue.

  7. Fishrock123 commented on May 1, 2017

    @Fishrock123
    Fishrock123
    on May 1, 2017
    Contributor

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

  8. gblazex commented on May 2, 2017

    @gblazex
    gblazex
    on May 2, 2017

    @Fishrock123 was i CC'd by mistake?

  9. sambthompson commented on May 2, 2017

    @sambthompson
    sambthompson
    on May 2, 2017

    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.

  10. bnoordhuis commented on May 2, 2017

    @bnoordhuis
    bnoordhuis
    on May 2, 2017
    Member

    @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/?

  11. sambthompson commented on May 2, 2017

    @sambthompson
    sambthompson
    on May 2, 2017

    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)?

  12. bnoordhuis commented on May 2, 2017

    @bnoordhuis
    bnoordhuis
    on May 2, 2017
    Member

    @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.

  13. giacomodabisias commented on May 2, 2017

    @giacomodabisias
    giacomodabisias
    on May 2, 2017
    Author

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

  14. giacomodabisias
    closed this as completedon May 3, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    consoleIssues and PRs related to the console subsystem.macosIssues and PRs related to the macOS platform.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions