Skip to content

Consolidate logging for HTTP requests, especially in timeout logging - #634

Merged
torcolvin merged 1 commit into
mainfrom
shell2http-timeouts
Oct 7, 2026
Merged

torcolvin merged 1 commit into
mainfrom
shell2http-timeouts

Conversation

@torcolvin

@torcolvin torcolvin commented Oct 6, 2026 •

Copy link
Copy Markdown
Collaborator

Inspiration

@vipbhardwaj noticed that calling cbcollect would result in a timeout. It is definitely possible for some calls to timeout if part of the system times out. This could include shell2http, CBS REST, Sync Gateway REST, etc. Most of the code enforces a client side timeout (300s), but if it times you, can not necessarily figure out what times out.

What

  • Modify shell2http setup to take a timeout argument so that it can return the output of the process before it is killed. I pass 95% of the http timeout to leave time for shell2http to fail. This would help debug possibly understand where the process hangs. This is implemented using standard timeout command.

  • Modify all the shell2http scripts to support with-timeout.sh to get picked up for CBS, SG, Edge Server.

  • Fail if status for shell2http calls is not 200. If there is a signal, it will return 200 status but set X-Shell2http-Exit-Code to a negative number. Make sure this exception will show the output from a command.

  • Use setsid in start-sgw.sh to avoid killing Sync Gateway if there's a request timeout, like edge server.

  • Move the code about timeouts to be consistent across testerserver.log and the http logs. When I look at code, I never look at either of these files but only look at pytest output. Centralize this logic across requests.

  • Make sure to log requests, timeouts into the log file. See below for changed. In order to do this, I catch and reraise exceptions.

Logging, before and after

Before this change, none of these cases wrote to testserver.log. ERROR lines also go to the console, at every --cbl-log-level.

# Case http_log before http_log after testserver.log before testserver.log after
1 Edge Server sidecar call succeeds _begin and _end, as Edge Server host [<h>] _begin and _end, as Edge Server sidecar [<h>], with (exit code 0) nothing nothing
2 Sync Gateway or Couchbase Server sidecar call succeeds nothing _begin and _end nothing nothing
3 Script exits non-zero Edge Server: _end with 500. Sync Gateway and Couchbase Server: nothing, output only in the exception _end with 500 (exit code 1) and the output nothing ERROR line with the output
4 Script runs past its timeout Edge Server: _begin only. Sync Gateway and Couchbase Server: nothing. No limit on the host _end with 500 (exit code 124) and the output nothing ERROR line with the output
5 Script killed by a signal Edge Server: _end with 200, and the call passed. Sync Gateway and Couchbase Server: nothing _end with 200 (exit code -1), and the call fails nothing ERROR line with the output
6 Path the sidecar does not serve Edge Server: _end with 404. Sync Gateway and Couchbase Server: nothing _end with 404 (exit code None) nothing ERROR line with the body
7 Sidecar call gets no response (client timeout, connection error) Edge Server: _begin only. Sync Gateway and Couchbase Server: nothing _begin and _error nothing the _error line, which ends with the timeouts that applied
8 Sync Gateway or Edge Server REST request gets no response _begin only _begin and _error nothing the _error line, except for readiness polls, which log nothing
9 Sync Gateway or Edge Server REST request gets a bad status _begin and _end unchanged nothing nothing

Examples

Host names are changed. The "after" output comes from runs against AWS hosts, a local shell2http v1.17.0 binary, or the unit tests.

1. Edge Server sidecar call succeeds

Before, http_log:  Edge Server host [10.0.0.2] -> POST /kill-edgeserver
                   Edge Server host [10.0.0.2] <- POST /kill-edgeserver 200

                   Edge server stopped

After, http_log:   Edge Server sidecar [10.0.0.2] -> POST /kill-edgeserver
                   Edge Server sidecar [10.0.0.2] <- POST /kill-edgeserver 200 (exit code 0)

                   Edge server stopped

2. Sync Gateway sidecar call succeeds

