No apparent flushing for TrackMessage or TrackException

[drmmr763]

I'm trying to connect this to Laravel 9.x with logging.

I was not able to get any log messages to come into app insights until I modified Mondago\ApplicationInsights\ApplicationInsights and called flush() in the trackMessage and trackException methods:

https://github.com/mondago/laravel-azure-application-insights/blob/main/src/ApplicationInsights.php#L243
https://github.com/mondago/laravel-azure-application-insights/blob/main/src/ApplicationInsights.php#L259

I'm not sure when / how the flushing is supposed to happen unless its added here? Obviously if someone is wanting to just use:

Log::debug('debugging');

They don't want to have to also inject the client class and call flush do they? I can see flush was used in a few of the other tracking types, but not here. So, I'm not sure if I'm missing something about the expected usage or if this is a bug?

[ossentoo]

I can't get this package to log either. @drmmr763 , can you give more detail about how you got it to log? Are you saying that you created your own fork/branch and added a couple of extra "flush" statements and after doing that, the package worked as expected?

[drmmr763]

So I modified the vendor package and added the flush method call just to experiment and see what was going on.

It did work, but I'm not using the package because of this issue. I hoped a new release would come out with a fix.

[ingalless]

Hey @ossentoo and @drmmr763
Sorry for the delayed reply. Delighted to hear our package is being used. We're sorry that it isn't quite working as you'd expect.
We appreciate the time taken to open an issue as this increases our awareness to real world usage.

You can see from our readme section on middleware that we suggest using our TrackRequest middleware. The reason we don't flush until after the request is sent is because each flush makes a HTTP request to my understanding. This would slow down your response, dependent on how quickly Microsoft can respond to each event. This grows linearly the more logging you have. Instead, we queue up the telemetry (exceptions, logs, traces, request, response) and send them all in one batch from TrackRequest after the response has been sent to the browser (so long as you are running in a FastCGI environment. See Laravel's documentation on this)

We'd happily consider a PR that made flushing on every event configurable however. I'm sure other consumers would love to have the option. Perhaps always_flush or something similar, what do you both think?

[drmmr763]

Hi @ingalless

Thank you for explaining I will experiment with that. I do a lot of console based processing of information that throws exceptions and I have a lot of logging related to that. Because it is console based and not API / HTTP requested based, I'm assuming that the TrackRequest middleware might never fire for me in that context, is that right?

Additionally, in my use case, i actually have a background processing server that consumes and executes queue jobs that doesn't have any http service on it at all. It just processes queues. Then another HTTP server that processes api requests for the same application. In that environment I'm assuming the queue processor will just always be queueing telemetry on that machine, but never flush due to the fact a TrackRequest will never be handled.

An always flush or something a little smarter such as buffer based would be a great option. Looks like they did something similar here
app-insights-php/monolog-handler#4

[ingalless]

@drmmr763 Thank you for the additional context, really useful and interesting stuff going on here!

I do a lot of console based processing of information that throws exceptions and I have a lot of logging related to that. Because it is console based and not API / HTTP requested based, I'm assuming that the TrackRequest middleware might never fire for me in that context, is that right?

You're right that TrackRequest won't be doing anything if it's console based. In our use-cases internally we are calling the trackEvent method for logging which does call flush every time.

In that environment I'm assuming the queue processor will just always be queueing telemetry on that machine, but never flush due to the fact a TrackRequest will never be handled.

Again, your assumption seems correct.

There are events we can listen to for Artisan commands, Jobs and Queues, which seem like a good place to flush. Which do you think fits your use case?

• https://laravel.com/docs/10.x/scheduling#events
• https://laravel.com/docs/10.x/artisan#events
• https://laravel.com/docs/10.x/queues#job-events (These feel user-land. Might not be relevant but included just in case)

[drmmr763]

Hi @ingalless thanks for taking the time to reply.

So I have kind of homebrewed my own desired functionality for now. I based it on the Monolog repo and also took some inspiration from your TrackRequest.

What I ended up with is this:

