search

dart-lang / sdk

The Dart SDK, including the VM, JS and Wasm compilers, analysis, core libraries, and more.
https://dart.dev
BSD 3-Clause "New" or "Revised" License
10.21k stars 1.57k forks source link

Flaky timeout on standalone/io/raw_secure_server_socket_test #28046

Open mkustermann opened 7 years ago

mkustermann commented 7 years ago

From buildbot failure:

FAILED: none-vm debug_ia32 standalone/io/raw_secure_server_socket_test
Expected: Pass 
Actual: Timeout
CommandOutput[vm]:
diagnostics: PID 10767 - process
    TID 10767:
    #0  0xf7708440 __kernel_vsyscall
    #1  0xf76d8d0b pthread_cond_wait@@GLIBC_2.3.2
    #2  0x085b623e dart::Monitor::WaitMicros(long long)
    #3  0x085b6526 dart::Monitor::Wait(long long)
    #4  0x082b7e0a Dart_RunLoop
    #5  0x0815b3c6 dart::bin::RunMainIsolate(char const*, dart::bin::CommandLineOptions*)
    #6  0x0815c34e dart::bin::main(int, char**)
    #7  0x0815c575 main
    #8  0xf73e3af3 __libc_start_main
    #9  0x08158261 _start
    TID 10769:
    #0  0xf7708440 __kernel_vsyscall
    #1  0xf74b6a36 epoll_wait
    #2  0x0816124a dart::bin::EventHandlerImplementation::Poll(unsigned int)
    #3  0x0818e4a4 dart::bin::ThreadStart(void*)
    #4  0xf76d4f72 start_thread
    #5  0xf74b5f8e __clone
    TID 10770:
    #0  0xf7708440 __kernel_vsyscall
    #1  0xf76d8d0b pthread_cond_wait@@GLIBC_2.3.2
    #2  0x085b623e dart::Monitor::WaitMicros(long long)
    #3  0x0871f324 dart::ThreadInterrupter::ThreadMain(unsigned int)
    #4  0x085b4b99 dart::ThreadStart(void*)
    #5  0xf76d4f72 start_thread
    #6  0xf74b5f8e __clone
    TID 10774:
    #0  0xf7708440 __kernel_vsyscall
    #1  0xf76d8d0b pthread_cond_wait@@GLIBC_2.3.2
    #2  0x085b623e dart::Monitor::WaitMicros(long long)
    #3  0x085b6526 dart::Monitor::Wait(long long)
    #4  0x0832db00 dart::BackgroundCompiler::Run()
    #5  0x087220a3 dart::ThreadPool::Worker::Loop()
    #6  0x087226fe dart::ThreadPool::Worker::Main(unsigned int)
    #7  0x085b4b99 dart::ThreadStart(void*)
    #8  0xf76d4f72 start_thread
    #9  0xf74b5f8e __clone
    TID 10798:
    #0  0xf7708440 __kernel_vsyscall
    #1  0xf76d8d0b pthread_cond_wait@@GLIBC_2.3.2
    #2  0x085b623e dart::Monitor::WaitMicros(long long)
    #3  0x085b6526 dart::Monitor::Wait(long long)
    #4  0x0832db00 dart::BackgroundCompiler::Run()
    #5  0x087220a3 dart::ThreadPool::Worker::Loop()
    #6  0x087226fe dart::ThreadPool::Worker::Main(unsigned int)
    #7  0x085b4b99 dart::ThreadStart(void*)
    #8  0xf76d4f72 start_thread
    #9  0xf74b5f8e __clone

    eu-stack: dwfl_thread_getframes tid 10767 at 0x8158260 in /mnt/data/b/build/slave/vm-linux-debug-ia32-be/build/sdk/out/DebugIA32/dart: no matching address range

stdout:
unittest-suite-wait-for-done
unittest-suite-success

Command[vm]: DART_CONFIGURATION=DebugIA32 out/DebugIA32/dart --short_socket_read --ignore-unrecognized-flags --packages=/mnt/data/b/build/slave/vm-linux-debug-ia32-be/build/sdk/.packages /mnt/data/b/build/slave/vm-linux-debug-ia32-be/build/sdk/tests/standalone/io/raw_secure_server_socket_test.dart
Took 0:02:00.043436

