CF worker to log all REST API activity in a non-blocking way to an external service - including response time


#1

I want to use a CF worker to intercept all requests to our REST API endpoint on Tallyfy and log the following to an external service:

  1. HTTP verb
  2. Source geo/country
  3. Time elapsed between request and response.
  4. User bearer token
  5. Payload, URL.
  6. … etc.

Does anyone have any sample code/approach to demonstrate the above being done after the initial request has been responded to? We want this to be non-blocking i.e. the original API request is served with no extra lag time, and after it’s been served, we then asynchronously log information about the call to an external logging service.

The important part is (3) - how can I actually measure the elapsed time to serve the request (to later do performance analytics in my API) accurately and properly?

From what I understand, promises are async, whereas in this case - we must wait for the full request to be ready to send back before attempting to log it.

Thanks for any help!
Amit


#2

Tagging @KentonVarda, he may know of something. Never looked into it myself, but would be extremely interested.


#3

This what I use:


#4

Some light has been shed on this issue:

Based on that thread, you may be able to use event.waitUntil() to perform a non-blocking fetch call after the request has been sent, but I haven’t tested this.


#5

Yes, exactly. You can see an example of how we use this function at Cloudflare in a Sentry integration in this blog post: https://blog.cloudflare.com/dogfooding-edge-workers/

@tallyfy,

You can do a rough measurement of response time with Date.now(). Note that Date.now() only advances when I/O is performed, however, and is intentionally coarse. A rough (untested!) sketch might be

addEventListener("fetch", event => event.respondWith(handle(event)))

async function handle(event) {
  let request = event.request
  let then = Date.now()
  let response = await fetch(request)

  let logData = {
    method: request.method,
    url: request.url,
    country: request.headers.get("cf-ipcountry"),
    token: ...,
    payload: ...,
    elapsed: Date.now() - then,
  }

  let logRequest = new Request("https://my-logging-service", {
    method: "POST",
    body: JSON.stringify(logData),
    headers: { "Content-Type": "application/json", /* auth headers, too */ },
  })

  event.waitUntil(fetch(logRequest))

  return response
}

That would measure the rough amount of time between the Workers runtime’s receipt of the request and receipt of the response headers. The time required to pump the response body back to the visitor would not be accounted for, however. Doing so would require the ReadableStream.pipeTo() method, which is coming soon-ish.

Note that if you have a high volume of requests, then sending one logging request per visitor request doesn’t scale, and it’s necessary to come up with a batching solution, e.g., start a 10-15 second timer on the first request that pushes logs to the logging server upon timeout, then add text logging data to some global variable on each request. Each request also has to check to make sure that the timer is still active, or didn’t get spuriously canceled.

Harris


#6

Thanks @Judge @harris

I had follow up questions.

  1. How rough is “coarse time” i.e. to what rounding error or decimal place will this be in milliseconds?
  2. Why doesn’t the log-per-request method scale? My impression was that CF workers are spawned in isolated containers, and that you can run code per-request - even if it’s a ton of requests per second. In general, the serverless value-prop seems to hinge around this scale-out idea - so what exactly prevents say 100 calls/second working properly if each of those requests had to be logged independently, in their own threads?

Noted on the time for the response body to the visitor - since I can understand that once a response is pushed back to the user-agent, it’s essentially outside of CF control and at the mercy of routing via the outside web.


#7

@harris I have to admit that this worries me:

Note that if you have a high volume of requests, then sending one logging request per visitor request doesn’t scale

I had a ton of ideas and plans to build specific things that are uniquely suited to workers, and actually use them as a foundation for new kinds of businesses.

The entire premise of a CF worker is that it runs at the edge within 50ms CPU and 15 real seconds and can infinitely scale because each http request is pre-processed and post-processed in isolation, with no regard to the volume of requests. Why did you state it doesn’t scale?

Tagging @KentonVarda @matteo @Judge @adaptive in case there’s further feedback here.


#8

I think his doesn’t scale comment is more related to the remote endpoint. If you send them hundreds/thousands of requests a second they will increase latency (if not even failures), resulting in higher usage in the worker risking ram/CPU limits.

Obviously can’t know exactly what he thought, but these are my two cents.


#9

Got it @matteo, thanks. I guess I misunderstood.

The remote endpoint is fine - since these are all logging tools with collector endpoints designed to accept a large stream of log pushes. Many of them also have real-time feeds which indicates they’re logging in real-time.


#10

Even if your endpoint doesn’t scale, you can use an array as a global variable to store temporarily the log lines, then batch the logs every 100 to 500 lines or every 30 seconds. Reducing x500 the request helps with spikes. Cloudflare Workers are great to offload pressure to endpoints.