Merge pull request #59 from jcchavezs/improvements

refactor: improves performance of the library
jcchavezs · Apr 8, 2020 · 68004ba · 68004ba
2 parents 1cabcfd + b76b932
commit 68004ba
Show file tree

Hide file tree

Showing 10 changed files with 235 additions and 61 deletions.
diff --git a/.circleci/config.yml b/.circleci/config.yml
@@ -32,7 +32,10 @@ jobs:
       - run: |
           # wait just in case
           sleep 1
+          # makes sure we get one trace
           test $(curl -s 127.0.0.1:9411/api/v2/traces | jq '.[0] | length') -eq 1
+          # makes sure the trace does not contain errors
+          test $(curl -s 127.0.0.1:9411/api/v2/traces | jq -c '.[0][0].tags.error') = "null"
           exit $?
 
   symfony-4:
@@ -66,7 +69,10 @@ jobs:
       - run: |
           # wait just in case
           sleep 1
+          # makes sure we get one trace
           test $(curl -s 127.0.0.1:9411/api/v2/traces | jq '.[0] | length') -eq 1
+          # makes sure the trace does not contain errors
+          test $(curl -s 127.0.0.1:9411/api/v2/traces | jq -c '.[0][0].tags.error') = "null"
           exit $?
 
   symfony-5:
@@ -100,7 +106,10 @@ jobs:
       - run: |
           # wait just in case
           sleep 1
+          # makes sure we get one trace
           test $(curl -s 127.0.0.1:9411/api/v2/traces | jq '.[0] | length') -eq 1
+          # makes sure the trace does not contain errors
+          test $(curl -s 127.0.0.1:9411/api/v2/traces | jq -c '.[0][0].tags.error') = "null"
           exit $?
 
 workflows:

diff --git a/.travis.yml b/.travis.yml
@@ -12,6 +12,12 @@ jobs:
       env: SYMFONY_VERSION=4.4
     - php: "7.3"
       env: SYMFONY_VERSION=4.4
+    - php: "7.2"
+      env: SYMFONY_VERSION=5.0
+    - php: "7.3"
+      env: SYMFONY_VERSION=5.0
+    - php: "7.4"
+      env: SYMFONY_VERSION=5.0
 
 install:
   - composer require symfony/config:"^$SYMFONY_VERSION" symfony/http-kernel:"^$SYMFONY_VERSION" symfony/routing:"^$SYMFONY_VERSION" symfony/dependency-injection:"^$SYMFONY_VERSION"

diff --git a/README.md b/README.md
@@ -30,9 +30,10 @@ services:
       - "@zipkin.default_tracing"
       - "@logger"
     tags:
-      - { name: kernel.event_listener, event: kernel.request, priority: 256 }
-      - { name: kernel.event_listener, event: kernel.terminate }
+      - { name: kernel.event_listener, event: kernel.request, priority: 2560 }
+      - { name: kernel.event_listener, event: kernel.response, priority: -2560 }
       - { name: kernel.event_listener, event: kernel.exception }
+      - { name: kernel.event_listener, event: kernel.terminate }
 ```
 
 `@zipkin.default_tracing` is a `Zipkin\DefaultTracing` instance which is being 
@@ -144,9 +145,10 @@ services:
       - "@logger"
       - { instance: %instance_name% }
     tags:
-      - { name: kernel.event_listener, event: kernel.request, priority: 256 }
-      - { name: kernel.event_listener, event: kernel.terminate }
+      - { name: kernel.event_listener, event: kernel.request, priority: 2560 }
+      - { name: kernel.event_listener, event: kernel.response, priority: -2560 }
       - { name: kernel.event_listener, event: kernel.exception }
+      - { name: kernel.event_listener, event: kernel.terminate }
 ```
 
 ## Custom Tracing
@@ -163,9 +165,10 @@ services:
       - "@my_own_tracing"
       - "@logger"
     tags:
-      - { name: kernel.event_listener, event: kernel.request, priority: 256 }
-      - { name: kernel.event_listener, event: kernel.terminate }
+      - { name: kernel.event_listener, event: kernel.request, priority: 2560 }
+      - { name: kernel.event_listener, event: kernel.response, priority: -2560 }
       - { name: kernel.event_listener, event: kernel.exception }
