Logs out of order
I'm seeing at least two cases where this is happening:
1. Cached response - the timestamp is older than when the response actually occurred, but it seems to be the timestamp is actually from when the cached response was originally served, which is useful info, but the actual served timestamp would be more useful.
2. Not sure what causes this, but here's an example case:
- An action logs something
- The action then calls a mutation
- The mutation throws
- In convex logs, I see the error from the mutation before the log
- The timestamp from the log is one second before the mutation error
- Timestamp is correct, order is not
I'm guessing logging isn't guaranteed to be in order, but wondering if it's a bug, or if there's any way to help improve output from my end.
6 Replies
Hey @erquhart thanks for the patience on this — I see we haven't responded to https://discord.com/channels/1019350475847499849/1019350478817079338/1167718287040323584 yet either.
Agreed on 1, no timeline on this but it makes sense the both of these pieces of information are useful and the primary one displayed should be when this request occured. Since Convex takes care of caching, it's just an implementation detail (possibly useful for debugging cache behavior) when the cached response was created.
For 2. the order of logs in the Convex dashboard is the order in which we received them, shown as quickly as possible. A current implementation detail leaking out here is that logs during an action aren't collected until the action has completed; we've called implementing the behavior you're asking for "log streaming" before internally, but it's still possible once we did that that we'd receive logs in a different order than in which they were logged.
Are you using a log export, e.g. to datadog? There it should be possible to order logs by wall clock timestamp which should produce an order which makes more sense.
I'm not exporting logs, and definitely not at a place where that's a requirement yet, just wanted to understand it. Good to at least know why, thanks for this.
In the dashboard there's a tradeoff between showing an append-only log (you don't have to look for logs appearing at previous points in time) vs showing logs in the order they happened. We may make logs show up sooner in the future (an Node.js action that took 2 minutes to run could stream log messages to convex as they occurred) but because we're collecting logs from multiple sources we still have to decide between out of order logs, logs that appear back in time, or a delay on the logs while we aggregate them. Right now we're going with showing logs as soon as possible.
Gotcha, that makes sense
Thanks for the explainer!
Thanks for the feedback, re these tradeoffs it's helpful to hear how these are used! It's possible we'd move to a logs display that showd more logical/causal hierarchy, e.g. the action that initiated a mutation might show the logs for that mutation scoped to it somehow
ooh that would be awesome