Errors and logs

A thrown error

A function that throws, or returns a rejected promise, fails the call:

• An HTTP route call returns HTTP 500 with a JSON error body containing the error's message (error.message).
• substrio_function_invoke and the invoke endpoint return status: "error" with error_code, http_status and error.
• The message is the error's message; a thrown non-Error value is the text of the value. A failure with no message says "The function failed".
• The call's isolate is kept (a thrown error does not discard it) unless a limit killed the call.

Limit failures return their status and name the limit: CPU time 408, heap exhausted 413, a concurrency refusal 429, a full queue 503, a response body over 64 MiB 413. A direct call nested past 64 deep throws into its caller instead (call_depth_exceeded); uncaught, it is an ordinary thrown error (HTTP 500, above).

A promise that never settles within the wall clock fails with "The function's promise never settled".

Unhandled rejections

A promise that rejects with no handler does not change the call's response, and it is not written to function.logs. Attach a .catch (or await it inside try/catch) and log the failure with console.error to see it.

console

console.log, info, warn, error, debug, time and timeEnd write a line per call into the app's function log: timestamp, function name, level, message, the request id of the invocation and seq, the line's number within the request (1, 2, 3 ...). A request's lines sort by (request_id, seq) and are stored in that order.

console.log("order", id);
console.warn("slow", 120);
console.error(new Error("x").message);

No line is dropped, and every line of a call that has answered is readable at once.

Reading logs back

• MCP: substrio_function_logs; HTTP: GET /v1/_logs (operation function.logs). Both take the same options, named alike (over HTTP as query parameters).
• Clearing: function.logs.clear (DELETE /v1/_logs) purges the app's logs.

The response is an object:

{ "logs": [ {...} ], "count": 3, "next_cursor": "...", "has_more": false, "latest_cursor": "..." }

A log entry contains log_seq (which orders the whole log), timestamp (Unix milliseconds), function, level, message, and request_id. A page cursor is the log_seq of its last entry. next_cursor is present on a full page when the limit is reached. Pass it as cursor for later lines. latest_cursor is the newest stored line when the response was made; every line up to it was considered. An invalid cursor returns 400 (cursor: a next_cursor this operation answered).

Long poll: wait_ms

With a cursor, a request with no later line can wait for one:

GET /v1/_logs?function=orders&cursor=<latest_cursor>&wait_ms=10000

The request waits until a matching line is stored and returns the first non-empty page, or returns an empty page (count 0) at the deadline. wait_ms is at most 30000; a larger value returns 400 (wait_ms: at most 30000 milliseconds). Without a cursor, it returns 400 (wait_ms: needs a cursor (the latest_cursor or next_cursor of a function.logs answer)). An app can have at most 64 parked waits at once; the next returns SERVER_BUSY immediately. Read once, then repeat using the response's latest_cursor.

Live tail: function.logs.stream

GET /v1/_logs/ws is a WebSocket (same authentication) that pushes lines as they are stored. Query: function, request_id, level, q (as function.logs) and cursor (default: only new lines, none of the stored ones). Frames are JSON text:

{"type":"connected","cursor":"<16 hex digits>"}
{"type":"logs","cursor":"<cursor>","logs":[ {...}, ... ]}
{"type":"lagged","cursor":"<cursor>"}

connected comes first. Each logs frame carries the cursor to resume from. A socket that reads too slowly gets lagged and continues from its cursor, or reconnect with cursor=. A malformed cursor is refused with HTTP 400 at the upgrade.

To debug a failing function: invoke it (substrio_function_invoke or a route call), read the error answer, then read substrio_function_logs filtered by function and level: "error" for what it printed before failing.

Traces

An app sends the spans of its function calls to an OpenTelemetry collector over OTLP/HTTP (JSON) by setting trace.endpoint (the collector's traces URL, for example https://collector.example.com:4318/v1/traces). Unset, nothing is traced.

The settings are the app's generic settings (settings.set), typed: a value that does not suit its setting is refused with 400.

Spans of one call:

• the call (kind server, named by its function id app/name), a child of the request's traceparent span (W3C Trace Context) when one came in, else the root of a new trace;
• every query or write through the db object (db, kind client);
• every outbound fetch (fetch <METHOD>, kind client, with url.full and http.response.status_code), which sends a traceparent naming its own span (a traceparent header the function sets itself is replaced);
• every function the call invokes directly (invoke app/name).

A request whose traceparent is not sampled (flags 00) is not recorded and no traceparent is forwarded. Spans are exported in batches after the call. If the collector refuses or cannot take a request, it is retried with increasing delays until accepted. No span is dropped while trace.endpoint stays set. Turning the setting off drops spans still waiting.

Searching logs

q is full-text search over the messages of the stored lines, with every other option still applying (function, level, request_id, since and until, a cursor, limit). A line matches when its message holds every word of q, in any order; words are the ones the message is indexed by (runs of ASCII letters, digits and underscores, case folded), so punctuation in q does nothing and a q with no word at all matches nothing:

GET /v1/_logs?q=timeout%20node7&level=warn&since=1760000000&limit=50

Lines come oldest first, as without q, and page by cursor the same way: next_cursor on a full page, has_more while the log goes on past it. A rare Errors are log lines (below), so searching an error's text finds it.

Errors are lines too

Every thrown error is also stored as a line of the log, in the call's own order (its seq follows the call's earlier lines): kind is error, level is error, and message is the error's name: message and its stack. A line a function wrote with console has kind line. function.errors still holds the typed entry with its frames and revision. One ordered stream (log_seq) therefore carries every event, which log drains, search and alerts read.

