Fix profiler for plugins like redirect #128

fbourigault · 2017-02-02T22:15:42Z

Q	A
Bug fix?	yes
New feature?	no
BC breaks?	no
Deprecations?	no
Related tickets	fixes #121
Documentation	n/a
License	MIT

fix #121.
The issue occurs when a plugin like redirect is triggered, it's code create a new request and then calls $first($newRequest). By doing so, the data collector is completely messed up and show the new request in the stack which created the request and in a new request stack.

We have to find a way to not mess the display. My proposal is to inject in the debug stack a plugin that when called with a RequestInterface mark the beginning of a new request and when called with a ResponseInterface mark the end of the current request.
If called with a RequestInterface twice without intermediary call with ResponseInterface, we could mark the beginning of a new request and also mark this new request as coming from the first one.

Current panel rendering (1.8MB png)

HttplugBundle configuration:

httplug:
    clients:
        centrale:
            config:
                timeout: 2
            factory: httplug.factory.guzzle6
            plugins:
                - App\Http\Plugin\AuthorizationPlugin
                - add_host:
                    host: 'localhost'
                - header_set:
                    headers:
                        Accept: application/json
                - httplug.plugin.error
                - httplug.plugin.logger
                - httplug.plugin.redirect
    plugins:
        logger:
            logger: monolog.logger.httplug

The triggered request was GET /api/user which redirects to /api/entities/1e24fb4a-e250-11e6-b52d-0242ac140002

To Do

Nyholm

Thank you for trying to solve this. I've just briefly given it some thought... the solution I had in mind is to replace the arrays (FailureStack, RequestStack, ResponseStack, PluginNames) with one or more objects/managers/collections. Then handle index out of bounds errors in that objects.

What do you think about that?

Nyholm · 2017-02-03T10:11:21Z

Resources/views/webprofiler.html.twig

@@ -115,7 +115,7 @@
                    </tr>
                {% else %}
                    <tr class="httplug-request-stack">
-                        <td class="httplug-plugin-name">&darr; {{ pluginNames[idx-1] }} </td>
+                        <td class="httplug-plugin-name">&darr; {#{{ pluginNames[idx-1] }}#}PLUGIN-NAME </td>


Hm, this needs to be done better.

It's just to avoid page breaking and get the screenshot :)

fbourigault · 2017-02-03T10:27:00Z

I like your idea. Using objects is probably better and will help to write tests and will also hold all the extra informations like the plugin name :)

If you look at my screenshot, the output is completely cluttered.

Initial request was GET /api/user which redirects to /api/entities/1e24fb4a-e250-11e6-b52d-0242ac140002.

What do you think about stopping the current profile when a new request start and mark this new request as child of the first one?

Nyholm · 2017-02-03T10:28:50Z

What do you think about stopping the current profile when a new request start and mark this new request as child of the first one?

Yes, lets try that.

joelwurtz · 2017-02-03T10:39:41Z

Keep in mind that you can also have request in parallels when doing async, this is why tracking origin of redirect request is very hard.

fbourigault · 2017-02-03T10:43:53Z

Thanks for this reminder. What about adding an uuid as header in messages for better tracking? The only drawback I see is begin a header so it will be sent with the request! But only when using the profiler.

joelwurtz · 2017-02-03T10:48:23Z

What about adding an uuid as header in messages for better tracking? The only drawback I see is begin a header so it will be sent with the request! But only when using the profiler.

I have a hard feeling with custom header, but the more i see the RedirectPlugin the more i think it's the only way to do that

fbourigault · 2017-02-03T11:17:54Z

