Why your serverless function loses its last logs

Your serverless function logs ten things. Eight arrive. Two vanish.

No error. No warning. No failed request in your dashboard. The two missing lines are the last two — the ones written right before the response went out, which are of course the ones you wanted.

I chased this exact shape of bug through the log pipeline in @developerehsan/nextjs-logger, and the cause turned out to be a fight between two perfectly sensible ideas. Here is the fight, the numbers I measured, and the single line that ends it.

First, why logs get batched at all

The naive way to ship logs somewhere is one HTTP request per log line. Write a line, send a request. Simple.

It falls over immediately. A route handler that logs 50 times now makes 50 outbound HTTP calls on top of the work it was actually hired to do. Your logging becomes more network traffic than your app.

So every real log shipper batches. Collect entries in memory, send them in groups. That is the sensible idea number one.

Sensible idea number two is serverless: the platform may freeze or destroy your function instance the instant you send a response, because you are done and nobody wants to pay for idle compute.

Put those two together and you get a batch of log lines sitting in memory, politely waiting for more company, inside a process that is about to stop existing.

timeline
    title A batch that never leaves
    0ms : handler starts, logs "request received"
    12ms : logs "db query done"
    18ms : logs "sending response" — 3 entries buffered, timer has 1982ms to go
    19ms : response sent
    20ms : platform freezes the instance
    2000ms : the flush timer would have fired here. There is no here.

Nothing threw. Nothing retried. The entries simply never left the process.

Watching it happen

I do not trust an explanation I have not watched fail, so I ran the pipeline directly with a transport that takes 40ms to deliver a batch, and printed what had arrived before and after the flush:

const delivered: string[] = []

const pipeline = new TransportPipeline(
  [{ name: 't', write: async (entries) => {
      await new Promise((r) => setTimeout(r, 40))
      delivered.push(...entries.map((e) => e.message))
    } }],
  { maxBatchSize: 1000, flushIntervalMs: 60_000 },
)

pipeline.push(entry('a'))
pipeline.push(entry('b'))
console.log('before flush:', delivered)
await pipeline.flush('manual')
console.log('after flush: ', delivered)

It printed:

before flush: []
after flush:  [ "a", "b" ]

That empty array is the whole problem. Both entries were accepted. Neither had gone anywhere. If the process had ended on the line between those two logs, both would be gone — and push() would still have returned cleanly, because push() returning does not mean delivered, it means accepted.

The one line that fixes it

The library cannot solve this on its own. The freeze decision happens outside any code it controls. What it can do is hand you an explicit way to say “I am done, send everything now”:

import { flushTransports } from '@developerehsan/nextjs-logger'

export async function POST(req: Request) {
  const res = await handle(req)
  await flushTransports()   // ← the line
  return res
}

flushTransports() walks every active pipeline in the process and resolves only once every buffered entry has actually been delivered. Await it right before your handler returns, at the one moment your code knows the request is finished and the platform is about to take the wheel.

Miss the await and you have written the bug back in, with extra steps.

Four rules the buffer follows while it waits

Between push() and delivery, the buffer is not just sitting there. Four rules run, and each one exists because of a specific failure. I measured all four.

It drops the oldest entries, not the newest

The buffer has a hard cap of 10,000 entries. Past that, something has to go. I set the cap to 3, pushed six entries named e1 through e6, and flushed:

delivered: [ "e4", "e5", "e6" ]
dropped counter: 3

The three oldest died. That is the right direction, and it is worth pausing on why. During an incident, the newest lines describe what is breaking right now. The ten-minutes-ago lines describe a world that already ended. If you must lose some, lose the history.

The drops are counted, not silent. getTransportStats() reports dropped per transport, so a pipeline shedding load tells you so instead of quietly lying about your log volume.

One batch in flight per sink, ever

I pointed ten entries at a transport that takes 30ms per batch, with batches firing every 2 entries, and counted how many write() calls ran at once:

max concurrent write() calls on one transport: 1

Always one. A timer-triggered flush and a size-triggered flush arriving milliseconds apart do not race each other to the same endpoint — the second one chains onto the first. Two transports still run independently, so a slow collector having a bad day does not hold up a fast one.

Retries back off, with randomness on purpose

A failed batch is retried up to 3 times. With maxRetries: 3, I counted the actual calls:

total write() attempts: 4   (1 original + 3 retries)
dropped: 1 entry            (after all 4 failed)

The delay doubles each round — 250ms, 500ms, 1000ms — but every delay is then multiplied by a random number between 0 and 1. That multiplication looks like a rounding detail and is doing real work. I ran the same failing config ten times and timed the full retry sequence:

[557, 588, 942, 977, 1077, 1111, 1156, 1241, 1512, 1542] ms

Same code, same settings, spread across a full second. Now picture a hundred serverless instances all failing against the same collector at the same instant. Without that random factor, all hundred would retry at exactly 250ms, then all at 500ms — rebuilding the traffic spike that knocked the collector over, on a schedule. With it, the retries smear across a window and the collector gets a ramp instead of a wall.

On shutdown, it stops waiting

Backoff is a luxury you cannot afford while the platform is closing the door. Same three retries, same 250ms base, timed twice:

normal flush:   1621ms
shutdown flush:    0ms

When the reason is shutdown, the remaining attempts fire back-to-back with no sleeping. Better to burn four fast attempts than to doze through a 1.6-second backoff inside an instance that gets suspended at second one.

The trap I did not expect

A transport here can take two shapes. The batched object form — { name, write } — gets everything above. The plain function form, (entry) => void, gets none of it.

I pushed three entries through a plain function transport:

plain function transport called 3 times for 3 pushes
getStats(): []

Called once per entry, inline, no batching, no retry. And it does not appear in getTransportStats() at all — an empty array, not a row of zeros.

That is deliberate and correct for what the function form is for: incrementing a counter, bumping a metric, something cheap and synchronous. It is the wrong shape for anything touching the network. If you wrote configureLogger({ transports: [(e) => fetch(url, ...)] }), you have a fire-and-forget promise nobody is watching, flushTransports() cannot wait for it, and the stats will insist everything is fine. Use the object form the moment a sink makes a network call.

While we are on things that quietly disappear: entries that never reach a transport for a different reason are covered in why error objects print as empty in JSON logs, and the client-side half of this pipeline is in how client logs reach your terminal.

The question to ask before you build any buffer

This is not really about logging. It applies to anything that collects work in memory and ships it later — analytics events, metrics, webhook queues, email batches.

Before you write the batching logic, answer this: if the process dies right now, what happens to what is in the buffer?

If the answer is “I do not know,” that is the gap, and more retry logic inside the library will not close it. Retries protect you from a failed send. Nothing protects you from a send that never got attempted. The fix is an explicit flush that your code calls at the one point where it knows the work is done — which, on serverless, is the last line before you hand control back to a platform that has every right to pull the plug.

The Vercel docs put the underlying constraint plainly: work started but not awaited before the response may not finish. Your buffer is that work.

One await. Put it in.