Logs are out of order

Scope

k8s worker, all action execution logs. Logs shown for an execution (run view, run logs API, live websocket) can come out in a different order from the one the action wrote them in.

Why ordering is not guaranteed today

Nothing that travels from the worker to the runner says where a batch of log lines belongs, so the runner can only store lines in the order it happens to process them.

  1. The message carries no position. ExecutionLogsUpdated is just execution_id + logs (core/ryax/common/messaging/messages/worker_messages_v2.proto:15-18). There is no sequence number and no timestamp.
  2. The worker sends logs from two sources. It publishes the live pod log stream in batches, then a final full-log fetch that sends the tail the stream missed (core/ryax/worker_k8s/application/execution_handlers.py:65-100, :510-521). The pod log read is done without timestamps=true, so the lines carry no time either.
  3. The runner consumes without a bound and without per-execution serialization. set_qos(prefetch_count=0) (core/ryax/common/messaging/consumer.py:110). Two batches for the same execution can be handled concurrently by new_log_lineV2 (core/ryax/runner/application/handlers/v2_execution_handlers.py:316).
  4. The runner's index is computed at arrival. ActionLogs.append hands out self.index and increments it (core/ryax/runner/domain/action_logs/action_logs_entities.py:39-43), so it records arrival order, not emission order. Two concurrent appends both read the same starting index and write overlapping values.
  5. The read does not even sort by it. get_logs_as_string does select(LogLine).where(logs_id == …) with no ORDER BY (core/ryax/runner/infrastructure/database/repositories/action_logs_repository.py:43-53). Both the run logs API (action_logs_service.get_logs) and the trigger-logs websocket go through it, so Postgres is free to return rows in any order. The ORM relationship has order_by=LogLine.index, but this query bypasses it.

Proposal

Have the producer stamp the position, not the consumer:

  • Worker: give each ExecutionLogsUpdated a monotonically increasing per-execution sequence number, covering both the stream batches and the final fetch. Alternatively, read pod logs with timestamps=true and send a timestamp per line. The timestamp also helps across a worker restart, where a counter would reset.
  • Proto: add the field to ExecutionLogsUpdated (e.g. uint64 sequence and/or a per-line timestamp).
  • Runner:
    • Store the worker-provided position in log_lines instead of the arrival counter.
    • Read with ORDER BY it.
    • Order the live websocket push the same way, or let the front reorder by it.

Not done yet

This is from code reading. I have not reproduced the reordering live. A test would be an action that prints numbered lines quickly for longer than one stream batch, then a check of the order returned by GET /api/runner/…/logs.

Edited by Michael Mercier