Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

bad proxy exits node without any error #739

Closed
ghost opened this issue Feb 27, 2020 · 17 comments · Fixed by #1064
Closed

bad proxy exits node without any error #739

ghost opened this issue Feb 27, 2020 · 17 comments · Fixed by #1064
Labels

Comments

@ghost
Copy link

ghost commented Feb 27, 2020

I've been using node-fetch with different proxies and https-proxy-agent for years. Never had a problem. I switched to another proxy service and every 50 requests or so, the node.js process exits without warning. I know it's the proxy because if I switch to a different proxy it works perfectly.

How can I debug this issue if it just exits without warning and I don't have access to the logs of the proxy service?

This is the code I'm using for testing:

    let counter = 1
    while (true) {
      const agent = new HttpsProxyAgent(proxyUri)
      try {
        const html = await fetch(
          `https://www.google.com`,
          {headers: {'User-Agent': userAgent}, agent, timeout: 5000}
        ).then(res => res.text())
      }
      catch (e) {
        console.log(e.message)
      }
      console.log(counter++)
    }

It always exits without warning between 30-50 iterations with that proxy

@maszaa
Copy link

maszaa commented Mar 4, 2020

I've faced the same issue. Didn't use custom timeout or attempted to read the response, just wanted to know if the request through proxy was successful (no timeout etc.)

@maszaa
Copy link

maszaa commented Mar 5, 2020

I also face sometimes the node.js process getting stuck after firing the request with proxy/agent. I attempt to read the status of the response but the execution never gets there.

@urbanio
Copy link

urbanio commented Mar 25, 2020

same for me

@jimliang
Copy link

same. It will exits node without any error if proxy is unavailable

@ghost
Copy link
Author

ghost commented Apr 19, 2020

I think the error might be due to https-proxy-agent, not node-fetch, but haven't had time to test since it takes me like 30min to reproduce the error a single time.

@davidje13
Copy link

davidje13 commented Jan 3, 2021

I am encountering a similar (the same?) issue with just node-fetch and no proxy. NodeJS exits with status code 0 and no errors (no promise rejection or unhandledRejection / uncaughtException events, just an immediate shutdown).

I believe in my case it is triggered because the connection is very unstable and has high packet loss (5% or more). Could this also be the case for the proxies you are seeing problems with? (I'm not saying this isn't a bug in either node or node-fetch; just trying to narrow down possible causes)

@tekwiz
Copy link
Member

tekwiz commented Jan 3, 2021

Can you try running the script with NODE_DEBUG=*? That should give you some insight as to what is happening when it stops

@davidje13
Copy link

I'll give it a try. Might take a while before it next crashes.

The output from NODE_DEBUG=* is very verbose and I'll have to leave this looping for a while; is there a reduced set I could specify? (e.g. NODE_DEBUG=net?) The file's already getting pretty big! (it tends to take some time between crashes)

@davidje13
Copy link

Spoke too soon; it already crashed! I'll have the logs here soon.

@davidje13
Copy link

davidje13 commented Jan 3, 2021

