diff --git a/.changeset/command-stream-cancel-logging.md b/.changeset/command-stream-cancel-logging.md new file mode 100644 index 0000000000..5a861d94bc --- /dev/null +++ b/.changeset/command-stream-cancel-logging.md @@ -0,0 +1,6 @@ +--- +"e2b": patch +"@e2b/python-sdk": patch +--- + +Log the local cause when a command output stream is cancelled. `CommandHandle` (sync and async, in both the Python and JS SDKs) now records, via the logger the sandbox was constructed with, why the stream ended — explicit `disconnect()`, an early stop of iteration/cancellation, or a stream error before the end event — tagged with the command pid, at most once per handle. This is a no-op when no logger is configured, so behavior is unchanged for callers that did not opt into logging. It gives the client-side reason to correlate with the server-side "stream end" line (e2b-dev/E2B#1877, e2b-dev/runtime#3647). diff --git a/packages/js-sdk/src/sandbox/commands/commandHandle.ts b/packages/js-sdk/src/sandbox/commands/commandHandle.ts index 759d17fe51..f5a5a854c7 100644 --- a/packages/js-sdk/src/sandbox/commands/commandHandle.ts +++ b/packages/js-sdk/src/sandbox/commands/commandHandle.ts @@ -4,6 +4,7 @@ import { } from '../../envd/rpc' import { SandboxError } from '../../errors' import { ConnectResponse, StartResponse } from '../../envd/process/process_pb' +import { Logger } from '../../logs' import type { CommandRequestOpts } from '.' declare const __brand: unique symbol @@ -121,11 +122,31 @@ export class CommandHandle private readonly handleCloseStdin?: ( opts?: CommandRequestOpts ) => Promise, - private readonly checkHealth?: SandboxHealthCheck + private readonly checkHealth?: SandboxHealthCheck, + private readonly logger?: Logger ) { this._wait = this.handleEvents() } + private streamEndLogged = false + + /** + * Record why the command's output stream ended on the client side. + * + * The server (envd) only sees that the stream was cancelled, not why; this + * logs the local cause so the two can be correlated. No-op when no logger was + * configured. Records at most once per handle so the disconnect() and + * stream-error paths cannot emit two contradictory causes for the same + * command. See e2b-dev/E2B#1877. + */ + private logStreamEnded(reason: string) { + if (!this.logger?.info || this.streamEndLogged) { + return + } + this.streamEndLogged = true + this.logger.info(`command stream ended (pid=${this.pid}): ${reason}`) + } + /** * Command execution exit code. * `0` if the command finished successfully. @@ -193,6 +214,7 @@ export class CommandHandle * whose stream produces no further output. */ async disconnect() { + this.logStreamEnded('explicit disconnect() (command left running)') this.disconnected = true this.handleDisconnect() } @@ -328,6 +350,9 @@ export class CommandHandle // failure). Flush any bytes still buffered in the decoders so incomplete // trailing sequences surface as replacement characters instead of being // silently dropped, then re-raise so the error is still surfaced. + this.logStreamEnded( + `stream error before end event: ${e instanceof Error ? `${e.name}: ${e.message}` : String(e)}` + ) yield* this.flushDecoders() throw e } diff --git a/packages/js-sdk/src/sandbox/commands/index.ts b/packages/js-sdk/src/sandbox/commands/index.ts index 22c9a4028d..245e6c2d06 100644 --- a/packages/js-sdk/src/sandbox/commands/index.ts +++ b/packages/js-sdk/src/sandbox/commands/index.ts @@ -37,9 +37,8 @@ export { Pty } from './pty' /** * Options for sending a command request. */ -export interface CommandRequestOpts extends Partial< - Pick -> {} +export interface CommandRequestOpts + extends Partial> {} /** * Options for starting a new command. @@ -364,7 +363,8 @@ export class Commands { undefined, (data, stdinOpts) => this.sendStdin(pid, data, stdinOpts), (stdinOpts) => this.closeStdin(pid, stdinOpts), - this.checkHealth + this.checkHealth, + this.connectionConfig.logger ) } catch (err) { cleanup() @@ -479,7 +479,8 @@ export class Commands { undefined, (data, stdinOpts) => this.sendStdin(pid, data, stdinOpts), (stdinOpts) => this.closeStdin(pid, stdinOpts), - this.checkHealth + this.checkHealth, + this.connectionConfig.logger ) } catch (err) { cleanup() diff --git a/packages/js-sdk/src/sandbox/commands/pty.ts b/packages/js-sdk/src/sandbox/commands/pty.ts index 29928a92f3..960bac7b52 100644 --- a/packages/js-sdk/src/sandbox/commands/pty.ts +++ b/packages/js-sdk/src/sandbox/commands/pty.ts @@ -30,10 +30,8 @@ import { handleProcessStartEvent, } from '../../envd/api' -export interface PtyCreateOpts extends Pick< - ConnectionOpts, - 'requestTimeoutMs' | 'signal' -> { +export interface PtyCreateOpts + extends Pick { /** * Number of columns for the PTY. */ @@ -157,7 +155,8 @@ export class Pty { opts.onData, undefined, undefined, - this.checkHealth + this.checkHealth, + this.connectionConfig.logger ) } catch (err) { cleanup() @@ -214,7 +213,8 @@ export class Pty { opts?.onData, undefined, undefined, - this.checkHealth + this.checkHealth, + this.connectionConfig.logger ) } catch (err) { cleanup() diff --git a/packages/python-sdk/e2b/sandbox_async/commands/command.py b/packages/python-sdk/e2b/sandbox_async/commands/command.py index 19d7e23649..1e484783d7 100644 --- a/packages/python-sdk/e2b/sandbox_async/commands/command.py +++ b/packages/python-sdk/e2b/sandbox_async/commands/command.py @@ -334,6 +334,7 @@ async def _start( pid, request_timeout ), check_health=self._check_health, + logger=self._connection_config.logger, ) except Exception as e: try: @@ -393,6 +394,7 @@ async def connect( pid, request_timeout ), check_health=self._check_health, + logger=self._connection_config.logger, ) except Exception as e: try: diff --git a/packages/python-sdk/e2b/sandbox_async/commands/command_handle.py b/packages/python-sdk/e2b/sandbox_async/commands/command_handle.py index 4168cfe63d..6b4dd06189 100644 --- a/packages/python-sdk/e2b/sandbox_async/commands/command_handle.py +++ b/packages/python-sdk/e2b/sandbox_async/commands/command_handle.py @@ -1,6 +1,7 @@ import asyncio import codecs import inspect +import logging from typing import ( Optional, Callable, @@ -95,6 +96,8 @@ def __init__( Callable[[Optional[float]], Coroutine[Any, Any, None]] ] = None, check_health: Optional[Callable[[], Awaitable[Optional[bool]]]] = None, + *, + logger: Optional[logging.Logger] = None, ): self._pid = pid self._handle_kill = handle_kill @@ -102,6 +105,8 @@ def __init__( self._handle_close_stdin = handle_close_stdin self._check_health = check_health self._events = events + self._logger = logger + self._stream_end_logged = False self._stdout_chunks: List[str] = [] self._stderr_chunks: List[str] = [] @@ -138,6 +143,21 @@ def _flush_decoders( events.append((None, err, None)) return events + def _log_stream_ended(self, reason: str) -> None: + """ + Record why the command's output stream ended on the client side. + + The server (envd) only sees that the stream was cancelled, not why; this + logs the local cause so the two can be correlated. No-op when no logger + was configured. Records at most once per handle so the disconnect() and + reader-task paths cannot emit two contradictory causes for the same + command. + """ + if self._logger is None or self._stream_end_logged: + return + self._stream_end_logged = True + self._logger.info("command stream ended (pid=%s): %s", self._pid, reason) + async def _iterate_events( self, ) -> AsyncGenerator[ @@ -209,6 +229,7 @@ async def disconnect(self) -> None: The command is not killed, but SDK stops receiving events from the command. You can reconnect to the command using `sandbox.commands.connect` method. """ + self._log_stream_ended("explicit disconnect() (command left running)") self._wait.cancel() await asyncio.wait([self._wait]) try: @@ -234,6 +255,9 @@ async def _handle_events(self): except StopAsyncIteration: pass except Exception as e: + self._log_stream_ended( + f"stream error before end event: {type(e).__name__}: {e}" + ) self._iteration_exception = await ahandle_rpc_exception_with_health( e, self._check_health ) diff --git a/packages/python-sdk/e2b/sandbox_async/commands/pty.py b/packages/python-sdk/e2b/sandbox_async/commands/pty.py index dda9d2e6f3..03f05fb86a 100644 --- a/packages/python-sdk/e2b/sandbox_async/commands/pty.py +++ b/packages/python-sdk/e2b/sandbox_async/commands/pty.py @@ -172,6 +172,7 @@ async def create( events=events, on_pty=on_data, check_health=self._check_health, + logger=self._connection_config.logger, ) except Exception as e: try: @@ -221,6 +222,7 @@ async def connect( events=events, on_pty=on_data, check_health=self._check_health, + logger=self._connection_config.logger, ) except Exception as e: try: diff --git a/packages/python-sdk/e2b/sandbox_sync/commands/command.py b/packages/python-sdk/e2b/sandbox_sync/commands/command.py index 0198c42c5a..80005dc602 100644 --- a/packages/python-sdk/e2b/sandbox_sync/commands/command.py +++ b/packages/python-sdk/e2b/sandbox_sync/commands/command.py @@ -330,6 +330,7 @@ def _start( pid, request_timeout ), check_health=self._check_health, + logger=self._connection_config.logger, ) except Exception as e: try: @@ -381,6 +382,7 @@ def connect( pid, request_timeout ), check_health=self._check_health, + logger=self._connection_config.logger, ) except Exception as e: try: diff --git a/packages/python-sdk/e2b/sandbox_sync/commands/command_handle.py b/packages/python-sdk/e2b/sandbox_sync/commands/command_handle.py index ea2b3fdad7..700d31eb40 100644 --- a/packages/python-sdk/e2b/sandbox_sync/commands/command_handle.py +++ b/packages/python-sdk/e2b/sandbox_sync/commands/command_handle.py @@ -1,4 +1,5 @@ import codecs +import logging from typing import Optional, Callable, Any, Generator, List, Union, Tuple @@ -42,6 +43,8 @@ def __init__( ] = None, handle_close_stdin: Optional[Callable[[Optional[float]], None]] = None, check_health: Optional[Callable[[], Optional[bool]]] = None, + *, + logger: Optional[logging.Logger] = None, ): self._pid = pid self._handle_kill = handle_kill @@ -49,6 +52,8 @@ def __init__( self._handle_close_stdin = handle_close_stdin self._check_health = check_health self._events = events + self._logger = logger + self._stream_end_logged = False self._stdout_chunks: List[str] = [] self._stderr_chunks: List[str] = [] @@ -67,6 +72,21 @@ def __iter__(self): """ return self._handle_events() + def _log_stream_ended(self, reason: str) -> None: + """ + Record why the command's output stream ended on the client side. + + The server (envd) only sees that the stream was cancelled, not why; this + logs the local cause so the two can be correlated. No-op when no logger + was configured. Records at most once per handle so the disconnect() and + generator-close paths cannot emit two contradictory causes for the same + command. + """ + if self._logger is None or self._stream_end_logged: + return + self._stream_end_logged = True + self._logger.info("command stream ended (pid=%s): %s", self._pid, reason) + def _flush_decoders( self, ) -> List[Union[Tuple[Stdout, None, None], Tuple[None, Stderr, None]]]: @@ -140,11 +160,24 @@ def _handle_events( # characters instead of being silently dropped. if self._result is None: yield from self._flush_decoders() + except GeneratorExit: + # The consumer stopped iterating before an end event (e.g. it broke + # out of the loop, was cancelled by a timeout/sibling task, or the + # caller exited). Closing this generator closes the underlying event + # stream, which the server (envd) records as a client cancellation — + # note the process itself is NOT killed and keeps running. Log the + # local cause so it can be correlated with the server-side line; + # see e2b-dev/E2B#1877. + self._log_stream_ended("consumer stopped iterating (break/cancel/exit)") + raise except Exception as e: # The stream raised before an end event (e.g. disconnect or RPC # failure). Flush any bytes still buffered in the decoders so # incomplete trailing sequences surface as replacement characters # instead of being silently dropped, then surface the error. + self._log_stream_ended( + f"stream error before end event: {type(e).__name__}: {e}" + ) yield from self._flush_decoders() raise handle_rpc_exception_with_health(e, self._check_health) @@ -155,6 +188,7 @@ def disconnect(self) -> None: The command is not killed, but SDK stops receiving events from the command. You can reconnect to the command using `sandbox.commands.connect` method. """ + self._log_stream_ended("explicit disconnect() (command left running)") self._events.close() def wait( diff --git a/packages/python-sdk/e2b/sandbox_sync/commands/pty.py b/packages/python-sdk/e2b/sandbox_sync/commands/pty.py index 9465007759..b4893bf0f6 100644 --- a/packages/python-sdk/e2b/sandbox_sync/commands/pty.py +++ b/packages/python-sdk/e2b/sandbox_sync/commands/pty.py @@ -163,6 +163,7 @@ def create( handle_kill=lambda: self.kill(pid), events=events, check_health=self._check_health, + logger=self._connection_config.logger, ) except Exception as e: try: @@ -207,6 +208,7 @@ def connect( handle_kill=lambda: self.kill(pid), events=events, check_health=self._check_health, + logger=self._connection_config.logger, ) except Exception as e: try: diff --git a/packages/python-sdk/tests/test_command_handle.py b/packages/python-sdk/tests/test_command_handle.py index 6a2f81c1ad..84683778dc 100644 --- a/packages/python-sdk/tests/test_command_handle.py +++ b/packages/python-sdk/tests/test_command_handle.py @@ -1,4 +1,5 @@ import asyncio +import logging from typing import Any, cast import pytest @@ -288,3 +289,98 @@ async def events(): # be flushed to the stdout callback as a replacement character. assert "".join(chunks) == "a�" assert isinstance(handle._iteration_exception, RuntimeError) + + +def _capturing_logger(name: str): + """A real logging.Logger whose INFO messages are captured into a list.""" + messages: list[str] = [] + + class _ListHandler(logging.Handler): + def emit(self, record: logging.LogRecord) -> None: + messages.append(record.getMessage()) + + logger = logging.getLogger(name) + logger.handlers = [_ListHandler()] + logger.setLevel(logging.INFO) + logger.propagate = False + return logger, messages + + +def test_sync_logs_stream_end_cause_on_stream_error(): + def events(): + yield _stdout_event(b"a") + raise RuntimeError("stream died") + + logger, messages = _capturing_logger("e2b.test.sync.err") + handle = CommandHandle( + pid=42, handle_kill=lambda: True, events=events(), logger=logger + ) + + with pytest.raises(RuntimeError): + handle.wait() + + assert len(messages) == 1 + assert "pid=42" in messages[0] + assert "stream error before end event" in messages[0] + assert "RuntimeError" in messages[0] + + +def test_sync_logs_disconnect_cause_once(): + # disconnect() records the cause; the subsequent GeneratorExit path must not + # add a second, contradictory line for the same command (T-62 idempotency). + def events(): + yield _stdout_event(b"a") + yield _end_event() + + logger, messages = _capturing_logger("e2b.test.sync.disc") + handle = CommandHandle( + pid=7, handle_kill=lambda: True, events=events(), logger=logger + ) + handle.disconnect() + + assert len(messages) == 1 + assert "pid=7" in messages[0] + assert "disconnect()" in messages[0] + + +def test_sync_no_log_without_logger(): + # No logger configured -> no logging attribute access, no error, no output. + def events(): + yield _end_event() + + handle = CommandHandle(pid=1, handle_kill=lambda: True, events=events()) + handle.disconnect() # must not raise + + +async def test_async_logs_stream_end_cause_on_stream_error(): + async def events(): + yield _stdout_event(b"a") + raise RuntimeError("stream died") + + logger, messages = _capturing_logger("e2b.test.async.err") + handle = AsyncCommandHandle( + pid=99, handle_kill=_kill, events=events(), logger=logger + ) + await handle._wait + + assert len(messages) == 1 + assert "pid=99" in messages[0] + assert "stream error before end event" in messages[0] + + +async def test_async_logs_disconnect_cause_once(): + events = _AsyncControllableEvents() + logger, messages = _capturing_logger("e2b.test.async.disc") + handle = AsyncCommandHandle( + pid=8, + handle_kill=_kill, + events=cast(Any, events), + logger=logger, + ) + await handle.disconnect() + + # Exactly one cause, even though disconnect() cancels the reader task whose + # own error path would otherwise log a second line (T-62 idempotency). + assert len(messages) == 1 + assert "pid=8" in messages[0] + assert "disconnect()" in messages[0]