Errors and logs

A thrown error

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

• An HTTP route call answers HTTP 500 with a JSON error body carrying the error's message (error.message).
• substrio_function_invoke and the invoke endpoint answer 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 answer their own status, with the limit named: 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 never changes the call's answer, 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 answer is an object:

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

A log carries log_seq (orders the whole log; a cursor is the log_seq of a page's last entry), timestamp (Unix milliseconds), function, level, message and request_id. next_cursor is present on a full page (a limit reached): pass it as cursor for the lines after it. latest_cursor is the newest stored line when the answer was made; every line up to it was considered by this answer. A cursor that is not one of these answers a 400 (cursor: a next_cursor this operation answered).

Long poll: wait_ms

With a cursor, an answer with no line past it can wait for one:

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

The request parks until a line that matches the filters is stored, then answers the first non-empty page, or answers an empty page (count 0) at the deadline. wait_ms is at most 30000; more answers 400 (wait_ms: at most 30000 milliseconds). Without a cursor it answers 400 (wait_ms: needs a cursor (the latest_cursor or next_cursor of a function.logs answer)). An app holds at most 64 parked waits at once; the next is answered SERVER_BUSY at once. Loop: read once, then repeat with the answer'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. Exporting never slows a call: spans are sent in batches after the call, and a request the collector refuses or cannot take is sent again after a growing delay until it is accepted; no span is dropped while trace.endpoint stays set. Turning the setting off drops the 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 word is as fast to find on a large log as on a small one. Errors are 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 every log line and error of the app to an HTTP endpoint, in log order and at least once, as NDJSON (Content-Type: application/x-ndjson): one line object per row, the same objects function.logs answers (log_seq, timestamp, function, level, kind, message, request_id, seq). With a secret each request carries the app's signature header, Substrio-Signature unless the app setting webhooks.brand names another brand, with the webhooks' value t=<unix seconds>,v1=<hex HMAC-SHA256 of "<t>.<body>">. url, secret and headers follow the same rules as in webhook.create (the headers may not set the signature or delivery headers), so a drain and a webhook accept and refuse the same values.

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. A drain's only state is its cursor, the log_seq of the last line its endpoint accepted, saved with its settings after every accepted batch. A request counts as accepted on any 2xx answer. An endpoint that is down, slow or refusing stops the cursor and nothing is dropped: the lines stay stored and the drain sends them in order, in the same batches, when the endpoint answers, also after a server restart. Delivery is at least once: if the server stops between the endpoint accepting a batch and the cursor being saved, that batch is sent again, so a receiver that must not see a line twice drops a log_seq it already has. 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 watches the app's functions and publishes the app event log.alert when its condition first holds in a window, once per window. Windows are fixed slots of unix time: with window_ms 60000, window n is the minute [n * 60000, (n + 1) * 60000). Nothing waits for a window to end: the alert fires the moment its condition holds, then not 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.