Got: DNS cache (`cacheable-lookup@^4.2.3`) causes a memory leak

[adityapatadia]

Describe the bug

• Node.js version: 12.16
• OS & version: Debian buster

Actual behavior

When I use GOT v10, my production systems work perfectly fine but when I switch to v11 without any other change, the memory keeps increasing in a period of 6-7 hours and eventually, OS kills the process.
...

Expected behavior

Memory should not grow when GOT version is upgraded
...

Code to reproduce

I am no expert in debugging memory leak but I can privately provide my heap snapshot to help debug this.

Checklist

• [x] I have read the documentation.
• [x] I have tried my code with the latest version of Node.js and Got.

[szmarczak]

I need these information:

• have you tried running Node.js 12.16.3, 13.13.0
• are you using an HTTP cache (the cache option)
• have you tried disabling the DNS cache (set dnsCache to false)
• do you do got.mergeOptions(...)
  
  
  
  • related fixes:
  
  
  • 157e02bcb613ab506829326e7af96e8155b4e186 (hasn't been released yet)
  
  
  • 429db406c6e55b0deac254004682cdddabfcddad (has been released already)
  
  
  • d914a7e7a0d97b03745b9b47623e4ac3532b4dae (has been released already)
  
  
• do you do got.extend(...)
• do you set an afterResponse hook

Alternatively you can try this:

• upgrade to 13.13.0
• clone the Got repository
• run npm run build
• use the local master build instead

OS kills the process.

Ummm... OS shouldn't kill the process I think. On my machine the Node.js process usually crashes with a C++ stack trace dump. If available, please provide one.

I am no expert in debugging memory leak but I can privately provide my heap snapshot to help debug this.

Sure. sz.marczak [at] gmail.com

[PopGoesTheWza]

I too experience memory issues (even with `pagination.stackAllItems: false)

For exemple when iterating a large set of data while doing zero processing, node crashes:

<--- Last few GCs --->

[25082:0x102a79000]    41360 ms: Mark-sweep 2197.9 (2231.2) -> 2197.7 (2200.2) MB, 655.8 / 0.0 ms  (average mu = 0.491, current mu = 0.000) last resort GC in old space requested
[25082:0x102a79000]    42041 ms: Mark-sweep 2197.7 (2200.2) -> 2197.7 (2200.2) MB, 681.0 / 0.0 ms  (average mu = 0.317, current mu = 0.000) last resort GC in old space requested


<--- JS stacktrace --->

==== JS stack trace =========================================

    0: ExitFrame [pc: 0x10097cc39]
Security context: 0x1dda764808d1 <JSObject>
    1: normalizeArguments(aka normalizeArguments) [0x1ddaa7e4fbd1] [/Users/guillaumec/rc-dev/rcsf/node_modules/got/dist/source/core/index.js:~285] [pc=0x2e8e3c9a0d33](this=0x1dda577004b1 <undefined>,0x1dda577004b1 <undefined>,0x1ddad705aec9 <Object map = 0x1dda334b80b9>,0x1dda75aa1841 <Object map = 0x1dda334acf89>)
    2: normalizeArguments(aka normalizeArgumen...

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory

Writing Node.js report to file: report.20200505.155029.25082.0.001.json
Node.js report completed
 1: 0x1010285f9 node::Abort() (.cold.1) [/Users/guillaumec/.nvm/versions/node/v12.16.3/bin/node]
 2: 0x10008634d node::FatalError(char const*, char const*) [/Users/guillaumec/.nvm/versions/node/v12.16.3/bin/node]
 3: 0x10008648e node::OnFatalError(char const*, char const*) [/Users/guillaumec/.nvm/versions/node/v12.16.3/bin/node]
 4: 0x100187c07 v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [/Users/guillaumec/.nvm/versions/node/v12.16.3/bin/node]
 5: 0x100187ba7 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/Users/guillaumec/.nvm/versions/node/v12.16.3/bin/node]
 6: 0x100315955 v8::internal::Heap::FatalProcessOutOfMemory(char const*) [/Users/guillaumec/.nvm/versions/node/v12.16.3/bin/node]
 7: 0x10031d9fc v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/Users/guillaumec/.nvm/versions/node/v12.16.3/bin/node]
 8: 0x1002e9fed v8::internal::Factory::NewFixedArrayWithFiller(v8::internal::RootIndex, int, v8::internal::Object, v8::internal::AllocationType) [/Users/guillaumec/.nvm/versions/node/v12.16.3/bin/node]
 9: 0x100465fe4 v8::internal::(anonymous namespace)::ElementsAccessorBase<v8::internal::(anonymous namespace)::FastPackedObjectElementsAccessor, v8::internal::(anonymous namespace)::ElementsKindTraits<(v8::internal::ElementsKind)2> >::GrowCapacity(v8::internal::Handle<v8::internal::JSObject>, unsigned int) [/Users/guillaumec/.nvm/versions/node/v12.16.3/bin/node]
10: 0x100617f74 v8::internal::Runtime_GrowArrayElements(int, unsigned long*, v8::internal::Isolate*) [/Users/guillaumec/.nvm/versions/node/v12.16.3/bin/node]
11: 0x10097cc39 Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit [/Users/guillaumec/.nvm/versions/node/v12.16.3/bin/node]
12: 0x2e8e3c9a0d33
13: 0x1009025e4 Builtins_InterpreterEntryTrampoline [/Users/guillaumec/.nvm/versions/node/v12.16.3/bin/node]
[1]    25082 abort      node packages/crm/dist/accounts.js

[dylang]

I just found the same thing. Simply require('got') is causing 3-4 MB loss each time.

FOUND THE LEAK

https://github.com/sindresorhus/got/blob/master/source/index.ts#L57
https://github.com/szmarczak/cacheable-lookup

Having this code multiple times (like Jest tests) will lead to running out of memory.

const CL = require('cacheable-lookup');
new CL();

[dylang]

Great job fixing the leak @szmarczak! The fixes aren't published yet so I just used the source from master https://github.com/szmarczak/cacheable-lookup with got to test it using Jest and the memory usage stayed the same instead of growing with each run.

[adityapatadia]

My case is not exactly similar. I hardly do require once or twice in code.

• have you tried running Node.js 12.16.3, 13.13.0

I already tried with 12.16.3.

• are you using an HTTP cache (the cache option)

I used cache option in one module and it's disabled in another module. Both seem to crash. The one with cache option crashes faster though.

• have you tried disabling the DNS cache (set dnsCache to false)

dnsCache is always false in my code.

I don't do any mergeOptions, extend or afterRequest hooks.

I have mailed you the heap stacks.

[szmarczak]

Are you using got.paginate(...)? @PopGoesTheWza discovered that hooks are duplicated when using that, so it can also lead to a memory leak.

[szmarczak]

Do you have http2 set to true?

[PopGoesTheWza]

Do you have http2 set to true?

No I don't.

[szmarczak]

And @adityapatadia ?

[adityapatadia]

I neither use http2 nor pagination. I create new agents with keepalive options and use them for http and https.

[szmarczak]

@PopGoesTheWza What Got version were you using when you got the dump?

Edit: nvm, it was 11.1.0

[PopGoesTheWza]

Also, my dump may be more relevant to #1223

[szmarczak]

@adityapatadia What's the ratio of requests - memory usage?

[adityapatadia]

@adityapatadia What's the ratio of requests - memory usage?

My production system runs from 20 requests per second to 60 requests per second. Memory usage gradually rises and stabilises at around 2.93 GB. Sometimes it crashes anytime after that. Let me put GOT 11 in my code which has more frequent crash issue and send you heap stacks.

[szmarczak]

@PopGoesTheWza Can you try again with [email protected]?

@adityapatadia Can you try again with these:

npm install [email protected] [email protected]

Make sure to include dnsCache in the options and let me know if the leak still occurs.

// ...
const CacheableLookup = require('cacheable-lookup');

const dnsCache = new CacheableLookup();

got('...', {dnsCache});

[PopGoesTheWza]

@szmarczak do the two test cases I submitted pass with [email protected] ?

[szmarczak]

no

[szmarczak]

Are you sure that the memory leak came from the hook duplicates?

[PopGoesTheWza]

In my on very case… yes.

Using the workarounds I posted in #1221 and #1223 I was able to traverse about 450k records (20 per page) in about 5 minutes with no error.

[PopGoesTheWza]

Without the kludgy hooks deduping, it would fail around 4500-5000 records :/

[PopGoesTheWza]

My use cases relies heavily on the pagination feature in fact. Otherwise I would probably not experience as much issues.

Note that it is not a complain.

Edit: my memory leak issue was due to bad definition of pagination.paginate and is now resolved.

[szmarczak]

I'm able to reproduce the memory leak. To reproduce:

1. Install dnsmasq
2. Add address=/.test/127.0.0.1 to /etc/dnsmasq.conf

3. sudo /usr/bin/dnsmasq (start the server)

4. Run ([email protected]):

const CacheableLookup = require('cacheable-lookup');
const cacheable = new CacheableLookup();

cacheable.servers = ['127.0.0.1'];

setInterval(() => {
    cacheable.lookup(`${Math.random().toString().substr(2)}.test`, () => {});
}, 1);

The memory usage slowly increases every minute. To cause an instant crash, replace setInterval with while (true).

[szmarczak]

I ran it for 12 minutes and got a crash:

<--- Last few GCs --->

[71685:0x4b04260]  1417938 ms: Mark-sweep 2033.5 (2067.6) -> 2027.8 (2082.6) MB, 1241.2 / 3.2 ms  (average mu = 0.315, current mu = 0.369) allocation failure scavenge might not succeed


<--- JS stacktrace --->

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
 1: 0xa295e0 node::Abort() [node]
 2: 0x9782df node::FatalError(char const*, char const*) [node]
 3: 0xb99c2e v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [node]
 4: 0xb99fa7 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [node]
 5: 0xd3a3b5  [node]
 6: 0xd3ad5b v8::internal::Heap::RecomputeLimits(v8::internal::GarbageCollector) [node]
 7: 0xd48b52 v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) [node]
 8: 0xd499a5 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [node]
 9: 0xd4a126 v8::internal::Heap::FinalizeIncrementalMarkingIfComplete(v8::internal::GarbageCollectionReason) [node]
10: 0xd4de97 v8::internal::IncrementalMarkingJob::Task::RunInternal() [node]
11: 0xc886bb non-virtual thunk to v8::internal::CancelableTask::Run() [node]
12: 0xa96fb4 node::PerIsolatePlatformData::RunForegroundTask(std::unique_ptr<v8::Task, std::default_delete<v8::Task> >) [node]
13: 0xa98e19 node::PerIsolatePlatformData::FlushForegroundTasksInternal() [node]
14: 0x13203a9  [node]
15: 0x1332810  [node]
16: 0x1320cb8 uv_run [node]
17: 0xa6a334 node::NodeMainInstance::Run() [node]
18: 0x9f9651 node::Start(int, char**) [node]
19: 0x7f88529a80d3 __libc_start_main [/usr/lib/haswell/libc.so.6]
20: 0x992f0c  [node]
Aborted

[szmarczak]

If you run

const CacheableLookup = require('.');
const cacheable = new CacheableLookup();

cacheable.servers = ['127.0.0.1'];

while (true) {
    cacheable.lookup(`${Math.random().toString().substr(2)}.test`, console.log);
    console.log(cacheable._cache.size, Object.keys(cacheable._pending).length, cacheable._nextRemovalTime);
}

you will see some logs. It crashes in less than a minute. The first numbers shows how many entries are in the cache, the next one shows how many requests are pending, the next one tells if there's any timeout set to remove outdated entries. You'll see

0 0 false

or

0 1 false

This is definitely a bug in the DNS cache...