debugger,test: fix flaky debug logging on SmartOS #3615

Trott · 2015-10-31T16:00:08Z

SmartOS sometimes munges output from process._rawDebug()
but Windows can't use console.error() in the debug agent.
So inject logic to chose the right thing based on platform.

Fixes: #2476

Trott · 2015-10-31T16:02:34Z

CI: https://ci.nodejs.org/job/node-test-pull-request/653/

cjihrig · 2015-10-31T16:05:28Z

lib/_debug_agent.js

+    // SmartOS sometimes munges output from `process._rawDebug()`
+    // but Windows can't use `console.error()`.
+    // https://github.com/nodejs/node/issues/2476
+    if (process.platform == 'win32') {


I usually feel like I need a bath after typing == instead of ===. Not sure how that happened. Will change for sure.

Trott · 2015-10-31T16:24:44Z

Addressed @cjihrig suggestions, pushed a fixup commit, killed the prior CI and re-running.

New CI at: https://ci.nodejs.org/job/node-test-pull-request/654/

UPDATE: CI looks good. One went offline during the build failure and a single failure on Windows with a test that's been flaky for a while. Otherwise, all success.

thefourtheye · 2015-11-02T03:20:23Z

lib/_debug_agent.js

+  // SmartOS sometimes munges output from `process._rawDebug()`
+  // but Windows can't use `console.error()`.
+  // https://github.com/nodejs/node/issues/2476
+  const log = process.platform === 'win32' ? process._rawDebug : console.error;


You can use common.isWindows

Edit: Nvm. This is not a test.

is _rawDebug out of scope to fix?

@jbergstroem I suppose not, although I'm not even sure this is a bug in _rawDebug and not an OS bug. I don't have a SmartOS machine to mess around with.

happy to give you access if you want to tinker around.

Cool, I may be in touch. (Going to focus on getting to sleep now.) BTW, it could also go the other way, I imagine, and be a "fix console.error() in this context for Windows" . If that happened, there would be no reason for _rawDebug() to exist. Of course, that might be an impossibility for all I know...

@jbergstroem My public keys are at https://github.com/trott.keys. What else would you need to give me access?

@Trott ping me at bugs at bergstroem.nu or jbergstroem@irc.

Fishrock123 · 2015-11-03T15:54:21Z

Sounds like a _rawDebug() bug. If anything should work, it's _rawDebug().

jbergstroem · 2015-11-03T22:01:01Z

Just to be clear then; what actually needs fixing is PrintErrorString.

Trott · 2015-11-03T23:22:27Z

Guess it's time for me to brush up a bit on my so-rusty-as-to-be-nonexistent C++ skillz....

SmartOS sometimes munges output from `process._rawDebug()` but Windows can't use `console.error()` in the debug agent. So inject logic to chose the right thing based on platform. Fixes: nodejs#2476

Trott · 2015-11-04T06:17:44Z

If I change line 3066 of node.cc from...

PrintErrorString("%s\n", *message);

...to...

PrintErrorString("%s (%d bytes)\n", *message, message.length());

...and trigger the bug, the output looks like this:

Debugger listening on port 12390Debugger listening on port 12389 (32 bytes)
 (32 bytes)

The one thing this proves is that PrintErrorString() is getting called twice with the correct character strings. Otherwise, there wouldn't be two instances of (32 bytes) in the string. There would be one instance and the byte count would be around 64 bytes or so.

But how the heck are the lines getting interwoven like that?!

PrintErrorString() itself is very simple. With all the Windows stuff ifdef'ed out, it amounts to this:

static void PrintErrorString(const char* format, ...) {
  va_list ap;
  va_start(ap, format);
  vfprintf(stderr, format, ap);
  va_end(ap);
}

For fun, I tried adding fflush(stderr) after the vfprintf() call but that didn't fix anything.

My somewhat ignorant guesses are:

Something weird going on where a carriage return or other weird character is somehow ending up in the line causing the display to somehow munge the two lines together. This seems unlikely to me, but what do I know?
Some OS-specific bug or "feature" that causes stderr and/or vfprintf() to do this weirdness.

Does someone more knowledgable than me see something obvious I'm missing? I'm happy to keep pushing on this but it feels like something someone with more experience on the C++ side might see right away.

Trott · 2015-11-05T04:34:12Z

Replacing PrintErrorString() with fprintf() doesn't fix the issue. https://ci.nodejs.org/job/node-test-commit-smartos/221/nodes=smartos14-32/console

SmartOS bug/feature?

Trott · 2015-11-06T22:13:04Z

It looks like ultimately the problem is that stderr is unbuffered on SmartOS so we're getting some interleaving. Forcing it to line-buffering seems to fix it. Going to test some more and then submit a fix soon hopefully if the fix doesn't break a ton of other stuff in CI or something...

Trott · 2015-11-06T23:48:25Z

Closing in favor of #3701

SmartOS does not line buffer stderr by default, or at least that is the behavior on the Node project Jenkins server. Force line buffering. This resolves the flakiness observed on SmartOS for test-debug-signal-cluster. Fixes: nodejs#2476 Refs: nodejs#3615

SmartOS does not line buffer stderr by default, or at least that is the behavior on the Node project Jenkins server. Force line buffering. This resolves the flakiness observed on SmartOS for test-debug-signal-cluster. PR-URL: nodejs#3701 Fixes: nodejs#2476 Refs: nodejs#3615 Reviewed-By: Johan Bergström <bugs@bergstroem.nu> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl>

SmartOS does not line buffer stderr by default, or at least that is the behavior on the Node project Jenkins server. Force line buffering. This resolves the flakiness observed on SmartOS for test-debug-signal-cluster. PR-URL: #3701 Fixes: #2476 Refs: #3615 Reviewed-By: Johan Bergström <bugs@bergstroem.nu> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl>

MylesBorins · 2015-11-16T23:28:18Z

removing lts-watch tag as this did not land

SmartOS does not line buffer stderr by default, or at least that is the behavior on the Node project Jenkins server. Force line buffering. This resolves the flakiness observed on SmartOS for test-debug-signal-cluster. PR-URL: #3701 Fixes: #2476 Refs: #3615 Reviewed-By: Johan Bergström <bugs@bergstroem.nu> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl>

Trott mentioned this pull request Oct 31, 2015

Investigate flaky test test-debug-signal-cluster #2476

Closed

cjihrig reviewed Oct 31, 2015
View reviewed changes

mscdex added debugger test Issues and PRs related to the tests. labels Oct 31, 2015

Trott changed the title ~~test: fix flaky test-debug-signal-cluster.js~~ debugger,test: fix flaky test-debug-signal-cluster.js Nov 1, 2015

Trott changed the title ~~debugger,test: fix flaky test-debug-signal-cluster.js~~ debugger,test: fix flaky debug logging on SmartOS Nov 1, 2015

thefourtheye reviewed Nov 2, 2015
View reviewed changes

jasnell added the lts-watch-v4.x label Nov 3, 2015

Trott force-pushed the smartos-flaky branch from 8f534a9 to b1b7e13 Compare November 3, 2015 23:18

Trott added 2 commits November 3, 2015 20:19

test: fix flaky test-debug-signal-cluster.js

8076de4

SmartOS sometimes munges output from `process._rawDebug()` but Windows can't use `console.error()` in the debug agent. So inject logic to chose the right thing based on platform. Fixes: nodejs#2476

fixup: cjihrig comments

6cc5743

Trott force-pushed the smartos-flaky branch from b1b7e13 to 6cc5743 Compare November 4, 2015 04:20

Trott added smartos Issues and PRs related to the SmartOS platform. c++ Issues and PRs that require attention from people who are familiar with C++. labels Nov 4, 2015

Trott mentioned this pull request Nov 6, 2015

Force line-buffering for stderr #3701

Closed

Trott closed this Nov 6, 2015

MylesBorins removed the lts-watch-v4.x label Nov 16, 2015

Trott deleted the smartos-flaky branch January 13, 2022 22:29

This was referenced Dec 7, 2023

[Snyk] Fix for 1 vulnerabilities aliscco/alisco-node#1140

Open

[Snyk] Security upgrade karma from 5.2.3 to 6.0.0 aliscco/alisco-node#1146

Open

[Snyk] Security upgrade karma from 5.2.3 to 6.0.0 aliscco/alisco-node#1156

Open

leonardoadame mentioned this pull request Dec 8, 2023

[Snyk] Fix for 1 vulnerabilities leonardoadame/node#567

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

debugger,test: fix flaky debug logging on SmartOS #3615

debugger,test: fix flaky debug logging on SmartOS #3615

Trott commented Oct 31, 2015

Trott commented Oct 31, 2015

cjihrig Oct 31, 2015

Trott Oct 31, 2015

Trott commented Oct 31, 2015

thefourtheye Nov 2, 2015

jbergstroem Nov 2, 2015

Trott Nov 2, 2015

jbergstroem Nov 2, 2015

Trott Nov 2, 2015

Trott Nov 3, 2015

jbergstroem Nov 3, 2015

Fishrock123 commented Nov 3, 2015

jbergstroem commented Nov 3, 2015

Trott commented Nov 3, 2015

Trott commented Nov 4, 2015

Trott commented Nov 5, 2015

Trott commented Nov 6, 2015

Trott commented Nov 6, 2015

MylesBorins commented Nov 16, 2015

debugger,test: fix flaky debug logging on SmartOS #3615

debugger,test: fix flaky debug logging on SmartOS #3615

Conversation

Trott commented Oct 31, 2015

Trott commented Oct 31, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Trott commented Oct 31, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Fishrock123 commented Nov 3, 2015

jbergstroem commented Nov 3, 2015

Trott commented Nov 3, 2015

Trott commented Nov 4, 2015

Trott commented Nov 5, 2015

Trott commented Nov 6, 2015

Trott commented Nov 6, 2015

MylesBorins commented Nov 16, 2015