Feature Request - Queuing Request Logs

[Sammyjo20]

Hey, absolutely love this package - great work on it!

We're currently running into an issue where because every request is written to the request_logs table. This results in a single point of failure (if our writer instance fails). It also means that for even read-based operations our writer is only being used. It would be really cool if this library allowed us to queue the storing of request logs. This would allow our GET requests to only touch our load-balanced reader instances and never touch the writer. It would also speed up our requests as we currently have the request logs table on a separate database connection.

[bilfeldt]

Hi @Sammyjo20 👋

absolutely love this package - great work on it!

Thanks so much 🙏

We're currently running into an issue where because every request is written to the request_logs table. This results in a single point of failure (if our writer instance fails). It also means that for even read-based operations our writer is only being used. It would be really cool if this library allowed us to queue the storing of request logs. This would allow our GET requests to only touch our load-balanced reader instances and never touch the writer. It would also speed up our requests as we currently have the request logs table on a separate database connection.

I see your use case 🤔 I originally avoided queued jobs and looked at Terminable Middleware but finally decided to use a synchronous listener (aka non-queued) for the event Illuminate\Foundation\Http\Events\RequestHandled.

Solution right now

Could we not just queue the listener we already have for the Illuminate\Foundation\Http\Events\RequestHandled? No - because the Request object is not serializable.

That means that we need to call the logger (implementing RequestLoggerInterface) synchronously, but there is no problem in using a logger that does the actual writing using a queued job.

This can actually be done already, in two ways (option 2 is easier):

1. Add your own driver which uses a queued job. Add this driver to the config and set that as the default
2. Make a new model which extends \Bilfeldt\RequestLogger\Models\RequestLog and simply override the log function to queue the actual saving. Then configure that the package should use your new child class instead.

Should we implement it into this package as a core feature?

Albeit it is already possible, then there is no build in config for it, which would be the ideal for any developer wanting to achieve this.

I originally thought there were no use cases for this, since the performance concern makes no sense simply because writing is done after the response has been returned to the user. But I do understand your concerns and could imagine there could be other edgecases.

Hence I am okay adding this as a build in feature of the package. I will keep this issue open for now, and if I find the time to add this myself I will probably do so. But I am open for any PRs for this feature already.

[Sammyjo20]

Hey @bilfeldt I'm really sorry for not replying sooner - I feel awful!

Thank you for such a detailed reply. It would be great if this was a feature in the library but I understand you may have other commitments at this point in time. I wanted to share this with you - we wanted to see what was slowing some of our requests down and it was what I expected:

I was wondering if I could somehow make the middleware terminatable. I'm going to have a look today and let you know if I can.

[bilfeldt]

No worries at all @Sammyjo20 :)

Just to be clear, that query is being executed after the response has been returned to the user right?

[Sammyjo20]

No, the middleware isn't terminatable - so it'll be part of the request - this is why it's being picked up in the request lifecycle

[bilfeldt]

No, the middleware isn't terminatable - so it'll be part of the request - this is why it's being picked up in the request lifecycle

The middleware is only used to "tag" that the request should be logged. Logging happens using the event listener here

laravel-request-logger/src/EventServiceProvider.php

Lines 11 to 15 in 2fe2f6e

	protected $listen = [
	RequestHandled::class => [
	LogRequest::class,
	],
	];

And the event RequestHandled is fired after the response has been returned - right?

[Sammyjo20]

Hmm, the listener isn't queued so that leaves me to think it might be running synchronously? I might be wrong - where abouts is the RequestHandled event being fired?

[Sammyjo20]

Sorry - I didn't realise it was a Laravel event:

https://github.com/laravel/framework/blob/988206bcacf79829bda66af4a016778e4b4d762a/src/Illuminate/Foundation/Http/Kernel.php#L152

But it doesn't look like this is after the request lifecycle. I'll keep digging haha

[Sammyjo20]

