Debugger not shown on some servers with recent session changes

[adrianbj]

Since 5c46e98 (all the session changes) I no longer see the debugger bar on one of my servers. I haven't tested widely yet to narrow it down, but here are a few key differences between one that works and one that doesn't.

Works:
PHP 5.6.6
Server API: Apache 2.0 Handler
session.save_handler: files

Doesn't Work:
PHP 5.5.35
Server API: CGI/FastCGI
session.save_handler: user

Let me know if I can provide ant further info.

[JanTvrdik]

Try following the hint in #154 (comment)

[adrianbj]

Thanks for the tip, but either I am not getting it, or it's still not working. I tried manually doing a: session_start();

and also tried adding: Debugger::dispatch(); after enabling, and still no luck.

Any chance of some more details on how to actually implement?

Thanks!

[JanTvrdik]

When using nginx you must use try_files $uri $uri/ /index.php?$args; not just try_files $uri $uri/ /index.php; otherwise $_GET is uninitialized.

[adrianbj]

Not running nginx - just good ol' apache.

I still have no idea how to get the debug bar to display on this one server.

[adrianbj]

I have started investigating the problem and I think there are a few things going on.

1. None of the $_SESSION['_tracy']['bar'] indexes have any content.

2. If you trigger an error in strict mode so that it is sent to bluescreen, I get the following:

?_tracy_bar=content.bdbdc38d34:1 Uncaught SyntaxError: Unexpected token <

which actually contains the complete html of the loaded page.

3. triggering an error starts the session, but resets sessions started from other php scripts on the page. In my case this results in me being logged out.

[dg]

When you open this url and dump $_GET, do you see parameter _tracy_bar?

[adrianbj]

$_GET is empty.

$_SESSION['_tracy'] is:

array (2)
bar => array (6)
ba68a5fdc5 => NULL
dd35620d90 => NULL
96011140cc => NULL
240f954a98 => NULL
7cd87a458b => NULL
5095d5b709 => NULL
bluescreen => array (6)
ba68a5fdc5 => NULL
dd35620d90 => NULL
96011140cc => NULL
240f954a98 => NULL
7cd87a458b => NULL
5095d5b709 => NULL

Here are the bar resources that are loaded:

[adrianbj]

Sometimes the ?_tracy_bar=content resource is not loaded

[dg]

$_GET is empty on url ?_tracy_bar=content.bdbdc38d34?

[adrianbj]

The url has an empty Response when loaded directly with ?_tracy_bar=content.bdbdc38d34. If I remove the _ prefix it loads and the value is displayed in the value of the dumped $_GET

[adrianbj]

I guess the key thing is that the $_GET['tracy_bar'] is not available inside the dispatchContent() method.

[dg]

Can you try investigate why your server removes this parameter?

[adrianbj]

I just figured out a hack to get the debug bar to display. These are the changes I made.

Basically it is all about getting the $contentId variable that is valid in the render() method into the $session variable in the dispatchContent() method.

I am not suggesting this is the right way to fix it all - it's definitely not, but I think it shows that the only problem is that $_GET['_tracy_bar'] is not allowing the $session variable to be correctly set.

Bar.php

@@ -18,7 +18,7 @@

    /** @var bool */
    private $dispatched;