TIMER 64014: unenroll: list empty
STREAM 64014: readableAddChunk <Buffer 31 00 00 00 04 32 00 00 00 04 6e 00 00 00 04 43 00 00 00 0d 55 50 44 41 54 45 20 31 00>
STREAM 64014: maybeReadMore read 0
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
NET 64014: _read
STREAM 64014: readableAddChunk <Buffer 5a 00 00 00 05 49>
TIMER 64014: no 10000 list was found in insert, creating a new one
STREAM 64014: maybeReadMore read 0
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
NET 64014: _read
HTTP 64014: call onSocket 0 0
HTTP 64014: createConnection api.zoopla.co.uk:443::::::::::::::::::::: {
  protocol: 'https:',
  slashes: true,
  auth: null,
  host: 'api.zoopla.co.uk',
  port: 443,
  hostname: 'api.zoopla.co.uk',
  hash: null,
  search: '?api_key=hidden&order_by=age&ordering=descending&listing_status=sale&lat_min=-90&lat_max=90&lon_min=-180&lon_max=180&new_homes=no&minimum_price=50000&maximum_price=75000&page_number=60&page_size=100',
  query: 'api_key=hidden&order_by=age&ordering=descending&listing_status=sale&lat_min=-90&lat_max=90&lon_min=-180&lon_max=180&new_homes=no&minimum_price=50000&maximum_price=75000&page_number=60&page_size=100',
  pathname: '/api/v1/property_listings.json',
  path: null,
  href: 'https://api.zoopla.co.uk/api/v1/property_listings.json?api_key=hidden&order_by=age&ordering=descending&listing_status=sale&lat_min=-90&lat_max=90&lon_min=-180&lon_max=180&new_homes=no&minimum_price=50000&maximum_price=75000&page_number=60&page_size=100',
  method: 'GET',
  headers: [Object: null prototype] {
    Accept: [ '*/*' ],
    'User-Agent': [ 'node-fetch/1.0 (+https://github.com/bitinn/node-fetch)' ],
    'Accept-Encoding': [ 'gzip,deflate' ],
    Connection: [ 'close' ]
  },
  agent: undefined,
  _defaultAgent: Agent {
    _events: [Object: null prototype] {
      free: [Function (anonymous)],
      newListener: [Function: maybeEnableKeylog]
    },
    _eventsCount: 2,
    _maxListeners: undefined,
    defaultPort: 443,
    protocol: 'https:',
    options: { path: null },
    requests: {},
    sockets: { 'api.zoopla.co.uk:443:::::::::::::::::::::': [] },
    freeSockets: {},
    keepAliveMsecs: 1000,
    keepAlive: false,
    maxSockets: Infinity,
    maxFreeSockets: 256,
    scheduling: 'fifo',
    maxTotalSockets: Infinity,
    totalSocketCount: 0,
    maxCachedSessions: 100,
    _sessionCache: { map: [Object], list: [Array] },
    [Symbol(kCapture)]: false
  },
  servername: 'api.zoopla.co.uk',
  _agentKey: 'api.zoopla.co.uk:443:::::::::::::::::::::'
}
HTTPS 64014: createConnection {
  protocol: 'https:',
  slashes: true,
  auth: null,
  host: 'api.zoopla.co.uk',
  port: 443,
  hostname: 'api.zoopla.co.uk',
  hash: null,
  search: '?api_key=hidden&order_by=age&ordering=descending&listing_status=sale&lat_min=-90&lat_max=90&lon_min=-180&lon_max=180&new_homes=no&minimum_price=50000&maximum_price=75000&page_number=60&page_size=100',
  query: 'api_key=hidden&order_by=age&ordering=descending&listing_status=sale&lat_min=-90&lat_max=90&lon_min=-180&lon_max=180&new_homes=no&minimum_price=50000&maximum_price=75000&page_number=60&page_size=100',
  pathname: '/api/v1/property_listings.json',
  path: null,
  href: 'https://api.zoopla.co.uk/api/v1/property_listings.json?api_key=hidden&order_by=age&ordering=descending&listing_status=sale&lat_min=-90&lat_max=90&lon_min=-180&lon_max=180&new_homes=no&minimum_price=50000&maximum_price=75000&page_number=60&page_size=100',
  method: 'GET',
  headers: [Object: null prototype] {
    Accept: [ '*/*' ],
    'User-Agent': [ 'node-fetch/1.0 (+https://github.com/bitinn/node-fetch)' ],
    'Accept-Encoding': [ 'gzip,deflate' ],
    Connection: [ 'close' ]
  },
  agent: undefined,
  _defaultAgent: Agent {
    _events: [Object: null prototype] {
      free: [Function (anonymous)],
      newListener: [Function: maybeEnableKeylog]
    },
    _eventsCount: 2,
    _maxListeners: undefined,
    defaultPort: 443,
    protocol: 'https:',
    options: { path: null },
    requests: {},
    sockets: { 'api.zoopla.co.uk:443:::::::::::::::::::::': [] },
    freeSockets: {},
    keepAliveMsecs: 1000,
    keepAlive: false,
    maxSockets: Infinity,
    maxFreeSockets: 256,
    scheduling: 'fifo',
    maxTotalSockets: Infinity,
    totalSocketCount: 0,
    maxCachedSessions: 100,
    _sessionCache: { map: [Object], list: [Array] },
    [Symbol(kCapture)]: false
  },
  servername: 'api.zoopla.co.uk',
  _agentKey: 'api.zoopla.co.uk:443:::::::::::::::::::::',
  encoding: null
}
HTTPS 64014: reuse session for "api.zoopla.co.uk:443:::::::::::::::::::::"
TLS 64014: client _init handle? true
NET 64014: pipe false null
NET 64014: connect: find host api.zoopla.co.uk
NET 64014: connect: dns options { family: undefined, hints: 1024 }
HTTP 64014: sockets api.zoopla.co.uk:443::::::::::::::::::::: 1 1
HTTP 64014: outgoing message end.
TLS 64014: client initRead handle? true buffered? false
STREAM 64014: read 0
STREAM 64014: need readable false
STREAM 64014: length less than watermark true
STREAM 64014: do read
NET 64014: _read
NET 64014: _read wait for connection
STREAM 64014: resume
STREAM 64014: resume true
STREAM 64014: flow true
STREAM 64014: read undefined
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: reading, ended or constructing false
NET 64014: afterConnect
TLS 64014: client _start handle? true connecting? false requestOCSP? false
NET 64014: _read
NET 64014: Socket._handle.readStart
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: reading, ended or constructing false
TLS 64014: client onhandshakedone
TLS 64014: client _finishInit handle? true alpn false servername api.zoopla.co.uk
TLS 64014: client emit secureConnect. authorized: true
STREAM 64014: onWriteComplete 0 undefined
TIMER 64014: process timer lists 264089
TIMER 64014: process timer lists 266348
TIMER 64014: timeout callback 10000
TIMER 64014: unenroll: list empty
TIMER 64014: 10000 list empty
NET 64014: _final: not ended, call shutdown()
NET 64014: afterShutdown destroyed=false ReadableState {
  objectMode: false,
  highWaterMark: 16384,
  buffer: BufferList { head: null, tail: null, length: 0 },
  length: 0,
  pipes: [],
  flowing: true,
  ended: false,
  endEmitted: false,
  reading: true,
  constructed: true,
  sync: false,
  needReadable: true,
  emittedReadable: false,
  readableListening: false,
  resumeScheduled: false,
  errorEmitted: false,
  emitClose: false,
  autoDestroy: true,
  destroyed: false,
  errored: null,
  closed: false,
  closeEmitted: false,
  defaultEncoding: 'utf8',
  awaitDrainWriters: null,
  multiAwaitDrain: false,
  readingMore: false,
  decoder: null,
  encoding: null,
  [Symbol(kPaused)]: false
}
STREAM 64014: readableAddChunk null
STREAM 64014: onEofChunk
STREAM 64014: emitReadable_ false 0 true
STREAM 64014: flow true
STREAM 64014: read undefined
STREAM 64014: endReadable false
STREAM 64014: read 0
STREAM 64014: endReadable false
STREAM 64014: endReadableNT false 0
NET 64014: destroy
NET 64014: close
NET 64014: close handle
STREAM 64014: endReadableNT true 0
NET 64014: emit close
STREAM 64014: readableAddChunk <Buffer 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d 0a 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70 70 6c 69 63 61 74 69 6f 6e 2f 6a 73 6f 6e 3b 63 68 ... 114 more bytes>
HTTP 64014: requestTimeout timer moved to req
HTTP 64014: AGENT incoming response!
STREAM 64014: pipe count=1 opts=undefined
STREAM 64014: resume
STREAM 64014: resume false
STREAM 64014: read 0
STREAM 64014: need readable false
STREAM 64014: length less than watermark true
STREAM 64014: do read
STREAM 64014: flow true
STREAM 64014: read undefined
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: reading, ended or constructing false
STREAM 64014: maybeReadMore read 0
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
NET 64014: _read
STREAM 64014: resume
STREAM 64014: resume false
STREAM 64014: read 0
STREAM 64014: need readable false
STREAM 64014: length less than watermark true
STREAM 64014: do read
STREAM 64014: flow true
STREAM 64014: read undefined
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: reading, ended or constructing false
STREAM 64014: readableAddChunk <Buffer 38 30 30 30 0d 0a 7b 22 72 65 73 75 6c 74 5f 63 6f 75 6e 74 22 3a 37 33 30 38 2c 22 6c 6f 6e 67 69 74 75 64 65 22 3a 30 2c 22 61 72 65 61 5f 6e 61 6d ... 16334 more bytes>
STREAM 64014: readableAddChunk <Buffer 7b 22 72 65 73 75 6c 74 5f 63 6f 75 6e 74 22 3a 37 33 30 38 2c 22 6c 6f 6e 67 69 74 75 64 65 22 3a 30 2c 22 61 72 65 61 5f 6e 61 6d 65 22 3a 22 22 2c ... 16328 more bytes>
STREAM 64014: ondata
STREAM 64014: readableAddChunk <Buffer 7b 22 72 65 73 75 6c 74 5f 63 6f 75 6e 74 22 3a 37 33 30 38 2c 22 6c 6f 6e 67 69 74 75 64 65 22 3a 30 2c 22 61 72 65 61 5f 6e 61 6d 65 22 3a 22 22 2c ... 16328 more bytes>
STREAM 64014: dest.write true
STREAM 64014: maybeReadMore read 0
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
STREAM 64014: maybeReadMore read 0
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
STREAM 64014: maybeReadMore read 0
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
NET 64014: _read
STREAM 64014: readableAddChunk <Buffer 22 3a 2d 31 2e 33 31 34 38 37 35 2c 22 74 68 75 6d 62 6e 61 69 6c 5f 75 72 6c 22 3a 22 68 74 74 70 73 3a 2f 2f 6c 69 64 2e 7a 6f 6f 63 64 6e 2e 63 6f ... 16334 more bytes>
STREAM 64014: readableAddChunk <Buffer 22 3a 2d 31 2e 33 31 34 38 37 35 2c 22 74 68 75 6d 62 6e 61 69 6c 5f 75 72 6c 22 3a 22 68 74 74 70 73 3a 2f 2f 6c 69 64 2e 7a 6f 6f 63 64 6e 2e 63 6f ... 16334 more bytes>
STREAM 64014: ondata
STREAM 64014: readableAddChunk <Buffer 22 3a 2d 31 2e 33 31 34 38 37 35 2c 22 74 68 75 6d 62 6e 61 69 6c 5f 75 72 6c 22 3a 22 68 74 74 70 73 3a 2f 2f 6c 69 64 2e 7a 6f 6f 63 64 6e 2e 63 6f ... 16334 more bytes>
STREAM 64014: dest.write false
STREAM 64014: false write response, pause 0
STREAM 64014: call pause flowing=true
STREAM 64014: pause
STREAM 64014: maybeReadMore read 0
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
STREAM 64014: pipeOnDrain 1
STREAM 64014: flow true
STREAM 64014: read undefined
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
STREAM 64014: maybeReadMore read 0
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
NET 64014: _read
STREAM 64014: readableAddChunk <Buffer 75 6e 74 79 22 3a 0d 0a>
STREAM 64014: readableAddChunk <Buffer 75 6e 74 79 22 3a>
STREAM 64014: ondata
STREAM 64014: readableAddChunk <Buffer 75 6e 74 79 22 3a>
STREAM 64014: dest.write true
STREAM 64014: maybeReadMore read 0
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
STREAM 64014: maybeReadMore read 0
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
STREAM 64014: maybeReadMore read 0
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
NET 64014: _read
STREAM 64014: readableAddChunk <Buffer 39 33 39 0d 0a 22 4f 78 66 6f 72 64 73 68 69 72 65 22 2c 22 70 72 69 63 65 22 3a 22 37 30 30 30 30 22 2c 22 6c 69 73 74 69 6e 67 5f 69 64 22 3a 22 35 ... 2318 more bytes>
STREAM 64014: readableAddChunk <Buffer 22 4f 78 66 6f 72 64 73 68 69 72 65 22 2c 22 70 72 69 63 65 22 3a 22 37 30 30 30 30 22 2c 22 6c 69 73 74 69 6e 67 5f 69 64 22 3a 22 35 33 30 34 33 37 ... 2311 more bytes>
STREAM 64014: ondata
STREAM 64014: readableAddChunk <Buffer 22 4f 78 66 6f 72 64 73 68 69 72 65 22 2c 22 70 72 69 63 65 22 3a 22 37 30 30 30 30 22 2c 22 6c 69 73 74 69 6e 67 5f 69 64 22 3a 22 35 33 30 34 33 37 ... 2311 more bytes>
STREAM 64014: dest.write true
STREAM 64014: maybeReadMore read 0
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
STREAM 64014: maybeReadMore read 0
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
STREAM 64014: maybeReadMore read 0
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
NET 64014: _read
STREAM 64014: readableAddChunk <Buffer 33 66 66 38 0d 0a 20 61 72 65 61 2c 20 66 69 74 74 65 64 20 6b 69 74 63 68 65 6e 20 61 6e 64 20 62 61 74 68 72 6f 6f 6d 20 77 69 74 68 20 62 61 74 68 ... 16334 more bytes>
STREAM 64014: readableAddChunk <Buffer 20 61 72 65 61 2c 20 66 69 74 74 65 64 20 6b 69 74 63 68 65 6e 20 61 6e 64 20 62 61 74 68 72 6f 6f 6d 20 77 69 74 68 20 62 61 74 68 2c 20 77 61 73 68 ... 16326 more bytes>
STREAM 64014: ondata
STREAM 64014: readableAddChunk <Buffer 20 61 72 65 61 2c 20 66 69 74 74 65 64 20 6b 69 74 63 68 65 6e 20 61 6e 64 20 62 61 74 68 72 6f 6f 6d 20 77 69 74 68 20 62 61 74 68 2c 20 77 61 73 68 ... 16326 more bytes>
STREAM 64014: dest.write true
STREAM 64014: maybeReadMore read 0
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
STREAM 64014: maybeReadMore read 0
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
STREAM 64014: maybeReadMore read 0
STREAM 64014: read 0
STREAM 64014: need readable true
STREAM 64014: length less than watermark true
STREAM 64014: do read
NET 64014: _read
STREAM 64014: readableAddChunk null
STREAM 64014: onEofChunk
STREAM 64014: emitReadable_ false 0 true
STREAM 64014: flow true
STREAM 64014: read undefined
STREAM 64014: endReadable false
STREAM 64014: read 0
STREAM 64014: endReadable false
STREAM 64014: endReadableNT false 0
NET 64014: destroy
NET 64014: close
NET 64014: close handle
STREAM 64014: endReadableNT true 0
NET 64014: emit close
HTTP 64014: CLIENT socket onClose
HTTP 64014: removeSocket api.zoopla.co.uk:443::::::::::::::::::::: writable: false
HTTP 64014: HTTP socket close
STREAM 64014: read undefined
STREAM 64014: endReadable true

