Unreference watchers #149

enumag · 2020-11-08T10:21:32Z

Superseeds #140

Still need to check your comment from #117 (comment). It might be easier now with the exceptions fixed.

coveralls · 2020-11-08T10:35:01Z

Pull Request Test Coverage Report for Build 806

55 of 56 (98.21%) changed or added relevant lines in 14 files are covered.
No unchanged relevant lines lost coverage.
Overall coverage increased (+0.3%) to 71.874%

Changes Missing Coverage	Covered Lines	Changed/Added Lines	%
src/Internal/Message/TcpConnectionErrorMessage.php	0	1	0.0%

Totals
Change from base Build 797:	0.3%
Covered Lines:	3432
Relevant Lines:	4775

💛 - Coveralls

prolic · 2020-11-11T01:41:58Z

tests/connect.php

@@ -110,6 +119,10 @@ public function should_close_connection_after_configured_amount_of_failed_reconn
            $closed->resolve(true);
        });

+        // Need a watcher to keep the loop running after connection is closed.
+        $watcher = Loop::delay(180000, function (): void {


This is highly suspicious. I never encountered a scenario where this would be needed.

Not at all. Let me explain. In this test you're creating a connection which can't succeed and will fail with timeout, yes? This means that afterwards there is no active watcher anymore and the loop would just end immediately. But you still want to use the broken connection in order to call appendToStreamAsync and expect it to throw InvalidOperationException.

It's only needed for this particular test case. In a real life application you would be okay with the loop ending immediately. But we still need the test because again in real life application the loop might stay active because of something else entirely.

enumag · 2020-11-27T18:48:17Z

@enumag During testing I found that when I remove all $connection->close() calls from the test suite, the tests hang forever, thus I'd say it doesn't resolve the issue we are trying to solve.

@prolic Okay, I tried commenting out the ->close() calls. Most of them don't cause any problem if removed but a few of them indeed do cause the tests to hang.

So I changed \Amp\PHPUnit\AsyncTestCase to call $this->setTimeout(20000); at the beginning of each test. With this the AsyncTestCase will jump out from a hanging test after the timeout and fail it with a message.

Then I added the AMP_DEBUG_TRACE_WATCHERS env variable which activates Amp's TracingDriver. With this I get some helpful dump which watchers are keeping the loop up.

This is the command I ended up with to run the tests (mainly a note for myself):

docker-compose -f docker/unittest/docker-compose.yml restart && docker-compose -f docker/unittest/docker-compose.yml run -e AMP_DEBUG_TRACE_WATCHERS=1 php /app/vendor/bin/phpunit -c phpunit/phpunit.xml --exclude-group=ignore --debug --stop-on-failure

To my surprise, the watcher causing the issue isn't from prooph but from Amphp:

Enabled, referenced watchers keeping the loop running: Watcher ID: q
#0 /app/vendor/amphp/amp/lib/Loop.php:194 Amp\Loop\TracingDriver->onReadable()
#1 /app/vendor/amphp/byte-stream/lib/ResourceInputStream.php:102 Amp\Loop::onReadable()
#2 /app/vendor/amphp/socket/src/ResourceSocket.php:75 Amp\ByteStream\ResourceInputStream->__construct()
#3 /app/vendor/amphp/socket/src/ResourceSocket.php:40 Amp\Socket\ResourceSocket->__construct()
#4 /app/vendor/amphp/socket/src/DnsConnector.php:134 Amp\Socket\ResourceSocket::fromClientSocket()
#5 Amp\Socket\DnsConnector::Amp\Socket\{closure}()
#6 /app/vendor/amphp/amp/lib/Coroutine.php:118 Generator->send()
#7 /app/vendor/amphp/amp/lib/Internal/Placeholder.php:46 Amp\Coroutine->Amp\{closure}()
#8 /app/vendor/amphp/amp/lib/Internal/PrivatePromise.php:23 class@anonymous/app/vendor/amphp/amp/lib/Deferred.php0x7f82d5856efa->onResolve()
#9 /app/vendor/amphp/amp/lib/Internal/Placeholder.php:143 Amp\Internal\PrivatePromise->onResolve()
#10 /app/vendor/amphp/amp/lib/Deferred.php:52 class@anonymous/app/vendor/amphp/amp/lib/Deferred.php0x7f82d5856efa->resolve()
#11 /app/vendor/amphp/amp/lib/functions.php:282 Amp\Deferred->resolve()
#12 /app/vendor/amphp/amp/lib/Internal/Placeholder.php:149 Amp\Promise\{closure}()
#13 /app/vendor/amphp/amp/lib/Deferred.php:52 class@anonymous/app/vendor/amphp/amp/lib/Deferred.php0x7f82d5856efa->resolve()
#14 /app/vendor/amphp/socket/src/DnsConnector.php:85 Amp\Deferred->resolve()
#15 /app/vendor/amphp/amp/lib/Loop/NativeDriver.php:216 Amp\Socket\DnsConnector::Amp\Socket\{closure}()
#16 /app/vendor/amphp/amp/lib/Loop/NativeDriver.php:96 Amp\Loop\NativeDriver->selectStreams()
#17 /app/vendor/amphp/amp/lib/Loop/Driver.php:138 Amp\Loop\NativeDriver->dispatch()
#18 /app/vendor/amphp/amp/lib/Loop/Driver.php:72 Amp\Loop\Driver->tick()
#19 /app/vendor/amphp/amp/lib/Loop/TracingDriver.php:27 Amp\Loop\Driver->run()
#20 /app/vendor/amphp/amp/lib/Loop.php:95 Amp\Loop\TracingDriver->run()
#21 /app/vendor/amphp/phpunit-util/src/AsyncTestCase.php:65 Amp\Loop::run()
#22 /app/vendor/phpunit/phpunit/src/Framework/TestCase.php:1536 Amp\PHPUnit\AsyncTestCase->runAsyncTest()
#23 /app/vendor/amphp/phpunit-util/src/AsyncTestCase.php:132 PHPUnit\Framework\TestCase->runTest()
#24 /app/vendor/phpunit/phpunit/src/Framework/TestCase.php:1142 Amp\PHPUnit\AsyncTestCase->runTest()
#25 /app/vendor/phpunit/phpunit/src/Framework/TestResult.php:730 PHPUnit\Framework\TestCase->runBare()
#26 /app/vendor/phpunit/phpunit/src/Framework/TestCase.php:883 PHPUnit\Framework\TestResult->run()
#27 /app/vendor/phpunit/phpunit/src/Framework/TestSuite.php:669 PHPUnit\Framework\TestCase->run()
#28 /app/vendor/phpunit/phpunit/src/Framework/TestSuite.php:669 PHPUnit\Framework\TestSuite->run()
#29 /app/vendor/phpunit/phpunit/src/Framework/TestSuite.php:669 PHPUnit\Framework\TestSuite->run()
#30 /app/vendor/phpunit/phpunit/src/TextUI/TestRunner.php:673 PHPUnit\Framework\TestSuite->run()
#31 /app/vendor/phpunit/phpunit/src/TextUI/Command.php:148 PHPUnit\TextUI\TestRunner->run()
#32 /app/vendor/phpunit/phpunit/src/TextUI/Command.php:101 PHPUnit\TextUI\Command->run()
#33 /app/vendor/phpunit/phpunit/phpunit:61 PHPUnit\TextUI\Command::main()

~~Namely it's this watcher. This doesn't make much sense since the watcher is supposed to be deactivated here but that's what I got.~~

Actually no. It's the Socket.

enumag · 2020-11-27T19:17:11Z

Ah wait, nevermind. The socket created here is actually the same one that ends up in \Prooph\EventStoreClient\Transport\Tcp\TcpPackageConnection::$connection. Which means it's not properly unreferenced. Okay, more digging needed. 😆

enumag · 2020-11-27T19:38:34Z

@prolic Ah okay. It's actually quite clear in the end. The unreferencing system works fine. What's hanging are the tests for subscriptions - namely those with a subscription still active at the end of the test. When this happens there are two options:

either manually close the connection in tearDown (which effectively kills the running subscription), this is what we were doing until now
or end the subscription at the end of each such test - then I'm confident that the tests would not hang anymore even without explicit connection close because the connection would no longer keep the loop alive

prolic · 2020-11-27T20:29:36Z

* or end the subscription at the end of each such test - then I'm confident that the tests would not hang anymore even without explicit connection close because the connection would no longer keep the loop alive

This sounds good to me.

enumag · 2020-11-27T20:59:13Z

Okay, the tests did actually identify a bug. The issue is that if connecting to a subscription fails with AccessDenied / NotAuthenticated / MaximumSubscribersReached etc. the tests still hang. It's because the subscriptionDropped callback (which I'm using to keep track of active subscriptions) is never called.

I should be able to fix this but it will still take some time.

enumag · 2020-11-28T13:38:56Z

@prolic Okay, there is an issue with catchup subscriptions not counting the references correctly. Or rather when EventStoreCatchUpSubscription::stop() is called, the internal EventStoreSubscription actually isn't cancelled (= $this->subscription->unsubscribe() is not called). Do you have an idea why? Should we add $this->subscription->unsubscribe() into the EventStoreCatchUpSubscription::stop() method? If so, where exactly in the stop method should it be?

enumag · 2020-11-28T14:00:10Z

Apparently it's supposed to be called by EventStoreCatchUpSubscription::dropSubscription() but it seems that this method is never called either. I have no idea how this should be fixed.

prolic · 2020-11-28T22:37:59Z

This looks all good, I fixed those hanging tests for you. The problem was, that once a subscription was started, there is still some watcher active. So we need to either close the connection or stop the subscription. I did that in another branch and all tests are green again.

enumag · 2020-11-28T22:42:58Z

@prolic I'm aware, I did the same locally. But that's not a good fix. You were right earlier that the tests should NOT hang even with all ->close() calls removed. In most cases I just need to fix the tests to close the subscription but for catch up subscription there is an actual bug in the library - there is an active watcher when there shouldn't be one. I'll fix everything else and let you know so that you can have a look at it without anything else failing.

prolic · 2020-11-28T23:16:17Z

Can you tell me which test case is the problematic one?

…

On Sat, Nov 28, 2020, 19:43 Jáchym Toušek ***@***.***> wrote: @prolic <https://github.com/prolic> I'm aware, I did the same locally. But that's not a good fix. You were right earlier that the tests should NOT hang even with all ->close() calls removed. In most cases I just need to fix the tests to close the subscription but for catch up subscription there is an actual bug there and there is an active watcher when there shouldn't be one. I'll fix everything else and let you know. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#149 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AADAJPBWDRCBEJFE3PBBXULSSF4HZANCNFSM4TOHKKBA> .

enumag · 2020-11-29T08:10:33Z

Ah sorry the problem is something else... The problem isn't that dropSubscription() is not called, it's that it's called too early. It's called when $this->subscription is still null.

Basically the subscription starts processing events before the promise returned by $this->connection->subscribeToAllAsync() is resolved. This shouldn't be the case of course.

The problematic test, or one of them, is ProophTest\EventStoreClient\subscribe_to_all_catching_up_should::call_dropped_callback_when_an_error_occurs_while_processing_an_event. Then like 3 tests in ProophTest\EventStoreClient\subscribe_to_stream_catching_up_should.

I pushed my other fixes.

prolic · 2020-11-30T00:56:11Z

Thanks, I'll have a look asap.

enumag · 2020-12-09T07:00:20Z

ping @prolic

prolic · 2020-12-29T17:32:14Z

I had a look yesterday, couldn't resolve it, I try to get some time for it these upcoming days.

prolic · 2021-03-22T22:58:11Z

More than 2 months ago? I am really sorry @enumag
I will try to work on this tomorrow.

enumag · 2021-06-25T05:52:59Z

ping @prolic :-P

prolic · 2021-06-30T02:29:41Z

I tried 2 days ago, couldn't solve it, hopefully this weekend I have some time again.

enumag · 2021-06-30T04:15:39Z

Yeah it's a tough one. Would have solved it myself if it was easy.

enumag force-pushed the feature/unreference-heartbeat branch 2 times, most recently from da4ff6c to 2870746 Compare November 8, 2020 10:32

enumag added 10 commits November 8, 2020 11:34

Unreference heartbeat watcher

183ec8b

Unreference TCP connection socket when not active

86408b4

Use SplObjectStorage

7ae954f

Fix test

00685a6

Rename method

c69145d

Fix test

39a0d7d

Fix persistent subscriptions

387d372

Fix catchup subscriptions

44fbeb5

Fix test

d8d7b6a

Fix rebase

5ae1719

enumag force-pushed the feature/unreference-heartbeat branch from 2870746 to 5ae1719 Compare November 8, 2020 10:34

prolic reviewed Nov 11, 2020

View reviewed changes

enumag added 2 commits November 27, 2020 17:14

Migrate phpunit configuration

dc6e5bf

Comment EventStoreNodeConnection::close() calls

7bfe9bd

enumag closed this Nov 27, 2020

enumag reopened this Nov 27, 2020

Refactor

1b6880e

enumag added 2 commits November 29, 2020 08:02

Fix reference counting on subscription exception

c52642d

Fix reference counting on persistent subscription exception

810ccf3

enumag added 3 commits November 29, 2020 09:23

Fix tests

4fd3724

Fix tests

6820046

Fix tests

c04a3de

enumag force-pushed the feature/unreference-heartbeat branch from bf0bc49 to c04a3de Compare November 29, 2020 08:23

prolic closed this Sep 22, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Unreference watchers #149

Unreference watchers #149

enumag commented Nov 8, 2020 •

edited

coveralls commented Nov 8, 2020 •

edited

prolic Nov 11, 2020

enumag Nov 11, 2020

enumag Nov 11, 2020

enumag commented Nov 27, 2020 •

edited

enumag commented Nov 27, 2020 •

edited

enumag commented Nov 27, 2020 •

edited

prolic commented Nov 27, 2020

enumag commented Nov 27, 2020

enumag commented Nov 28, 2020 •

edited

enumag commented Nov 28, 2020

prolic commented Nov 28, 2020

enumag commented Nov 28, 2020 •

edited

prolic commented Nov 28, 2020 via email

enumag commented Nov 29, 2020

prolic commented Nov 30, 2020

enumag commented Dec 9, 2020

prolic commented Dec 29, 2020

prolic commented Mar 22, 2021

enumag commented Jun 25, 2021

prolic commented Jun 30, 2021

enumag commented Jun 30, 2021

Unreference watchers #149

Unreference watchers #149

Conversation

enumag commented Nov 8, 2020 • edited

coveralls commented Nov 8, 2020 • edited

Pull Request Test Coverage Report for Build 806

💛 - Coveralls

prolic Nov 11, 2020

Choose a reason for hiding this comment

enumag Nov 11, 2020

Choose a reason for hiding this comment

enumag Nov 11, 2020

Choose a reason for hiding this comment

enumag commented Nov 27, 2020 • edited

enumag commented Nov 27, 2020 • edited

enumag commented Nov 27, 2020 • edited

prolic commented Nov 27, 2020

enumag commented Nov 27, 2020

enumag commented Nov 28, 2020 • edited

enumag commented Nov 28, 2020

prolic commented Nov 28, 2020

enumag commented Nov 28, 2020 • edited

prolic commented Nov 28, 2020 via email

enumag commented Nov 29, 2020

prolic commented Nov 30, 2020

enumag commented Dec 9, 2020

prolic commented Dec 29, 2020

prolic commented Mar 22, 2021

enumag commented Jun 25, 2021

prolic commented Jun 30, 2021

enumag commented Jun 30, 2021

enumag commented Nov 8, 2020 •

edited

coveralls commented Nov 8, 2020 •

edited

enumag commented Nov 27, 2020 •

edited

enumag commented Nov 27, 2020 •

edited

enumag commented Nov 27, 2020 •

edited

enumag commented Nov 28, 2020 •

edited

enumag commented Nov 28, 2020 •

edited