-
+   public $contentId;

    /**
     * Add custom panel.
@@ -125,14 +125,14 @@
        require __DIR__ . '/assets/Bar/panels.phtml';
        require __DIR__ . '/assets/Bar/bar.phtml';
        $content = Helpers::fixEncoding(ob_get_clean());
-       $contentId = NULL;
+       $this->contentId = NULL;

        if ($this->dispatched) {
-           $contentId = Helpers::isAjax()
+           $this->contentId = Helpers::isAjax()
                ? $_SERVER['HTTP_X_TRACY_AJAX'] . '-ajax'
                : substr(md5(uniqid('', TRUE)), 0, 10);

-           $_SESSION['_tracy']['bar'][$contentId] = ['content' => $content, 'dumps' => $dumps];
+           $_SESSION['_tracy']['bar'][$this->contentId] = ['content' => $content, 'dumps' => $dumps];
        }

        if (Helpers::isHtmlMode()) {
@@ -185,7 +185,7 @@
            header('X-Tracy-Ajax: 1'); // session must be already locked
        }
        if (preg_match('#^content(-ajax)?.(\w+)$#', isset($_GET['_tracy_bar']) ? $_GET['_tracy_bar'] : '', $m)) {
-           $session = & $_SESSION['_tracy']['bar'][$m[2] . $m[1]];
+           $session = & $_SESSION['_tracy']['bar'][$this->contentId];
            header('Content-Type: text/javascript');
            header('Cache-Control: max-age=60');
            header_remove('Set-Cookie');
@@ -203,4 +203,4 @@
        }
    }

[adrianbj]

It seems like there is no call to ?_tracy_bar=content.bdbdc38d34 anymore - it was before, but maybe this is part of the session problem. I guess this is why passes the $contentId through to dispatchContent() is allowing it to working even without that call.

[adrianbj]

Ok, so I see that the call to ?_tracy_bar=content.bdbdc38d34 won't happen unless $contentId is available to loader.phtml

<?php if ($contentId): ?>
<script src="?<?=http_build_query(['_tracy_bar' => "content.$contentId"] + $stopXdebug, NULL, '&amp;')?>"></script>
<?php else: ?>

I haven't traced back further than that yet, but I am guessing it will likely be obvious to you now?

[adrianbj]

Commenting out these line like this also works without any of the changes above because it gets the valid $contentId to loader.phtml:

        ob_start(function () {});
        require __DIR__ . '/assets/Bar/panels.phtml';
        require __DIR__ . '/assets/Bar/bar.phtml';
        $content = Helpers::fixEncoding(ob_get_clean());
        //$contentId = NULL;

        if ($this->dispatched) {
            /*$contentId = Helpers::isAjax()
                ? $_SERVER['HTTP_X_TRACY_AJAX'] . '-ajax'
                : substr(md5(uniqid('', TRUE)), 0, 10);*/

            $_SESSION['_tracy']['bar'][$contentId] = ['content' => $content, 'dumps' => $dumps];
        }

Hopefully this is helpful and I am not too far removed from the source of the problem.

[adrianbj]

Apologies - that last post wasn't really true - the $contentId is obviously not set at all, but not setting is what allows the debug bar to show.

[adrianbj]

Even if I dump($_GET) inside the dispatchContent() method on my local dev setup where the debug bar works fine, it still returns NULL, even though there is a call to ?_tracy_bar=content.dd9018b908 and the debug bar shows. Sorry, I don't think I am being much help at all :)

[adrianbj]

Sorry for the very fragmented feedback on this - trying to finish up some other things and pack to go on vacation tomorrow.

So it looks like the GET['_tracy_bar'] is there, but it only gets populated the second time dispatchContent() is called. I logged it a different way which helped me notice this. I can't see any difference in the behaviour of this on the server that's not working and on my local dev that is working. Back to the $contentId problem?

[milo]

@adrianbj Could you try to dump $_SERVER['REQUEST_URI'] when $_GET is empty?

[adrianbj]

Ok, here are the results on this log statement placed just before the preg_match in the dispatchContent() function.

log($_SERVER['REQUEST_URI']).' : '.json_encode($_GET));

Working Local Dev

2016-05-24 08:04:18 http://mysite.dev/  "\/" : []
2016-05-24 08:04:21 http://mysite.dev//-_tracy_bar-content.ef09c91d53/?_tracy_bar=content.ef09c91d53    "\/?_tracy_bar=content.ef09c91d53" : {"_tracy_bar":"content.ef09c91d53"}

Not Working Production Server

2016-05-24 08:11:16 http://mysite.com/  "\/" : []
2016-05-24 08:11:17 http://mysite.com//-_tracy_bar-content.d01560f848/?_tracy_bar=content.d01560f848    "\/?_tracy_bar=content.d01560f848" : {"_tracy_bar":"content.d01560f848"}