+      - { name: kernel.event_listener, event: kernel.terminate }
 ```
 
 ## Span customizers
@@ -201,9 +204,10 @@ services:
       - { instance: %instance_name% }
       - "@zipkin.span_customizer.by_path_namer"
     tags:
-      - { name: kernel.event_listener, event: kernel.request, priority: 256 }
-      - { name: kernel.event_listener, event: kernel.terminate }
+      - { name: kernel.event_listener, event: kernel.request, priority: 2560 }
+      - { name: kernel.event_listener, event: kernel.response, priority: -2560 }
       - { name: kernel.event_listener, event: kernel.exception }
+      - { name: kernel.event_listener, event: kernel.terminate }
 ```
 
 ## Contributing

diff --git a/src/ZipkinBundle/DependencyInjection/Configuration.php b/src/ZipkinBundle/DependencyInjection/Configuration.php
@@ -10,7 +10,7 @@ final class Configuration implements ConfigurationInterface
 {
     public function getConfigTreeBuilder()
     {
-        if (Kernel::VERSION[0] == '5') {
+        if (Kernel::VERSION[0] === '5') {
             $treeBuilder = new TreeBuilder('zipkin');
             $rootNode = $treeBuilder->getRootNode();
         } else {

diff --git a/src/ZipkinBundle/Middleware.php b/src/ZipkinBundle/Middleware.php
@@ -15,15 +15,21 @@
 use Symfony\Component\HttpKernel\Kernel;
 use Symfony\Component\HttpFoundation\Request;
 use Symfony\Component\HttpKernel\Event\KernelEvent;
+use Symfony\Component\HttpKernel\Event\ResponseEvent;
 
 final class Middleware
 {
     const SPAN_CLOSER_KEY = 'zipkin_bundle_span_closer';
 
     /**
-     * @var Tracing
+     * @var Tracer
      */
-    private $tracing;
+    private $tracer;
+
+    /**
+     * @var callable
+     */
+    private $extractor;
 
     /**
      * @var LoggerInterface
@@ -43,15 +49,16 @@ final class Middleware
     /**
      * @var bool
      */
-    private $usesDeprecatedEvents = false;
+    private $usesDeprecatedEvents;
 
     public function __construct(
         Tracing $tracing,
         LoggerInterface $logger,
         array $tags = [],
         SpanCustomizer ...$spanCustomizers
     ) {
-        $this->tracing = $tracing;
+        $this->tracer = $tracing->getTracer();
+        $this->extractor = $tracing->getPropagation()->getExtractor(new Map());
         $this->logger = $logger;
         $this->tags = $tags;
         $this->spanCustomizers = $spanCustomizers;
@@ -77,7 +84,7 @@ public function onKernelRequest(KernelEvent $event)
             return;
         }
 
-        $span = $this->tracing->getTracer()->nextSpan($spanContext);
+        $span = $this->tracer->nextSpan($spanContext);
         $span->start();
         $span->setName($request->getMethod());
         $span->setKind(Kind\SERVER);
@@ -88,7 +95,7 @@ public function onKernelRequest(KernelEvent $event)
             $span->tag($key, $value);
         }
 
-        $request->attributes->set(self::SPAN_CLOSER_KEY, $this->tracing->getTracer()->openScope($span));
+        $request->attributes->set(self::SPAN_CLOSER_KEY, $this->tracer->openScope($span));
     }
 
     /**
@@ -100,7 +107,7 @@ public function onKernelController(KernelEvent $event)
             return;
         }
 
-        $span = $this->tracing->getTracer()->getCurrentSpan();
+        $span = $this->tracer->getCurrentSpan();
         if ($span !== null) {
             $span->annotate('symfony.kernel.controller', now());
         }
@@ -115,32 +122,79 @@ public function onKernelException(KernelEvent $event)
             return;
         }
 
-        $span = $this->tracing->getTracer()->getCurrentSpan();
-        if ($span !== null) {
+        $span = $this->tracer->getCurrentSpan();
+        if ($span === null) {
+            return;
+        }
+
+        if ($this->usesDeprecatedEvents) {
+            /**
+             * @var \Symfony\Component\HttpKernel\Event\GetResponseForExceptionEvent $event
+             */
+            $errorMessage = $event->getException()->getMessage();
+        } else {
+            /**
+             * @var \Symfony\Component\HttpKernel\Event\ExceptionEvent $event
+             */
+            $errorMessage = $event->getThrowable()->getMessage();
+        }
+
+        $span->tag(Tags\ERROR, $errorMessage);
+        $this->finishSpan($event->getRequest(), null);
+    }
+
+    /**
+     * @see https://symfony.com/doc/4.4/reference/events.html#kernel-response
+     */
+    public function onKernelResponse(KernelEvent $event)
+    {
+        if ($this->usesDeprecatedEvents) {
+            /**
+             * @var \Symfony\Component\HttpKernel\Event\FilterResponseEvent $event
+             */
+        } else {
+            /**
+             * @var \Symfony\Component\HttpKernel\Event\ResponseEvent $event
+             */
+        }
+
+        $this->finishSpan($event->getRequest(), $event->getResponse());
+    }
+
+    /**
+     * @see https://symfony.com/doc/4.4/reference/events.html#kernel-terminate
+     */
+    public function onKernelTerminate(KernelEvent $event)
+    {
+        // Previously, the onKernelResponse listener did not exist in this class
+        // and hence we finished the span and closed the scope on terminate.
+        // However, terminate happens after the response have been sent and it could
+        // happen that span is being finished after some other processing attached by
+        // the user. onKernelResponse is the right place to finish the span but in order
+        // to not to break existing user relaying on the onKernelTerminate to finish
+        // the span we add this temporary fix.
+
+        $scopeCloser = $event->getRequest()->attributes->get(self::SPAN_CLOSER_KEY);
+        if ($scopeCloser !== null) {
             if ($this->usesDeprecatedEvents) {
                 /**
-                 * @var Symfony\Component\HttpKernel\Event\GetResponseForExceptionEvent $event
+                 * @var \Symfony\Component\HttpKernel\Event\PostResponseEvent $event
                  */
-                $errorMessage = $event->getException()->getMessage();
             } else {
                 /**
-                 * @var Symfony\Component\HttpKernel\Event\ExceptionEvent $event
+                 * @var \Symfony\Component\HttpKernel\Event\TerminateEvent $event
                  */
-                $errorMessage = $event->getThrowable()->getMessage();
             }
 
-            $span->tag(Tags\ERROR, $errorMessage);
+            $this->finishSpan($event->getRequest(), $event->getResponse());
         }
+
+        $this->flushTracer();
     }
 
-    /**
-     * @see https://symfony.com/doc/4.4/reference/events.html#kernel-terminate
-     */
-    public function onKernelTerminate(KernelEvent $event)
+    private function finishSpan(Request $request, $response)
     {
-        $request = $event->getRequest();
-
-        $span = $this->tracing->getTracer()->getCurrentSpan();
+        $span = $this->tracer->getCurrentSpan();
         if ($span === null) {
             return;
         }
@@ -154,20 +208,19 @@ public function onKernelTerminate(KernelEvent $event)
             $span->tag('symfony.route', $routeName);
         }
 
-        $statusCode = $event->getResponse()->getStatusCode();
-        if ($statusCode > 399) {
-            $span->tag(Tags\ERROR, (string) $statusCode);
+        if ($response != null) {
+            $statusCode = $response->getStatusCode();
+            if ($statusCode > 399) {
+                $span->tag(Tags\ERROR, (string) $statusCode);
+            }
+            $span->tag(Tags\HTTP_STATUS_CODE, (string) $statusCode);
         }
 
-        $span->tag(Tags\HTTP_STATUS_CODE, (string) $statusCode);
         $span->finish();
-
         $scopeCloser = $request->attributes->get(self::SPAN_CLOSER_KEY);
         if ($scopeCloser !== null) {
             $scopeCloser();
         }
-
-        $this->flushTracer();
     }
 
     /**
@@ -176,9 +229,7 @@ public function onKernelTerminate(KernelEvent $event)
      */
     private function extractContextFromRequest(Request $request)
     {
-        $extractor = $this->tracing->getPropagation()->getExtractor(new Map());
-
-        return $extractor(array_map(
+        return ($this->extractor)(array_map(
             function ($values) {
                 return $values[0];
             },
@@ -188,12 +239,10 @@ function ($values) {
 
     private function flushTracer()
     {
-        register_shutdown_function(function (Tracer $tracer, LoggerInterface $logger) {
-            try {
-                $tracer->flush();
-            } catch (Exception $e) {
-                $logger->error($e->getMessage());
-            }
-        }, $this->tracing->getTracer(), $this->logger);
+        try {
+            $this->tracer->flush();
+        } catch (Exception $e) {
+            $this->logger->error($e->getMessage());
+        }
     }
 }
diff --git a/tests/Integration/Makefile b/tests/Integration/Makefile
@@ -1,5 +1,5 @@
-SYMFONY_VERSION ?= dev-master
-LIBRARY_BRANCH ?= 3.0
+SYMFONY_VERSION ?= 4.4
+LIBRARY_BRANCH ?= master
 
 build: ## Builds the symfony app
 	./build.sh $(SYMFONY_VERSION) $(LIBRARY_BRANCH) $(SAMPLER)

diff --git a/tests/Integration/tracing.custom.yaml b/tests/Integration/tracing.custom.yaml
@@ -35,6 +35,7 @@ services:
       - { "version": "xxx" }
       - "@zipkin.span_namer.route"
     tags:
-      - { name: kernel.event_listener, event: kernel.request, priority: 256 }
-      - { name: kernel.event_listener, event: kernel.terminate }
+      - { name: kernel.event_listener, event: kernel.request, priority: 2560 }
+      - { name: kernel.event_listener, event: kernel.response, priority: -2560 }
       - { name: kernel.event_listener, event: kernel.exception }
+      - { name: kernel.event_listener, event: kernel.terminate }
diff --git a/tests/Integration/tracing.default.yaml b/tests/Integration/tracing.default.yaml
@@ -14,7 +14,7 @@ zipkin:
 services:
   zipkin.span_namer.route:
     class: ZipkinBundle\SpanCustomizers\ByPathNamer\SpanCustomizer
-    factory: [ZipkinBundle\SpanCustomizers\ByPathNamer\SpanCustomizer, 'create']
+    factory: [ZipkinBundle\SpanCustomizers\ByPathNamer\SpanCustomizer, "create"]
     arguments:
       - "%kernel.cache_dir%"
 
@@ -33,6 +33,7 @@ services:
       - { "version": "xxx" }
       - "@zipkin.span_namer.route"
     tags:
-      - { name: kernel.event_listener, event: kernel.request, priority: 256 }
-      - { name: kernel.event_listener, event: kernel.terminate }
+      - { name: kernel.event_listener, event: kernel.request, priority: 2560 }
+      - { name: kernel.event_listener, event: kernel.response, priority: -2560 }
       - { name: kernel.event_listener, event: kernel.exception }
+      - { name: kernel.event_listener, event: kernel.terminate }
diff --git a/tests/Integration/tracing.percentage.yaml b/tests/Integration/tracing.percentage.yaml
@@ -12,7 +12,7 @@ zipkin:
 services:
   zipkin.span_namer.route:
     class: ZipkinBundle\SpanCustomizers\ByPathNamer\SpanCustomizer
-    factory: [ZipkinBundle\SpanCustomizers\ByPathNamer\SpanCustomizer, 'create']
+    factory: [ZipkinBundle\SpanCustomizers\ByPathNamer\SpanCustomizer, "create"]
     arguments:
       - "%kernel.cache_dir%"
 
@@ -31,6 +31,7 @@ services:
       - { "version": "xxx" }
       - "@zipkin.span_namer.route"
     tags:
-      - { name: kernel.event_listener, event: kernel.request, priority: 256 }
-      - { name: kernel.event_listener, event: kernel.terminate }
+      - { name: kernel.event_listener, event: kernel.request, priority: 2560 }
+      - { name: kernel.event_listener, event: kernel.response, priority: -2560 }
       - { name: kernel.event_listener, event: kernel.exception }
+      - { name: kernel.event_listener, event: kernel.terminate }