TD causing exceptions to be thrown when they shouldn't be

[ryancramerdesign]

@adrianbj I noticed exceptions getting thrown unexpectedly here and eventually tracked it down to a hook added in TracyDebugger.module.php:

// override default PW core behavior that converts exceptions to string
$this->wire()->addHookAfter('Wire::trackException', function($event) {
    $exception = $event->arguments(0);
    if($this->wire('config')->ajax && ($exception instanceof WireException || $exception instanceof \ProcessWire\WireException)) {
        // intentionally blank
    }
    else {
        throw $exception;
    }
});

PW is only supposed to throw the given Exception (arg0) from the trackException() method if the $severe argument (arg1) is true and $config->allowExceptions === true;. I think the hook above shouldn't throw the exception because it would have been already thrown in the trackException() method if it was supposed to be (since this is an after hook).

The issue is that PW calls the trackException() method sometimes for non-fatal errors ($severe===false) and it is hookable so that anything else can log or report the error for additional debugging info. If the $config->allowExceptions is true, then the exception is considered fatal only if the $severe argument is also true... in which case it throws the exception. But if the $severe argument is false, then PW expects to be able to continue its business and fix whatever caused the exception. So when TD comes in and throws an exception when it shouldn't be, it potentially bypasses code that is meant to resolve a non-fatal exception.

[adrianbj]

Hi @ryancramerdesign - thanks for reporting this. Are you suggesting that all I need to is simply check if arg1 one of that hook is severe before throwing the exception? Do you think I need any other changes?

If you're interested in reading why this was introduced, take a look at: https://github.com/adrianbj/TracyDebugger/issues/35 https://github.com/adrianbj/TracyDebugger/issues/36

[ryancramerdesign]

@adrianbj I will come back to read those links later, as I'm out the door to pick up kids. But I'd say if possible don't throw an exception at all since PW will already throw it when it's supposed to. But if you need to for some reason, then I would only throw it if the $severe argument is true. That would at least prevent non-fatal/non-severe errors from getting exceptions.

[adrianbj]

Sounds good @ryancramerdesign - the key thing is that PW converts the exceptions it does throw to a string and that breaks Tracy's bluescreen (red) output. You can read more about this here: https://github.com/processwire/processwire-issues/issues/829

That issue is why I actually added that hook in the first place. The other two issues I posted above were about refining it with the ajax and instanceof WireException conditions.

[ryancramerdesign]

@adrianbj I've looked at the stuff you've linked but am still not sure I understand what you mean about "converts exceptions to string" , or do you mean that it catches them in the index.php and sends them to trigger_error() ? (after sending to trackException). As far as I know trigger_error() requires a string, so it just sends the exception message to it rather than the exception. Though I'm not sure if that's what you mean about converting to a string.

Not sure if this is an alternative but I'll mention it just in case: What if TD skipped over any trackException() calls that didn't come from classes ProcessWire or Config? That would make it focus just on the ones caught in index.php, and skip over the rest that PW handles internally, leaving just the fatal ones that bubble through to index.php for TD to handle?

