DNS cache (`cacheable-lookup@^4.2.3`) causes a memory leak #1220

adityapatadia · 2020-05-04T16:45:21Z

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

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

szmarczak · 2020-05-04T19:38:15Z

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:
  - 157e02b (hasn't been released yet)
  - 429db40 (has been released already)
  - d914a7e (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 · 2020-05-05T14:08:24Z

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 · 2020-05-05T19:00:19Z

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 · 2020-05-07T16:09:24Z

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 · 2020-05-07T16:15:53Z

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 · 2020-05-07T16:38:22Z

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

szmarczak · 2020-05-07T16:38:41Z

Do you have http2 set to true?

PopGoesTheWza · 2020-05-07T16:40:35Z

Do you have http2 set to true?

No I don't.

szmarczak · 2020-05-07T16:40:52Z

And @adityapatadia ?

adityapatadia · 2020-05-07T16:44:33Z

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

szmarczak · 2020-05-07T17:00:34Z

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

Edit: nvm, it was 11.1.0

PopGoesTheWza · 2020-05-07T17:51:46Z

Also, my dump may be more relevant to #1223

szmarczak · 2020-05-07T18:20:53Z

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

adityapatadia · 2020-05-07T19:20:43Z

@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 · 2020-05-09T18:12:12Z

@PopGoesTheWza Can you try again with got@11.1.2?

@adityapatadia Can you try again with these:

npm install got@11.1.2 cacheable-lookup@5.0.0

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 · 2020-05-09T18:55:35Z

@szmarczak do the two test cases I submitted pass with Got@11.1.2 ?

szmarczak · 2020-05-09T18:56:27Z

no

szmarczak · 2020-05-09T18:56:46Z

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

PopGoesTheWza · 2020-05-09T19:00:50Z

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 · 2020-05-09T19:06:02Z

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

PopGoesTheWza · 2020-05-09T19:09:42Z

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 · 2020-05-11T09:12:32Z

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

Install dnsmasq
Add address=/.test/127.0.0.1 to /etc/dnsmasq.conf
sudo /usr/bin/dnsmasq (start the server)
Run (cacheable-lookup@5.0.2):

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 · 2020-05-11T09:27:46Z

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 · 2020-05-11T09:36:31Z

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

PopGoesTheWza mentioned this issue May 5, 2020

HTTPError: Response code 422 (Unprocessable Entity) upon second execution of pagination.paginate #1221

Closed

2 tasks

PopGoesTheWza mentioned this issue May 5, 2020

hooks are being duplicated with each pagination.paginate() iteration #1223

Closed

2 tasks

szmarczak added bug Something does not work as it should ✭ help wanted ✭ labels May 5, 2020

dylang mentioned this issue May 5, 2020

Memory leak each time cachableLookup is imported and constructed. szmarczak/cacheable-lookup#25

Closed

niftylettuce mentioned this issue May 7, 2020

Core bugs with got@10.x + got@11.x - may have issues with prior versions, tested on Node LTS stable v12.x #1232

Closed

szmarczak changed the title ~~GOT v11 has memory leak issue~~ DNS cache (cacheable-lookup@^4.2.3) causes a memory leak May 10, 2020

szmarczak mentioned this issue May 10, 2020

Support for Configurable Request Library MONEI/Shopify-api-node#371

Closed

szmarczak closed this as completed in 9770e54 May 11, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

DNS cache (`cacheable-lookup@^4.2.3`) causes a memory leak #1220

DNS cache (`cacheable-lookup@^4.2.3`) causes a memory leak #1220

adityapatadia commented May 4, 2020

szmarczak commented May 4, 2020

PopGoesTheWza commented May 5, 2020

dylang commented May 5, 2020

dylang commented May 7, 2020 •

edited

adityapatadia commented May 7, 2020

szmarczak commented May 7, 2020

szmarczak commented May 7, 2020

PopGoesTheWza commented May 7, 2020

szmarczak commented May 7, 2020

adityapatadia commented May 7, 2020

szmarczak commented May 7, 2020 •

edited

PopGoesTheWza commented May 7, 2020

szmarczak commented May 7, 2020

adityapatadia commented May 7, 2020

szmarczak commented May 9, 2020 •

edited

PopGoesTheWza commented May 9, 2020

szmarczak commented May 9, 2020

szmarczak commented May 9, 2020

PopGoesTheWza commented May 9, 2020

PopGoesTheWza commented May 9, 2020

PopGoesTheWza commented May 9, 2020 •

edited

szmarczak commented May 11, 2020 •

edited

szmarczak commented May 11, 2020

szmarczak commented May 11, 2020 •

edited

DNS cache (cacheable-lookup@^4.2.3) causes a memory leak #1220

DNS cache (cacheable-lookup@^4.2.3) causes a memory leak #1220

Comments

adityapatadia commented May 4, 2020

Describe the bug

Actual behavior

Expected behavior

Code to reproduce

Checklist

szmarczak commented May 4, 2020

PopGoesTheWza commented May 5, 2020

dylang commented May 5, 2020

dylang commented May 7, 2020 • edited

adityapatadia commented May 7, 2020

szmarczak commented May 7, 2020

szmarczak commented May 7, 2020

PopGoesTheWza commented May 7, 2020

szmarczak commented May 7, 2020

adityapatadia commented May 7, 2020

szmarczak commented May 7, 2020 • edited

PopGoesTheWza commented May 7, 2020

szmarczak commented May 7, 2020

adityapatadia commented May 7, 2020

szmarczak commented May 9, 2020 • edited

PopGoesTheWza commented May 9, 2020

szmarczak commented May 9, 2020

szmarczak commented May 9, 2020

PopGoesTheWza commented May 9, 2020

PopGoesTheWza commented May 9, 2020

PopGoesTheWza commented May 9, 2020 • edited

szmarczak commented May 11, 2020 • edited

szmarczak commented May 11, 2020

szmarczak commented May 11, 2020 • edited

DNS cache (`cacheable-lookup@^4.2.3`) causes a memory leak #1220

DNS cache (`cacheable-lookup@^4.2.3`) causes a memory leak #1220

dylang commented May 7, 2020 •

edited

szmarczak commented May 7, 2020 •

edited

szmarczak commented May 9, 2020 •

edited

PopGoesTheWza commented May 9, 2020 •

edited

szmarczak commented May 11, 2020 •

edited

szmarczak commented May 11, 2020 •

edited