Skip to content

Add additional logging to subscribe route and simplify calling client_connected#2998

Merged
gefjon merged 2 commits into
masterfrom
phoebe/subscribe-route-extra-logging
Jul 29, 2025
Merged

Add additional logging to subscribe route and simplify calling client_connected#2998
gefjon merged 2 commits into
masterfrom
phoebe/subscribe-route-extra-logging

Conversation

@gefjon
Copy link
Copy Markdown
Contributor

@gefjon gefjon commented Jul 29, 2025

Description of Changes

Out-of-band discussions with the BitCraft team brought up questions about whether it was possible for a rejected client connection to start an expensive computation like a subscription before their connection was killed, e.g. by sending a Subscribe message along the WebSocket before client_connected had finished returning Err.

I don't believe this was actually possible, as ClientConnection::spawn called and awaited call_identity_connected before invoking its actor closure, and it was that actor which processed Subscribe messages. But it was somewhat difficult to verify that behavior, and so I re-organized the code so that the outer layer of the subscribe handler obviously had that property without having to step into ClientConnection::spawn.

I also added some additional logging to the subscribe route, including the X-Forwarded-For header in more messages, as the BitCraft team complained about having difficulty correlating IP addresses with connections. The log levels remain the same as before, just with additional information added:

  • Successful connections are at debug level,
  • Rejected connections are at info level (these are the ones BitCraft cares about in this case).
  • Failed connections are at warn.

As the levels are unchanged, this should not add undesirable log noise.

API and ABI breaking changes

N/a

Expected complexity level and risk

3? The subscribe route was complex and remains so. I believe this change simplifies the code and makes the logic more obvious, but reviewers should take care to verify that the behavior actually is equivalent as I believe.

Testing

  • I would like a test deployment of BitCraft to staging or something, or to include this patch in the next bot test that we do anyways, just for sanity's sake.

…t_connected`

Out-of-band discussions with the BitCraft team
brought up questions about whether it was possible for a rejected client connection
to start an expensive computation like a subscription before their connection was killed,
e.g. by sending a `Subscribe` message along the WebSocket
before `client_connected` had finished returning `Err`.

I don't believe this was actually possible,
as `ClientConnection::spawn` called and awaited `call_identity_connected`
before invoking its `actor` closure,
and it was that `actor` which processed `Subscribe` messages.
But it was somewhat difficult to verify that behavior,
and so I re-organized the code so that the outer layer of the `subscribe` handler
obviously had that property without having to step into `ClientConnection::spawn`.

I also added some additional logging to the subscribe route,
including the `X-Forwarded-For` header in more messages,
as the BitCraft team complained about having difficulty correlating IP addresses with connections.
The log levels remain the same as before, just with additional information added:

- Successful connections are at `debug` level,
- Rejected connections are at `info` level
  (these are the ones BitCraft cares about in this case).
- Failed connections are at `warn`.

As the levels are unchanged, this should not add undesirable log noise.
@gefjon gefjon requested a review from kim July 29, 2025 16:00
Copy link
Copy Markdown
Contributor

@kim kim left a comment

Choose a reason for hiding this comment

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

Looks reasonable to me. fwiw, there is a smoketest that tests rejection via the client_connected reducer.

Comment thread crates/core/src/client/client_connection.rs
Comment thread crates/client-api/src/routes/subscribe.rs Outdated
Comment thread crates/client-api/src/routes/subscribe.rs Outdated
- Add `struct Connected` which acts as a "proof" of having called `client_connected`,
  rather than just relying on docstrings to enforce correct usage.
- Drop a log that prints on successful connections to `debug`,
  in keeping with the PR description.
- Slap the prefix `websocket: ` into log messages for easier filtering.
@gefjon gefjon enabled auto-merge July 29, 2025 18:03
@gefjon gefjon added this pull request to the merge queue Jul 29, 2025
Merged via the queue into master with commit c18b291 Jul 29, 2025
25 checks passed
mamcx pushed a commit that referenced this pull request Aug 26, 2025
…t_connected` (#2998)

# Description of Changes

Out-of-band discussions with the BitCraft team brought up questions
about whether it was possible for a rejected client connection to start
an expensive computation like a subscription before their connection was
killed, e.g. by sending a `Subscribe` message along the WebSocket before
`client_connected` had finished returning `Err`.

I don't believe this was actually possible, as `ClientConnection::spawn`
called and awaited `call_identity_connected` before invoking its `actor`
closure, and it was that `actor` which processed `Subscribe` messages.
But it was somewhat difficult to verify that behavior, and so I
re-organized the code so that the outer layer of the `subscribe` handler
obviously had that property without having to step into
`ClientConnection::spawn`.

I also added some additional logging to the subscribe route, including
the `X-Forwarded-For` header in more messages, as the BitCraft team
complained about having difficulty correlating IP addresses with
connections. The log levels remain the same as before, just with
additional information added:

- Successful connections are at `debug` level,
- Rejected connections are at `info` level (these are the ones BitCraft
cares about in this case).
- Failed connections are at `warn`.

As the levels are unchanged, this should not add undesirable log noise.

# API and ABI breaking changes

N/a

# Expected complexity level and risk

3? The `subscribe` route was complex and remains so. I believe this
change simplifies the code and makes the logic more obvious, but
reviewers should take care to verify that the behavior actually is
equivalent as I believe.

# Testing

- [ ] I would like a test deployment of BitCraft to staging or
something, or to include this patch in the next bot test that we do
anyways, just for sanity's sake.
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.

2 participants