Short reproduction command (experimental):
    python tools/test.py -aia32 -t120 standalone/io/raw_secure_server_socket_test

@fsc8000 Maybe you would like to take a look this time?

fsc8000 commented 7 years ago

I could not reproduce this one locally, but saw a similar timeout on my machine with another test:

FAILED: none-vm debug_ia32 standalone/io/socket_close_test
Expected: Pass 
Actual: Timeout
CommandOutput[vm]:
diagnostics: PID 1396 - process
    TID 1396:
    #0  0xf7753440 __kernel_vsyscall
    #1  0xf771bd0b pthread_cond_wait@@GLIBC_2.3.2
    #2  0x08523583 dart::Monitor::WaitMicros(long long)
    #3  0x08201238 Dart_RunLoop
    #4  0x081d0a17 dart::bin::RunMainIsolate(char const*, dart::bin::CommandLineOptions*)
    #5  0x081c7efc dart::bin::main(int, char**)
    #6  0x081c82fb main
    #7  0xf7421af3 __libc_start_main
    #8  0x081ce4a2 _start
    TID 1397:
    #0  0xf7753440 __kernel_vsyscall
    #1  0xf74f4a36 epoll_wait
    #2  0x0821cfbf dart::bin::EventHandlerImplementation::Poll(unsigned int)
    #3  0x0821839d dart::bin::ThreadStart(void*)
    #4  0xf7717f72 start_thread
    #5  0xf74f3f8e __clone
    TID 1400:
    #0  0xf7753440 __kernel_vsyscall
    #1  0xf771bd0b pthread_cond_wait@@GLIBC_2.3.2
    #2  0x08523583 dart::Monitor::WaitMicros(long long)
    #3  0x0867f9f5 dart::ThreadInterrupter::ThreadMain(unsigned int)
    #4  0x08521e85 dart::ThreadStart(void*)
    #5  0xf7717f72 start_thread
    #6  0xf74f3f8e __clone
    TID 1419:
    #0  0xf7753440 __kernel_vsyscall
    #1  0xf771bd0b pthread_cond_wait@@GLIBC_2.3.2
    #2  0x08523583 dart::Monitor::WaitMicros(long long)
    #3  0x082b4f90 dart::BackgroundCompiler::Run()
    #4  0x086827e0 dart::ThreadPool::Worker::Loop()
    #5  0x08682dbb dart::ThreadPool::Worker::Main(unsigned int)
    #6  0x08521e85 dart::ThreadStart(void*)
    #7  0xf7717f72 start_thread
    #8  0xf74f3f8e __clone
    TID 1888:
    #0  0xf7753440 __kernel_vsyscall
    #1  0xf771bd0b pthread_cond_wait@@GLIBC_2.3.2
    #2  0x08523583 dart::Monitor::WaitMicros(long long)
    #3  0x082b4f90 dart::BackgroundCompiler::Run()
    #4  0x086827e0 dart::ThreadPool::Worker::Loop()
    #5  0x08682dbb dart::ThreadPool::Worker::Main(unsigned int)
    #6  0x08521e85 dart::ThreadStart(void*)
    #7  0xf7717f72 start_thread
    #8  0xf74f3f8e __clone

    eu-stack: dwfl_thread_getframes tid 1396 at 0x81ce4a1 in /usr/local/google/home/fschneider/dartgit2/sdk/out/DebugIA32/dart: no matching address range

stdout:
unittest-suite-wait-for-done

Command[vm]: DART_CONFIGURATION=DebugIA32 out/DebugIA32/dart --short_socket_write --ignore-unrecognized-flags --packages=.packages tests/standalone/io/socket_close_test.dart
Took 0:02:00.038066

Short reproduction command (experimental):
    python tools/test.py -aia32 -t120 standalone/io/socket_close_test
mkustermann commented 7 years ago

I wonder whether this is some kind of deadlock where the eventhandler forgot to send a close event to dart and the dart side therefore didn't close the last ReceivePort or something like that.

With a reproduction we could investigate the running process (e.g. if there are still sockets, timers open ...).

