parallel/test-tick-processor-unknown failures

[mhdawson]

• Version: master
• Platform: smartos [EDIT by Trott: Windows, Raspberry Pi, probably others too]
• Subsystem:test

not ok 1166 parallel/test-tick-processor-unknown
# TIMEOUT
  ---

In my last run to test a unrelated test change.

smartos - https://ci.nodejs.org/job/node-test-commit-smartos/nodes=smartos14-32/4379/console

also seemed to fail in next run that was launched as well.

[targos]

Stress test: https://ci.nodejs.org/job/node-stress-single-test/954/nodes=smartos14-32/

[jbergstroem]

ping @nodejs/platform-solaris (time to rename?) @geek

[geek]

@jbergstroem agreed on the rename

not ok 1166 parallel/test-tick-processor-unknown
# TIMEOUT
  ---
  duration_ms: 60.140

Is 60ms just too low for a timeout?

[addaleax]

Is 60ms just too low for a timeout?

It’s a terrible name but afaik duration_ms is given in seconds, and we can’t really change that name.

[imyller]

This is not limited to SmartOS:

not ok 237 parallel/test-tick-processor-unknown
# TIMEOUT
  ---
  duration_ms: 62.541

https://ci.nodejs.org/job/node-test-binary-windows/3975/RUN_SUBSET=1,VS_VERSION=vs2015,label=win2012r2/console

Could this be related to V8 5.4 beta now in master?

[Trott]

It’s a terrible name but afaik duration_ms is given in seconds

Yes, and we don't change the name from duration_ms because IIRC it's actually specified that way in TAP, believe it or not.

[Trott]

Could this be related to V8 5.4 beta now in master?

Anything's possible, but test-tick-processor (now three different test-tick-processor-* tests) is non-deterministic and has been flaky across pretty much every platform at one time or another.

/cc @matthewloring @indutny

[targos]

The stress test failed with 43/100 runs. I think all of them are because of the timeout but it's interesting to see that sometimes there is additional output:

OOM error

not ok 1 parallel/test-tick-processor-unknown
# TIMEOUT
# FATAL ERROR: invalid array length Allocation failed - JavaScript heap out of memory
#  1: node::Abort() [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
#  2: node::OnFatalError(char const*, char const*) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
#  3: v8::Utils::ReportOOMFailure(char const*, bool) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
#  4: v8::internal::V8::FatalProcessOutOfMemory(char const*, bool) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
#  5: v8::internal::Heap::AllocateUninitializedFixedArray(int) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
#  6: v8::internal::Factory::NewUninitializedFixedArray(int) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
#  7: v8::internal::(anonymous namespace)::ElementsAccessorBase<v8::internal::(anonymous namespace)::FastPackedSmiElementsAccessor, v8::internal::(anonymous namespace)::ElementsKindTraits<(v8::internal::ElementsKind)0> >::GrowCapacityAndConvertImpl(v8::internal::Handle<v8::internal::JSObject>, unsigned int) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
#  8: v8::internal::Runtime_GrowArrayElements(int, v8::internal::Object**, v8::internal::Isolate*) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
#  9: ad80a23e
# 10: 8c74511b
# 11: 8c75f591
# 12: 8c73d3bc
# 13: 8c73d0c4
# 14: 8c73cf9f
# 15: 8c74d8eb
# 16: 8c737fa4
# 17: 8c737a8e
# 18: 8c7378ae
# 19: 8c718902
# 20: 8c7189ff
# 21: ad80b6b6
# 22: 8c71496f
# 23: ad80b6b6
# 24: ad86537d
# 25: ad864baf
# 26: ad863e0e
# 27: ad86198a
# 28: ad83e83e
# 29: ad827878
# 30: v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
# 31: v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
# 32: v8::Function::Call(v8::Local<v8::Value>, int, v8::Local<v8::Value>*) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
# 33: node::LoadEnvironment(node::Environment*) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
# 34: node::StartNodeInstance(void*) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
# 35: node::Start(int, char**) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
# 36: main [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
# 37: _start [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
# FATAL ERROR: invalid array length Allocation failed - JavaScript heap out of memory
#  1: node::Abort() [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
#  2: node::OnFatalError(char const*, char const*) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
#  3: v8::Utils::ReportOOMFailure(char const*, bool) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
#  4: v8::internal::V8::FatalProcessOutOfMemory(char const*, bool) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
#  5: v8::internal::Heap::AllocateUninitializedFixedArray(int) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
#  6: v8::internal::Factory::NewUninitializedFixedArray(int) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
#  7: v8::internal::(anonymous namespace)::ElementsAccessorBase<v8::internal::(anonymous namespace)::FastPackedSmiElementsAccessor, v8::internal::(anonymous namespace)::ElementsKindTraits<(v8::internal::ElementsKind)0> >::GrowCapacityAndConvertImpl(v8::internal::Handle<v8::internal::JSObject>, unsigned int) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
#  8: v8::internal::Runtime_GrowArrayElements(int, v8::internal::Object**, v8::internal::Isolate*) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
#  9: 8260a23e
# 10: 92b426db
# 11: 92b5f9d1
# 12: 92b3d3bc
# 13: 92b3d0c4
# 14: 92b3cf9f
# 15: 92b4c58b
# 16: 92b37fa4
# 17: 92b37a8e
# 18: 92b378ae
# 19: 92b18902
# 20: 92b189ff
# 21: 8260b6b6
# 22: 92b1496f
# 23: 8260b6b6
# 24: 8266537d
# 25: 82664baf
# 26: 82663e0e
# 27: 8266198a
# 28: 8263e83e
# 29: 82627878
# 30: v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
# 31: v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
# 32: v8::Function::Call(v8::Local<v8::Value>, int, v8::Local<v8::Value>*) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
# 33: node::LoadEnvironment(node::Environment*) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
# 34: node::StartNodeInstance(void*) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
# 35: node::Start(int, char**) [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
# 36: main [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
# 37: _start [/home/iojs/build/workspace/node-stress-single-test/nodes/smartos14-32/out/Release/node]
  ---
  duration_ms: 60.140
  ...

