`SANDBOX` log level deprecation #44

craigwalton-dsit · 2025-01-03T12:06:03Z

The SANDBOX log level was removed when the TRACE log level and associated functionality (docs) was added to Inspect (PR).

JJ recommended (Slack) using:

trace_action() for any long running tasks that we'd like the lifecycle logged of (so in our case, Helm install/uninstall and Pod ops like exec())
trace_message() for any other informational logging which used to be at SANDBOX log level (like listing Pods, or logging exec() results)

It is great that these logs will be automatically captured. Though there will be some added friction of dumping these logs, filtering them to just K8s-relevant ones (i.e. removing model API calls), then extracting just the relevant message to build up an equivalent view of what the old SANDBOX log level provided.

src/k8s_sandbox/_sandbox_environment.py

craigwalton-dsit · 2025-01-03T12:25:19Z

Here is the TRACE log from a very simple eval which does

await sandbox().exec(["echo", "Hello, world!"])
await sandbox().read_file("/etc/fake")

[
  {
    "timestamp": "2025-01-03T12:23:33.212484",
    "level": "TRACE",
    "message": "Subprocess: helm version --short (enter)",
    "action": "Subprocess",
    "event": "enter",
    "trace_id": "H3HUrwrmkRRcdgvC35sacK",
    "detail": "helm version --short",
    "start_time": 1735907013.2124557,
    "pid": 61008
  },
  {
    "timestamp": "2025-01-03T12:23:33.306512",
    "level": "TRACE",
    "message": "Subprocess: helm version --short (exit)",
    "action": "Subprocess",
    "event": "exit",
    "trace_id": "H3HUrwrmkRRcdgvC35sacK",
    "detail": "helm version --short",
    "duration": 0.0940287090052152,
    "pid": 61008
  },
  {
    "timestamp": "2025-01-03T12:23:34.171327",
    "level": "TRACE",
    "message": "K8s install Helm chart: {\"chart\": \"/home/ubuntu/r/inspect_k8s_sandbox/src/k8s_sandbox/resources/helm/agent-env\", \"release\": \"wc3wp4ys\", \"values\": \"None\", \"namespace\": \"agent\", \"task\": \"my_task\"} (enter)",
    "action": "K8s install Helm chart",
    "event": "enter",
    "trace_id": "BLgPH27yW3FHxcHbXvPRt3",
    "detail": "{\"chart\": \"/home/ubuntu/r/inspect_k8s_sandbox/src/k8s_sandbox/resources/helm/agent-env\", \"release\": \"wc3wp4ys\", \"values\": \"None\", \"namespace\": \"agent\", \"task\": \"my_task\"}",
    "start_time": 1735907014.171301,
    "pid": 61008
  },
  {
    "timestamp": "2025-01-03T12:23:39.330657",
    "level": "TRACE",
    "message": "K8s install Helm chart: {\"chart\": \"/home/ubuntu/r/inspect_k8s_sandbox/src/k8s_sandbox/resources/helm/agent-env\", \"release\": \"wc3wp4ys\", \"values\": \"None\", \"namespace\": \"agent\", \"task\": \"my_task\"} (exit)",
    "action": "K8s install Helm chart",
    "event": "exit",
    "trace_id": "BLgPH27yW3FHxcHbXvPRt3",
    "detail": "{\"chart\": \"/home/ubuntu/r/inspect_k8s_sandbox/src/k8s_sandbox/resources/helm/agent-env\", \"release\": \"wc3wp4ys\", \"values\": \"None\", \"namespace\": \"agent\", \"task\": \"my_task\"}",
    "duration": 5.159330975991907,
    "pid": 61008
  },
  {
    "timestamp": "2025-01-03T12:23:39.360260",
    "level": "TRACE",
    "message": "[K8s] Available sandboxes: ['default']"
  },
  {
    "timestamp": "2025-01-03T12:23:39.361150",
    "level": "TRACE",
    "message": "K8s execute command in Pod: {\"pod\": \"agent-env-wc3wp4ys-default-0\", \"task_name\": \"my_task\", \"cmd\": \"['echo', 'Hello, world!']\", \"stdin\": \"None\", \"cwd\": \"None\", \"env\": \"{}\", \"timeout\": \"None\"} (enter)",
    "action": "K8s execute command in Pod",
    "event": "enter",
    "trace_id": "5tAWFGHx2uQZ2ra9Wosr3H",
    "detail": "{\"pod\": \"agent-env-wc3wp4ys-default-0\", \"task_name\": \"my_task\", \"cmd\": \"['echo', 'Hello, world!']\", \"stdin\": \"None\", \"cwd\": \"None\", \"env\": \"{}\", \"timeout\": \"None\"}",
    "start_time": 1735907019.3611326,
    "pid": 61008
  },
  {
    "timestamp": "2025-01-03T12:23:39.361315",
    "level": "TRACE",
    "message": "[K8s] Creating PodOpExecutor. {\"max_workers\": \"64\"}"
  },
  {
    "timestamp": "2025-01-03T12:23:39.502075",
    "level": "TRACE",
    "message": "[K8s] Completed: K8s execute command in Pod. {\"cmd\": \"['echo', 'Hello, world!']\", \"stdin\": \"None\", \"cwd\": \"None\", \"env\": \"{}\", \"timeout\": \"None\", \"result\": \"ExecResult(success=True, returncode=0, stdout='Hello, world!\\\\n', stderr='')\"}"
  },
  {
    "timestamp": "2025-01-03T12:23:39.502209",
    "level": "TRACE",
    "message": "K8s execute command in Pod: {\"pod\": \"agent-env-wc3wp4ys-default-0\", \"task_name\": \"my_task\", \"cmd\": \"['echo', 'Hello, world!']\", \"stdin\": \"None\", \"cwd\": \"None\", \"env\": \"{}\", \"timeout\": \"None\"} (exit)",
    "action": "K8s execute command in Pod",
    "event": "exit",
    "trace_id": "5tAWFGHx2uQZ2ra9Wosr3H",
    "detail": "{\"pod\": \"agent-env-wc3wp4ys-default-0\", \"task_name\": \"my_task\", \"cmd\": \"['echo', 'Hello, world!']\", \"stdin\": \"None\", \"cwd\": \"None\", \"env\": \"{}\", \"timeout\": \"None\"}",
    "duration": 0.1410653100028867,
    "pid": 61008
  },
  {
    "timestamp": "2025-01-03T12:23:39.502476",
    "level": "TRACE",
    "message": "K8s read file from Pod: {\"pod\": \"agent-env-wc3wp4ys-default-0\", \"task_name\": \"my_task\", \"file\": \"/etc/fake\"} (enter)",
    "action": "K8s read file from Pod",
    "event": "enter",
    "trace_id": "ZqfnRFFmE5DTqpjSWcovVT",
    "detail": "{\"pod\": \"agent-env-wc3wp4ys-default-0\", \"task_name\": \"my_task\", \"file\": \"/etc/fake\"}",
    "start_time": 1735907019.502465,
    "pid": 61008
  },
  {
    "timestamp": "2025-01-03T12:23:39.648277",
    "level": "TRACE",
    "message": "K8s read file from Pod: {\"pod\": \"agent-env-wc3wp4ys-default-0\", \"task_name\": \"my_task\", \"file\": \"/etc/fake\"} (error)",
    "action": "K8s read file from Pod",
    "event": "error",
    "trace_id": "ZqfnRFFmE5DTqpjSWcovVT",
    "detail": "{\"pod\": \"agent-env-wc3wp4ys-default-0\", \"task_name\": \"my_task\", \"file\": \"/etc/fake\"}",
    "duration": 0.14460575599514414,
    "error": "head: cannot open '/etc/fake' for reading: No such file or directory\n",
    "error_type": "FileNotFoundError",
    "stacktrace": "Traceback (most recent call last):\n  File \"/home/ubuntu/r/inspect_k8s_sandbox/.venv/lib/python3.12/site-packages/inspect_ai/_util/trace.py\", line 55, in trace_action\n    yield\n  File \"/home/ubuntu/r/inspect_k8s_sandbox/src/k8s_sandbox/_logger.py\", line 73, in inspect_trace_action\n    yield\n  File \"/home/ubuntu/r/inspect_k8s_sandbox/src/k8s_sandbox/_sandbox_environment.py\", line 201, in _log_op\n    yield\n  File \"/home/ubuntu/r/inspect_k8s_sandbox/src/k8s_sandbox/_sandbox_environment.py\", line 174, in read_file\n    await self._pod.read_file(Path(file), temp_file)\n  File \"/home/ubuntu/r/inspect_k8s_sandbox/src/k8s_sandbox/_pod/pod.py\", line 108, in read_file\n    await self._run_async(lambda: reader.read_file(src, dst))\n  File \"/home/ubuntu/r/inspect_k8s_sandbox/src/k8s_sandbox/_pod/pod.py\", line 113, in _run_async\n    return await executor.queue_operation(callable)\n           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/home/ubuntu/r/inspect_k8s_sandbox/src/k8s_sandbox/_pod/executor.py\", line 64, in queue_operation\n    return await asyncio.get_event_loop().run_in_executor(\n           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/usr/lib/python3.12/concurrent/futures/thread.py\", line 58, in run\n    result = self.fn(*self.args, **self.kwargs)\n             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/home/ubuntu/r/inspect_k8s_sandbox/src/k8s_sandbox/_pod/pod.py\", line 108, in <lambda>\n    await self._run_async(lambda: reader.read_file(src, dst))\n                                  ^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/home/ubuntu/r/inspect_k8s_sandbox/src/k8s_sandbox/_pod/read.py\", line 21, in read_file\n    self._handle_stream_output(ws_client, dst)\n  File \"/home/ubuntu/r/inspect_k8s_sandbox/src/k8s_sandbox/_pod/read.py\", line 55, in _handle_stream_output\n    raise_for_known_read_write_errors(stderr_str)\n  File \"/home/ubuntu/r/inspect_k8s_sandbox/src/k8s_sandbox/_pod/op.py\", line 101, in raise_for_known_read_write_errors\n    raise FileNotFoundError(stderr)\nFileNotFoundError: head: cannot open '/etc/fake' for reading: No such file or directory\n\n",
    "pid": 61008
  },
  {
    "timestamp": "2025-01-03T12:23:39.653624",
    "level": "TRACE",
    "message": "K8s uninstall Helm chart: {\"release\": \"wc3wp4ys\", \"namespace\": \"agent\"} (enter)",
    "action": "K8s uninstall Helm chart",
    "event": "enter",
    "trace_id": "Vo6mRGSDYPgfMC6jwAA2qw",
    "detail": "{\"release\": \"wc3wp4ys\", \"namespace\": \"agent\"}",
    "start_time": 1735907019.6536076,
    "pid": 61008
  },
  {
    "timestamp": "2025-01-03T12:23:40.644737",
    "level": "TRACE",
    "message": "K8s uninstall Helm chart: {\"release\": \"wc3wp4ys\", \"namespace\": \"agent\"} (exit)",
    "action": "K8s uninstall Helm chart",
    "event": "exit",
    "trace_id": "Vo6mRGSDYPgfMC6jwAA2qw",
    "detail": "{\"release\": \"wc3wp4ys\", \"namespace\": \"agent\"}",
    "duration": 0.9911043200118002,
    "pid": 61008
  },
  {
    "timestamp": "2025-01-03T12:23:40.754066",
    "level": "TRACE",
    "message": "Log Write: /home/ubuntu/r/inspect_k8s_sandbox/logs/2025-01-03T12-23-33+00-00_my-task_3LRdMRwMXjGhih36PiBAes.eval (enter)",
    "action": "Log Write",
    "event": "enter",
    "trace_id": "7PTNRquWgiy6WGDTkSJvyU",
    "detail": "/home/ubuntu/r/inspect_k8s_sandbox/logs/2025-01-03T12-23-33+00-00_my-task_3LRdMRwMXjGhih36PiBAes.eval",
    "start_time": 1735907020.7540398,
    "pid": 61008
  },
  {
    "timestamp": "2025-01-03T12:23:40.754984",
    "level": "TRACE",
    "message": "Log Write: /home/ubuntu/r/inspect_k8s_sandbox/logs/2025-01-03T12-23-33+00-00_my-task_3LRdMRwMXjGhih36PiBAes.eval (exit)",
    "action": "Log Write",
    "event": "exit",
    "trace_id": "7PTNRquWgiy6WGDTkSJvyU",
    "detail": "/home/ubuntu/r/inspect_k8s_sandbox/logs/2025-01-03T12-23-33+00-00_my-task_3LRdMRwMXjGhih36PiBAes.eval",
    "duration": 0.0009293270122725517,
    "pid": 61008
  }
]