// this
$wire->addHookAfter('ProcessWire::trackException, Config::trackException', function($e) { 
  ... 
}

// or this
$wire->addHookAfter('Wire::trackException', function($e) {
  if(!in_array($e->object->className(), [ 'ProcessWire', 'Config' ])) return;
  ...
}); 

[adrianbj]

@ryancramerdesign - yes, I think you have it - it converts it to a string and sends it to trigger_error(() - that's the point I make in the initial post here: https://github.com/processwire/processwire-issues/issues/829

What this means is that we lose the ability to see the full stack trace on the bluescreen - we just get what you see in the second screenshot in that same post.

I must admit I wasn't aware that I could hook into just ProcessWire::trackException or Config::trackException because of the way they are defined they don't show up in the docs or Tracy's CaptainHook panel.

I changed the entire thing to just this:

        // override default PW core behavior that converts exceptions to string for passing to trigger_error()
        $this->wire()->addHookAfter('ProcessWire::trackException, Config::trackException', function($event) {
            $exception = $event->arguments(0);
            throw $exception;
        });

I don't think we need the ajax or instance of WireException checks anymore - I added those to allow PW to handle and display errors from things like image uploads, but I think with your new approach of hooking more specifically, this should be taken care already. My initial testing seems to confirm this, so thanks for the insight and nice improvement to this.

[ryancramerdesign]

@adrianbj Great, thanks! The only thing I want to mention is that the ability to hook multiple things in the same string is relatively now to PW (last year or so I think), so I'm not sure if that's consistent with the versions that TD supports or not. The alternative would be just to hook them separately:

$this->wire()->addHookAfter('ProcessWire::trackException', function($event) {
  $exception = $event->arguments(0);
  throw $exception;
});

$this->wire()->addHookAfter('Config::trackException', function($event) {
  $exception = $event->arguments(0);
  throw $exception;
});

[adrianbj]

The only thing I want to mention is that the ability to hook multiple things in the same string is relatively now to PW

Good catch, thanks - I forgot that was pretty new. I am still supporting PW 2.x so will definitely use the separate hook calls.

[adrianbj]

@ryancramerdesign - I wonder if I might be able to get you to take a deeper look into this again please.

Those ProcessWire::trackException and Config::trackException hooks don't actually take care of all the issues.

I was trying to debug something today and it was ending up like this: https://github.com/processwire/processwire-issues/issues/829

The current code (in the released version of Tracy) is:

        // override default PW core behavior that converts exceptions to string for passing to trigger_error()
        // check that argument 1 ($severe) is not set to false before overriding
        $this->wire()->addHookAfter('ProcessWire::trackException', function($event) {
            $exception = $event->arguments(0);
            if(!$exception instanceof WireException && $event->arguments(1) !== false) {
                throw $exception;
            }
        });
        $this->wire()->addHookAfter('Config::trackException', function($event) {
            $exception = $event->arguments(0);
            if(!$exception instanceof WireException && $event->arguments(1) !== false) {
                throw $exception;
            }
        });

What I had to do was the if(!$exception instanceof WireException && $event->arguments(1) !== false) { condition.

Now I know you didn't suggest adding that, but it made it in in response to this issue: https://github.com/adrianbj/TracyDebugger/issues/36 which it solved, but clearly there are other consequences.

In case it helps, the exception that I was getting was a WirePermissionException which is obviously an instance of WireException, but clearly we still want to throw the full exception in this case, rather than the string the PW is returning.

Do you have any insights into how to improve this please?

Thanks!

[adrianbj]

Just pinging you on this again @ryancramerdesign - it would be great to improve things on this front if possible.

[ryancramerdesign]

Those ProcessWire::trackException and Config::trackException hooks don't actually take care of all the issues.

@adrianbj Can you describe the issues you are talking about further? I'd probably need an example I can reproduce locally to understand it better. I did try the example from the thread you linked with a trigger_error() at the top of a template file, but I'm getting the expected Tracy output there... I think because you already solved that issue. As I understand from what you've written, there are similar issues occurring somewhere, but not sure what those are?

[adrianbj]

@ryancramerdesign - I think the simplest way of reproducing is to put these into a template file and load a page with that template.

Compare the result for: throw new \Exception()

vs the much less useful result with this:

throw new WireException()

[ryancramerdesign]

@adrianbj Okay I think I understand. Since you want Tracy to handle the exception, I think that it just needs to re-throw it then, so that Tracy's catch(...) can capture it instead? If I add this hook to my /site/init.php then it provides output like your first exception for the regular \Exception:

$wire->addHookAfter('Wire::trackException', function($event) {
        $user = $event->wire()->user; 
        $config = $event->wire()->config;
        // use whatever conditions necessary to determine Tracy will handle exception
        if(($user && $user->isSuperuser()) || ($config && $config->debug)) {
                throw $event->arguments(0);
        } 
});    

This also works, manipulating the $severe argument to force it to re-throw the Exception:

$wire->addHookBefore('Wire::trackException', function($event) {
        $event->wire()->config->allowExceptions = true;
        $event->arguments(1, true); // severe=true
});  

[adrianbj]

Thanks @ryancramerdesign but the problem is that we can't always throw the exception or force it to severe because it breaks things like size limit checks on image upload ajax calls or page sorting in the page tree - see the second post (https://github.com/adrianbj/TracyDebugger/issues/58#issuecomment-842358944) at the top of this thread for links to more details.

That's why I am currently using the version posted above here: https://github.com/adrianbj/TracyDebugger/issues/58#issuecomment-1058830934 which checks to see if the severe argument is not set to false before re-throwing. but this doesn't work in all situations like the above noted "WirePermissionException" where I still get the string instead of the full exception.

[ryancramerdesign]

@adrianbj I still don't follow 100% but am getting there.

this doesn't work in all situations like the above noted "WirePermissionException" where I still get the string instead of the full exception.

Can you clarify further? It sounds like you are saying that you are getting a string where you expect to get an Exception object? That shouldn't be possible because the function definition only allows an Exception object as the first argument...

public function ___trackException(\Exception $e, $severe = true, $text = null) {

...so I think I misunderstand where you are getting the unexpected string, but it might clarify a lot once I understand.

I'm also wondering why you hook Config::trackException and ProcessWire::trackException rather than Wire::trackException? It sounds familiar, like maybe we talked about it before, but I can't remember and just trying to get refreshed.

Also, it might be helpful if I could see a debug backtrace from the situation you described with WirePermissionException and getting the unexpected string. Either that, or just instructions on how to duplicate that case locally so I could see it.

[adrianbj]

@ryancramerdesign - let me step back a little. The string I am talking about is generated via $e->getTraceAsString() here: https://github.com/processwire/processwire/blob/6ff498f503db118d5b6c190b35bd937b38b80a77/index.php#L63

This is needed by PW for AJAX error messages when uploading images, sorting pages, etc, but when it's not an ajax call, the string version breaks Tracy's ability to nicely populate its bluescreen with expandable information (code, arguments, etc) within each file in the stack trace.

For a while I had an ajax check in there: https://github.com/adrianbj/TracyDebugger/commit/9344be2b6317efa200528791a9fc6c97823251c7 but I removed that at some point (can't seem to find why exactly, but I do recall it wasn't working as hoped).

Eventually I made more changes (https://github.com/adrianbj/TracyDebugger/commit/609296d974c08d7e0d98d35da00726ee99ec6f64) to deal with: https://github.com/adrianbj/TracyDebugger/issues/59

At some point you chimed in above (https://github.com/adrianbj/TracyDebugger/issues/58#issuecomment-842515627) and suggested hooking Config::trackException and ProcessWire::trackException instead of Wire::trackException. That seemed to make most things work as expected until I noticed the issue with WirePermissionException not being handled properly.

I can't manage to get the WirePermissionException to fire at the moment - I think it was likely from https://github.com/processwire/processwire/blob/6ff498f503db118d5b6c190b35bd937b38b80a77/wire/modules/Process/ProcessPageSort.module#L96 but not certain.

I guess the key ask figuring out the best way to modify https://github.com/adrianbj/TracyDebugger/blob/8e010d146333c5a2db869f0e6c2b8e6e42e213ea/TracyDebugger.module.php#L913-L926 so that it forcing throwing full exceptions (rather than the results of the $e->getTraceAsString() override by PW, except in cases where PW relies on that string to post an inline error message, like the image upload size failure, page sorting failure, etc.

Hope that helps.

[ryancramerdesign]

@adrianbj Thanks, that definitely helps. I think it comes down to a couple of catch statements in /wire/core/admin.php. First is the one for WirePermissionException: https://github.com/processwire/processwire/blob/master/wire/core/admin.php#L170

Then is the fallback for any Exception, which is the one I think you are seeing the issue from: https://github.com/processwire/processwire/blob/master/wire/core/admin.php#L184

Most likely this is the the meat of it: https://github.com/processwire/processwire/blob/master/wire/core/admin.php#L198

I also noticed the catch statement for WirePermissionException doesn't call trackException(), whereas the fallback one does. I think this is because PW admin handles the permission errors internally rather than passing along an Exception. For instance, if you aren't logged in, it'll show a login form when a WirePermissionException occurs.

I noticed the issue occurs when attempting to drag-sort pages that aren't manually sortable (because they auto-sort by name or date or something). This is a case where it's throwing a WireException when it should be throwing a WirePermissionException. I'll have to fix that.

I'm not certain this is an issue that can be resolved in TD or if it needs to be resolved in PW, but feel like I'm starting to see where it's happening. I was curious what happened without TD to temporarily uninstalled and noticed that drag-sorting a non-sortable page results in an endless ajax spinner because the non-WirePermissionExceptions never ends up in the ajax message. If I change it to use a WirePermissionException, then it starts working properly. So it does seem like it's potentially a core issue. I'll keep looking at it here.

[ryancramerdesign]

@adrianbj In looking at this further, I found that I was barking up the wrong tree before. It turns out I had this in my site/init.php file on my test install, which was the source of the issue:

$wire->addHookBefore('Wire::trackException', function($event) {
        $event->wire()->config->allowExceptions = true;
        $event->arguments(1, true); // severe=true
});

That must have been a leftover from the conversation above and I just neglected to remove it. Once I removed it, all started working normally with and without TD installed. So the page sorting/moving I described above now works properly, as does a throw new WireException(); in /site/templates/home.php, which now shows the same result as throw new \Exception(); in Tracy.

Is it possible you've also got a bit of code like the above, leftover somewhere in your installation like I did on mine?

[adrianbj]

Hi @ryancramerdesign - the only place I have trackException hooks is in Tracy itself (as I pointed to above). I have tried the comparison between throw new WireException() and throw new \Exception() on multiple PW installs and all have the same issue.

If Tracy isn't installed (or temporarily disabled), both will result in:

It's only when Tracy is installed that the problem shows itself because PW's call to $e->getTraceAsString() breaks Tracy's enhanced view of the stack trace, as demonstrated in the screenshots here: https://github.com/adrianbj/TracyDebugger/issues/58#issuecomment-1666973333

[ryancramerdesign]

@adrianbj I seem to be coming back full circle, but just noticed the$config->allowExceptions seems to be what makes the difference on my install. (Another thing I had set differently than the default on my test install). Try adding this to your /site/config.php file and then throwing a WireException and an \Exception should produce the same result. Do you find that to be the case there as well? This all happens before the index.php getTraceAsString() that you mentioned.

$config->allowExceptions = true; 

If so, and you don't have a convenient place to set it to true, you could always do it with a hook too:

$wire->addHookBefore('Wire::trackException', function($e) {
  $e->wire()->config->allowExceptions = true;
});

[adrianbj]

@ryancramerdesign - that does seem to work nicely. I have replaced my old hooks on ProcessWire::trackException and Config::trackException that just would throw the exception again if it was severe with your suggested hook to override allowExceptions and so far so good. I double checked that image upload size errors were reported inline and those work as expected so it seems that PW still handles that properly even with the change to allowExceptions.

This seems like a much cleaner solution all around, so thank you for your time in figuring this out.

I'll keep testing (by using) for a little while before committing to the Tracy repo, but hopefully this will be the end of this issue.

Thanks again.

[ryancramerdesign]

@adrianbj Great! Thanks, glad that works.

[adrianbj]

@ryancramerdesign - I've committed that change to the latest version. Hopefully all good now.

I'm going to close this, but just a follow up question for you - should unallowed page sort and page move actions result in an exception being logged to the exceptions.txt file? Should these really be exceptions at all? Just seems a bit weird to me.

[ryancramerdesign]

@adrianbj I don't think it is particularly useful for those to be logged, but when the Exceptions log is enabled then it'll log all exceptions, and it doesn't know which ones you'd want logged or not. Throwing an Exception is necessary here as it's a fatal error for the request, and exceptions become a JSON object when in AJAX mode, making it easy for the JS side of things to consume and report errors. I suppose we could always have a WireExceptionNoLog or something.