That's where the logs end. Process exits with exit code 0. I know for sure it isn't a clean exit because there are a lot more logs it would print if that were the case (a lot more API calls too).

Last stdout line (any stderr output is in the logs above):

calling https://api.zoopla.co.uk/api/v1/property_listings.json?api_key=hidden&order_by=age&ordering=descending&listing_status=sale&lat_min=-90&lat_max=90&lon_min=-180&lon_max=180&new_homes=no&minimum_price=50000&maximum_price=75000&page_number=60&page_size=100

The calling code (sorry it's a bit messy, I've been adding lots of special-case error handling to diagnose what's going on here):

function getText(res) {
  return res.text().catch(() => '<failed to get response text>');
}

export async function callAPI(api, params) {
  const url = `${API_BASE}/${api}.json?${new URLSearchParams({ api_key: API_KEY, ...params })}`;

  while (true) {
    await apiThrottle.check();
    console.info(`calling ${url}`); // <-- this is the last line we see printed
    // [this is simplified from the real code to remove paths which I know are not taken based on the log output]
    const res = await fetch(url); // <-- node-fetch call
    // I added a console log line here in a later experiment and it DOES get printed before dying
    if (res.ok) {
      try {
        const json = await res.json(); // <-- problem seems to be here
        // I added a console log line here in a later experiment and it DOES NOT get printed
        return json; // <-- all paths from here print messages which we do not see in the logs
      } catch (e) {
        console.log('failed to parse JSON', e); // NOT printed
        throw e;
      }
    }
    const text = await getText(res);
    // [...cut since not relevant...] (error handling; all paths print or throw, none observed in output)
  }
}

Finally, to give an idea of the quality of the network connection (which I think is relevant here since it seems to exit after hanging on a request for a while):

PING 8.8.8.8 (8.8.8.8): 56 data bytes
64 bytes from 8.8.8.8: icmp_seq=0 ttl=117 time=24.881 ms
Request timeout for icmp_seq 1
Request timeout for icmp_seq 2
Request timeout for icmp_seq 3
Request timeout for icmp_seq 4
Request timeout for icmp_seq 5
Request timeout for icmp_seq 6
Request timeout for icmp_seq 7
Request timeout for icmp_seq 8
Request timeout for icmp_seq 9
Request timeout for icmp_seq 10
Request timeout for icmp_seq 11
Request timeout for icmp_seq 12
Request timeout for icmp_seq 13
Request timeout for icmp_seq 14
Request timeout for icmp_seq 15
64 bytes from 8.8.8.8: icmp_seq=16 ttl=117 time=13.509 ms
64 bytes from 8.8.8.8: icmp_seq=17 ttl=117 time=88.904 ms
64 bytes from 8.8.8.8: icmp_seq=18 ttl=117 time=17.180 ms
64 bytes from 8.8.8.8: icmp_seq=19 ttl=117 time=18.099 ms
64 bytes from 8.8.8.8: icmp_seq=20 ttl=117 time=18.361 ms
64 bytes from 8.8.8.8: icmp_seq=21 ttl=117 time=14.650 ms
64 bytes from 8.8.8.8: icmp_seq=22 ttl=117 time=18.180 ms
64 bytes from 8.8.8.8: icmp_seq=23 ttl=117 time=16.492 ms
64 bytes from 8.8.8.8: icmp_seq=24 ttl=117 time=17.578 ms
64 bytes from 8.8.8.8: icmp_seq=25 ttl=117 time=14.657 ms
64 bytes from 8.8.8.8: icmp_seq=26 ttl=117 time=20.067 ms
64 bytes from 8.8.8.8: icmp_seq=27 ttl=117 time=17.467 ms
64 bytes from 8.8.8.8: icmp_seq=28 ttl=117 time=18.755 ms
64 bytes from 8.8.8.8: icmp_seq=29 ttl=117 time=27.641 ms
Request timeout for icmp_seq 30
Request timeout for icmp_seq 31
64 bytes from 8.8.8.8: icmp_seq=32 ttl=117 time=19.896 ms
64 bytes from 8.8.8.8: icmp_seq=33 ttl=117 time=16.942 ms
64 bytes from 8.8.8.8: icmp_seq=34 ttl=117 time=17.822 ms
64 bytes from 8.8.8.8: icmp_seq=35 ttl=117 time=16.890 ms
64 bytes from 8.8.8.8: icmp_seq=36 ttl=117 time=16.125 ms
64 bytes from 8.8.8.8: icmp_seq=37 ttl=117 time=19.972 ms
64 bytes from 8.8.8.8: icmp_seq=38 ttl=117 time=14.620 ms
64 bytes from 8.8.8.8: icmp_seq=39 ttl=117 time=19.665 ms
64 bytes from 8.8.8.8: icmp_seq=40 ttl=117 time=15.541 ms
64 bytes from 8.8.8.8: icmp_seq=41 ttl=117 time=20.897 ms
64 bytes from 8.8.8.8: icmp_seq=42 ttl=117 time=14.651 ms
64 bytes from 8.8.8.8: icmp_seq=43 ttl=117 time=20.318 ms
64 bytes from 8.8.8.8: icmp_seq=44 ttl=117 time=18.366 ms
64 bytes from 8.8.8.8: icmp_seq=45 ttl=117 time=20.279 ms
64 bytes from 8.8.8.8: icmp_seq=46 ttl=117 time=19.103 ms
64 bytes from 8.8.8.8: icmp_seq=47 ttl=117 time=14.035 ms
64 bytes from 8.8.8.8: icmp_seq=48 ttl=117 time=23.969 ms
64 bytes from 8.8.8.8: icmp_seq=49 ttl=117 time=23.960 ms
64 bytes from 8.8.8.8: icmp_seq=50 ttl=117 time=18.509 ms
64 bytes from 8.8.8.8: icmp_seq=51 ttl=117 time=18.404 ms
64 bytes from 8.8.8.8: icmp_seq=52 ttl=117 time=23.362 ms
Request timeout for icmp_seq 53
64 bytes from 8.8.8.8: icmp_seq=54 ttl=117 time=20.108 ms
Request timeout for icmp_seq 55
Request timeout for icmp_seq 56
Request timeout for icmp_seq 57
Request timeout for icmp_seq 58
Request timeout for icmp_seq 59
Request timeout for icmp_seq 60
Request timeout for icmp_seq 61
Request timeout for icmp_seq 62
Request timeout for icmp_seq 63
Request timeout for icmp_seq 64
Request timeout for icmp_seq 65
Request timeout for icmp_seq 66
Request timeout for icmp_seq 67
Request timeout for icmp_seq 68
Request timeout for icmp_seq 69
64 bytes from 8.8.8.8: icmp_seq=70 ttl=117 time=37.188 ms
64 bytes from 8.8.8.8: icmp_seq=71 ttl=117 time=25.021 ms
64 bytes from 8.8.8.8: icmp_seq=72 ttl=117 time=190.881 ms
64 bytes from 8.8.8.8: icmp_seq=73 ttl=117 time=518.533 ms
64 bytes from 8.8.8.8: icmp_seq=74 ttl=117 time=55.874 ms
64 bytes from 8.8.8.8: icmp_seq=75 ttl=117 time=15.179 ms
64 bytes from 8.8.8.8: icmp_seq=76 ttl=117 time=19.193 ms
64 bytes from 8.8.8.8: icmp_seq=77 ttl=117 time=18.925 ms
64 bytes from 8.8.8.8: icmp_seq=78 ttl=117 time=18.174 ms
64 bytes from 8.8.8.8: icmp_seq=79 ttl=117 time=17.807 ms
64 bytes from 8.8.8.8: icmp_seq=80 ttl=117 time=17.171 ms
64 bytes from 8.8.8.8: icmp_seq=81 ttl=117 time=17.781 ms
64 bytes from 8.8.8.8: icmp_seq=82 ttl=117 time=22.036 ms
64 bytes from 8.8.8.8: icmp_seq=83 ttl=117 time=20.088 ms
64 bytes from 8.8.8.8: icmp_seq=84 ttl=117 time=18.218 ms
64 bytes from 8.8.8.8: icmp_seq=85 ttl=117 time=18.024 ms
64 bytes from 8.8.8.8: icmp_seq=86 ttl=117 time=17.540 ms
64 bytes from 8.8.8.8: icmp_seq=87 ttl=117 time=17.315 ms
64 bytes from 8.8.8.8: icmp_seq=88 ttl=117 time=16.773 ms
Request timeout for icmp_seq 89
Request timeout for icmp_seq 90
Request timeout for icmp_seq 91
Request timeout for icmp_seq 92
Request timeout for icmp_seq 93
Request timeout for icmp_seq 94
Request timeout for icmp_seq 95
Request timeout for icmp_seq 96
Request timeout for icmp_seq 97
Request timeout for icmp_seq 98
Request timeout for icmp_seq 99
Request timeout for icmp_seq 100
^C
--- 8.8.8.8 ping statistics ---
102 packets transmitted, 56 packets received, 45.1% packet loss
round-trip min/avg/max/stddev = 13.509/32.885/518.533/70.115 ms

It seems to be particularly bad at the moment! Which might explain why the error is reproducing so readily.

@tekwiz
Copy link
Member

tekwiz commented Jan 3, 2021

@davidje13 Thank you for all the details! This is very helpful. I believe the problem you are hitting is a content-length or chunked transfer-encoding bug. I actually have this on my hit list for tomorrow, so hopefully I'll have some kind of resolution by then. In the meantime, you may have some luck if you switch to Node.js 12 from 14/15 or from 12 to 14. I've noticed slightly different behaviors in tests (e.g #1056). If you do see a change in switching (positive or negative), please post the results.

@davidje13
Copy link

Glad you've got a suspected cause!

A few final points for now:

  • I'm running Node 15. I'll try installing 12 and running a test with it if I get some time later.

  • The files being downloaded are large-ish (~1MB)

  • The server is indeed using chunked encoding;

    > GET /api/v1/property_listings.json?blah HTTP/1.1
    > Host: api.zoopla.co.uk
    > User-Agent: curl/7.54.0
    > Accept: */*
    > 
    < HTTP/1.1 200 OK
    < Content-Type: application/json;charset=utf-8
    < Date: Sun, 03 Jan 2021 05:16:13 GMT
    < Server: nginx
    < transfer-encoding: chunked
    < Connection: keep-alive
    < 
    

@tekwiz
Copy link
Member

tekwiz commented Jan 4, 2021

@davidje13 I have created a branch with a hopeful fix. Please give it a try when you can: tekwiz:node-fetch/fix-chunked-transfer-premature-close-1. You should be able to install it with

npm install 'github:tekwiz/node-fetch#fix-chunked-transfer-premature-close-1'

@davidje13
Copy link

Yes, that branch works better; instead of exiting silently it now throws (still using Node15):

FetchError: Invalid response body while trying to fetch https://api.zoopla.co.uk/foo: Premature close
    at consumeBody (file:///.../node_modules/node-fetch/src/body.js:214:10)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:93:5)
    at async Response.json (file:///.../node_modules/node-fetch/src/body.js:119:18)
    at async callAPI (file:///.../api.mjs:34:16)
    ...
    at async run (file:///.../src/load/index.mjs:61:5) {
  type: 'system',
  errno: 'ERR_STREAM_PREMATURE_CLOSE',
  code: 'ERR_STREAM_PREMATURE_CLOSE',
  erroredSysCall: undefined
}

Which seems reasonable. I can catch this error and retry the request.

Out of curiosity: did you find out what was causing the node process to die before? I don't see any smoking gun in your diffs (I suspect there is also a bug to report in NodeJS itself here).

@exitss

This comment was marked as spam.

@Alluseri

This comment was marked as spam.

@daviddayag

This comment was marked as spam.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
9 participants