fix: stream connections longer than 5 minutes are dropped #244

cwaldren-ld · 2023-09-12T18:10:10Z

This fixes streaming connection dropping after 5 minutes.

The problem was applying a 5 minute timeout to an async_read operation, when the actual intent was to apply it to the act of receiving any data.

The timeout exists to prevent the client from hanging infinitely if the server stops responding. LaunchDarkly sends heartbeats to clear the timer.

With async_read, the operation won't complete until the response body is finished. Since the body will never finish until the client shuts down (or server interrupts it), it's not possible to institute a timeout.

The solution is to use async_read_some, which completes whenever data arrives.

This way, we can assign the 5 minute timeout as an upper bound on receiving any data, as was originally intended.

A side effect of this change was breaking the reconnection SSE contract tests, which proved to be somewhat of a rabbithole.

The upshot is that we weren't handling chunked encoding properly when chunked encoding ends. The original code assumes we either terminate an async read with an error, or it goes on forever.

In fact it should perform the backoff algorithm if we detect the end of chunked encoding.

I've also included more comments, more debug logging, and renamed some symbols for clarity. This should aid in debugging issues like this more efficiently.

Long running connection test (4 hours no drops)

shortcut-integration · 2023-09-12T18:10:14Z

This pull request has been linked to Shortcut Story #216849: Fix stream timing out after 5 minutes.

cwaldren-ld · 2023-09-13T00:15:25Z

libs/common/src/config/logging_builder.cpp

-    : level_(Defaults<AnySDK>::LogLevel()), tag_(Defaults<AnySDK>::LogTag()) {}
+    : level_(GetLogLevelEnum(std::getenv("LD_LOG_LEVEL"),
+                             Defaults<AnySDK>::LogLevel())),
+      tag_(Defaults<AnySDK>::LogTag()) {}


Ideally, we can just run LD_LOG_LEVEL=debug ./binary but the Console Logger constructed in the client passes in a default value, so the environment variable isn't inspected.

Now it works like you'd want.

cwaldren-ld · 2023-09-13T00:16:08Z

libs/server-sent-events/src/client.cpp

+     * The timestamp of the last read is initialized after receiving successful
+     * headers, but before initiating the first body read. Future reads then
+     * update the timestamp.
+     */


Added this helper so we can more easily tell how fast / when data is being received. For example, this clearly shows heartbeats arriving every 180 seconds.

cwaldren-ld · 2023-09-13T00:28:42Z

libs/server-sent-events/src/client.cpp

@@ -79,21 +79,49 @@ class FoxyClient : public Client,
          read_timeout_(read_timeout),
          write_timeout_(write_timeout),
          req_(std::move(req)),


Re-arranging to match declaration order.

cwaldren-ld · 2023-09-13T00:32:19Z

libs/server-sent-events/src/client.cpp