fsc8000 commented 7 years ago

I suspect it is an issue with an unbalanced asyncStart/asyncEnd in the test code. I found one instance of this problem in another test already.

floitschG commented 7 years ago

I suggest adding debugging information to the test, to make it easier to figure out what test (and why) is failing. https://codereview.chromium.org/2571603004

jensjoha commented 7 years ago

Similar stacktrace today for another http test:

FAILED: none-vm-checked release_x64 standalone/io/http_basic_test
Expected: Pass Slow 
Actual: Timeout
CommandOutput[vm]:
diagnostics: PID 10496 - process
    TID 10496:
    #0  0x00007f6e1812c404 pthread_cond_wait@@GLIBC_2.3.2
    #1  0x0000000000872995 dart::Monitor::WaitMicros(long)
    #2  0x00000000006527ea Dart_RunLoop
    #3  0x0000000000522db3 dart::bin::RunMainIsolate(char const*, dart::bin::CommandLineOptions*)
    #4  0x00000000005242ea dart::bin::main(int, char**)
    #5  0x0000000000524a89 main
    #6  0x00007f6e17354f45 __libc_start_main
    #7  0x0000000000522717 _start
    TID 10498:
    #0  0x00007f6e1742da13 epoll_wait
    #1  0x0000000000527555 dart::bin::EventHandlerImplementation::Poll(unsigned long)
    #2  0x000000000054286e dart::bin::ThreadStart(void*)
    #3  0x00007f6e18128184 start_thread
    #4  0x00007f6e1742d37d __clone
    TID 10500:
    #0  0x00007f6e1812c7be pthread_cond_timedwait@@GLIBC_2.3.2
    #1  0x000000000087297f dart::Monitor::WaitMicros(long)
    #2  0x000000000097f4a3 dart::ThreadInterrupter::ThreadMain(unsigned long)
    #3  0x00000000008720c9 dart::ThreadStart(void*)
    #4  0x00007f6e18128184 start_thread
    #5  0x00007f6e1742d37d __clone
    TID 10505:
    #0  0x00007f6e1812c404 pthread_cond_wait@@GLIBC_2.3.2
    #1  0x0000000000872995 dart::Monitor::WaitMicros(long)
    #2  0x00000000006b995a dart::BackgroundCompiler::Run()
    #3  0x000000000098016d dart::ThreadPool::Worker::Loop()
    #4  0x0000000000980038 dart::ThreadPool::Worker::Main(unsigned long)
    #5  0x00000000008720c9 dart::ThreadStart(void*)
    #6  0x00007f6e18128184 start_thread
    #7  0x00007f6e1742d37d __clone
    TID 10509:
    #0  0x00007f6e1812c404 pthread_cond_wait@@GLIBC_2.3.2
    #1  0x0000000000872995 dart::Monitor::WaitMicros(long)
    #2  0x00000000006b995a dart::BackgroundCompiler::Run()
    #3  0x000000000098016d dart::ThreadPool::Worker::Loop()
    #4  0x0000000000980038 dart::ThreadPool::Worker::Main(unsigned long)
    #5  0x00000000008720c9 dart::ThreadStart(void*)
    #6  0x00007f6e18128184 start_thread
    #7  0x00007f6e1742d37d __clone
    TID 10538:
    #0  0x00000000009c4ed1 dart::DRT_FixCallersTarget(dart::NativeArguments)
    #1  0x00007f6e185c361b
    TID 10550:
    #0  0x00007f6e1812c404 pthread_cond_wait@@GLIBC_2.3.2
    #1  0x0000000000872995 dart::Monitor::WaitMicros(long)
    #2  0x00000000006b995a dart::BackgroundCompiler::Run()
    #3  0x000000000098016d dart::ThreadPool::Worker::Loop()
    #4  0x0000000000980038 dart::ThreadPool::Worker::Main(unsigned long)
    #5  0x00000000008720c9 dart::ThreadStart(void*)
    #6  0x00007f6e18128184 start_thread
    #7  0x00007f6e1742d37d __clone

    eu-stack: dwfl_thread_getframes tid 10538 at 0x7f6e185c361a in /lib/x86_64-linux-gnu/ld-2.19.so: no matching address range

Command[vm]: DART_CONFIGURATION=ReleaseX64 out/ReleaseX64/dart --enable_asserts --enable_type_checks --trace_shutdown --short_socket_write --optimization-counter-threshold=5 --ignore-unrecognized-flags --packages=/mnt/data/b/build/slave/vm-linux-release-x64-optcounter-threshold-be/build/sdk/.packages /mnt/data/b/build/slave/vm-linux-release-x64-optcounter-threshold-be/build/sdk/tests/standalone/io/http_basic_test.dart
Took 0:04:00.082780

Short reproduction command (experimental):
    python tools/test.py -mrelease --checked -t60 --vm-options --optimization-counter-threshold=5 standalone/io/http_basic_test

Done none-vm-checked release_x64 standalone/io/http_basic_test: fail
mhausner commented 7 years ago

Another test with similar flakiness: http_launch_test

FAILED: none-vm release_x64 standalone/http_launch_test
Expected: Pass 
Actual: Timeout
CommandOutput[vm]:
diagnostics: PID 8072 - process
    TID 8072:
    #0  0x00007f229c7b6404 pthread_cond_wait@@GLIBC_2.3.2
    #1  0x0000000000872685 dart::Monitor::WaitMicros(long)
    #2  0x00000000006528aa Dart_RunLoop
    #3  0x0000000000522ef3 dart::bin::RunMainIsolate(char const*, dart::bin::CommandLineOptions*)
    #4  0x0000000000524368 dart::bin::main(int, char**)
    #5  0x0000000000524b29 main
    #6  0x00007f229b9def45 __libc_start_main
    #7  0x0000000000522857 _start
    TID 8075:
    #0  0x00007f229bab7a13 epoll_wait
    #1  0x00000000005275f5 dart::bin::EventHandlerImplementation::Poll(unsigned long)
    #2  0x000000000054290e dart::bin::ThreadStart(void*)
    #3  0x00007f229c7b2184 start_thread
    #4  0x00007f229bab737d __clone
    TID 8076:
    #0  0x00007f229c7b67be pthread_cond_timedwait@@GLIBC_2.3.2
    #1  0x000000000087266f dart::Monitor::WaitMicros(long)
    #2  0x0000000000980783 dart::ThreadInterrupter::ThreadMain(unsigned long)
    #3  0x0000000000871db9 dart::ThreadStart(void*)
    #4  0x00007f229c7b2184 start_thread
    #5  0x00007f229bab737d __clone
    TID 8083:
    #0  0x00007f229c7b6404 pthread_cond_wait@@GLIBC_2.3.2
    #1  0x0000000000872685 dart::Monitor::WaitMicros(long)
    #2  0x00000000006b9a1a dart::BackgroundCompiler::Run()
    #3  0x000000000098144d dart::ThreadPool::Worker::Loop()
    #4  0x0000000000981318 dart::ThreadPool::Worker::Main(unsigned long)
    #5  0x0000000000871db9 dart::ThreadStart(void*)
    #6  0x00007f229c7b2184 start_thread
    #7  0x00007f229bab737d __clone
    TID 8085:
    #0  0x00007f229c7b6404 pthread_cond_wait@@GLIBC_2.3.2
    #1  0x0000000000872685 dart::Monitor::WaitMicros(long)
    #2  0x00000000006b9a1a dart::BackgroundCompiler::Run()
    #3  0x000000000098144d dart::ThreadPool::Worker::Loop()
    #4  0x0000000000981318 dart::ThreadPool::Worker::Main(unsigned long)
    #5  0x0000000000871db9 dart::ThreadStart(void*)
    #6  0x00007f229c7b2184 start_thread
    #7  0x00007f229bab737d __clone
    TID 8088:
    #0  0x00000000009c6068 dart::DRT_FixCallersTarget(dart::NativeArguments)
    #1  0x00007f229cc4d61b
    TID 8149:
    #0  0x00007f229c7b9e44 wait
    #1  0x000000000052d4e8 dart::bin::ExitCodeHandler::ExitCodeHandlerEntry(unsigned long)
    #2  0x000000000054290e dart::bin::ThreadStart(void*)
    #3  0x00007f229c7b2184 start_thread
    #4  0x00007f229bab737d __clone

    eu-stack: dwfl_thread_getframes tid 8088 at 0x7f229cc4d61a in /lib/x86_64-linux-gnu/ld-2.19.so: no matching address range

