Skip to content

awaiting a promise within for-await-of loop prematurely ends stream #29410

@fl0w

Description

@fl0w
  • Version: v10.16.0 (breaks), v11.0.0 - v.11.4.0 (works), v11.5.0+ (breaks), v12.9.1 (breaks)
  • Platform: macOS Mojave Version 10.14.6
$ uname -a
Darwin portman.local 18.7.0 Darwin Kernel Version 18.7.0: Thu Jun 20 18:42:21 PDT 2019; root:xnu-4903.270.47~4/RELEASE_X86_64 x86_64
  • Subsystem: stream

I apologise in advance, as I was unable to create a test case using bare streams as my knowledge is lacking. Thus, this report includes external dependencies.

I'm streaming data from database using pg library with pg-query-stream. For some reason when I await within a for await-loop, the stream seems to be "dropping" objects.

As I was debugging the libraries in question, I noticed that switching to node v11.0.0-v11.4.0 it works, but from v11.5.0+ and above (up to v12.9.1) it breaks which leads me to believe a change in node lib caused this.

const assert = require('assert')
const { Client } = require('pg')
const QueryStream = require('pg-query-stream')

async function main () {
  const client = new Client()
  await client.connect()

  const sql = 'select * from generate_series(1, $1)'
  const n = 10 // num rows to generate
  const query = new QueryStream(sql, [n])
  const stream = client.query(query)

  let i = 0
  for await (const row of stream) {
    console.log(stream._readableState.length)

    i += 1
    await new Promise((resolve) => setTimeout(() => resolve(), 0))
    // ^-- This await breaks it all in v10.16, v11.5+ but works in from v11.0 to v.11.4
  }

  await client.end()
  assert.strictEqual(i, n)
}

if (!module.parent) {
  main()
}

Note: I abbreviated ExperimentalWarning and DeprecationWarning from output

$ node -v
v11.4.0
$ node what.js
9
8
7
6
5
4
3
2
1
0
$ node -v
v11.5.0
$ node what.js
9
8
(node:21383) UnhandledPromiseRejectionWarning: AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

2 !== 10

    at main (/Users/fl0w/async-iterator-stream/what.js:24:10)
    at process.internalTickCallback (internal/process/next_tick.js:77:7)
$ node -v
v12.9.1
$ node what.js
9
8
(node:21562) UnhandledPromiseRejectionWarning: AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

2 !== 10

    at main (/Users/fl0w/src/async-iterator-stream/what.js:24:10)
    at processTicksAndRejections (internal/process/task_queues.js:85:5)

I took a look at what happened between node v11.4 and v11.5 and to my understand (which is subpar) I found the following three PR which might have had an impact on this. Maybe it's expected and even desired? I am also aware this is an experimental feature.

2456a545a6
d449c36500
39af61faa2

I understand that this bug report includes external dependencies but I can continue debugging with a little handholding or direction?

Addendum (edit):

I compiled node locally (first time, hurrah) and it's definitely 39af61faa2 that broke this. I tried by reverting it on master and it passed.

Out put with NODE_DEBUG=stream (maybe it helps?):