Before: nothing logged

After, http_log:   Sync Gateway sidecar [10.0.0.1] -> GET /stop-sgw?timeout=57
                   Sync Gateway sidecar [10.0.0.1] <- GET /stop-sgw?timeout=57 200 (exit code 0)

                   Stopping Sync Gateway...
                   Sync Gateway stopped successfully

3. Script exits non-zero (/start-cbs)

Before: nothing logged. The output was only in the exception:
        CblTestError: Failed to start CBS: 500 - Starting CBS...
        ...
        ERROR: CBS did not start within 60s

        exec error: exit status 1

After, http_log _end and testserver.log:
        [ERROR]: Couchbase Server sidecar [10.0.0.3]: POST /start-cbs returned 500 (exit code 1):
        Starting CBS...
        ok: run: /etc/service/couchbase-server: (pid 861) 2s
        ERROR: CBS did not start within 60s

        exec error: exit status 1

4. Script runs past its timeout (/start-sgw with a 0.6s timeout)

Before: nothing logged. No output reached the client, and the script kept running. Exception only:
        CblTimeoutError: GET http://10.0.0.1:20001/start-sgw?config=bootstrap timed out after 0.6s waiting for the response (total 0.6s)

After, http_log _end and testserver.log:
        [ERROR]: Sync Gateway sidecar [10.0.0.1]: GET /start-sgw?config=bootstrap&timeout=0.57 returned 500 (exit code 124):
        Starting Sync Gateway with config: /home/ec2-user/config/bootstrap.json...
        Waiting for Sync Gateway to start (PID: 27759)...
        start-sgw.sh timed out after 0.57s

        exec error: exit status 124

A script can ignore SIGTERM. Then SIGKILL follows 1s later, and the exit code is 137. GNU timeout returns 137 for any SIGKILL, so the wrapper does not claim a timeout:

... returned 500 (exit code 137):
ignore.sh was killed by SIGKILL, either because it ignored SIGTERM at the 1s timeout or from elsewhere

5. Script killed by a signal (/start-edgeserver)

Before, http_log:  Edge Server host [10.0.0.2] <- POST /start-edgeserver 200

                   before kill

                   exec error: signal: killed
Before, testserver.log: nothing. The call passed.

After, http_log _end and testserver.log:
        [ERROR]: Edge Server sidecar [10.0.0.2]: POST /start-edgeserver returned 200 (exit code -1):
        before kill

        exec error: signal: killed

6. Path the sidecar does not serve

Before, http_log (Edge Server only):  Edge Server host [10.0.0.2] <- POST /missing 404

                                      404 page not found
Before, Sync Gateway and Couchbase Server: nothing logged

After, http_log _end and testserver.log:
        [ERROR]: Edge Server sidecar [10.0.0.2]: POST /missing returned 404 (exit code None):
        404 page not found

7. Sidecar call gets no response

Before, http_log (Edge Server only): _begin only
Before, Sync Gateway and Couchbase Server: nothing logged
Before, testserver.log: nothing. Exception only:
        CblTimeoutError: GET http://10.0.0.1:20001/stop-sgw timed out after 60.0s waiting for the response (total 60s)

After, http_log _error and testserver.log (same line):
        [ERROR]: Sync Gateway sidecar [10.0.0.1] <- GET /stop-sgw?timeout=57 failed: GET http://10.0.0.1:20001/stop-sgw?timeout=57 timed out after 60.0s waiting for the response (total 60s, sock_connect 30s)

8. REST request gets no response

Before, http_log:       _begin only
Before, testserver.log: nothing. Exception only.