Command[vm]: DART_CONFIGURATION=ReleaseX64 out/ReleaseX64/dart --short_socket_read --short_socket_write --optimization-counter-threshold=5 --ignore-unrecognized-flags --packages=/mnt/data/b/build/slave/vm-linux-release-x64-optcounter-threshold-be/build/sdk/.packages /mnt/data/b/build/slave/vm-linux-release-x64-optcounter-threshold-be/build/sdk/tests/standalone/http_launch_test.dart
Took 0:01:00.128945
mhausner commented 7 years ago

http tests also time out on other platforms, e.g. Windows. If there is a race condition, it's likely in code that is not platform-specific.

mraleph commented 6 years ago

This issue has been last updated 279 days ago. Please consider investigating whether it is still meaningful and if not close it. If the issue is still meaningful please find a relevant owner. Thank you.

dcharkes commented 5 years ago

Yes, this is still an issue (trybot log):

FAILED: dartk-vm release_x64 standalone_2/io/http_bind_test
Expected: Pass
Actual: Timeout

--- Command "vm" (took 02:00.000438s):
DART_CONFIGURATION=ReleaseX64 out/ReleaseX64/dart --hot-reload-test-mode --sync-async --ignore-unrecognized-flags --packages=/b/s/w/ir/.packages /b/s/w/ir/tests/standalone_2/io/http_bind_test.dart

exit code:
-15

diagnostics:
Process list including children: [6396]
Trying to capture stack trace for pid 6396
PID 6396 - process
TID 6396:
#0  0x00007f4ea61a8404 pthread_cond_wait@@GLIBC_2.3.2
#1  0x000055f7b445b858 dart::Monitor::WaitMicros(long)
#2  0x000055f7b466599a Dart_RunLoop
#3  0x000055f7b4128d9d dart::bin::RunMainIsolate(char const*, dart::bin::CommandLineOptions*)
#4  0x000055f7b41298b7 dart::bin::main(int, char**)
#5  0x000055f7b412a169 main
#6  0x00007f4ea58e6f45 __libc_start_main
#7  0x000055f7b4128029 _start
TID 6397:
#0  0x00007f4ea59c36d3 epoll_wait
#1  0x000055f7b4131055 dart::bin::EventHandlerImplementation::Poll(unsigned long)
#2  0x000055f7b415082e dart::bin::ThreadStart(void*)
#3  0x00007f4ea61a4184 start_thread
#4  0x00007f4ea59c303d __clone
TID 6399:
#0  0x00007f4ea61a8404 pthread_cond_wait@@GLIBC_2.3.2
#1  0x000055f7b445b858 dart::Monitor::WaitMicros(long)
#2  0x000055f7b46316fa dart::BackgroundCompiler::Run()
#3  0x000055f7b44f8227 dart::ThreadPool::Worker::Loop()
#4  0x000055f7b44f80b3 dart::ThreadPool::Worker::Main(unsigned long)
#5  0x000055f7b445b149 dart::ThreadStart(void*)
#6  0x00007f4ea61a4184 start_thread
#7  0x00007f4ea59c303d __clone
TID 6404:
#0  0x00007f4ea61a8404 pthread_cond_wait@@GLIBC_2.3.2
#1  0x000055f7b445b858 dart::Monitor::WaitMicros(long)
#2  0x000055f7b46316fa dart::BackgroundCompiler::Run()
#3  0x000055f7b44f8227 dart::ThreadPool::Worker::Loop()
#4  0x000055f7b44f80b3 dart::ThreadPool::Worker::Main(unsigned long)
#5  0x000055f7b445b149 dart::ThreadStart(void*)
#6  0x00007f4ea61a4184 start_thread
#7  0x00007f4ea59c303d __clone

stdout:
unittest-suite-wait-for-done

--- Re-run this test:
python tools/test.py -m release -n dartk-reload-linux-release-x64 standalone_2/io/http_bind_test