So looking in public/index.php it looks like handle is run to create the response (and fire the RequestHandled event) and then the terminate method is run after, which runs the terminatable middleware.

I wonder if we could move all of the logic out of a listener and put it into terminate instead. This would have the added benefit of it running after the request is completed and I don't think it would be a breaking change?

[bilfeldt]

Yes the listener is not queued (and cannot be, because of the serialization issue I mentioned).

I might have misunderstood the RequestHandled event. I was almost certain it fired after the response was returned to the user, but your reference would indicate I am wrong there 😒

If that is indeed the case then we/I should definitly make it possible to log sync either using a queued job or using terminatable middleware.

[bilfeldt]

Sorry @Sammyjo20 had not seen your answer when I posted above.

So we agree that my original postulate was wrong and that the event RequestHandled is fired before the response is returned to the user correct?

I wonder if there is a RequestTerminated event we could listen for 🤔

[Sammyjo20]

I'm currently working off a fork and I will see if it works - just installing it locally - the PR will be a little crude without testing but I am happy to put one up if you like? Thank you so much for being so cooperative on this one!

[bilfeldt]

I'm currently working off a fork and I will see if it works - just installing it locally - the PR will be a little crude without testing but I am happy to put one up if you like? Thank you so much for being so cooperative on this one!

Feel free to post a PR for this - absolutely 👍

A few ideas I have here:

1. Simply add a new queued config and then simply move this part into a queued job:

   laravel-request-logger/src/Models/RequestLog.php

   Lines 97 to 124 in 2fe2f6e

   	$model = new static();
   	$model->uuid = $request->getUniqueId();
   	$model->correlation_id = $this->truncateToLength($request->getCorrelationId());
   	$model->client_request_id = $this->truncateToLength($request->getClientRequestId());
   	$model->ip = $request->ip();
   	$model->session = $request->hasSession() ? $request->session()->getId() : null;
   	$model->middleware = array_values(optional($request->route())->gatherMiddleware() ?? []);
   	$model->method = $request->getMethod();
   	$model->route = $this->truncateToLength(optional($request->route())->getName() ?? optional($request->route())->uri()); // Note that $request->route()->uri() does not replace the placeholders while $request->getRequestUri() replaces the placeholders
   	$model->path = $this->truncateToLength($request->path());
   	$model->status = $response->getStatusCode();
   	$model->headers = $this->getFiltered($request->headers->all()) ?: null;
   	$model->payload = $this->getFiltered($request->input()) ?: null;
   	$model->response_headers = $this->getFiltered($response->headers->all()) ?: null;
   	$model->response_body = $this->getLoggableResponseContent($response);
   	$model->duration = $duration;
   	$model->memory = round($memory / 1024 / 1024, 2); // [MB]
   	if ($user = $request->user()) {
   	$model->user()->associate($user);
   	}
   	if ($team = $this->getRequestTeam($request)) {
   	$model->team()->associate($team);
   	}
   	$model->save();

2. Instead of listening for the RequestHandled event, then we register a terminatedCallback: https://github.com/laravel/framework/blob/7c680bb58dfb15923209045f99ed5cf46c31f45d/src/Illuminate/Foundation/Application.php#L1354-L1364
3. Instead of using the RequestHandled event then we use a terminatable middleware - that would be a breaking change, because it would require everybody to use that middleware, and there are currently other ways to enable logging.

[bilfeldt]

I personally vote for combining option 1 and 2 btw 👍

[Sammyjo20]

I think either option 1 or 2 could be good. For people who haven't enabled queueing it will still run in sync, but for others it'll queue it. Option 2 is probably easier to implement because instead of an event being fired, you could run the terminatable middleware which checks for a request.

I'd be happy to try and change my PR to option 2 if you would like.

[Sammyjo20]

With option 1 you could even Job::dispatchAfterResponse() which would possibly reduce latency even further.

[bilfeldt]

Good idea. Yes a PR would be much appriciated.