Bug in tests using lib-uv
Closed this issue · 13 comments
When running the test suite of event-store-client
I'm always getting this segfault, but not always on the same test case and if the test case is tested seperately it's green. So I cannot reproduce a single failing test, but only that the test suite itself somehow fails to pass the tests.
php: src/unix/core.c:925: uv__io_stop: Assertion `loop->watchers[w->fd] == w' failed.
[1] 8509 abort (core dumped) ./vendor/bin/phpunit --exclude=ignore --testdox
./vendor/bin/phpunit --exclude=ignore --testdox 8,90s user 1,21s system 23% cpu 42,284 total
Given what I could find about this on google, libuv source code (f.e. libuv/libuv#2387), I have no idea where this can come from. For each test case I create a new event store connection via TCP protocol using \Amp\Socket\connect. As logger (another source where something could read / write) a NullLogger is used during the tests.
Maybe it is also related to #49 ?
Do you have any idea where I can look at?
System: Ubuntu 19.10
PHP: 7.4.2
uv: libuv1/eoan,now 1.30.1-1 amd64 [installed,automatic] (via Ubuntu's apt)
see also prooph/event-store-client#75
GDB backtrace:
#0 0x00007fdca2a293eb in raise () from /usr/lib/x86_64-linux-gnu/libc.so.6
(gdb) bt
#0 0x00007fdca2a293eb in raise () from /usr/lib/x86_64-linux-gnu/libc.so.6
#1 0x00007fdca2a08899 in abort () from /usr/lib/x86_64-linux-gnu/libc.so.6
#2 0x00007fdca2a08769 in ?? () from /usr/lib/x86_64-linux-gnu/libc.so.6
#3 0x00007fdca2a1a006 in __assert_fail () from /usr/lib/x86_64-linux-gnu/libc.so.6
#4 0x00007fdca0010319 in uv.io_stop () from /lib/x86_64-linux-gnu/libuv.so.1
#5 0x00007fdca00166a6 in ?? () from /lib/x86_64-linux-gnu/libuv.so.1
#6 0x00007fdca000f205 in uv_close () from /lib/x86_64-linux-gnu/libuv.so.1
#7 0x00007fdca004bb7e in php_uv_close (uv=0x7fdc9dcdf800) at /tmp/pear/temp/uv/php_uv.c:2115
#8 0x00007fdca004989e in destruct_uv (obj=0x7fdc9dcdf800) at /tmp/pear/temp/uv/php_uv.c:1273
#9 0x00005603aabd015e in zend_objects_store_del (object=0x7fdc9dcdf800) at /home/sasa/Downloads/php-7.4.2/Zend/zend_objects_API.c:178
#10 0x00005603aab7348f in rc_dtor_func (p=0x7fdc9dcdf800) at /home/sasa/Downloads/php-7.4.2/Zend/zend_variables.c:57
#11 0x00005603aab8ac0b in i_zval_ptr_dtor (zval_ptr=0x7fdc9d339e88) at /home/sasa/Downloads/php-7.4.2/Zend/zend_variables.h:44
#12 0x00005603aab8ffdc in zend_array_destroy (ht=0x7fdc9de57780) at /home/sasa/Downloads/php-7.4.2/Zend/zend_hash.c:1611
#13 0x00005603aab7348f in rc_dtor_func (p=0x7fdc9de57780) at /home/sasa/Downloads/php-7.4.2/Zend/zend_variables.c:57
#14 0x00005603aab8ac0b in i_zval_ptr_dtor (zval_ptr=0x7fdc9ca1c9a0) at /home/sasa/Downloads/php-7.4.2/Zend/zend_variables.h:44
#15 0x00005603aab8ffdc in zend_array_destroy (ht=0x7fdc9d206c60) at /home/sasa/Downloads/php-7.4.2/Zend/zend_hash.c:1611
#16 0x00005603aab7348f in rc_dtor_func (p=0x7fdc9d206c60) at /home/sasa/Downloads/php-7.4.2/Zend/zend_variables.c:57
#17 0x00005603aab8ac0b in i_zval_ptr_dtor (zval_ptr=0x7fdc9d589a48) at /home/sasa/Downloads/php-7.4.2/Zend/zend_variables.h:44
#18 0x00005603aab8ffdc in zend_array_destroy (ht=0x7fdc9d5d8a20) at /home/sasa/Downloads/php-7.4.2/Zend/zend_hash.c:1611
#19 0x00005603aab7348f in rc_dtor_func (p=0x7fdc9d5d8a20) at /home/sasa/Downloads/php-7.4.2/Zend/zend_variables.c:57
#20 0x00005603aabc83c5 in i_zval_ptr_dtor (zval_ptr=0x7fdc9cf34df8) at /home/sasa/Downloads/php-7.4.2/Zend/zend_variables.h:44
#21 0x00005603aabc87d5 in zend_object_std_dtor (object=0x7fdc9cf34d80) at /home/sasa/Downloads/php-7.4.2/Zend/zend_objects.c:70
#22 0x00005603aabd0275 in zend_objects_store_del (object=0x7fdc9cf34d80) at /home/sasa/Downloads/php-7.4.2/Zend/zend_objects_API.c:193
#23 0x00005603aab7348f in rc_dtor_func (p=0x7fdc9cf34d80) at /home/sasa/Downloads/php-7.4.2/Zend/zend_variables.c:57
#24 0x00005603aabc83c5 in i_zval_ptr_dtor (zval_ptr=0x7fdc9d567028) at /home/sasa/Downloads/php-7.4.2/Zend/zend_variables.h:44
#25 0x00005603aabc87d5 in zend_object_std_dtor (object=0x7fdc9d567000) at /home/sasa/Downloads/php-7.4.2/Zend/zend_objects.c:70
#26 0x00005603aabd0275 in zend_objects_store_del (object=0x7fdc9d567000) at /home/sasa/Downloads/php-7.4.2/Zend/zend_objects_API.c:193
#27 0x00005603aab7348f in rc_dtor_func (p=0x7fdc9d567000) at /home/sasa/Downloads/php-7.4.2/Zend/zend_variables.c:57
#28 0x00005603aabdc476 in zend_assign_to_variable (variable_ptr=0x7fdc9d95c038, value=0x7fdc9edef150, value_type=1 '\001', strict=0 '\000')
at /home/sasa/Downloads/php-7.4.2/Zend/zend_execute.h:131
#29 0x00005603aac2d791 in ZEND_ASSIGN_OBJ_SPEC_UNUSED_CONST_OP_DATA_CONST_HANDLER () at /home/sasa/Downloads/php-7.4.2/Zend/zend_vm_execute.h:31086
#30 0x00005603aac55cae in execute_ex (ex=0x7fdc9fe182c0) at /home/sasa/Downloads/php-7.4.2/Zend/zend_vm_execute.h:56487
#31 0x00005603aab5e3ff in zend_call_function (fci=0x7ffe24d72b10, fci_cache=0x7ffe24d72af0) at /home/sasa/Downloads/php-7.4.2/Zend/zend_execute_API.c:811
#32 0x00005603aabc8bf6 in zend_objects_destroy_object (object=0x7fdc9d95c000) at /home/sasa/Downloads/php-7.4.2/Zend/zend_objects.c:179
#33 0x00005603aabb2a66 in zend_gc_collect_cycles () at /home/sasa/Downloads/php-7.4.2/Zend/zend_gc.c:1537
#34 0x00005603aabb04a3 in gc_possible_root_when_full (ref=0x7fdc9d42a668) at /home/sasa/Downloads/php-7.4.2/Zend/zend_gc.c:592
#35 0x00005603aabb062c in gc_possible_root (ref=0x7fdc9d42a668) at /home/sasa/Downloads/php-7.4.2/Zend/zend_gc.c:642
#36 0x00005603aabdbf60 in zend_object_release (obj=0x7fdc9d42a668) at /home/sasa/Downloads/php-7.4.2/Zend/zend_objects_API.h:77
#37 0x00005603aabecdd3 in ZEND_DO_FCALL_SPEC_RETVAL_USED_HANDLER () at /home/sasa/Downloads/php-7.4.2/Zend/zend_vm_execute.h:1767
How can you reproduce this issue? (assuming Ubuntu 16.04 or higher)
// first clone and install the project
git clone git@github.com:prooph/event-store-client.git
cd event-store-client
composer install
// second get event store up and running
wget https://eventstore.org/downloads/ubuntu/EventStore-OSS-Linux-Ubuntu-16.04-v5.0.5.tar.gz
tar xf EventStore-OSS-Linux-Ubuntu-16.04-v5.0.5.tar.gz
cd EventStore-OSS-Linux-Ubuntu-16.04-v5.0.5
./run-node.sh --run-projections=all --mem-db
./vendor/bin/phpunit --exclude-group=ignore
wait for it...
you'll get this output:
PHPUnit 9.0.1 by Sebastian Bergmann and contributors.
............................................................... 63 / 482 ( 13%)
............................................................... 126 / 482 ( 26%)
............................................................... 189 / 482 ( 39%)
............................................................... 252 / 482 ( 52%)
.................................php: src/unix/core.c:925: uv__io_stop: Assertion `loop->watchers[w->fd] == w' failed.
[1] 19181 abort (core dumped) /opt/php/7.4.2-debug/bin/php ./vendor/bin/phpunit --exclude-group=ignore
/opt/php/7.4.2-debug/bin/php ./vendor/bin/phpunit --exclude-group=ignore 19,51s user 1,10s system 41% cpu 49,270 totat
It's possible that it is not a bug in php-uv but in the php library itself. I spent already more than 40 hours of my freetime debugging this issue and trying to find the root cause, without success so far.
I am totally fine with spending another 40+ hours debugging this problem, but currently I am stuck with this. We currently have 27325 downloads on packagist and a lot of users want to use php-uv as event loop extension. I need to tell them all to use amp's native driver instead. Would be absolutely cool if we can get this solved somehow.
The URL https://eventstore.org/downloads/ubuntu/EventStore-OSS-Linux-Ubuntu-16.04-v5.0.5.tar.gz is not pointing to anything downloadable - can you please give me the correct URL?
I'm on macOS right now, so also tried https://eventstore.org/downloads/macos/EventStore-OSS-MacOS-macOS-v5.0.5.tar.gz, but the URLs just give me:
404 Not Found
Code: NoSuchWebsiteConfiguration
Message: The specified bucket does not have a website configuration
BucketName: eventstore.org
RequestId: 8D7F81BC0C969BF2
HostId: Zr+4srDEmwc8k/TU3mMEx2IzQ48D3mhr7L1Wgke7m/UeadgpnMZT8Q42ieDoGPsh1f+UV+jMNNM=
FWIW: The bug may occur in general if a same file descriptor is used twice. e.g. if you use STDIN and then fopen("php://fd/0", "r"). … Anyway, I'll need to check out your code with the debugger … if I can get it to run :-)
@bwoebi Both of the URLs you posted work fine for me. Maybe it was some temporary problem on their server.
Yeah, works now.
@bwoebi Thank you very much. If you need anything, I try to provide whatever it takes.
The bad news is that it is a ticking time bomb which may or may not explode...
That it does not always happen at the same test case depends on when exactly the cycle collector gets invoked.
You can work around your test suite issues by running gc_collect_cycles() after each test…
I do recommend to use https://github.com/amphp/phpunit-util though, which takes care of that for you.
The issue is that the tcp stream resource gets freed (not part of the cycle or fclose()'d explicitly) and its file descriptor reused later for another tcp stream, while still being part of the loop (disabled, but still part of loop). The re-adding works fine (obviously, the other poll resource is disabled at that point).
Then … the cycle collector decides to free the other poll resource, calls uv_close() on it … and the assertion sees another resource there. And explodes.
I think this is a bug in libuv TBH. I don't think the assertion should be checked at all if uv_poll_s.io_watcher.pevents == 0. I'll open an issue on upstream.
Side-note: To debug the issue, I really needed to see the file descriptors on the poll objects. I've exposed them in debug_info (i.e. var_dump) now: 9c08cdc - Without this it's defacto impossible to debug this.
Wow, thanks a lot @bwoebi - actually I didn't expect this quick result. Absolutely awesome. Thank you. I'll try your suggestion and keep you posted.
@bwoebi I tried your suggestion using phpunit-util but I am running into problems. The loop won't stop and runs indefinitely, which hangs the test-suite then. Shall I submit an issue at phpunit-util repo? Or should I provide you with a branch where you can test that yourself?
I found out why the loop hangs: The event store connection is still running so the loop doesn't stop. I need to manually close the connection from within the test-case in order to bring to loop to a stop. This feels somehow wrong to me, when the task is completed, why should the loop still be running?
Also stuff like $this->expectException(StreamDeleted::class); doesn't work with phpunit-util. I get an error like this: An exception was thrown from the test method or promise returned from test method failed, but the event loop continued to run; Prooph\EventStore\Exception\StreamDeleted, although the exception was expected.
@bwoebi You can ignore my latest questions, as I got some response from amp team already.
Fixed in upstream, build their newest master or next release if you ever see that issue again :-)