So I don't think there is any difference and I don't think the issue is related to $_GET['_tracy_bar']

[dg]

I would like to release stable next week. Did you found reason why it does not work? What about last dev version?

[adrianbj]

In the latest dev version the debug bar works fine for normal loading if I make just this one change in loader.phtml

<?php if ($contentId): ?>

to:

<?php if (!$contentId): ?>

However it still doesn't show the AJAX version of the bar. This

tracy/src/Tracy/Bar.php

Line 64 in 1503008

} elseif (Helpers::isAjax()) {

is being triggered and $this->dispatched is returning TRUE

[adrianbj]

Just going to keep adding more things as I notice them. Obviously add the ! like I did above prevents the:

http://mysite.com/admin/page/?_tracy_bar=content-ajax.df463f62a9&XDEBUG_SESSION_STOP=1&XDEBUG_PROFILE=0&XDEBUG_TRACE=0&v=0.9820714200674963

links from being created.

So, this approach allows that:

<?php if ($contentId): ?>
<script src="?<?=http_build_query(['_tracy_bar' => "content.$contentId"] + $stopXdebug, NULL, '&amp;')?>"></script>
<?php endif ?>
<script>
Tracy.Debug.init(<?= json_encode($content) ?>, <?= json_encode($dumps) ?>);
</script>

This means that Debug is initiated regardless of $contentId. AJAX calls still don't work though.

[adrianbj]

Ok, I am very confused. I have access to my local dev environment, a dedicated self managed server (where I host most of my sites), and two separate shared hosts. The latest dev version works on my local dev environment and the self managed server, but not on the shared hosts. On the shared hosts I have changed PHP versions, session settings and some other stuff with no luck.

Have you tested on a basic shared host?

[adrianbj]

Actually, it might come back to this:

session.save_handler: files vs session.save_handler: user

OR:

Server API: Apache 2.0 Handler vs Server API: CGI/FastCGI

because my dedicated production server matches my dev environment for both of these settings.

I am not very experienced with shared hosting - I have always been lucky to manage my own servers, but these two settings are the same on the problematic shared hosts.

Any thoughts on this?

[JanTvrdik]

It's quite possible that the custom session save handler is not implemented properly.

[dg]

@adrianbj can you try to put session_write_close() before

tracy/src/Tracy/Bar.php

Line 99 in 587cced

}

?

[adrianbj]

Sorry @dg - still no luck with session_write_close()

[dg]

Can you create for me account on this host?

[adrianbj]

Can you create for me account on this host?

Email with access details sent.

[dg]

@adrianbj So I know where the problem is!

Session was closed earlier than bar was rendered. Probably there is session_write_close somewhere in your code.

I tried to re-open session in Bar.php, but it throws PDOException with message 1406 Data too long for column 'data' at row 1' in SessionHandlerDB/SessionHandlerDB.module:109.

It should be fixed now, but you need to discover why is session closed in order to see AJAX requests. And maybe there is really problem with session size.

[adrianbj]

Thanks @dg - I really appreciate you taking a look - your discovery helped me figure out the difference between the servers that work and those that don't. Turns out that on the ones that don't work I was using a module that stores session info in the database, rather than the filesystem. If this is disabled, then it immediately works as expected with AJAX requests.

The data too long error can be fixed by changing the field from text to longtext, but then I end up with:

SQLSTATE[08S01]: Communication link failure: 1153 Got a packet bigger than 'max_allowed_packet' bytes'

Changing my max_allowed_packet setting prevents the error, but AJAX requests are still not working. I guess that is still related to the session being closed.

Hopefully this is something that can be fixed on my end, but I'll let you know if there is anything I think could be changed in Tracy to help, short of doing things the old way (ie before 5c46e98).

[adrianbj]

I just wanted to add one final followup that might be useful for others that come across this problem. I now have Tracy reporting AJAX requests even with the database session handler. The key was actually to call Debugger::shutdownHandler() before my main script finished and closed its session. So far everything seems to be working using this approach.