TrackRequest terminable middleware extremely similar to what you have. There's some differences to get things like the userID showing in Azure -- for some reason the session stuff wasn't loading in the user. It may be because I'm using stateless oauth passport based authentication.

For TrackRequest You'll see its basically a combination of the TrackRequest and the ApplicationInsights classes into one single class. This does flush on every request - but since it is terminable it is fairly async imho and hasn't had an affect on performance so far.

Then for logging I went for an all in one approach. A monolog-azure handler. This benefits from having Monolog handle buffering and queuing, and flushing automatically for me. So, I haven't had to solve that since they are doing it higher up the chain.

Hopefully this helps give you some ideas on what I ended up needing / wanting.

TrackRequest.php

<?php
// inspired by mondago/laravel-azure-application-insights

namespace App\Http\Middleware;

use AppInsightsPHP\Client\Client;
use AppInsightsPHP\Client\TelemetryData;
use ApplicationInsights\Channel\Contracts\Request_Data;
use ApplicationInsights\Channel\Contracts\User;
use Closure;
use Illuminate\Http\Request;
use Symfony\Component\HttpFoundation\Response;

/**
 * TrackRequest
 */
class TrackRequest
{
    /**
     * @var Client $telemetryClient
     */
    private $telemetryClient;

    /**
     * @var Request_Data $requestData
     */
    private $requestData;

    /**
     * @var $requestProperties
     */
    protected $requestProperties;

    /**
     * @param Client $telemetryClient
     */
    public function __construct(Client $telemetryClient)
    {
        $this->telemetryClient = $telemetryClient;
    }

    /**
     * Handle an incoming request.
     *
     * @param \Illuminate\Http\Request $request
     * @param \Closure                 $next
     * @return mixed
     */
    public function handle(Request $request, Closure $next)
    {
        $this->requestData = $this->telemetryClient->beginRequest(
            'app ' . $request->getMethod() . ' ' . $request->getUri(),
            $request->fullUrl(),
            $this->getRequestStartTime(),
        );

        return $next($request);
    }

    /**
     * Post request processor
     * @param Request  $request
     * @param Response $response
     * @return void
     */
    public function terminate(Request $request, Response $response)
    {
        $this->setDefaultRequestProperties($request);
        $this->setUserId($request);

        $this->telemetryClient->endRequest(
            $this->requestData,
            $this->getRequestDurationTime(),
            $response->getStatusCode(),
            $response->isSuccessful(),
            $this->getRequestProperties(),
            null
        );

        $this->telemetryClient->flush();
    }

    /**
     * Set the user information for an authenticated user
     * @param Request $request
     * @return void
     */
    public function setUserId(Request $request)
    {
        if ($request->user() == null) {
            return;
        }

        /** @var \App\Models\User $user */
        $user = $request->user();

        $userContext = $this->telemetryClient->getContext()->getUserContext() ?? new User();
        $userContext->setAuthUserId($user->id);
        $userContext->setId("$user->first_name $user->last_name");
        $this->telemetryClient->getContext()->setUserContext($userContext);
    }

    /**
     * Start time of the request
     * @SuppressWarnings(PHPMD.Superglobals)
     * @return mixed
     */
    private function getRequestStartTime()
    {
        return $_SERVER['REQUEST_TIME_FLOAT'];
    }

    /**
     * Approximate duration of the request
     *
     * @return float|integer
     */
    private function getRequestDurationTime()
    {
        return (microtime(true) - $this->getRequestStartTime()) * 1000;
    }

    /**
     * Extract default properties from request
     *
     * @param Request $request
     * @return void
     */
    private function setDefaultRequestProperties(Request $request) : void
    {
        $this->addRequestProperty('url', $request->fullUrl());
        $this->addRequestProperty('querystring', $request->getQueryString());
        $this->addRequestProperty('ip', $request->ip());
        $this->addRequestProperty('client-ip', $request->ip());
        $this->addRequestProperty('user-agent', $request->userAgent());
        $this->addRequestProperty('secure', $request->secure());
        $this->addRequestProperty('referer', $request->server->get('referer'));
        $this->addRequestProperty('method', $request->method());

        if ($request->route()) {
            $this->addRequestProperty('route', $request->route()->getName());
        }
    }