We could use X-Request-ID: f058ebd6-02f7-4d3f-942e-904344e8cde5 (https://en.wikipedia.org/wiki/List_of_HTTP_header_fields#Common_non-standard_request_fields)

I didn't yet know well all httplug internals, but where could we copy the header from the request to the response to continue tracking?

dbu · 2017-02-03T11:27:48Z

the response won't have the custom header. it feels very iffy to have to send a header for a profiler that runs locally in our application.

does the profiler need to be last in the chain to see the response before redirection is executed? or do we need two plugins, one at the start and one at the end?

fbourigault · 2017-02-03T12:15:08Z

According to https://github.com/php-http/HttplugBundle/blob/master/Collector/DebugPlugin.php#L11 the debug plugin is inserted between each plugin. Could we write something like this:

        return $next($request)->then(function (ResponseInterface $response) use ($request, $collector, $clientName, &$depth) {
            //Copy the header from request to response.
            $response->withHeader('X-REQUEST-ID', $request->getHeader('X-REQUEST-ID');
            $collector->addResponse($response, $clientName, $depth--);

            return $response;
        }, function (Exception $exception) use ($collector, $clientName, &$depth) {
            //Do something here too.
            $collector->addFailure($exception, $clientName, $depth--);

            throw $exception;
        });

We could also, just before sending the request to the client, remove the header to don't get it sent and add it in the response returned by the client.

dbu · 2017-02-03T13:44:44Z

i did not look into the code in detail, but can't we use our code to track it in the callback we pass? i just think having to change request / response in any way to track them is wrong - but also should not be needed.

dbu · 2017-02-03T13:46:25Z

something like

        $id = generate_uuid();

        return $next($request)->then(function (ResponseInterface $response) use ($request, $collector, $clientName, &$depth, $id) {
            ...

            return $response;
        }, function (Exception $exception) use ($collector, $clientName, &$depth) {
            //Do something here too.
            $collector->addFailure($exception, $clientName, $depth--);

            throw $exception;
        });

fbourigault · 2017-02-03T15:04:55Z

After some valuable thoughts with @dbu on Slack, I propose a new solution for tracking messages.

The idea is to decorate each stack plugin with a DebugPluginDecorator which wraps the $next and $first callback before calling the plugin.

As you can see in the following code, each response or failure is linked to the corresponding request. This allows for any request to get the corresponding response or failure when rendering a row in the panel.

Each request object is linked to the previous one which allows to get the request message chain.

When a request is added to the collector with addFirstRequest, it's marked as a new request which will be displayed as #Request {id} in the profiler.

With such tracking we should avoid mess created by async requests and by plugins that use the $first callback.

class DebugPluginDecorator implements Plugin
{
    /**
     * @var Plugin
     */
    private $plugin;

    /**
     * @var Collector
     */
    private $collector;

    /**
     * @param Plugin $plugin
     */
    public function __construct(Plugin $plugin, Collector $collector)
    {
        $this->plugin = $plugin;
        $this->collector = $collector;
    }

    /**
     * {@inheritdoc}
     */
    public function handleRequest(RequestInterface $request, callable $next, callable $first)
    {
        $originalRequest = $request;

        $nextWrapper = function (RequestInterface $request) use ($next, $originalRequest) {
            $this->collector->addRequest($request, $originalRequest); //Add the request to the collector with the original request as parent.
            return $next($request)->then(function (ResponseInterface $response) use ($originalRequest) {
                $this->collector->addResponse($response, $originalRequest); //Add the response corresponding to the original request.
                return $response;
            }, function (Exception $exception) use ($originalRequest) {
                $this->collector->addException($exception, $originalRequest); //Add the exception corresponding to the original request.
                throw $exception;
            });
        };

        $firstWrapper = function (RequestInterface $request) use ($first, $originalRequest) {
            $this->collector->addFirstRequest($request, $originalRequest); //Add the request as a first request to the collector with the original request as parent.
            return $first($request)->then(function (ResponseInterface $response) use ($originalRequest) {
                $this->collector->addResponse($response, $originalRequest); //Add the response corresponding to the original request.
                return $response;
            }, function (Exception $exception) use ($originalRequest) {
                $this->collector->addException($exception, $originalRequest); //Add the exception corresponding to the original request.
                throw $exception;
            });
        };

        $this->plugin->handleRequest($request, $nextWrapper, $firstWrapper);
    }
}

fbourigault · 2017-02-04T15:35:26Z

I added the concept of profiles to keep together the request, response and failure of every executed plugin.

To get the tracking working, each plugin has to be decorated with a DebugPluginDecorator.

Such implementation still lack tracking profile chain. I'm looking for ideas for this topic.

I didn't tried yet, but this implementation will also suffer of the same request sent more than once. Ideas are welcome for this topic too!

dbu · 2017-02-06T18:11:53Z

Collector/Collector.php

+     */
+    public function getProfile(Plugin $plugin, RequestInterface $request)
+    {
+        $key = spl_object_hash($plugin).'-'.spl_object_hash($request);


if we want to keep request/response together through all plugins, i think this will not work. any plugin can change the request, making it a different object. or maybe i misunderstand what a "profile" is.

A profile is the result of one plugin execution. However this lack storage is not perfect as executing the same request will override values. I probably should not hash profile to avoid such case.

fbourigault · 2017-02-07T13:51:33Z

Collector/DebugPluginDecorator.php

+    private function wrap(callable $callable, Profile $profile)
+    {
+        return function (RequestInterface $request) use ($callable, $profile) {
+            return $callable($request)->then(function (ResponseInterface $response) use ($profile) {


I get an error at this line. The $callable($request) call didn't return a Promise as I expected but null. I probably misunderstood something :/ As I said before, each plugin is decorated with a DebugPluginDecorator instance so I expected a Promise as specified by Plugin::handleRequest. Help is welcome here!

Nevermind. I just forgot to return the decorated plugin result...

fbourigault · 2017-02-08T16:35:35Z

I have something working locally. Should I care BC? I'm asking for BC because I made a lot of changes in the profiler internals to get this working.

Nyholm · 2017-02-08T16:40:36Z

Awesome. Yes, we should care about BC. Though, you should know our BC promise. http://docs.php-http.org/en/latest/httplug/backwards-compatibility.html

I've just checked quickly. But I think your changes are safe.

fbourigault · 2017-02-08T22:48:41Z

I pushed my new profiler implementation. I didn't fixed tests yet as we have to chose to break BC or not. I also didn't added yet unit tests. I also need to make styleci and scrutinizer happy!

fbourigault · 2017-02-14T22:32:06Z

Code is now ready to review.

After getting this PR merged, we will be able to deprecate the debug_plugins as there are no longer used by the profiler.

dbu

thank you! i trust you tested that this works on redirections in a real symfony application? i only looked at the code but did not run it.

i think we should indeed delete those classes and not keep them around as deprecated, to reduce noise in the code. we should at least bump the minor version however.

dbu · 2017-02-15T08:07:51Z

Tests/Unit/Collector/FormatterTest.php

+
+    public function setUp()
+    {
+        $this->formatter = $this->createMock(Formatter::class);


the phpunit version that supports this is unfortunately php 5.6 and above only. this bundle still supports 5.5 so you need getMock - and if formatter has no interface and constructor arguments, the full getMockBuilder->disableOriginalConstructor->getMock() stuff.

dbu · 2017-02-15T08:11:10Z

Collector/ProfileFactory.php

+ *
+ * @internal
+ */
+class ProfileFactory


as there are no interfaces on profile and factory: why not just do new in the place where we need a profile? as these classes are internal anyways, they do not need to be extensible. having factory and all this invites people to customize...

I added factories to be able to write expectations on the created Profile. I can make the ProfileFactory and the StackFactory final or do something else if you have ideas!

ah, i see. yeah lets make all 4 classes final then, to avoid people extending them. both profile / stack and the factories.

If I mock the factories, I'm no loner able to have control on the Stack or Profile objects during tests :/
Maybe my tests over describe the plugin behaviors.

as stack and profile are basically value objects, it would probably be better to just use the real objects and make assertions on what ends up being in them. this does slightly violate the isolation, but if we still have a isolated unit test on both value objects, it should be good enough. also, we do need the plugin to work correctly with the value objects, so this low level of integration test seems like a good thing to me.

I will try this. It sould work as I can mock the Collector::getCurrentStack method to return a real Stack object and I will be able to write some assert around it. Looks promising. If doing so, I will remove the two factories as I created both while writing tests.

dbu · 2017-02-15T08:11:57Z

Collector/StackFactory.php

+ *
+ * @internal
+ */
+class StackFactory


same with this factory: can't we just new Stack()?

dbu · 2017-02-15T08:13:45Z

Collector/Formatter.php

+        }
+
+        if ($exception instanceof TransferException) {
+            return $exception->getMessage();


should we add some sort of prompt? message alone could be incomplete or even empty... "Request failed: " maybe?

I just get this code from the old DebugCollector, but I can improve this :)

ah sorry. but i think its worth it to improve.

dbu · 2017-02-15T08:14:07Z

Collector/Formatter.php

+use Exception;
+use Http\Client\Exception\HttpException;
+use Http\Client\Exception\TransferException;
+use Http\Message\Formatter as FormatterInterface;


maybe as MessageFormatter?

dbu · 2017-02-15T08:14:47Z

Collector/Formatter.php

+use Psr\Http\Message\RequestInterface;
+use Psr\Http\Message\ResponseInterface;
+
+/**


can you please add a class phpdoc comment here that this class is a decorator for the message formatter that also formats exceptions?

dbu · 2017-02-15T08:15:33Z

Collector/Formatter.php

+            return $exception->getMessage();
+        }
+
+        return sprintf('Unexpected exception of type "%s"', get_class($exception));


i think we should also include $exception->getMessage here.

fbourigault · 2017-02-15T13:17:27Z

@dbu I addressed all changes you requested.

I tried this new profiler in a specially crafted symfony app.
If you think it's valuable, I could add functional tests :)

dbu

i am now basically at the nitpicking level. that means we are almost done :-)

suggested some further code cleanups. at least we should delete the now unused stack factory

dbu · 2017-02-15T13:22:09Z

Collector/Profile.php

+    /**
+     * @param string $plugin
+     */
+    public function setPlugin(string $plugin)


sorry to only come up with this now, but: do we ever need to change this value? it looks like this and setRequest should be replaced with mandatory constructor arguments. only response and failed are added later.

I will also remove php 7 string hint. I probably misconfigured phpstorm!

dbu · 2017-02-15T13:24:56Z

Collector/Stack.php

+    /**
+     * @param string $client
+     */
+    public function setClient($client)


same here, i think this and setRequest should be mandatory constructor arguments

dbu · 2017-02-15T13:26:31Z

Tests/Unit/Collector/FormatterTest.php

+use Http\Client\Exception\HttpException;
+use Http\Client\Exception\TransferException;
+use Http\HttplugBundle\Collector\Formatter as CollectorFormatter;
+use Http\Message\Formatter;


could we alias this to MessageFormatter and not alias the formatter we are testing, for better readability?

dbu · 2017-02-15T13:27:56Z

Collector/StackFactory.php

+ *
+ * @internal
+ */
+final class StackFactory


this class can now be deleted i think

dbu · 2017-02-15T13:31:00Z

If you think it's valuable, I could add functional tests :)

well, this is no production feature, so i think its ok without them. some amount of functional tests would not hurt but we should probably focus on things that might break in a live system. if the debug mode has an issue its not as terrible.

fbourigault · 2017-02-16T13:00:22Z

I'm working on fixing unit tests. I replaced $this->expectsException calls with $this->setExpectedException which is deprecated since phpunit 5.2. But I don't think there is an alternative that works with older phpunit and does not throw any deprecation notice.

I also have an error I don't understand. Could someone look at https://travis-ci.org/php-http/HttplugBundle/jobs/201864827#L291?

fbourigault · 2017-02-16T13:10:59Z

I addressed the "code cleanups". I added constructors for Profile and Stack and removed no longer used set methods.

fbourigault · 2017-02-16T13:57:16Z

For the build still failing, is it possible to re-trigger a build on master. It may be related to something incompatible since twig 2.0 is out (https://travis-ci.org/php-http/HttplugBundle/jobs/186351795#L192).

EDIT: tests are now green 🎉

Nyholm · 2017-02-16T15:30:34Z

Just made a quick test. Im using a plugin client with RedirectPlugin and RetryPlugin. Im sending a request to http://www.happyr.com which should redirect to https://happyr.com and then to https://happyr.com/sv

Im getting 3 requests which is fine. But I am not too sure the response is correct in all requests. See screenshot.

fbourigault · 2017-02-16T15:46:34Z

The output may looks weird as in request 2, in the response column of the redirect plugin, you get the final response from request 3 and in the same happens with the response column of the redirect plugin from request 1 being exactly the same as the final response from request 2.

Nyholm

I like this PR.

If we encounter a redirect, shouldn't the response of that request show the redirect headers. IE, not to show the end response (When all redirects has been followed)?

Nyholm · 2017-02-16T15:37:28Z

Collector/Collector.php

+use Symfony\Component\HttpKernel\DataCollector\DataCollector;
+
+/**
+ * @author Fabien Bourigault <bourigaultfabien@gmail.com>
