bugsnag / bugsnag-php

BugSnag error monitoring and crash reporting tool for PHP apps
https://docs.bugsnag.com/platforms/php
MIT License
554 stars 77 forks source link

startSession immediately triggers deliverSessions #666

Open alcohol opened 1 year ago

alcohol commented 1 year ago

Perhaps the behaviour I am about to describe is intentional, in which case this would be more of a feature (change) request than a bug report.

We currently use a Symfony EventSubscriber to automatically track sessions; see code:

<?php declare(strict_types=1);

namespace Vendor\Events\EventSubscriber;

use Bugsnag\Client;
use Symfony\Component\DependencyInjection\Attribute\Autowire;
use Symfony\Component\EventDispatcher\EventSubscriberInterface;
use Symfony\Component\HttpKernel\Event\RequestEvent;
use Symfony\Component\HttpKernel\Event\TerminateEvent;
use Symfony\Component\HttpKernel\KernelEvents;

class BugsnagSubscriber implements EventSubscriberInterface
{
    public function __construct(
        #[Autowire(value: '%kernel.environment%')]
        private readonly string $kernelEnvironment,
        private readonly Client $bugsnag
    ) {
    }

    public function onKernelRequest(RequestEvent $event): void
    {
        if ('docker' === $this->kernelEnvironment || ! $event->isMainRequest()) {
            return;
        }

        $this->bugsnag->startSession();
    }

    public function onKernelTerminate(TerminateEvent $event): void
    {
        if ('docker' === $this->kernelEnvironment || ! $event->isMainRequest()) {
            return;
        }

        $this->bugsnag->getSessionTracker()->sendSessions();
    }

    /** @return array<string, array{string, int}|array{string, int}[]|string|string[][]> */
    public static function getSubscribedEvents(): array
    {
        return [
            KernelEvents::REQUEST => ['onKernelRequest', 256],
            KernelEvents::TERMINATE => ['onKernelTerminate', 256],
        ];
    }
}

Recently our application suddenly became much slower on our production environment. Doing some quick profiling revealed that an http call to sessions.bugsnag.com was the root cause of this slowdown (the call took over 6 seconds on average).

Note: this was due to networking issues at digital ocean, not bugsnag itself.

I found this peculiar at first since we call deliverSessions in a kernel.terminate event in Symfony, which in theory means that I would have expected the call to sessions.bugsnag.com to happen after we had already delivered a response to the client.

Doing some quick reviewing of the code however, I learned that simply calling startSession already immediately triggers deliverSessions due to:

startSession calling incrementSessions https://github.com/bugsnag/bugsnag-php/blob/7fff8512b237a57323f600975ada6376e2b912c1/src/SessionTracker.php#L156

This $lastSent variable defaulting to 0 https://github.com/bugsnag/bugsnag-php/blob/7fff8512b237a57323f600975ada6376e2b912c1/src/SessionTracker.php#L300

Meaning this conditional is always true https://github.com/bugsnag/bugsnag-php/blob/7fff8512b237a57323f600975ada6376e2b912c1/src/SessionTracker.php#L302

Is this expected / intentional behaviour?

johnkiely1 commented 1 year ago

Hi @alcohol. This is something that we are aware of as an area of potential improvement. It is on our backlog to address as soon as priorities allow. We will post here as soon as we have any updates.