firstLine.split is not a function

not ok 1 parallel/test-tick-processor-unknown
# TIMEOUT
# undefined:92
#   firstLine = firstLine.split(',');
#                         ^
# 
# TypeError: firstLine.split is not a function
#     at versionCheck (eval at <anonymous> (internal/v8_prof_processor.js:32:1), <anonymous>:92:25)
#     at eval (eval at <anonymous> (internal/v8_prof_processor.js:32:1), <anonymous>:69:1)
#     at eval (eval at <anonymous> (internal/v8_prof_processor.js:32:1), <anonymous>:3574:3)
#     at internal/v8_prof_processor.js:32:1
#     at NativeModule.compile (bootstrap_node.js:485:7)
#     at Function.NativeModule.require (bootstrap_node.js:426:18)
#     at startup (bootstrap_node.js:86:20)
#     at bootstrap_node.js:497:3
  ---
  duration_ms: 60.174
  ...

List of times:

Details

  duration_ms: 60.93
  duration_ms: 60.89
  duration_ms: 60.140
  duration_ms: 2.362
  duration_ms: 2.366
  duration_ms: 60.82
  duration_ms: 60.107
  duration_ms: 60.128
  duration_ms: 9.515
  duration_ms: 60.110
  duration_ms: 9.749
  duration_ms: 9.189
  duration_ms: 9.402
  duration_ms: 8.893
  duration_ms: 60.166
  duration_ms: 60.85
  duration_ms: 13.922
  duration_ms: 10.655
  duration_ms: 13.224
  duration_ms: 13.917
  duration_ms: 60.87
  duration_ms: 10.628
  duration_ms: 11.395
  duration_ms: 60.190
  duration_ms: 28.31
  duration_ms: 10.219
  duration_ms: 60.177
  duration_ms: 60.123
  duration_ms: 12.298
  duration_ms: 15.384
  duration_ms: 60.115
  duration_ms: 60.136
  duration_ms: 19.151
  duration_ms: 34.309
  duration_ms: 60.117
  duration_ms: 60.140
  duration_ms: 60.158
  duration_ms: 26.923
  duration_ms: 60.104
  duration_ms: 60.170
  duration_ms: 15.433
  duration_ms: 15.343
  duration_ms: 60.112
  duration_ms: 60.165
  duration_ms: 26.553
  duration_ms: 26.11
  duration_ms: 17.701
  duration_ms: 21.575
  duration_ms: 12.34
  duration_ms: 15.664
  duration_ms: 18.818
  duration_ms: 10.372
  duration_ms: 60.116
  duration_ms: 43.494
  duration_ms: 25.313
  duration_ms: 60.97
  duration_ms: 60.135
  duration_ms: 10.229
  duration_ms: 10.75
  duration_ms: 16.998
  duration_ms: 16.586
  duration_ms: 33.236
  duration_ms: 60.158
  duration_ms: 25.110
  duration_ms: 60.119
  duration_ms: 9.868
  duration_ms: 60.172
  duration_ms: 60.113
  duration_ms: 23.27
  duration_ms: 60.108
  duration_ms: 60.147
  duration_ms: 60.142
  duration_ms: 60.171
  duration_ms: 15.103
  duration_ms: 17.712
  duration_ms: 17.618
  duration_ms: 60.165
  duration_ms: 9.793
  duration_ms: 14.5
  duration_ms: 20.811
  duration_ms: 60.101
  duration_ms: 17.34
  duration_ms: 60.98
  duration_ms: 41.845
  duration_ms: 28.982
  duration_ms: 60.124
  duration_ms: 60.151
  duration_ms: 60.94
  duration_ms: 60.131
  duration_ms: 17.684
  duration_ms: 39.495
  duration_ms: 23.895
  duration_ms: 11.651
  duration_ms: 20.881
  duration_ms: 60.168
  duration_ms: 27.426
  duration_ms: 60.166
  duration_ms: 36.347
  duration_ms: 60.174
  duration_ms: 22.403

[Trott]

Another failure on Windows too: https://ci.nodejs.org/job/node-test-binary-windows/3983/RUN_SUBSET=1,VS_VERSION=vs2015,label=win2012r2/console:

not ok 237 parallel/test-tick-processor-unknown
# TIMEOUT

Any objection to removing the SmartOS/Solaris specificity on this issue? Or would people prefer we have a separate issue for Windows? I could go either way, as there might or might not be a common cause for the failures on the different platforms.
¯_(ツ)_/¯

[Trott]

Any chance that we're only seeing these timeouts on single-processor machines?

EDIT: Answer: Nope.

[geek]

@Trott go for updating the title

test.py supports overriding the timeout. Should we adjust the timeout for our 32-bit builds?

Current:

/opt/local/bin/python2.7 tools/test.py -j 4 -p tap --logfile test.tap \
    --mode=release --flaky-tests=dontcare \
     addons doctool inspector known_issues message parallel pseudo-tty sequential

Suggested:

/opt/local/bin/python2.7 tools/test.py -j 4 -p tap --logfile test.tap \
    --timeout=120 \
    --mode=release --flaky-tests=dontcare \
     addons doctool inspector known_issues message parallel pseudo-tty sequential