@@ -263,8 +293,22 @@ class FoxyClient : public Client,
    void on_read_body(boost::system::error_code ec, std::size_t amount) {
        boost::ignore_unused(amount);
        if (ec == boost::asio::error::operation_aborted) {
+            logger_("read HTTP response body aborted");
            return;
        }


Here's the key: if the parser indicates that the chunked encoding is finished, initiate backoff instead of attempting to keep reading the body.

cwaldren-ld · 2023-09-13T00:33:23Z

libs/server-sent-events/src/client.cpp

@@ -276,6 +320,7 @@ class FoxyClient : public Client,
    }

    void do_shutdown(std::function<void()> completion) {


This was causing unnecessary hanging when the test service tells the client to close. By cancelling the backoff timer, that operation can complete immediately.

vendor/foxy/include/foxy/impl/session/async_read.impl.hpp

jdegges · 2023-09-13T01:08:55Z

libs/server-sent-events/src/client.cpp

@@ -290,13 +299,13 @@ class FoxyClient : public Client,

    void on_read_body(boost::system::error_code ec, std::size_t amount) {
        boost::ignore_unused(amount);
-        if (ec == boost::asio::error::operation_aborted) {
-            logger_("read HTTP response body aborted");
+        if (ec == boost::asio::error::operation_aborted && shutting_down_) {


If on_read_body() can ever be executed from a context that is different from where do_shutdown() is executed then we may have a race between modifying & accessing shutting_down_.

Edit: Never mind, I see this was removed in the last commit :)

This is a good callout, especially since I had to add the bool back.

Although the public async_shutdown method will post's to the session_'s executor, the run routine did not - I've fixed that.

Since those are the only two public entrypoints, we should be safe.

… is explicitely shut down

cwaldren-ld · 2023-09-13T16:03:26Z

contract-tests/sse-contract-tests/src/entity_manager.cpp

@@ -35,6 +35,11 @@ std::optional<std::string> EntityManager::create(ConfigParams const& params) {
            std::chrono::milliseconds(*params.readTimeoutMs));
    }



This builder option was missing, but it's already implemented. Easy win to speed up tests.

cwaldren-ld · 2023-09-13T17:53:56Z

contract-tests/sse-contract-tests/include/event_outbox.hpp

@@ -72,11 +72,11 @@ class EventOutbox : public std::enable_shared_from_this<EventOutbox> {
   private:


cwaldren-ld · 2023-09-13T17:54:37Z

contract-tests/sse-contract-tests/src/entity_manager.cpp

@@ -53,7 +59,7 @@ std::optional<std::string> EntityManager::create(ConfigParams const& params) {
        return std::nullopt;
    }

-    client->run();


Renamed run to async_connect to make it clear this is kicking off an asynchronous operation.

cwaldren-ld · 2023-09-13T17:54:45Z

contract-tests/sse-contract-tests/src/event_outbox.cpp

@@ -14,8 +14,6 @@ auto const kOutboxCapacity = 1023;
 EventOutbox::EventOutbox(net::any_io_executor executor,
                         std::string callback_url)


cwaldren-ld · 2023-09-13T17:55:11Z

contract-tests/sse-contract-tests/src/event_outbox.cpp

    RequestType req;

    req.set(http::field::host, callback_host_);
-    req.method(http::verb::get);
+    req.method(http::verb::post);


get was just plain wrong, but accepted by the contract tests.

cwaldren-ld · 2023-09-13T17:56:07Z

contract-tests/sse-contract-tests/src/main.cpp

@@ -38,6 +38,7 @@ int main(int argc, char* argv[]) {
        srv.add_capability("report");
        srv.add_capability("post");
        srv.add_capability("reconnection");
+        srv.add_capability("read-timeout");


We were already passing the parameter along, just hadn't advertised the capability.

cwaldren-ld · 2023-09-13T17:56:41Z

libs/server-sent-events/src/client.cpp

-          errors_(std::move(errors)) {
+          backoff_timer_(std::move(executor)),
+          last_read_(std::nullopt),
+          shutting_down_(false) {


Session construction now takes place in create_session(), so the logic can be reused for each new connection.

cwaldren-ld · 2023-09-13T17:58:27Z

libs/server-sent-events/src/client.cpp

    }

-    void run() override {
-        session_.async_connect(


After renaming run, I wrapped it in a post so we can ensure there is only one thread accessing session. This is the same as async_shutdown.

vendor/foxy/include/foxy/impl/session/async_read.impl.hpp

🤖 I have created a release *beep* *boop* --- <details><summary>launchdarkly-cpp-client: 3.0.8</summary> ## [3.0.8](launchdarkly-cpp-client-v3.0.7...launchdarkly-cpp-client-v3.0.8) (2023-09-13) ### Bug Fixes * stream connections longer than 5 minutes are dropped ([#244](#244)) ([e12664f](e12664f)) ### Dependencies * The following workspace dependencies were updated * dependencies * launchdarkly-cpp-internal bumped from 0.1.8 to 0.1.9 * launchdarkly-cpp-common bumped from 0.3.5 to 0.3.6 * launchdarkly-cpp-sse-client bumped from 0.1.2 to 0.1.3 </details> <details><summary>launchdarkly-cpp-common: 0.3.6</summary> ## [0.3.6](launchdarkly-cpp-common-v0.3.5...launchdarkly-cpp-common-v0.3.6) (2023-09-13) ### Bug Fixes * stream connections longer than 5 minutes are dropped ([#244](#244)) ([e12664f](e12664f)) </details> <details><summary>launchdarkly-cpp-internal: 0.1.9</summary> ### Dependencies * The following workspace dependencies were updated * dependencies * launchdarkly-cpp-common bumped from 0.3.5 to 0.3.6 </details> <details><summary>launchdarkly-cpp-sse-client: 0.1.3</summary> ## [0.1.3](launchdarkly-cpp-sse-client-v0.1.2...launchdarkly-cpp-sse-client-v0.1.3) (2023-09-13) ### Bug Fixes * stream connections longer than 5 minutes are dropped ([#244](#244)) ([e12664f](e12664f)) </details> --- This PR was generated with [Release Please](https://github.com/googleapis/release-please). See [documentation](https://github.com/googleapis/release-please#release-please). Co-authored-by: github-actions[bot] <41898282+github-actions[bot]@users.noreply.github.com>

cwaldren-ld added 2 commits September 12, 2023 10:54

add async_read_some to foxy

f5c907d

use async_read_some in sse-client

d94c4c2

cwaldren-ld added 2 commits September 12, 2023 15:06

fix sse behavior when reconnecting to streams

1e780ce

client should backoff when receiving final chunk

4f7dc9e

cwaldren-ld commented Sep 13, 2023

View reviewed changes

revert session construction changes

300acdc

cwaldren-ld commented Sep 13, 2023

View reviewed changes

vendor/foxy/include/foxy/impl/session/async_read.impl.hpp Outdated Show resolved Hide resolved

remove shutdown bool

ed5ff7f

cwaldren-ld force-pushed the cw/sc-216849/sse-read-timeout branch from 937b304 to ed5ff7f Compare September 13, 2023 00:37

jdegges reviewed Sep 13, 2023

View reviewed changes

ssl session cannot be resused for new connections

5e28860

cwaldren-ld force-pushed the cw/sc-216849/sse-read-timeout branch from 01bdc8b to 5e28860 Compare September 13, 2023 15:03

cwaldren-ld added 2 commits September 13, 2023 08:16

add shutdown sentinel to ensure async_read_some completes when client…

3765fcb

… is explicitely shut down

make run() post to sessions' executor; rename to async_connect

24fcdfc

cwaldren-ld force-pushed the cw/sc-216849/sse-read-timeout branch from 6d9ca86 to 24fcdfc Compare September 13, 2023 15:38

implement read timeout capability in contract tests

249e147

cwaldren-ld commented Sep 13, 2023

View reviewed changes

fix some lints

d8e7b1d

cwaldren-ld force-pushed the cw/sc-216849/sse-read-timeout branch from 23262e3 to d8e7b1d Compare September 13, 2023 16:43

add many comments

53567e4

cwaldren-ld commented Sep 13, 2023

View reviewed changes

cwaldren-ld marked this pull request as ready for review September 13, 2023 18:01

cwaldren-ld requested review from a team and kinyoklion September 13, 2023 18:01

kinyoklion requested changes Sep 13, 2023

View reviewed changes

vendor/foxy/include/foxy/impl/session/async_read.impl.hpp Outdated Show resolved Hide resolved

revert foxy formatting changes

346ff3d

kinyoklion approved these changes Sep 13, 2023

View reviewed changes

cwaldren-ld merged commit e12664f into main Sep 13, 2023

cwaldren-ld deleted the cw/sc-216849/sse-read-timeout branch September 13, 2023 21:46

github-actions bot mentioned this pull request Sep 13, 2023

chore: release main #245

Merged

This was referenced Oct 23, 2023

chore: release main #271

Closed

chore: release main #273

Merged

github-actions bot mentioned this pull request May 13, 2024

chore: release main #402

Closed

		@@ -276,6 +320,7 @@ class FoxyClient : public Client,
		}

		void do_shutdown(std::function<void()> completion) {

		@@ -35,6 +35,11 @@ std::optional<std::string> EntityManager::create(ConfigParams const& params) {
		std::chrono::milliseconds(*params.readTimeoutMs));
		}

		@@ -72,11 +72,11 @@ class EventOutbox : public std::enable_shared_from_this<EventOutbox> {
		private:

		@@ -14,8 +14,6 @@ auto const kOutboxCapacity = 1023;
		EventOutbox::EventOutbox(net::any_io_executor executor,
		std::string callback_url)

fix: stream connections longer than 5 minutes are dropped #244

fix: stream connections longer than 5 minutes are dropped #244

Uh oh!

Conversation

cwaldren-ld commented Sep 12, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

shortcut-integration bot commented Sep 12, 2023

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

cwaldren-ld Sep 13, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

jdegges Sep 13, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

cwaldren-ld Sep 13, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

cwaldren-ld commented Sep 12, 2023 •

edited

Loading

cwaldren-ld Sep 13, 2023 •

edited

Loading

jdegges Sep 13, 2023 •

edited

Loading

cwaldren-ld Sep 13, 2023 •

edited

Loading