Strange errors, segfaults when upgrading from v6.9.1 to v7.0.0

[SEAPUNK]

• Version: v7.0.0
• Platform: (Arch Linux) Linux alpha 4.8.6-1-ARCH deps: update openssl to 1.0.1j #1 SMP PREEMPT Mon Oct 31 18:51:30 CET 2016 x86_64 GNU/Linux
• Subsystem: v8 (?)

I'm not completely sure yet whether this is a v8 issue or a packaging issue w/ Arch Linux yet, but all I know is that when I install and use v7.0.0, I start getting weird errors, bugs and segfaults that I've never seen before with v6.9.1.

For example, one of the programs that I run had an impossible bug: It randomly left out some information that it's guaranteed to include when generating a feed. This bug has never happened before, and when I run it again, that time it just throws an error that it never threw before, something to do with accessing a missing property. When I switched back to v6.9.1, it starts working again just fine.

One consistent case I was able to find was cloning the yarn repo, and running tests on it. It gives me a segfault almost consistently at pretty much the same place, with the difference of npm sometimes segfaulting along with node in the journalctl logs: https://gist.github.com/SEAPUNK/652768e792f6f32bc8777230bc740a92
Again, switching back to v6.9.1 makes it work just fine.

I can't pinpoint the issue, but I'm pretty sure it's something to do with v8, or how nodejs was packaged for Arch Linux.

[Fishrock123]

The segfault mentions uv_kill, maybe this is a child_process issue?

[SEAPUNK]

I wouldn't know, but I don't think so.

I don't think it would fit in with the "impossible bug" scenario I described, since the program I wrote runs all in one process (although it is started with npm start) and did not segfault when it left out aforementioned data it was guaranteed to include. Nothing in the logs (other than deprecation warnings for os.tmpDir()) indicated a bug.