    /**
     *  Set request property
     *
     * @param string $key
     * @param mixed  $value
     * @return void
     */
    public function addRequestProperty(string $key, $value) : void
    {
        $this->requestProperties[$key] = $value;
    }

    /**
     * Information from the request
     *
     * @return array
     */
    private function getRequestProperties()
    {
        return $this->requestProperties;
    }
}

AppInsightsLogHandler.php

<?php

namespace App\Logging;

use AppInsightsPHP\Client\Client;
use AppInsightsPHP\Client\TelemetryData;
use ApplicationInsights\Channel\Contracts\Message_Severity_Level;
use ApplicationInsights\Channel\Contracts\User;
use Monolog\Formatter\FormatterInterface;
use Monolog\Handler\AbstractProcessingHandler;
use Monolog\Logger;
use Monolog\LogRecord;

/**
 * AppInsightsLoggingHandler
 */
class AppInsightsLoggingHandler extends AbstractProcessingHandler
{
    /**
     * @var Client
     */
    private $telemetryClient;

    /**
     * @param Client  $telemetryClient
     * @param integer $level
     * @param boolean $bubble
     * @suppressWarnings(PHPMD.BooleanArgumentFlag)
     */
    public function __construct(Client $telemetryClient, int $level = Logger::DEBUG, bool $bubble = true)
    {
        parent::__construct($level, $bubble);
        $this->telemetryClient = $telemetryClient;
    }

    /**
     * @param array $records
     * @return void
     */
    public function handleBatch(array $records) : void
    {
        parent::handleBatch($records);
        $this->reset();
    }

    /**
     * @return void
     */
    public function reset() : void
    {
        $this->telemetryClient->flush();
    }

    /**
     * @return void
     */
    public function close() : void
    {
        $this->reset();
    }

    /**
     * @param LogRecord $record
     * @return void
     */
    protected function write(LogRecord $record) : void
    {
        switch ($record['level']) {
            case Logger::DEBUG:
            case Logger::INFO:
                $level = Message_Severity_Level::INFORMATION;

                break;
            case Logger::NOTICE:
                $level = Message_Severity_Level::VERBOSE;

                break;
            case Logger::WARNING:
                $level = Message_Severity_Level::WARNING;

                break;
            case Logger::ERROR:
            case Logger::ALERT:
            case Logger::EMERGENCY:
                $level = Message_Severity_Level::ERROR;

                break;
            case Logger::CRITICAL:
                $level = Message_Severity_Level::CRITICAL;

                break;
        }

        $formattedRecord = $this->formatter->format($record);

        $message = $formattedRecord['message'];
        $properties = \array_merge(
            [
                'channel' => $record['channel'],
                'datetime' => ($record['datetime'] instanceof \DateTimeInterface) ?
                    $record['datetime']->format('c') : $record['datetime'],
                'monolog_level' => $record['level_name'],
            ],
            $formattedRecord['context']
        );

        if (TelemetryData::message($message, $properties)->exceededMaximumSize()) {
            return;
        }

        if (auth()->hasUser()) {
            /** @var \App\Models\User $user */
            $user = auth()->user();

            $userContext = $this->telemetryClient->getContext()->getUserContext() ?? new User();
            $userContext->setAuthUserId($user->id);
            $userContext->setId("$user->first_name $user->last_name");
            $this->telemetryClient->getContext()->setUserContext($userContext);
        }

        if (isset($record->context['exception'])) {
            $this->telemetryClient->trackException($record->context['exception']);
            return;
        }

        $this->telemetryClient->trackMessage($message, $level, $properties);
    }

    /**
     * @return FormatterInterface
     */
    protected function getDefaultFormatter() : FormatterInterface
    {
        return new ContextFlatterFormatter();
    }
}