--trace-sync-io regression between v10.10 and v10.11

[ChALkeR]

• Version: 10.11, 10.16.0, 12.7.0, v13.0.0-pre (master)
• Platform: Darwin MacBook-ChALkeR.local 18.5.0 Darwin Kernel Version 18.5.0: Mon Mar 11 20:40:32 PDT 2019; root:xnu-4903.251.3~3/RELEASE_X86_64 x86_64
• Subsystem: lib/src

--trace-sync-io is not expected to produce output before the first tick, and is not expected to print things when the source file does not trigger sync io. Both expectations fail now.

Examples:

Nothing

// Nothing

Expected, v10.10.0: nothing, .

Obtained (v10.11.0, v12.7.0 is almost equivalent with trace differences):

Click to expand

(node:18126) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18126) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18126) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18126) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18126) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18126) WARNING: Detected use of sync API
    at openSync (fs.js:433:26)
    at readFileSync (fs.js:341:35)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18126) WARNING: Detected use of sync API
    at tryStatSync (fs.js:303:25)
    at readFileSync (fs.js:343:17)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18126) WARNING: Detected use of sync API
    at readSync (fs.js:489:26)
    at tryReadSync (fs.js:330:20)
    at readFileSync (fs.js:367:19)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18126) WARNING: Detected use of sync API
    at closeSync (fs.js:400:11)
    at readFileSync (fs.js:376:8)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)

No output expected

const fs = require('fs');
fs.statSync(process.argv[0])

Expected, v10.10: nothing, .

Obtained (v10.11.0, v12.7.0 is almost equivalent with trace differences):

Click to expand

(node:18792) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at openSync (fs.js:433:26)
    at readFileSync (fs.js:341:35)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at tryStatSync (fs.js:303:25)
    at readFileSync (fs.js:343:17)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at readSync (fs.js:489:26)
    at tryReadSync (fs.js:330:20)
    at readFileSync (fs.js:359:19)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at closeSync (fs.js:400:11)
    at readFileSync (fs.js:376:8)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at statSync (fs.js:827:25)
    at /Users/chalker/repo/node/4.js:2:4
    at Module._compile (internal/modules/cjs/loader.js:689:30)
    at Module._extensions..js (internal/modules/cjs/loader.js:700:10)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)

Note how statSync call is also included (it shouldn't be), this is not just the garbage in the front.

Some output expected

const fs = require('fs');
setTimeout(() => {
  fs.statSync(process.argv[0])
}, 100)

Expected, v10.10:

(node:17902) WARNING: Detected use of sync API
    at statSync (fs.js:827:25)
    at setTimeout (/Users/chalker/repo/node/4.js:3:6)
    at ontimeout (timers.js:425:11)
    at tryOnTimeout (timers.js:289:5)
    at listOnTimeout (timers.js:252:5)

Obtained (v10.11.0, v12.7.0 is almost equivalent with trace differences):

Click to expand

(node:18815) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at openSync (fs.js:433:26)
    at readFileSync (fs.js:341:35)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at tryStatSync (fs.js:303:25)
    at readFileSync (fs.js:343:17)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at readSync (fs.js:489:26)
    at tryReadSync (fs.js:330:20)
    at readFileSync (fs.js:359:19)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at closeSync (fs.js:400:11)
    at readFileSync (fs.js:376:8)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at statSync (fs.js:827:25)
    at setTimeout (/Users/chalker/repo/node/4.js:3:6)
    at ontimeout (timers.js:425:11)
    at tryOnTimeout (timers.js:289:5)
    at listOnTimeout (timers.js:252:5)

---

Refs: #1707

[ChALkeR]

I will take a closer look

[ChALkeR]

Bisect shows that --trace-sync-io was broken by 7fa5f54, ref: #22726.

7fa5f54 is the first bad commit

/cc @danbev

[ChALkeR]

This is caused by removal of env.set_trace_sync_io(env.options()->trace_sync_io).

7fa5f54 breaks the logic behind --trace-sync-io, it should be enabled only at a certain point in time, while that commit enables it from the very start.

Revert in progress. Upd: #28926