src/k8s_sandbox/_sandbox_environment.py

…level.

…(`TRACE` level).

…w that SANDBOX log level does not exist).

…RACE level.

jasongwartz-aisi

Looks good to me, nice improvement! I've left a couple non-blocking comments.

docs/docs/tips/debugging-k8s-sandboxes.md

src/k8s_sandbox/_sandbox_environment.py

craigwalton-dsit commented Jan 3, 2025

View reviewed changes

src/k8s_sandbox/_sandbox_environment.py Show resolved Hide resolved

craigwalton-dsit force-pushed the craig/sandbox-log-level-deprecation branch 2 times, most recently from e2becef to 32b257d Compare January 3, 2025 12:19

craigwalton-dsit commented Jan 3, 2025

View reviewed changes

src/k8s_sandbox/_sandbox_environment.py Show resolved Hide resolved

craigwalton-dsit marked this pull request as ready for review January 3, 2025 14:07

craigwalton-dsit added 9 commits January 3, 2025 14:11

Update to latest inspect_ai ahead of removing usage of SANDBOX log …

d4fa52d

…level.

Remove usage of SANDBOX log level and replace with trace_message …

91ff17b

…(`TRACE` level).

Migrate to using Inspect's trace_action for Pod ops lifecycle logging.

b2fb6b5