$ node -v
v12.9.1
$ NODE_DEBUG=stream node what.js
STREAM 56035: resume
STREAM 56035: resume false
STREAM 56035: read 0
STREAM 56035: need readable false
STREAM 56035: length less than watermark true
STREAM 56035: do read
STREAM 56035: flow true
STREAM 56035: read undefined
STREAM 56035: need readable true
STREAM 56035: length less than watermark true
STREAM 56035: reading or ended false
STREAM 56035: read 0
STREAM 56035: need readable true
STREAM 56035: length less than watermark true
STREAM 56035: reading or ended false
STREAM 56035: readableAddChunk <Buffer 52 00 00 00 08 00 00 00 00 53 00 00 00 16 61 70 70 6c 69 63 61 74 69 6f 6e 5f 6e 61 6d 65 00 00 53 00 00 00 19 63 6c 69 65 6e 74 5f 65 6e 63 6f 64 69 ... 276 more bytes>
STREAM 56035: maybeReadMore read 0
STREAM 56035: read 0
STREAM 56035: need readable true
STREAM 56035: length less than watermark true
STREAM 56035: do read
STREAM 56035: on readable 0 false
STREAM 56035: read undefined
STREAM 56035: need readable true
STREAM 56035: length less than watermark true
STREAM 56035: do read
STREAM 56035: read undefined
STREAM 56035: need readable true
STREAM 56035: length less than watermark true
STREAM 56035: reading or ended false
STREAM 56035: readable nexttick read 0
STREAM 56035: read 0
STREAM 56035: need readable true
STREAM 56035: length less than watermark true
STREAM 56035: reading or ended false
STREAM 56035: readableAddChunk <Buffer 31 00 00 00 04 32 00 00 00 04 54 00 00 00 28 00 01 67 65 6e 65 72 61 74 65 5f 73 65 72 69 65 73 00 00 00 00 00 00 00 00 00 00 17 00 04 ff ff ff ff 00 ... 1 more byte>
STREAM 56035: maybeReadMore read 0
STREAM 56035: read 0
STREAM 56035: need readable true
STREAM 56035: length less than watermark true
STREAM 56035: do read
STREAM 56035: readableAddChunk <Buffer 44 00 00 00 0b 00 01 00 00 00 01 31 44 00 00 00 0b 00 01 00 00 00 01 32 44 00 00 00 0b 00 01 00 00 00 01 33 44 00 00 00 0b 00 01 00 00 00 01 34 44 00 ... 86 more bytes>
STREAM 56035: maybeReadMore read 0
STREAM 56035: read 0
STREAM 56035: need readable true
STREAM 56035: length less than watermark true
STREAM 56035: do read
STREAM 56035: readableAddChunk <Buffer 5a 00 00 00 05 49>
STREAM 56035: maybeReadMore read 0
STREAM 56035: read 0
STREAM 56035: need readable true
STREAM 56035: length less than watermark true
STREAM 56035: do read
STREAM 56035: readableAddChunk { generate_series: 1 }
STREAM 56035: emitReadable true false
STREAM 56035: emitReadable false
STREAM 56035: readableAddChunk { generate_series: 2 }
STREAM 56035: readableAddChunk { generate_series: 3 }
STREAM 56035: readableAddChunk { generate_series: 4 }
STREAM 56035: readableAddChunk { generate_series: 5 }
STREAM 56035: readableAddChunk { generate_series: 6 }
STREAM 56035: readableAddChunk { generate_series: 7 }
STREAM 56035: readableAddChunk { generate_series: 8 }
STREAM 56035: readableAddChunk { generate_series: 9 }
STREAM 56035: readableAddChunk { generate_series: 10 }
STREAM 56035: emitReadable_ false 10 false
STREAM 56035: flow false
STREAM 56035: maybeReadMore read 0
STREAM 56035: read 0
STREAM 56035: need readable true
STREAM 56035: length less than watermark true
STREAM 56035: do read
STREAM 56035: read undefined
STREAM 56035: need readable true
STREAM 56035: length less than watermark true
STREAM 56035: reading or ended false
9
STREAM 56035: read undefined
STREAM 56035: need readable true
STREAM 56035: length less than watermark true
STREAM 56035: reading or ended false
8
STREAM 56035: readableAddChunk null
STREAM 56035: onEofChunk
STREAM 56035: emitReadable_ false 8 true
STREAM 56035: flow false
STREAM 56035: readableAddChunk null
STREAM 56035: onEofChunk
STREAM 56035: emitReadable_ false 0 true
STREAM 56035: flow true
STREAM 56035: read undefined
STREAM 56035: endReadable false
STREAM 56035: read 0
STREAM 56035: endReadable false
STREAM 56035: endReadableNT false 0
STREAM 56035: endReadableNT true 0

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions