`fs.writeSync` truncates long lines

[segrey]

iojs 1.8.1
Linux Mint 17, x64, 3.13.0-24

function formatString(n) {
  var str = '';
  while (str.length < n) {
    str = str + ' ' + str.length;
  }
  return str;
}

var fs = require('fs')
  , str = formatString(100000)
  , buffer = new Buffer(str + '\n', 'utf8');

fs.writeSync(process.stdout.fd, buffer, 0, buffer.length, null);

Running this script produces a truncated output. Here is a tail of it ... 77530 77536 77542 77548 77554 77560 7.

Replacing fs.writeSync(process.stdout.fd, buffer, 0, buffer.length, null) with console.log(str) changes output. Now the full string is output correctly. Tail is ... 9964 99970 99976 99982 99988 99994.

[monsanto]

(I made/deleted an incorrect comment earlier -- sorry) This only happens for me when process.stdout.fd is a TTY. If you redirect the output of this script to a file it seems to work fine.

[monsanto]

Maybe this will be useful to someone with familiarity w/ libuv. The last good commit (that can build) was b444392 @ v0.11.12-pre, right before upgrading libuv to v0.11.22

git bisect start
# bad: [fd896d5acfe0832cfb211d861f78845bcad4f301] 2014.09.24, Version 0.11.14 (Unstable)
git bisect bad fd896d5acfe0832cfb211d861f78845bcad4f301
# bad: [547213913b2e1525c15968916452995ab14e2195] test: adjust Makefile/test-ci, add to vcbuild.bat
git bisect bad 547213913b2e1525c15968916452995ab14e2195
# good: [84952da24192da98746573f1086b7f393f423a3c] Now working on 0.10.33
git bisect good 84952da24192da98746573f1086b7f393f423a3c
# bad: [e643fe4c4b79f2683914c6435f7166fc6be9f1a7] dns: fix GetAddrInfo assert
git bisect bad e643fe4c4b79f2683914c6435f7166fc6be9f1a7
# good: [2e13d0ce17d75b30db22dea058f35207ecf1ad66] fs: remove duplicate !options case
git bisect good 2e13d0ce17d75b30db22dea058f35207ecf1ad66
# good: [c0d81f90996667a658aa4403123e02161262506a] process: allow changing `exitCode` in `on('exit')`
git bisect good c0d81f90996667a658aa4403123e02161262506a
# bad: [d0fc5538d1ac769885c7e449b0d1f6759a7d4230] stream: split `objectMode` for Duplex
git bisect bad d0fc5538d1ac769885c7e449b0d1f6759a7d4230
# bad: [e496707d3971d45cd0b9f4147ce6abe00e7d6cf1] mdb_v8: update to latest version
git bisect bad e496707d3971d45cd0b9f4147ce6abe00e7d6cf1
# good: [78a854f8721693cf9a9b33136b485825bfff2142] test: move pummel/test-fs-largefile to disabled
git bisect good 78a854f8721693cf9a9b33136b485825bfff2142
# good: [f3189ace6b5e31a874df421ac2f74da0e77cb14d] http: remove the circular dependency
git bisect good f3189ace6b5e31a874df421ac2f74da0e77cb14d
# good: [78d245f5b21eede58e79138330690d63cf3d86f8] Merge remote-tracking branch 'origin/v0.10'
git bisect good 78d245f5b21eede58e79138330690d63cf3d86f8
# good: [a18c9b7dde22cce6cec5d47cfd6a16694c9992e8] test: timers-ordering should be more precise
git bisect good a18c9b7dde22cce6cec5d47cfd6a16694c9992e8
# skip: [e92d35d80be6e193cb547e94c6fbf3654542dbaa] uv: Upgrade to v0.11.22
git bisect skip e92d35d80be6e193cb547e94c6fbf3654542dbaa
# skip: [d2f2a32b897840d91cf240830ad5cf5f0e33a0c8] src: adapt to API change in uv_cwd
git bisect skip d2f2a32b897840d91cf240830ad5cf5f0e33a0c8
# good: [b444392a98e66b49dfee8c7e36c59d4e7c6ea1ac] Merge remote-tracking branch 'upstream/v0.10'
git bisect good b444392a98e66b49dfee8c7e36c59d4e7c6ea1ac
# bad: [e2fcfea46e334743aed24993eeebb2482c6ea762] src: update from uv_read2_start removal
git bisect bad e2fcfea46e334743aed24993eeebb2482c6ea762
# only skipped commits left to test
# possible first bad commit: [e2fcfea46e334743aed24993eeebb2482c6ea762] src: update from uv_read2_start removal
# possible first bad commit: [d2f2a32b897840d91cf240830ad5cf5f0e33a0c8] src: adapt to API change in uv_cwd
# possible first bad commit: [e92d35d80be6e193cb547e94c6fbf3654542dbaa] uv: Upgrade to v0.11.22

I'll add that I've experienced this one in the wild--when I encountered it, I thought it was the process.send regression so I didn't investigate further. Turns out it is something different.

[ChALkeR]

Ok, this is an off-topic, but never do that type of string concatenation in javascript.
In real-world apps, I mean.

[segrey]

@ChALkeR Sorry for this kind of concatenation. It's for demonstration purposes only. Performance-friendly version would be more complicated obscuring the overall idea of formatString as it seems to me.

[bnoordhuis]

I suspect it is caused by libuv/libuv@b197515 but I'm not sure it qualifies as a regression.

The tty file descriptor is non-blocking now whenever possible; I don't think the documentation made any promises about the blocking or non-blocking nature of process.stdout.fd or indeed even documented its existence.

For the record, what happens is a partial write:

write(1, " 0 2 4 6 8 10 13 16 19 22 25 28 "..., 100001) = 90112

You don't have that issue with process.stdout.write() because it keeps the event loop alive until the string is fully written.

[segrey]

JFYI The issue is also reproducible for me when running ~/.nvm/versions/io.js/v1.8.1/bin/iojs test.js | less, i.e. when the file descriptor is a PIPE. In that case the tail of output is ... 65512 65518 65524 65530.

[monsanto]

@bnoordhuis If I keep the event loop alive with a timer, it still does not finish writing. It was my understanding that libuv retries writes (or at least that the fs functions retry writes), is this incorrect?

[bnoordhuis]

You mean with fs.writeSync()? It does a partial write and returns the number of bytes written. It doesn't retry.

[alexlamsl]

FWIW, the example works as expected on Windows (10 x64) with io.js 1.8.1

[monsanto]

@bnoordhuis Sorry for the confusion.

There is still a problem here though. You can reproduce this issue with process.stdout.write by simply putting a process.exit() afterwards. The docs say that that process.stdout.write is blocking for TTYs and pipes so this should not happen.

Merging #774 fixes pipes, but not TTYs.

For an example of a regression in the wild, see autoprefixer.

[Fishrock123]

Actually a duplicate of #784