Log drains

A drain delivers the app's log lines and errors to an HTTP endpoint in log order, at least once, as NDJSON (Content-Type: application/x-ndjson). Each row is a line object with the same fields returned by function.logs: log_seq, timestamp, function, level, kind, message, request_id, and seq. With a secret, each request carries the signature header Substrio-Signature, unless webhooks.brand specifies another brand. Its value uses the webhook format t=<unix seconds>,v1=<hex HMAC-SHA256 of "<t>.<body>">. The url, secret, and headers follow the same rules as webhook.create; headers may not set the signature or delivery headers.

Settings of a drain: url (http or https), secret, headers (sent with every delivery; the webhooks' rules), batch_lines (lines per request, at most; default 500), retry_ms (the wait after a failed delivery, doubling on each failure in a row; default 1000), max_retry_ms (the longest wait; default 60000) and enabled. start on create: now (default) delivers lines stored from then on, start also delivers everything already stored.

The stored log is the queue. The drain's cursor is the log_seq of the last line accepted by its endpoint and is saved with the settings after every accepted batch. Any 2xx response counts as accepted. If the endpoint is down, slow, or refusing requests, the cursor stops and lines remain stored. The drain sends them in order and in the same batches when the endpoint responds, including after a server restart. Delivery is at least once. If the server stops after the endpoint accepts a batch but before the cursor is saved, that batch is sent again. A receiver that needs to avoid duplicates can discard a log_seq it has already seen. log_drain.list shows each drain's acked cursor, the latest stored cursor, delivered_lines, failures_in_a_row, last_http_status and phase. A line larger than a batch is sent whole, alone. Clearing the logs does not touch the drains.

Log alerts

An alert publishes the app event log.alert when its condition first holds in a window, at most once per window. Windows are fixed slots of Unix time. With window_ms 60000, window n is the minute [n * 60000, (n + 1) * 60000). The alert fires as soon as its condition holds and does not fire again in that window.

kind (required on create) is one of:

• error_count: function errors (thrown errors, which are kind error lines) reach threshold (default 1) in the window.
• error_rate: errors over calls reach rate_percent (above 0, at most 100) in the window, with at least min_calls calls (default 1). A call is an error when it throws or answers a 5xx. Calls are counted from the moment the alert exists, not from the log.
• log_match: log lines whose message holds every word of match (the words of Searching logs above) reach threshold in the window.

function (a function's name) narrows every kind to one function; level narrows log_match to one level; enabled pauses the alert; name labels the notification.

An alert has no endpoint of its own. A webhook takes its notifications:

webhook.create { "app_event": "log.alert", "scope": "<alert id>", "url": "https://..." }

scope is the alert's id (as log_alert.list shows it) for one alert's notifications; leave it out for every alert's. app_event may also be *. The delivery is then the webhooks': stored before its first attempt, signed with the webhook's secret, retried by the app's delivery policy, dead-lettered when it gives up, listed with its delivery id and replayable (webhook.replay), also across a restart. Without a webhook the notification has no receiver: the alert still fires and records the window, and notified shows how many webhooks took it.

The notification is the JSON payload:

{ "type": "log_alert",
  "alert": { "id": "...", "name": "...", "kind": "error_count", "function": "orders",
             "window_ms": 60000, "threshold": 3 },
  "window": { "index": 28333333, "start_ms": 1700000000000, "end_ms": 1700000060000 },
  "fired_at": 1700000012345, "errors": 3, "calls": 0, "matches": 0, "value": 3 }

value is the number the condition compared: the errors, the matches, or the error percentage. A line counts in the window in which the alert saw it.

The window an alert last fired in is stored with it (fired_window, fired_at, notified), so a restart inside that window does not fire it again (the window's count is rebuilt from the log), and a change of settings never notifies twice for one window. The notification is published first and the window stored right after: a stop between the two repeats the notification of that window after the restart, never loses it, and window.index lets a receiver drop the repeat.