Efficient live access to container logs » History » Version 4
Tom Clegg, 08/08/2023 06:48 PM
1 | 1 | Tom Clegg | h1. Efficient live access to container logs |
---|---|---|---|
2 | |||
3 | 4 | Tom Clegg | See #16442 and related issues for implementation history. |
4 | |||
5 | 1 | Tom Clegg | {{toc}} |
6 | |||
7 | h2. Goals |
||
8 | |||
9 | * Low latency: deliver live logs to clients (workbench/cli) as quickly as possible |
||
10 | * Scalable: don't generate significant load in RailsAPI |
||
11 | * Scalable: don't generate significant load in PostgreSQL |
||
12 | * Efficient: don't waste resources on event streams that nobody is listening to |
||
13 | * Robust: Don't let a badly behaved container (writing many gigabytes of logs) impede others |
||
14 | * Dependable: Retain complete logs (container/crunch-run/crunchstat) _in the log collection_ even in the event that crunch-run or the compute instance itself dies unexpectedly (_e.g.,_ bug, out of memory, hardware failure) |
||
15 | |||
16 | h2. Proposed architecture |
||
17 | |||
18 | * crunch-run offers a “container logs” API at its container gateway server |
||
19 | * controller offers a “container logs” API that works whether the container is finished or not |
||
20 | ** proxies to crunch-run _or_ keep-web (depends on whether the container is running) |
||
21 | * “container logs” API has two parts: |
||
22 | ** webdav: read file content from the log collection |
||
23 | ** server-sent-events stream: get notifications as logs appear (see below) |
||
24 | * dispatcher provides “plan B” to save logs when crunch-run crashes, instance dies, etc. |
||
25 | ** dispatcher routinely retrieves live logs from container gateway, and buffers content to local disk |
||
26 | ** dispatcher discards buffered logs when crunch-run commits to log collection |
||
27 | ** when crunch-run exits, dispatcher checks whether crunch-run managed to save the full log collection and, if needed, appends the latest buffered logs |
||
28 | * command-line client can “tail” and “tail -f” logs from a running container |
||
29 | * workbench2 uses a single code path to retrieve logs (instead of choosing webdav or logs table based on whether container is running) |
||
30 | |||
31 | h2. API details |
||
32 | |||
33 | 2 | Tom Clegg | @GET /arvados/v1/container_requests/{uuid}/log/{container_uuid}/stderr.txt@ |
34 | 1 | Tom Clegg | |
35 | ** client will use Range headers to request partial content |
||
36 | 3 | Tom Clegg | ** client will add the @{container_uuid}/@ part explicitly using the @container_uuid@ field from the container request record -- @/arvados/v1/container_requests/{uuid}/log/@ is a valid WebDAV endpoint but the client cannot rely on that directory listing to return the @{container_uuid}/@ subdirectory |
37 | 1 | Tom Clegg | |
38 | 2 | Tom Clegg | @GET /arvados/v1/container_requests/{uuid}/log_events@ |
39 | 1 | Tom Clegg | |
40 | ** response is a "server-sent events":https://developer.mozilla.org/en-US/docs/Web/API/Server-sent_events/Using_server-sent_events stream, data is JSON-encoded |
||
41 | ** a “file_sizes” event indicates the current size of new/updated files in the log collection |
||
42 | @event: file_sizes@ |
||
43 | 2 | Tom Clegg | @data: {"{container_uuid}/stderr.txt":1234,"{container_uuid}/stdout.txt":0,"{container_uuid}/crunch-run.txt":2345}@ |
44 | 1 | Tom Clegg | ** after the first message, unchanged files may be omitted: |
45 | @event: file_sizes@ |
||
46 | 2 | Tom Clegg | @data: {"{container_uuid}/stderr.txt":1444,"{container_uuid}/stdout.txt":72}@ |
47 | 1 | Tom Clegg | ** a “final” message indicates that the log collection is finalized and no further file_sizes events will be sent: |
48 | @event: final@ |
||
49 | ** a “retry” message indicates how long, in milliseconds, the client should wait before reconnecting after a disconnect (per SSE spec): |
||
50 | @retry: 2000@ |
||
51 | ** empty comments are sent periodically to keep the connection alive during idle periods |
||
52 | @:@ |
||
53 | ** after the “final” message, the connection either remains open and silent, or closes after specifying a long reconnect delay in a “retry” message (the idea is to avoid sending an inattentive client into a reconnect cycle - this doesn't affect well-behaved clients because they will hang up after receiving the “final” message) |
||
54 | ** @?maxInterval=X@ sets the maximum interval between messages (i.e., keepalive) to X seconds, default 15 |
||
55 | ** @?minInterval=X@ increases the minimum interval between messages (i.e., throttle) to X seconds, default 1 |
||
56 | |||
57 | h2. Authentication |
||
58 | |||
59 | |||
60 | The browser's EventSource API allows the caller to enable existing cached credentials/cookies, but not to explicitly set an Authorization header or another custom header. |
||
61 | * @?api_token=v2/...@ in the URL is easy to support on the client and server |
||
62 | ** this is not ideal: the token is likely to be logged by HTTP servers/proxies |
||
63 | ** we already accept this situation in our websocket usage |
||
64 | |||
65 | Server also accepts the usual Authorization header, and this should be used by clients that have the capability (e.g., arvados-client). |
||
66 | |||
67 | Future version may also support a “copy Authorization header into cookie” endpoint |
||
68 | ** client requests @GET /arvados/v1/cookie@ request with the token in the Authorization request header |
||
69 | ** response sets a cookie with the provided token |
||
70 | ** client sets up EventSource using @{withCredentials: true}@ |
||
71 | ** this approach is inherently flawed in that applications in different tabs (e.g., wb2.clusterA and wb2.clusterB, where A and B are in a federation) will unknowingly fight over which cookie should be sent to cluster A. |
||
72 | |||
73 | Future version may also support a “provide short-lived token” endpoint |
||
74 | ** client requests @GET /arvados/v1/api_client_authorizations/:uuid/slt@ with the real API token in an Authorization request header |
||
75 | ** response contains a new token that will only be recognized for the next 15 seconds |
||
76 | ** client sets up EventSource using @?slt={newtoken}@ |
||
77 | ** event stream sends a message with the real token in the “id” field |
||
78 | ** when reconnecting, the browser automatically sends the real token in the Last-Event-Id header |
||
79 | ** server uses the token in the Last-Event-Id field, if provided |
||
80 | |||
81 | h2. Client pseudocode |
||
82 | |||
83 | to reliably display logs for container with uuid C: |
||
84 | |||
85 | <pre> |
||
86 | 2 | Tom Clegg | connect to server-sent-events endpoint /arvados/v1/container_requests/{CR}/log_events |
87 | 1 | Tom Clegg | on unexpected disconnect: |
88 | delay for duration indicated in last “retry” message |
||
89 | reconnect |
||
90 | on final: |
||
91 | disconnect |
||
92 | on file_sizes: |
||
93 | decode message data as json |
||
94 | compare each entry to last size received for corresponding file, if any |
||
95 | if desired, retrieve file data via webdav endpoint and present to user |
||
96 | </pre> |
||
97 | |||
98 | h2. Client (workbench2 / CLI) implementation notes |
||
99 | |||
100 | * optionally, if container state is complete/cancelled or CR state is final, client _may_ skip the log_events steps and just retrieve file data via webdav endpoint |
||
101 | * the client can rely on the server-sent-events stream to return a message, with sizes of all available log files, upon first connection, even if there are no available sizes yet (i.e., message.files may have zero keys) or the container is already finished |
||
102 | * message.files may have keys for newly added files that have not appeared in any previous message |
||
103 | * client should have logic to skip some content if the log file size grows faster than expected |
||
104 | |||
105 | h2. Crunch-run implementation notes |
||
106 | |||
107 | * buffer logs and periodically flush to keep (as before) |
||
108 | * container gateway has a new webdav endpoint that reads the (live) log collection |
||
109 | ** stdlib webdav server implements range requests for us |
||
110 | * container gateway has a new endpoint that returns a server-sent-events stream |
||
111 | ** upon connection, return one event per log file: [filename, current-size, last-saved-size] |
||
112 | ** when a file is updated, wait until the last returned event is more than 1s old, then return an event [filename, current-size, last-saved-size] |
||
113 | *** “current-size” enables client to construct a suitable range request to retrieve recent data |
||
114 | *** “current-size” enables client to skip ahead if appropriate |
||
115 | *** “last-saved-size” enables dispatcher to discard buffered data once it's safely written to storage and accessible via log collection |
||
116 | * crunch-run updates gateway_address as soon as the gateway service is up (instead of waiting until state=Running) |
||
117 | ** railsapi should allow gateway_address to be set when state=Locked |
||
118 | ** this allows clients to access early logs (e.g., while preparing the docker image) |
||
119 | |||
120 | h2. Controller implementation notes for log_events |
||
121 | |||
122 | * additional logic is needed here beyond a simple proxy, in order that a single client-to-controller connection can receive all log updates through the entire container lifecycle, including one with the final file sizes, even though |
||
123 | ** crunch-run is not running yet when state=Queued |
||
124 | ** crunch-run may exit/disconnect before returning the final update (many race possibilities, including container finishing while controller is trying to reconnect) |
||
125 | ** additional logs may be added by dispatcher if crunch-run exits before finalizing the container |
||
126 | * if state=Queued or container gateway_address is empty, send an empty file_sizes message, then send keepalive messages while waiting/polling for the gateway to come up |
||
127 | * if state=Complete or Cancelled, get the final log file sizes, send a file_sizes message, a long retry message, and a “final” message; delay a few seconds; and hang up |
||
128 | * connect to crunch-run's log_events endpoint (through controller tunnel if applicable), propagate client's last-id and min/maxInterval params, and relay messages (including keepalive) to client |
||
129 | * when crunch-run disconnects (or does not answer), wait a second, re-fetch the container record, and repeat from top |
||
130 | |||
131 | h2. Controller implementation notes for log data |
||
132 | |||
133 | * if container log is not empty, a specific range is requested, and the size of the requested file is compatible with the requested range, proxy to keep-web |
||
134 | * if state=Complete/Cancelled, proxy to keep-web |
||
135 | * if gateway_address is empty, return 404 |
||
136 | * if state=Locked/Running and gateway_address is not empty, proxy to gateway_address |
||
137 | |||
138 | h2. Dispatcher implementation (for retaining the last log entries when a worker instance crashes) |
||
139 | |||
140 | * routinely connect/reconnect to crunch-run gateway server of containers that are being supervised |
||
141 | * when unflushed logs appear, save them in a temporary buffer on local disk, up to a configurable size limit |
||
142 | * when crunch-run exits unexpectedly, check the latest saved log collection, and (if needed) append the buffered logs to the respective truncated files before finalizing the container |
||
143 | * in HPC environment where dispatcher→worker connections are not supported, connect through the worker→controller tunnel (see #19166) |