Make Helm install/uninstall use Inspect's trace_action.

a0c40f4

Remove log_level="SANDBOX" from test as this level no longer exists.

d881656

Prefix action names with K8s to facilitate grepping trace logs.

c65bd76

Rename logger functions to better reflect what they do (especially no…

1b8eb64

…w that SANDBOX log level does not exist).

Update docs to reflect removal of SANDBOX log level and replacement T…

034615f

…RACE level.

Add changelog entry for SANDBOX -> TRACE.

b3a15c9

craigwalton-dsit force-pushed the craig/sandbox-log-level-deprecation branch from 32b257d to b3a15c9 Compare January 3, 2025 14:14

craigwalton-dsit requested a review from jasongwartz-aisi January 3, 2025 15:20

jasongwartz-aisi approved these changes Jan 3, 2025

View reviewed changes

docs/docs/tips/debugging-k8s-sandboxes.md Show resolved Hide resolved

src/k8s_sandbox/_sandbox_environment.py Show resolved Hide resolved

src/k8s_sandbox/_sandbox_environment.py Show resolved Hide resolved

Require inspect_ai >= 0.3.54 for trace_action and trace_message.

04d2c93

craigwalton-dsit merged commit aaa42ee into main Jan 6, 2025
5 checks passed

craigwalton-dsit deleted the craig/sandbox-log-level-deprecation branch January 6, 2025 11:52

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

`SANDBOX` log level deprecation #44

`SANDBOX` log level deprecation #44

craigwalton-dsit commented Jan 3, 2025 •

edited

Loading

craigwalton-dsit commented Jan 3, 2025

jasongwartz-aisi left a comment

SANDBOX log level deprecation #44

SANDBOX log level deprecation #44

Conversation

craigwalton-dsit commented Jan 3, 2025 • edited Loading

craigwalton-dsit commented Jan 3, 2025

jasongwartz-aisi left a comment

Choose a reason for hiding this comment

`SANDBOX` log level deprecation #44

`SANDBOX` log level deprecation #44

craigwalton-dsit commented Jan 3, 2025 •

edited

Loading