With yarn (and the logs I included for it), npm seems to be segfaulting only after node (I'm assuming the test runner) segfaults, from what I'm seeing in the logs, which I think would make sense, unless that is a bug within itself.

[addaleax]

I think the uv_kill is just from npm raising the same signal for itself with which a lifecycle script exited (src)

[addaleax]

• Can you reproduce this using the binaries from https://nodejs.org/?
• Does the problem also occur when directly running the test script (jest --coverage --verbose) inside the yarn directory? (I assume it does but want to make sure).
• Would you be willing to upload a core dump? In the case of the output you posted, that would be the one of pid 25205

[SEAPUNK]

@addaleax

• Yes. https://gist.github.com/SEAPUNK/c902e9e3ee50d19bb6b7381a062170a2
• Yes. https://gist.github.com/SEAPUNK/5795132e63b02abf0c113f91374fcaef
• Sure; who do I email it to? I'm a bit paranoid about it potentially containing sensitive information, unless it really doesn't.

[addaleax]

@SEAPUNK That is more than reasonable – if you want to email it to me, that would be [email protected]. I don’t think we really have some kind of real collaborator-only storage for things like this… I mean, there’s the security email address and everything, but that obviously serves a different purpose.

[SEAPUNK]

Yeah, I'm uploading the file to my web server, I'll email you the link to the download when it's uploaded.

[addaleax]

@SEAPUNK Awesome… I couldn’t really make out any problem is from just looking at the code location mentioned in the stack traces, but I assume having at least the register and/or stack content available will be helpful.

If you want to take the time, you could also try to run the process under valgrind… it’s slow but if the source of this is some kind of memory corruption, it might turn out to be pretty useful.

[SEAPUNK]

@addaleax Emailed. Running valgrind in the meantime.

[SEAPUNK]

Valgrind's got node to the part of running the remove.js test, and this time, it didn't segfault, probably because it is running much slower now.

[SEAPUNK]

Valgrind output: https://gist.github.com/SEAPUNK/012420b1128019cc96c197f8cb84bdeb

Did not segfault.

[addaleax]

Yeah, that might just be because it’s so slow… sigh. I’m in our weekly conference call rn, but from what I could make out from the core dump, it does look like some kind of memory corruption. I’ll keep you updated if and when I find out more

[SEAPUNK]

Alright, cool. I'll use v6.9.1 in the meantime.

[addaleax]

Can you try to run the failing script with passing the --trace-ic flag to node?

[addaleax]

/cc @nodejs/v8

[SEAPUNK]

Yeah, it segfaults. Here's the ZIP (100+MB uncompressed): https://media.sq10.net/xtremebike/__node_trace_ic.zip

[ofrobots]

@SEAPUNK I am unable to repro on either linux or mac (I think you're on linux). I would be interested in looking at the core-dump too, if you can provide me the link.

[SEAPUNK]

I already deleted the coredump, but I can see if I can repro it on my laptop (different computer, but same OS)

Where should I email it to?

[ofrobots]

ofrobots-at-google.com

[SEAPUNK]

Yeah, I can't reproduce on my laptop. I'll play around some more and see if I can trigger some issue, otherwise I'll recreate a coredump tomorrow.

[SEAPUNK]

Oh! It coredumped! I had to run the test a few times to get it to do that. Zipping and uploading.

[SEAPUNK]

Emailed.

[indutny]

Will try to reproduce it on OS X

[SEAPUNK]

FYI, the coredump seems to happen more frequently when nothing else is using up the resources (particularly CPU)

[indutny]

No crash on mac so far, running it in the loop.

[indutny]

No crashes 😢

@SEAPUNK do you think you could try to install lldb and https://github.com/nodejs/llnode on that machine?

[SEAPUNK]

It doesn't seem to be working correctly. I have lldb version 3.9 installed, and after sudo make install-linux, I cannot do v8 help inside of lldb.

[SEAPUNK]

No prob. 👍

[indutny]

Seems like v8 bug, indeed. cc @ofrobots

[addaleax]

@indutny From the core dump, I could tell that CompareICState::NewInputState got called with *(void**)$rsi = *value = 0x6d65722f73646e61, which is obviously not a real pointer (and more likely an excerpt from an ascii string). I assume you were trying to figure out something like that?

I had no luck finding out where that value came from, though.

[ofrobots]

@SEAPUNK can you confirm that your node binary is the one you downloaded from http://nodejs.org/dist/v7.0.0/node-v7.0.0-linux-x64.tar.xz? I can't symbolize the core dump. Perhaps this is because my because my Linux system is a bit too different (I don't have an Arch linux box.)

While the core doesn't give me proper backtrace or symbols, I can corroborate what @addaleax is observing.

The NewICState function is called with old_state = UNINITIALIZED and the value handle pointing to an object at 0x6372732f6e726179 which isn't a valid pointer even though it is tagged correctly to be an object.

[addaleax]

fwiw, my inspection was based on the binary from the tarball you linked (with gdb on Ubuntu 16.04)

[SEAPUNK]

@ofrobots The coredump I gave you was from my package manager installed node.js binary. I'll try to get you a coredump from a downloaded nodejs binary sometime tonight.

@addaleax's coredump, OTOH, was made with the binary I was told to download and use, I believe.

[addaleax]

Hm… maybe there’s a chance @leafi would be willing to provide an Arch VM again for checking? This seems to be pretty reproducible there? That was really helpful for #8310 …

Conversely, it might help if you could think about anything special about your environment…?

[SEAPUNK]

I don't think my environment is special. Standard Linux kernel, standard core packages, etc...

I might be able to provide an Arch VM. I'm setting one up right now; I'll see if I can securely tunnel the SSH to the outside world.

[SEAPUNK]

I'm having trouble reproducing the issue on the VM and the laptop I created again. Sigh.

The only machine I know is more-or-less consistently coredumping is the one I have at work; I'll generate and upload a coredump from that machine.

[SEAPUNK]

Coredump and the binaries I used to run the tests with: http://files.sq10.net/node7coredump/

This time I'll make it public just because.

Commands used:

git clone ssh://[email protected]/yarnpkg/yarn
cd yarn
git checkout ebe899382fdb70222651380f299737c6625d87e4
wget https://nodejs.org/dist/v7.0.0/node-v7.0.0-linux-x64.tar.xz
tar xvf node-v7.0.0-linux-x64.tar.xz
yarn # I had node 7, npm 3.10.9, yarn 0.16.1 already globally installed w/ `sudo npm install -g yarn`
./node-v7.0.0-linux-x64/bin/node ./node-v7.0.0-linux-x64/bin/npm run build
./node-v7.0.0-linux-x64/bin/node node_modules/.bin/jest --coverage --verbose

/cc @ofrobots

[develar]

Tests of https://github.com/electron-userland/electron-builder often failed with this error (https://circleci.com/gh/electron-userland/electron-builder/285) on macOS and Linux (I cannot say about Windows because nodejs 6 is used (to test that it is definitely NodeJS 7 issue)). Not always, but often.

[SEAPUNK]

I was able to get a few segfaults out of the Arch Linux VM after changing the CPU cores from 1 to 4, but they were different in the sense of:

1. There were multiple segfaults in a single test run, so I'm assuming Yarn or Jest spawned multiple processes
2. It did not stop the main test process
3. Loading one of those segfault core dumps into lldb caused a segfault in lldb (lol)

[SEAPUNK]

Anyways, I think I have the VM ready for external use; be sure to let me know (and give me an email to send the login to) if you want to access the VM, even though the segfaults are definitely different and seemingly unusable in lldb.

[addaleax]

Loading one of those segfault core dumps into lldb caused a segfault in lldb (lol)

I think you get bonus point for that. ;) (Sending you my SSH public key)

[addaleax]

So, what I’ve found out so far:

• For reproducing, running jest -i __tests__/commands/remove.js in the cloned & set up yarn repo suffices (which nice for debugging as it’s a single process)
• The crash location for that command is different, but there’s still an invalid pointer containing ASCII data (strings like "otareneG" seem to indicate that it’s from JS source code)
• valgrind is happy, for some reason (i.e. everything passes when using it, no errors reported)

lldb info for one of the crashes (<details> tag in order not to spam the issue so you may have to click to see it):

(lldb) v8 bt
 * thread #1: tid = 8853, 0x00001aa536356c19, name = 'node', stop reason = signal SIGSEGV: invalid address (fault address: 0x0)
  * frame #0: 0x00001aa536356c19 (anonymous)(this=0x00003c32ff904311:<undefined>, 0x00003c32ff904351:<hole>, 0x00003c32ff904351:<hole>, 0x00003c32ff904351:<hole>, 0x00003c32ff904351:<hole>) at /home/user/yarn/src/cli/commands/remove.js:17:13 fn=0x0000281bd49a17b1
    frame #1: 0x00001aa53623a495 next(this=0x0000281bd49d5369:<unknown>, 0x00003c32ff904421:<false>) at (no script) fn=0x000022b2139384d9
    frame #2: 0x00001aa53674244e step(this=0x00003c32ff904311:<undefined>, 0x00003c32ff905249:<String: "next">, 0x00003c32ff904421:<false>) at /home/user/yarn/node_modules/babel-runtime/helpers/asyncToGenerator.js:15:20 fn=0x0000281bd49d5679
    frame #3: 0x00001aa53677d8c1 (anonymous)(this=0x00003c32ff904311:<undefined>, 0x00003c32ff904421:<false>) at /home/user/yarn/node_modules/babel-runtime/helpers/asyncToGenerator.js:27:65 fn=0x000016071b2a1ef1
    frame #4: 0x00001aa53678dc9e PromiseHandle(this=0x00003c32ff904311:<undefined>, 0x00003c32ff904421:<false>, 0x000016071b2a1ef1:<function: (anonymous) at /home/user/yarn/node_modules/babel-runtime/helpers/asyncToGenerator.js:27:65>, 0x000016071b2a2121:<Object: Object>) at native promise.js:1:10 fn=0x00003c32ff9b0c41
    frame #5: 0x00001aa5364afb16 (anonymous)(this=0x00003c32ff904311:<undefined>) at native promise.js:1:10 fn=0x000016071b2ae6d9
    frame #6: 0x00001aa53624a7c3 <internal>
    frame #7: 0x00001aa53622aa81 <entry>
    frame #8: 0x0000000000e10aa5 node`v8::internal::Execution::TryCall(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, v8::internal::MaybeHandle<v8::internal::Object>*) + 485
    frame #9: 0x0000000000f334d6 node`v8::internal::Isolate::RunMicrotasksInternal() + 742
    frame #10: 0x0000000000f337e1 node`v8::internal::Isolate::RunMicrotasks() + 49
    frame #11: 0x000000000124d279 node`node::AsyncWrap::MakeCallback(v8::Local<v8::Function>, int, v8::Local<v8::Value>*) + 1033
    frame #12: 0x0000000001280bb6 node`node::After(uv_fs_s*) + 326
    frame #13: 0x00000000015009c5 node`uv__work_done(handle=0x0000000002069f10) + 165 at threadpool.c:236
    frame #14: 0x00000000015029db node`uv__async_event(loop=0x0000000002069e60, w=<unavailable>, nevents=<unavailable>) + 171 at async.c:98
    frame #15: 0x0000000001502ab3 node`uv__async_io(loop=0x0000000002069e60, w=0x000000000206a028, events=<unavailable>) + 163 at async.c:138
    frame #16: 0x0000000001513080 node`uv__io_poll(loop=0x0000000002069e60, timeout=748) + 928 at linux-core.c:380
    frame #17: 0x0000000001503596 node`uv_run(loop=0x0000000002069e60, mode=UV_RUN_ONCE) + 342 at core.c:354
    frame #18: 0x0000000001268a2f node`node::StartNodeInstance(void*) + 1615
    frame #19: 0x0000000001269fef node`node::Start(int, char**) + 735
    frame #20: 0x00007ffff6b90291 libc.so.6`__libc_start_main + 241
    frame #21: 0x00000000008b6f01 node`_start + 41
(lldb) p (void*)$rbx    
(void *) $40 = 0x6f746172656e6547
(lldb) register read
General Purpose Registers:
       rax = 0x0000000200000000
       rbx = 0x6f746172656e6547
       rcx = 0x00001aa536237800
       rdx = 0x6f746172656e6547
       rdi = 0x00001aa536356ba0
       rsi = 0x000016071b2d14b1
       rbp = 0x00007fffffff9f20
       rsp = 0x00007fffffff9ef8
        r8 = 0x000000000000494a
        r9 = 0x0000000000494a08  
       r10 = 0x0000376947b04519
       r11 = 0x00003c32ff904351
       r12 = 0x00000000000047e0
       r13 = 0x0000000002082ea8
       r14 = 0x0000000000000003
       r15 = 0x00007fffffff9ec8
       rip = 0x00001aa536356c19
    rflags = 0x0000000000010206
        cs = 0x0000000000000033
        fs = 0x0000000000000000
        gs = 0x0000000000000000
        ss = 0x000000000000002b
        ds = 0x0000000000000000
        es = 0x0000000000000000

(lldb) disassemble -s $rip-0x30 -e $rip+0x30
    0x1aa536356be9: setp   %al
    0x1aa536356bec: retq   
    0x1aa536356bed: movl   $0x1, %r10d
    0x1aa536356bf3: andq   %rax, %r10
    0x1aa536356bf6: testl  %r10d, %edx
    0x1aa536356bf9: jne    0x1aa536356c27
    0x1aa536356bff: subq   $0x1, %r10
    0x1aa536356c03: movq   %rax, %rbx
    0x1aa536356c06: xorq   %rdx, %rbx
    0x1aa536356c09: andq   %r10, %rbx
    0x1aa536356c0c: xorq   %rax, %rbx
    0x1aa536356c0f: movabsq $0x376947b04519, %r10     ; imm = 0x376947B04519 
->  0x1aa536356c19: cmpq   %r10, -0x1(%rbx)
    0x1aa536356c1d: je     0x1aa536356c48
    0x1aa536356c23: movq   %rbx, %rax
    0x1aa536356c26: retq   
    0x1aa536356c27: movq   -0x1(%rax), %rcx
    0x1aa536356c2b: cmpb   $-0x51, 0xb(%rcx)
    0x1aa536356c2f: jb     0x1aa536356c32
    0x1aa536356c31: retq   
    0x1aa536356c32: cmpb   $-0x7d, 0xb(%rcx)
    0x1aa536356c36: je     0x1aa536356c31
    0x1aa536356c38: movq   -0x1(%rdx), %rcx
    0x1aa536356c3c: cmpb   $-0x51, 0xb(%rcx)
    0x1aa536356c40: jae    0x1aa536356c31
    0x1aa536356c42: cmpb   $-0x7d, 0xb(%rcx)
    0x1aa536356c46: je     0x1aa536356c31
(lldb) v8 inspect -s 0x0000281bd49a17b1
0x0000281bd49a17b1:<function: (anonymous) at /home/user/yarn/src/cli/commands/remove.js:17:13
  context=0x0000281bd498d311{
    (previous)=0x0000281bd498cd91
    (closure)=0x0000281bd498d2c9 {<function: Object.<anonymous>.exports.run at /home/user/yarn/src/cli/commands/remove.js:1:700>},
    _ref=0x0000281bd49a1831:<function: (anonymous) at /home/user/yarn/node_modules/babel-runtime/helpers/asyncToGenerator.js:12:19>}
  source:
function (
  config,
  reporter,
  flags,
  args)
  {
    if (!args.length) {
      throw new /* istanbul ignore next */(_errors || _load_errors()).MessageError(reporter.lang('tooFewArguments', 1));
    }

    const totalSteps = args.length + 1;
    let step = 0;

    // load manifests
    const lockfile = yield (/* istanbul ignore next */(_wrapper || _load_wrapper()).default.fromDirectory(config.cwd));
    const rootManifests = yield config.getRootManifests();
    const manifests = [];

    for (const name of args) {
      reporter.step(++step, totalSteps, `Removing module ${ name }`);

      let found = false;

      for (const registryName of Object.keys( /* istanbul ignore next */(_index || _load_index()).registries)) {
        const registry = config.registries[registryName];
        const object = rootManifests[registryName].object;

        for (const type of /* istanbul ignore next */(_constants || _load_constants()).DEPENDENCY_TYPES) {
          const deps = object[type];
          if (deps && deps[name]) {
            found = true;
            delete deps[name];
          }
        }

        const possibleManifestLoc = path.join(config.cwd, registry.folder, name);
        if (yield (/* istanbul ignore next */(_fs || _load_fs()).exists(possibleManifestLoc))) {
          manifests.push([
          possibleManifestLoc,
          yield config.readManifest(possibleManifestLoc, registryName)]);

        }
      }

      if (!found) {
        throw new /* istanbul ignore next */(_errors || _load_errors()).MessageError(reporter.lang('moduleNotInManifest'));
      }
    }

    // save manifests
    yield config.saveRootManifests(rootManifests);

    // run hooks - npm runs these one after another
    for (const action of ['preuninstall', 'uninstall', 'postuninstall']) {
      for ( /* istanbul ignore next */const _ref2 of manifests) {/* istanbul ignore next */var _ref3 = (0, (_slicedToArray2 || _load_slicedToArray()).default)(_ref2, 1);const loc = _ref3[0];
        yield config.executeLifecycleScript(action, loc);
      }
    }

    // reinstall so we can get the updated lockfile
    reporter.step(++step, totalSteps, reporter.lang('uninstallRegenerate'));
    const reinstall = new /* istanbul ignore next */(_install || _load_install()).Install( /* istanbul ignore next */(0, (_extends2 || _load_extends()).default)({ force: true }, flags), config, new /* istanbul ignore next */(_index2 || _load_index2()).NoopReporter(), lockfile);
    yield reinstall.init();

    //
    reporter.success(reporter.lang('uninstalledPackages'));
  }
>

(0x376947B04519 seems to be <Map(FAST_HOLEY_ELEMENTS)>)

cpuflags:

$ grep ^flags /proc/cpuinfo |head -1
flags       : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt rdtscp lm 3dnowext 3dnow rep_good nopl extd_apicid eagerfpu pni cx16 x2apic popcnt hypervisor lahf_lm cmp_legacy cr8_legacy abm sse4a misalignsse 3dnowprefetch vmmcall arat

[indutny]

@addaleax this assembly code looks like an internal instance-of check for optimized code.

[addaleax]

Okay, so, I think I tracked things down as well as I can. Reproducing the bug was pretty easy, cloning yarn into a directory with a sufficiently long path name and running the above test suffices:

mkdir /tmp/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
cd /tmp/a* && git clone https://github.com/yarnpkg/yarn.git && cd yarn
npm install
node ./node_modules/.bin/jest -i __tests__/commands/remove.js # segfaults

The segfault always occurs reliably by dereferencing 0x6161616161616161 (aaaaaaaa). It occurs on the throw in the source generated from this line, but I’m not sure how relevant that is.

The value seems to be read from some structure from code that looks like this:

   0x00001bbee8cc8dab:  callq  0x1bbee8506340
   0x00001bbee8cc8db0:  mov    %rsi,-0x8(%rbp)
   0x00001bbee8cc8db4:  mov    0x17(%rsi),%rax
   0x00001bbee8cc8db8:  mov    0x17(%rax),%rax
   0x00001bbee8cc8dbc:  mov    0x17(%rax),%rax
=> 0x00001bbee8cc8dc0:  pushq  0xe7(%rax)
   0x00001bbee8cc8dc6:  movabs $0x200000000,%rax
   0x00001bbee8cc8dd0:  pop    %rdx
   0x00001bbee8cc8dd1:  callq  0x1bbee85377c0
   0x00001bbee8cc8dd6:  nop

Judging from that, it looks like it’s trying to access a field in a V8 FixedArray that has partially been overwritten with garbage (I’m not sure any more, but I think at least at one point that FixedArray was a v8::internal::Context). The structure at rax contains the full script name:

(gdb) p (char*) (0xbf+$rax)
$6 = 0x3d20137fc268 "/tmp/", 'a' <repeats 120 times>, "/yarn/src/cli/commands/remove.js:babel-runtime/helpers/asyncToGenerator"

I have no idea how it ended up there.

Bisecting V8, v8/v8@2fec36d seems to be the offending commit, and reverting it makes everything pass without problems.

/cc @nodejs/v8

[bnoordhuis]

I think that was fixed by commit v8/v8@c56222c.

[addaleax]

@bnoordhuis Sorry, doesn’t look like it. I did also try yesterday’s V8 master and it still crashed.

[ofrobots]

I can reproduce with the latest node+v8 lkgr integration build as well. Opened upstream bug http://crbug.com/v8/5616.

[DeShadow]

I also have strange SIGSEGV errors. But I found dependencies.

I use WebStorm.

I have code with async/await and global try/catch (it's oncetime script to execute). And when I run it without debug, I have this errors. Because I have error in my code. But my catch-block not catches errors (console.error is not executed).

But when I run code with debugging, I can caught this exception and my catch-block is executed and I can see the exception in my logs with console.error.

[ofrobots]

Merging #9640 to this issue as a duplicate. Latest update from @targos:

The fix has been merged to V8 5.5 in https://chromium.googlesource.com/v8/v8/+/c23d33089e6040047ac2491c77880e747ff73253%5E%21/
It does not apply cleanly to 5.4.

[Qantas94Heavy]

Does the update to V8 5.5 mean this issue is fixed now?

[SEAPUNK]

Might be. I'll have to check it out later.

[SEAPUNK]

I think the issue is fixed for me w/ 7.6+; if nobody else is having the issue I was having, then I think this can be closed.