Hanging/crashing tests

[mikemorris]

Reproducing this locally on OS X but not seeing it on Travis.

Render test 1-0-1 hangs with HTTPRequest errors attempting to load tiles 1-1-1.vector.pbf, 1-1-0.vector.pbf and 1-0-0.vector.pbf.

Render tests 3-2-3@2x and 4-4-6@2x crash with Abort trap 6 but only when running multiple tests through the tape binary, not when running node test/render.test.js. Captured backtrace by running lldb node ./node_modules/.bin/tape test/*.test.js.

#4-4-6@2x
ok 28 null
Process 12348 stopped
* thread #106: tid = 0x1fa9bb, 0x00007fff863e1286 libsystem_kernel.dylib`__pthread_kill + 10, name = 'Worker', stop reason = signal SIGABRT
    frame #0: 0x00007fff863e1286 libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
->  0x7fff863e1286 <+10>: jae    0x7fff863e1290            ; <+20>
    0x7fff863e1288 <+12>: movq   %rax, %rdi
    0x7fff863e128b <+15>: jmp    0x7fff863dcc53            ; cerror_nocancel
    0x7fff863e1290 <+20>: retq
(lldb) bt
* thread #106: tid = 0x1fa9bb, 0x00007fff863e1286 libsystem_kernel.dylib`__pthread_kill + 10, name = 'Worker', stop reason = signal SIGABRT
  * frame #0: 0x00007fff863e1286 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff8cada42f libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x00007fff8b60db53 libsystem_c.dylib`abort + 129
    frame #3: 0x000000010044258b node`uv__loop_init + 552
    frame #4: 0x000000010043f34a node`uv_loop_new + 36
    frame #5: 0x00000001034c4bc1 mapbox-gl-native.node`mbgl::util::Thread<mbgl::Worker::Impl>::Thread<>(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, mbgl::util::ThreadPriority)::'lambda'()::operator()() const [inlined] uv::loop::loop() + 5 at uv_detail.hpp:35
    frame #6: 0x00000001034c4bbc mapbox-gl-native.node`mbgl::util::Thread<mbgl::Worker::Impl>::Thread<>(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, mbgl::util::ThreadPriority)::'lambda'()::operator()() const [inlined] uv::loop::loop() at uv_detail.hpp:43
    frame #7: 0x00000001034c4bbc mapbox-gl-native.node`mbgl::util::Thread<mbgl::Worker::Impl>::Thread<>(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, mbgl::util::ThreadPriority)::'lambda'()::operator()() const [inlined] void mbgl::util::Thread<mbgl::Worker::Impl>::run<std::__1::tuple<> >(std::__1::tuple<>&&, (anonymous namespace)::index_sequence<>) at thread.hpp:132
    frame #8: 0x00000001034c4bbc mapbox-gl-native.node`mbgl::util::Thread<mbgl::Worker::Impl>::Thread<>(this=<unavailable>)::'lambda'()::operator()() const + 76 at thread.hpp:123
    frame #9: 0x00000001034c4b23 mapbox-gl-native.node`std::__1::__thread_proxy<std::__1::tuple<mbgl::util::Thread<mbgl::Worker::Impl>::Thread<>(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, mbgl::util::ThreadPriority)::'lambda'()> >(void*, void*) [inlined] std::__1::__invoke<mbgl::util::Thread<mbgl::Worker::Impl>::Thread<>(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, mbgl::util::ThreadPriority)::'lambda'()>(__f=<unavailable>)::'lambda'()>(fp)(std::__1::forward<>(fp0))), mbgl::util::Thread<mbgl::Worker::Impl>::Thread<>(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, mbgl::util::ThreadPriority)::'lambda'()&&) + 99 at __functional_base:413
    frame #10: 0x00000001034c4b1b mapbox-gl-native.node`std::__1::__thread_proxy<std::__1::tuple<mbgl::util::Thread<mbgl::Worker::Impl>::Thread<>(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, mbgl::util::ThreadPriority)::'lambda'()> >(void*, void*) [inlined] _ZNSt3__116__thread_executeIZN4mbgl4util6ThreadINS1_6Worker4ImplEEC1IJEEERKNS_12basic_stringIcNS_11char_traitsIcEENS_9allocatorIcEEEENS2_14ThreadPriorityEDpOT_EUlvE_JEJEEEvRNS_5tupleIJT_DpT0_EEENS_15__tuple_indicesIJXspT1_EEEE at thread:332
    frame #11: 0x00000001034c4b1b mapbox-gl-native.node`std::__1::__thread_proxy<std::__1::tuple<mbgl::util::Thread<mbgl::Worker::Impl>::Thread<>(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, mbgl::util::ThreadPriority)::'lambda'()> >(__vp=0x0000000100d86090) + 91 at thread:342
    frame #12: 0x00007fff8cad8268 libsystem_pthread.dylib`_pthread_body + 131
    frame #13: 0x00007fff8cad81e5 libsystem_pthread.dylib`_pthread_start + 176
    frame #14: 0x00007fff8cad641d libsystem_pthread.dylib`thread_start + 13

[mikemorris]

I believe this stems from a bug in C++ tile loading code, where it does not properly handle missing or corrupt tiles. Possibly same underlying issue as https://github.com/mapbox/node-mapbox-gl-native/issues/114. This is currently blocking a new release of tilelive-gl.

/cc @tmpsantos @jfirebaugh

[mikemorris]

Backtrace looks similar enough to https://github.com/mapbox/node-mapbox-gl-native/issues/122 that the crashes (not hangs) I was seeing here could possibly be possibly be caused by that bug.

[mikemorris]

In case of a tile fails to load, it will go back to the invalid state which will cause a re-request of the tile. If the tile is corrupt on the server or if the server is down, etc it will cause an endless cycle of re-requests.

mapbox/mapbox-gl-native#1565

[tmpsantos]

@mikemorris have you observed this re-requesting cycle? This should be easy to sniff on the network.

[mikemorris]

@tmpsantos Hmm, nope, not seeing any re-requests actually. Adding URL logging to the FileSource request method and emitting errors from NodeLogObserver I'm seeing this:

# 1-0-1
ok 19 null
./fixtures/tiles.tilejson
./fixtures/tiles/1-1-1.vector.pbf
./fixtures/tiles/1-0-1.vector.pbf
./fixtures/tiles/1-1-0.vector.pbf
./fixtures/tiles/1-0-0.vector.pbf
{ class: 'HttpRequest',
  severity: 'ERROR',
  text: '[./fixtures/tiles/1-1-1.vector.pbf] tile loading failed: Error: ENOENT, open \'/Users/mikemorris/gyp/tilelive-gl/test/fixtures/tiles/1-1-1.vector.pbf\'',
  environment: 6,
  threadName: 'Map' }
{ class: 'HttpRequest',
  severity: 'ERROR',
  text: '[./fixtures/tiles/1-1-0.vector.pbf] tile loading failed: Error: ENOENT, open \'/Users/mikemorris/gyp/tilelive-gl/test/fixtures/tiles/1-1-0.vector.pbf\'',
  environment: 6,
  threadName: 'Map' }
{ class: 'HttpRequest',
  severity: 'ERROR',
  text: '[./fixtures/tiles/1-0-0.vector.pbf] tile loading failed: Error: ENOENT, open \'/Users/mikemorris/gyp/tilelive-gl/test/fixtures/tiles/1-0-0.vector.pbf\'',
  environment: 6,
  threadName: 'Map' }

Haven't checked if this behavior would be different over HTTP. Seeing the same pattern against a local HTTP server.