After, http_log _error and testserver.log (same line):
        [ERROR]: Sync Gateway [https://10.0.0.1:4985] <- GET /db/_changes?feed=normal failed: GET https://10.0.0.1:4985/db/_changes?feed=normal timed out after 300.0s waiting for the response (total 300s, sock_connect 30s)
        [ERROR]: Edge Server [10.0.0.2] <- GET / failed: Expecting value: line 1 column 1 (char 0)

9. REST request gets a bad status: unchanged.

Notes

  • The host change takes effect only after the hosts are set up again with start_backend.py. A host with the old sidecar ignores ?timeout=, and only the client's limit applies.
  • testserver.log and the console get the full script output of a failed sidecar call. In practice the output is small. The largest is a failed /start-edgeserver, which prints a fresh Edge Server log.
  • At 95%, the client keeps 5% of the timeout to receive the host's answer, and that margin must cover the network round trip. Against AWS, a 0.6s timeout (30ms margin) timed out on the client, and 0.9s and 5s worked. The current calls use 30s or more.
  • /start-cbs already failed on main. It waits for /pools/default without credentials, which always answers 401. Nothing in tests/ calls CouchbaseServer.start_server(). This PR does not fix that.

Testing

  • uv run ruff check ., uv run --group lint ty check, uvx pre-commit run --all-files: pass.
  • uv run -- pytest --config client/tests/empty_config.json client/tests: 395 passed.
    • The new client/tests/test_shell2http.py covers success with and without a timeout, and a client-side timeout. It also covers a 500, a 200 with exit code -1, a 404 and the error type.
    • New tests in test_syncgateway_helpers.py and test_edge_server.py cover REST requests that get no response.
  • AWS (Couchbase Server 8.0.3, Sync Gateway 4.1.1, Edge Server 1.1.0), on the final commit:
    • SyncGatewayManager.restart_with_config() took 2.7s and logged no ERROR lines. EdgeServerManager.start_server() logged none either.
    • /start-cbs with a 5s timeout returned a 500 (exit code 124) after 4.79s. The script's output was in the exception and in one ERROR line.
    • /start-edgeserver with a 0.9s timeout returned a 500 (exit code 124) with the script's output.
    • On the Sync Gateway host, /start-sgw?timeout=0.2 returned a 500. The Sync Gateway that the script started was still running 5s later and answered on port 4984, so setsid works.
  • Local shell2http v1.17.0: the wrapper with no timeout, a slow script, a script that ignores SIGTERM, and a script that kills itself.

🤖 Generated with Claude Code

@torcolvin
torcolvin force-pushed the shell2http-timeouts branch 2 times, most recently from 1e13b56 to 314b882 Compare October 7, 2026 00:32
@torcolvin torcolvin changed the title Enforce sidecar timeouts on the host, and log failed requests Consolidate logging for HTTP requests, especially in timeout logging Oct 7, 2026
@torcolvin
torcolvin requested a balanced review from Copilot October 7, 2026 00:51

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copilot review overview

🟡 Changes recommended

Edge Server and Couchbase Server calls omit timeout propagation, so scripts can still outlive client timeouts without returning diagnostics.

Review effort: Balanced
Findings: 2 Medium severity

Open (2)
What changed in this PR

Consolidates sidecar and REST request logging while adding host-side script timeouts and better diagnostics.

Changes:

  • Adds reusable shell2http timeout handling.
  • Centralizes request-failure logging.
  • Adds coverage for timeout, status, and malformed-response behavior.
File Description
environment/​aws/​sgw_setup/​shell2http/​start.sh Wraps SGW endpoints with timeout handling.
environment/​aws/​sgw_setup/​shell2http/​start-sgw.sh Isolates SGW from timeout signals.
environment/​aws/​sgw_setup/​setup_sgw.py Uses shared script uploader.
environment/​aws/​server_setup/​shell2http/​start.sh Wraps CBS endpoints.
environment/​aws/​server_setup/​setup_server.py Uses shared script uploader.
environment/​aws/​es_setup/​shell2http/​start.sh Wraps Edge Server endpoints.
environment/​aws/​es_setup/​setup_edge_servers.py Uses shared script uploader.
environment/​aws/​common/​shell2http/​with-timeout.sh Implements host-side timeout enforcement.
environment/​aws/​common/​io.py Adds shared sidecar-script upload utility.
environment/​AGENTS.md Documents shared timeout infrastructure.
client/​tests/​test_syncgateway_sgcollect.py Updates request test stub.
client/​tests/​test_syncgateway_helpers.py Tests SGW failure logging.
client/​tests/​test_shell2http.py Tests the new sidecar client.
client/​tests/​test_sgw_cluster_manager.py Updates timeout typing.
client/​tests/​test_replica_counts.py Mocks the new CBS sidecar client.
client/​tests/​test_edge_server.py Tests Edge Server failure logging.
client/​tests/​test_edge_server_manager.py Updates sidecar and readiness stubs.
client/​tests/​test_cluster.py Mocks the new CBS sidecar client.
client/​tests/​test_bucket_cleanup.py Mocks the new CBS sidecar client.
client/​src/​cbltest/​utils.py Clarifies sidecar-port usage.
client/​src/​cbltest/​shell2http.py Adds the shared logged sidecar client.
client/​src/​cbltest/​plugins/​sgw_cluster_manager.py Migrates SGW sidecar operations.
client/​src/​cbltest/​httplog.py Adds centralized exception recording.
client/​src/​cbltest/​api/​syncgateway.py Logs failed SGW requests.
client/​src/​cbltest/​api/​edgeservermanager.py Migrates Edge Server sidecar operations.
client/​src/​cbltest/​api/​edgeserver.py Logs failed Edge Server requests.
client/​src/​cbltest/​api/​couchbaseserver.py Migrates CBS sidecar operations.
client/​AGENTS.md Documents the sidecar client.

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

Comment thread client/src/cbltest/api/couchbaseserver.py
Comment thread client/src/cbltest/api/edgeservermanager.py Outdated
A client-side timeout on a sidecar call lost the script's output.
shell2http killed only the top bash process, and child processes kept
running. shell2http's own -timeout flag applies to every call, and it
answers 200 for a killed script.

Now every sidecar call has a total HTTP timeout. The client sends 95%
of it as ?timeout=, and with-timeout.sh runs the script under GNU
timeout (SIGTERM to the process group, then SIGKILL 1s later). The host
stops the script first, so its output comes back as a 500. A call
without a timeout uses aiohttp's default of 300s, so the host stops it
at 285s. Sync Gateway calls keep their old values.

- Add environment/aws/common/shell2http/with-timeout.sh. All three
  start.sh files run every endpoint through it.
- Add upload_shell2http_scripts() to environment/aws/common/io.py, so
  the Couchbase Server, Sync Gateway and Edge Server setups upload the
  wrapper.
- Add Shell2HttpClient in cbltest/shell2http.py. EdgeServerManager,
  SyncGatewayManager and CouchbaseServer use it.
- call() fails unless the status is 2xx and X-Shell2http-Exit-Code
  is 0. shell2http answers 200 when a signal kills the script.
- call() returns the script's output, and it raises the error type
  that the client was built with. Edge Server keeps
  CblEdgeServerBadResponseError. Sync Gateway and Couchbase Server now
  raise CblRemoteBadResponseError, not CblTestError.
- Sync Gateway and Edge Server REST requests that get no response now
  write an _error file and log to testserver.log, then raise again.
  The new _HttpLogWriter.record_failure() does this for the REST
  clients and the sidecar client.
- Readiness polls (Sync Gateway wait_for_rest_api, Edge Server start)
  pass log_failure=False. Their expected connection errors still get
  an _error file, but not a testserver.log line.
- start-sgw.sh starts Sync Gateway with setsid, as start-edgeserver.sh
  does, so a host-side timeout does not kill the new Sync Gateway.

Logging, before and after

Before this change, none of these cases wrote to testserver.log. ERROR
lines also go to the console, at every --cbl-log-level.

1. Edge Server sidecar call succeeds
   Before: http_log _begin and _end, as "Edge Server host [<h>]".
           testserver.log: nothing.
   After:  http_log _begin and _end, as "Edge Server sidecar [<h>]",
           and _end adds "(exit code 0)". testserver.log: nothing.

2. Sync Gateway or Couchbase Server sidecar call succeeds
   Before: nothing logged.
   After:  http_log _begin and _end. testserver.log: nothing.

3. Script exits non-zero
   Before: Edge Server: http_log _end with 500. Sync Gateway and
           Couchbase Server: nothing logged, output only in the
           exception. testserver.log: nothing.
   After:  http_log _end with "500 (exit code 1)" and the output.
           testserver.log: ERROR line with the output.

4. Script runs past its timeout
   Before: no limit on the host. Sync Gateway's client gave up at 120s
           with no output, and the script kept running. Nothing logged,
           except an Edge Server http_log _begin.
   After:  http_log _end with "500 (exit code 124)" and the output.
           testserver.log: ERROR line with the output.

5. Script killed by a signal
   Before: 200, so the call passed. Edge Server: http_log _end with
           200. Sync Gateway and Couchbase Server: nothing logged.
           testserver.log: nothing.
   After:  the call fails. http_log _end with "200 (exit code -1)".
           testserver.log: ERROR line with the output.

6. Path the sidecar does not serve
   Before: Edge Server: http_log _end with 404. Sync Gateway and
           Couchbase Server: nothing logged. testserver.log: nothing.
   After:  http_log _end with "404 (exit code None)".
           testserver.log: ERROR line with the body.

7. Sidecar call gets no response (client timeout, connection error)
   Before: Edge Server: http_log _begin only. Sync Gateway and
           Couchbase Server: nothing logged. testserver.log: nothing.
   After:  http_log _begin and _error. testserver.log: the same line
           as _error, which ends with the timeouts that applied.

8. Sync Gateway or Edge Server REST request gets no response
   Before: http_log _begin only. testserver.log: nothing.
   After:  http_log _begin and _error. testserver.log: the same line,
           except for readiness polls, which log nothing there.

9. Sync Gateway or Edge Server REST request gets a bad status
   Unchanged: http_log _begin and _end. testserver.log: nothing.

Examples (host names changed):

Case 2, http_log:

  Sync Gateway sidecar [10.0.0.1] -> GET /stop-sgw?timeout=57
  Sync Gateway sidecar [10.0.0.1] <- GET /stop-sgw?timeout=57 200 (exit code 0)

Case 4, testserver.log (http_log _end has the same output):

  [ERROR]: Sync Gateway sidecar [10.0.0.1]: GET /start-sgw?config=bootstrap&timeout=0.57 returned 500 (exit code 124):
  Starting Sync Gateway with config: /home/ec2-user/config/bootstrap.json...
  Waiting for Sync Gateway to start (PID: 27759)...
  start-sgw.sh timed out after 0.57s

  exec error: exit status 124

Case 5, testserver.log:

  [ERROR]: Edge Server sidecar [10.0.0.2]: POST /start-edgeserver returned 200 (exit code -1):
  before kill

  exec error: signal: killed

Case 7, http_log _error and testserver.log:

  [ERROR]: Sync Gateway sidecar [10.0.0.1] <- GET /stop-sgw?timeout=57 failed: GET http://10.0.0.1:20001/stop-sgw?timeout=57 timed out after 60.0s waiting for the response (total 60s, sock_connect 30s)

Case 8, http_log _error and testserver.log:

  [ERROR]: Edge Server [10.0.0.2] <- GET / failed: Expecting value: line 1 column 1 (char 0)

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
@torcolvin
torcolvin force-pushed the shell2http-timeouts branch from 314b882 to 81e6036 Compare October 7, 2026 01:14
@torcolvin
torcolvin marked this pull request as ready for review October 7, 2026 01:15
@torcolvin
torcolvin merged commit f242b2a into main Oct 7, 2026
3 checks passed
@torcolvin
torcolvin deleted the shell2http-timeouts branch October 7, 2026 13:42
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants