Module Tracy Debugger

[bernhard]

Hi @adrian

today Tracy cost me 1 hour of work ? 

$this->addHookAfter('Session::loginSuccess', function(HookEvent $event) {
  bd('Session::loginSuccess');
});

No matter what hook I tried (Session::login, ProcessLogin::loginSuccess etc) tracy did not dump anything. It seemed that the hook did never fire. I even placed a bd('Session.php') in Session.php... nothing! ?

I tried different Session Handlers (DB, default), tried hooking ::logout (which worked) etc etc.

Then I found:

$this->addHookAfter('Session::loginSuccess', function(HookEvent $event) {
  bd('Session::loginSuccess');
  $this->message('Session::loginSuccess');
});

So the hook fires, but the BD() call get's lost somewhere! The dumps recorder is also empty (not shown in the screenshot)!

Any ideas what could be going on?

 

PS: My new balance

• Tracy time costs: 1h
• Tracy time savings: 500h+ (thx once more!! ? )

[adrian]

Hey @bernhard - I just tested here with all combinations of the following on my local dev setup (MacOS)

1) SessionHandlerDB on and off
2) Your hook in init.php and ready.php and in the Console panel injected at init and ready

In all cases, the bd() shows up in one of the Tracy redirect bars.

Then I tried on one of my linux servers and in all tests, the bd() call was never activated. My thought is that it must be something to do with when Tracy is loaded. Because Tracy is loaded by PW's module system, it isn't loaded until site modules get loaded. Ryan made it so that it is the first of these site modules to be loaded which means we can always reliably use it to test development of other modules, but it doesn't load before the PW core which is why it's sometimes impossible to use it to debug the core. 

All that said, I don't know if load order is the problem in this case, or if it's something else. I'd actually love to know if you see a difference on different servers / PW installs. And anyone else who'd like to test also - it would be good to figure out if there is something consistent with when it does and doesn't work.

[bernhard]

Thx @adrian

the strange thing is. If the load order of the modules was the problem, shouldn't the bd() throw an error that the function does not exist? The hook seems to be fired, because the $this->message() shows up. ?

[adrian]

57 minutes ago, bernhard said:

the strange thing is. If the load order of the modules was the problem, shouldn't the bd() throw an error that the function does not exist? The hook seems to be fired, because the $this->message() shows up. ?

Yeah, that makes sense ?

Ok, so after spending way too much time, it's not specifically a Tracy issue. If you do a Tracy log call, eg:

$this->addHookAfter('Session::loginSuccess', function(HookEvent $event) {
    l('Session::loginSuccess');
});

then it works fine. The issue is that dumps are stored in a variable and added to as needed during the current request. But it seems like PW hasn't actually started its session at Session::loginSuccess. If you try the same bd() call at Session::init then it works as expected.

$this->addHookAfter('Session::init', function(HookEvent $event) {
    bd('Session::init'); // works
});

So, I looked into the possibility of making it possible to do bd() calls and have them carry over to the next PW session (after the login has actually started the session) and there are possibilities, but I think they all come with downsides. I think it might help the Dumps Recorder panel though in that I'll be able to make it keep data over sessions, so I might consider that. I'll mull it over for a bit.

As a reminder (almost just for myself), Session::loginSuccess does work on some setups (eg my local dev environment), so there must be some differences in how sessions are handled that is impacting this.

[adrian]

Just a quick update to you all know that there is a new keyboard shortcut for reloading a snippet from disk, clearing previous output, and running the code which should be a nice time saver and also prevent you from accidentally running old code in the console that hasn't been updated from the disk version when you are using an external editor.

I have also rejigged the execution of code when "Run" is called vs injecting. Hopefully the visual cues of the button changing from "Run" to "Inject" and the status in the header showing "Inject @ Ready" makes it more obvious what is going to happen when.

Another update is that the Dumps Recorder panel now stores its data in a file so that it will survive across sessions which may be useful if you are hooking certain session methods and other scenarios where the normal Dumps panel is not showing your bd() calls.

[adrian]

New toggle arrow to collapse / show the snippets side pane with the state remembered via cookie.

VS

[adrian]

If you work with deeply nested / large JSON data and you use Adminer, the latest update will allow you to speed things up significantly with a few new config options. I've also included a PR to the JSON preview plugin which this functionality relies on - my changes ensure the max text length setting is applied to json that is kept as a string due to the max level setting. 

[bernhard]

Hey @adrian unfortunately I have some very strange issues with the dumps feature ? 

This is the code I have (using Nette Forms):

[...]

    l('renderMail');
    bd('renderMail');

    // submit
    if($form->isSuccess()) {
      l('success!');
      bd('success!');
      $session->redirect('thank-you-page');

[...]

I have several problems:

1) The bd() calls do only show up in the dumps recorder, not in the regular AJAX bar dump.

2) The dumps recorder shows the entries twice whereas the tracy logs show them only once.

The tracy logs should be the correct results, because after the form success I do a session redirect to the thank you page. No idea why things show up twice in the dumps recorder. Of course I have cleared the dumps before submitting the form ? And it's the latest version of tracy from today (4.21.10)

Explanation of the dumps recorder:

1) renderMail is called on the initial page view (correct, logs at 18:10:12)

2) renderMail is called when the form was submitted (correct, logs at 18:10:21)

3) success is fired because the form was successfully submitted (correct)

4) send mail is fired correctly

5) 2, 3 and 4 are dumped again (not correct)

 

Here another dump showing timestamps:

 

Any ideas? ? 

Edit:

I checked by sending an email additionally to the "send mail" dump:

  public function send($message, $contact) {
    bd("send $message to $contact");
    $mail = new WireMail();
    $mail->to('foo@bar.com');
    $mail->from('foo@bar.com');
    $mail->subject("Test @ ".date('d.m.Y H:i:s'));
    $mail->send();
  }

The mail was actually sent twice, so it seems that the tracy dump is correct. So what about the tracy log? Shouldn't that also be listed twice then? No idea why that send() call fires twice at all... there is a session redirect that should prevent this ? 

[adrian]

3 minutes ago, bernhard said:

1) The bd() calls do only show up in the dumps recorder, not in the regular AJAX bar dump.

Is a new AJAX bar showing at all (even without a Dumps panel entry). If it's not, then it's probably an issue with Nette forms not sending the 'X-Requested-With': 'XMLHttpRequest'

8 minutes ago, bernhard said:

after the form success I do a session redirect to the thank you page

Or maybe it's related to that - if it's an AJAX form submission and then you do a redirect afterwards, that a) seems to defeat the reason for an ajax submission, and b) is probably why the AJAX bar is lost. Does it show in the ajax bar if you don't do the redirect?

11 minutes ago, bernhard said:

2) The dumps recorder shows the entries twice whereas the tracy logs show them only once.

Not sure about that - I'll look a little later and after I hear back about those possible reasons for #1

[bernhard]

2 hours ago, adrian said:

Is a new AJAX bar showing at all (even without a Dumps panel entry). If it's not, then it's probably an issue with Nette forms not sending the 'X-Requested-With': 'XMLHttpRequest'

There's only one single bar. But it's not an AJAX request. I'm submitting the form as regular POST and then doing a session->redirect to a new page. But usually tracy also log's redirected requests (like after page save).

Sorry about the ajax confusion! I meant those redirect bars:

[bernhard]

On 5/4/2020 at 6:24 PM, bernhard said:

The mail was actually sent twice, so it seems that the tracy dump is correct. So what about the tracy log? Shouldn't that also be listed twice then? No idea why that send() call fires twice at all... there is a session redirect that should prevent this ? 

I found the reason for this: I'm rendering a repeater with several blocks. There are two subscription blocks with nette forms. A form submit triggers the redirect but the redirect does not happen immediately because it does finish() the active process, hence renders the other blocks as well. That's why I got 2 dumps (one for each block). I added a custom instandRedirect method to my repeater blocks:

public function instantRedirect($url) {
  header("Location: $url");
  exit(0);
}

 

[MoritzLost]

Hi @adrian, I'm getting the following error in the RequestInfo panel with  many of my custom modules, do you know what's causing this?

ProcessWire\WireException: Method TrelloWire::getArray does not exist or is not callable in this context in /var/www/vhosts/klforexpats.preview-server.dev/httpdocs/public/wire/core/Wire.php:529
Stack trace:
#0 /var/www/vhosts/klforexpats.preview-server.dev/httpdocs/public/wire/core/Wire.php(386): ProcessWire\Wire->___callUnknown()
#1 /var/www/vhosts/klforexpats.preview-server.dev/httpdocs/public/wire/core/WireHooks.php(823): ProcessWire\Wire->_callMethod()
#2 /var/www/vhosts/klforexpats.preview-server.dev/httpdocs/public/wire/core/Wire.php(450): ProcessWire\WireHooks->runHooks()
#3 /var/www/vhosts/klforexpats.preview-server.dev/httpdocs/public/wire/core/Wire.php(453): ProcessWire\Wire->__call()
#4 /var/www/vhosts/klforexpats.preview-server.dev/httpdocs/public/site/assets/cache/FileCompiler/site/modules/TracyDebugger/panels/RequestInfoPanel.php(295): ProcessWire\Wire->__call()
#5 /var/www/vhosts/klforexpats.preview-server.dev/httpdocs/public/site/assets/cache/FileCompiler/site/modules/TracyDebugger/tracy-2.7.x/src/Tracy/Bar/Bar.php(150): RequestInfoPanel->getPanel()
#6 /var/www/vhosts/klforexpats.preview-server.dev/httpdocs/public/site/assets/cache/FileCompiler/site/modules/TracyDebugger/tracy-2.7.x/src/Tracy/Bar/Bar.php(122): Tracy\Bar->renderPanels()
#7 /var/www/vhosts/klforexpats.preview-server.dev/httpdocs/public/site/assets/cache/FileCompiler/site/modules/TracyDebugger/tracy-2.7.x/src/Tracy/Bar/Bar.php(98): Tracy\Bar->renderHtml()
#8 /var/www/vhosts/klforexpats.preview-server.dev/httpdocs/public/site/assets/cache/FileCompiler/site/modules/TracyDebugger/tracy-2.7.x/src/Tracy/Debugger/Debugger.php(293): Tracy\Bar->render()
#9 [internal function]: Tracy\Debugger::shutdownHandler()
#10 {main}

This happens in the module configuration (in this case the module is TrelloWire, but I get this with most custom modules). Is this indicative of some problem with my module? Or just some strange interaction between the module config and Tracy?

[adrian]

@MoritzLost - from my initial investigation, it looks like a PW core bug. You are using this (https://processwire.com/blog/posts/new-module-configuration-options/#enter-the-new-moduleconfig-class) approach to defining module settings which I have never used, but it appears that when that approach is used, the getArray() method doesn't exist on the module, hence the error.

Do you know of another module that uses that approach that I could test to confirm?

 

[MoritzLost]

@adrian I have tested my other modules; I think the error only occurs when the module does NOT extend WireData, since the getArray method comes from there.

• TextformatterPageTitleLinks extends Textformatter which extends WireData -> RequestInfoPanel is working.
• ProcessCacheControl extends Process which extends WireData -> RequestInfoPanel is working.
• TrelloWire extends Wire (instead of WireData) -> RequestInfoPanel displays the error.
  • When I change the class definition to extend WireData instead of Wire, the error disappears.

I have tested & confirmed this behaviour with another module I'm working on (currently not publicly available, will probably publish this next week or so). So I think it comes down to modules that don't extend WireData at all, which isn't required (at least according to the docs). I guess it's mostly a cosmetic choice, but for the modules that don't really keep track of data I didn't want to extend WireData. Maybe the RequestInfoPage could check for that case and use getModuleConfig instead?

[rick]

Hi @adrian,

I've been cleanin' up my latest project and noticed this warning:

Cookie “tracyClearDumpsRecorderItems” will be soon rejected because it has the “sameSite” attribute set to “none” or an invalid value, without the “secure” attribute. To know more about the “sameSite“ attribute, read https://developer.mozilla.org/docs/Web/HTTP/Cookies

I don't know if it means anything. If so, great. If not, please ignore this post. ?

[adrian]

Thanks @MoritzLost for figuring that out. I have added a check to prevent that error when a module doesn't extend WireData. Honestly, I think the getting of module settings in PW is a bit of a mess which is why I use 3 different approaches in Tracy because they all return different things for some modules. Let me know if you have any problems with the new version.

Thanks @rick for the heads up on that. I took a quick look, but I don't have time to fix things at the moment - I set a lot of cookies in various places in Tracy and I am not using a standard method so it's not easy to change them all and I sometimes set in JS and sometimes in PHP. Obviously I don't want to make them "secure" because I am sure many of us are running local dev setups without https, so I probably need to just set the sameSite rule to Lax, but maybe Strict is better? Not sure yet, but it's on my list to take care of soon.

[MoritzLost]

32 minutes ago, adrian said:

Thanks @MoritzLost for figuring that out. I have added a check to prevent that error when a module doesn't extend WireData. Honestly, I think the getting of module settings in PW is a bit of a mess which is why I use 3 different approaches in Tracy because they all return different things for some modules. Let me know if you have any problems with the new version.

Thanks for the fix @adrian, I just tested it and it seems to be working! I'm not getting errors any more with both modules I tested before ? 

34 minutes ago, adrian said:

Thanks @rick for the heads up on that. I took a quick look, but I don't have time to fix things at the moment - I set a lot of cookies in various places in Tracy and I am not using a standard method so it's not easy to change them all and I sometimes set in JS and sometimes in PHP. Obviously I don't want to make them "secure" because I am sure many of us are running local dev setups without https, so I probably need to just set the sameSite rule to Lax, but maybe Strict is better? Not sure yet, but it's on my list to take care of soon.

Just butting in here: I don't believe you want to use Strict, this may break the debugger for if you visit the site by clicking on a link from somewhere else. Since you can't really use Secure cookies because of the local dev environments like you said, you'll probably be best of with SameSite=Lax to most cookies. This article on web.dev is a good resource for the SameSite changes.

[adrian]

1 minute ago, MoritzLost said:

Just butting in here: I don't believe you want to use Strict, this may break the debugger for if you visit the site by clicking on a link from somewhere else. Since you can't really use Secure cookies because of the local dev environments like you said, you'll probably be best of with SameSite=Lax to most cookies. This article on web.dev is a good resource for the SameSite changes.

Much appreciated - I'll admit to not knowing too much about these options yet, so great to get some more knowledgeable input. Thanks!

[bernhard]

Hey @adrian,

would it somehow be possible to get the tracy console in a separate process module? I'm working on my RockFinder and there I have built a "RockFinderTester" process module that does basically the same thing like the tracy console, only a lot worse ? I have many modules where a console feature would be great for testing. At the moment I'm using the console for lots of things, but I wonder how complicated it would be to move the console to a separate page that we can modify to our needs.

So for example for testing a RockFinder it might be great to have the code input on the top and below that it would be great to have an area where I can not only dump variables but also show the result as paginated table (using tabulator.js). The tabulator part could totally be done by me - I'd only need to have the proper JS events I can listen for.

I know we have the console snippets at the moment, but I think the console is such a powerful tool, that it would be great if it could be used by other modules as well.

Do you understand my idea? Would that be very complicated to achieve? Thanks in advance for thinking about it ? 

[adrian]

16 minutes ago, bernhard said:

I wonder how complicated it would be to move the console to a separate page that we can modify to our needs

I have thought about making it a separate Process module so it can be opened on it's own page in the PW admin, but I am not sure about making it modifiable - what would you need to modify for you needs? Based on your tabulator example, it sounds like you are talking about extending the output options? But how best to do that? Is it just a matter of being able to inject (in the background) some additional JS to process the code and format as a table?

I am happy to talk about this more, but I haven't enough time at the moment to do anything substantial on this unfortunately. If you could think through how it should work in some more detail, that might make make it easier for me to implement. Of course PRs are also welcome, but I am happy to help implement if you figure out a plan for how it should work.

 

[bernhard]

Thx adrian,

this is what I have currently in my RockFinder2 module:

This is basically a sandbox where one can test finders, sees a dump and also sees the data listed as tabulator. When looking at the code of RockFinder2 today I was quite surprised that it has +1200 lines of code. I had in my mind that it is quite lightweight compared to RockFinder1 because it builds upon the pw core query classes. Then I realized that I actually have lots of stuff packed into RockFinder2 that imho does not belong there. The finder tester is one of those things! I want to remove that part from the module so that RockFinder3 will just do one thing: Finding PW data and returning it as array of objects.

Nevertheless the finder tester is useful! So I don't really want to drop it as a whole. I can use the tracy console and do this:

This is already great, but it would be even greater if I could see the data in a tabulator. That's what I have in my process module, BUT: What I do not have there is the dumping features of the tracy console. Look at the first screenshot: There is a dump, but I always dump the returned finder object. I cant to any other dumps, because it's a custom implementation of the console. I also don't have the same settings and shortcuts as in the console.

Vision: Ideally I'd like to build RockFinder3 with only the features that it needs and pack the tester in a separate module. This module would require tracy (but only the process module, not the finder module) and could use the tracy console process. This process would show an InputfieldForm that everybody could modify easily via hooks. So I could just add a new InputfieldMarkup to that form below the tracy console, add some lines of javascript that intercept the AJAX events sent by the console and then show the result as tabulator grid.

Hm. I see that the ajax response at the moment does only send the html of the dumps. Maybe it could instead send the response as JSON? One property being the dump: "<foo>bar</foo>" and the other property being the returned value:

In this case the code would return a RockFinder2 instance, so we would need something on the backend that transforms the returned data (here the rockfinder) in something readable by the client. Maybe something like this:

// pseudo code
$wire->addHookAfter("Console::getPayload", function($event) {
  $rockfinder = $event->arguments(0);
  $array = $rockfinder->toPlainArrayReadyForJavaScript(); // ['foo', 'bar']
  $event->return = $array;
});

This would result in this ajax response:

{
	dump: "<foo>bar</foo>",
	return: ['foo', 'bar']
}

So the console could just dump the markup and I could intercept that response with JS:

$(document).on('tracyConsoleResponse', function() {
  // get the return value of the xhr
  // render tabulator
});

Maybe that kind of refactoring could also make sense for the console? Maybe this approach could also make sense in an even bigger context: What if all panels where process modules? I for example have no idea how to build a panel for tracy (I'd have to study my hello world module again ? ), but it would be piece of cake to build a process module. Maybe I'm requesting too much here. But again: Maybe refactoring could make sense - I leave that assessment to you ? 

---

Side note: Also I have this bug when I open the console on my process module: The code of my ACE field gets quirky.

That's not a request how to fix it - just to let you know why it would be great to have one central solution that can be modified instead of building our own solution and fix bugs ? 

 

[adrian]

Hey @bernhard - thanks for all the details. I'll have to get back to you on most of them, but I can explain the reason for the quirky stuff in your module. It is due to the really old version of ACE included with the InputfieldAceExtended module that you are making use of. The same thing happens with Ryan's HannaCode module - there is an issue posted about that here: https://github.com/ryancramerdesign/ProcessHannaCode/issues/21

[bernhard]

Just had another idea that might be even more powerful and simpler to implement: What if we could define custom dumping functions? For example:

$rf = new RockFinder2();
[...]
tabulator($rf);

// modify tabulator and dump another one
tabulator($rf);

instead of a regular dump() this would render the markup of a tabulator, eg:

<div id="1905terf8dvuid"></div>
<script>
var table = new Tabulator("#1905terf8dvuid", {
 	height:205,
 	data:[
 	{id:1, name:"Oli Bob", age:"12", col:"red", dob:""},
 	{id:2, name:"Mary May", age:"1", col:"blue", dob:"14/05/1982"},
 	{id:3, name:"Christine Lobowski", age:"42", col:"green", dob:"22/05/1982"},
 	{id:4, name:"Brendon Philips", age:"125", col:"orange", dob:"01/08/1980"},
 	{id:5, name:"Margret Marmajuke", age:"16", col:"yellow", dob:"31/01/1999"},
 	],
 	layout:"fitColumns", //fit columns to width of table (optional)
 	columns:[ //Define Table Columns
	 	{title:"Name", field:"name", width:150},
	 	{title:"Age", field:"age", hozAlign:"left", formatter:"progress"},
	 	{title:"Favourite Color", field:"col"},
	 	{title:"Date Of Birth", field:"dob", sorter:"date", hozAlign:"center"},
 	],
 	rowClick:function(e, row){ //trigger an alert message when the row is clicked
 		alert("Row " + row.getData().id + " Clicked!!!!");
 	},
});
</script>

So basically we'd only need a way to define custom functions like "tabulator()" that define the returned markup and that's it ? 

[adrian]

@bernhard - I like you're thinking here. Surely it would be a simply matter of extending Tracy's TD class (https://github.com/adrianbj/TracyDebugger/blob/master/includes/TD.php) with the required new dumping methods.

[adrian]

@bernhard

Just a little rough experimentation - I've added a new echo() method to the TD class which outputs exactly what is sent to it.

With this addition, I managed to do this:

Obviously in this case I am not passing any data to the tabulator() method, but you can make this happen easily by modifying your new tabulator() function.

In a process module I have a couple of things to make this all work:

1) Load the tabulator js and css files in the init() method:

        $this->wire('config')->scripts->add("https://unpkg.com/tabulator-tables@4.6.3/dist/js/tabulator.min.js");
        $this->wire('config')->styles->add("https://unpkg.com/tabulator-tables@4.6.3/dist/css/tabulator.min.css");

2) Define a new tabulator function - note that in this case this is a global function outside the process module class, but you could also make it a class function and call $rf->tabulator()

function tabulator($str, $title = NULL) {
    \TD::echo('<div id="tabletest"></div>
    <script>
    var table = new Tabulator("#tabletest", {
         height:205,
         data:[
         {id:1, name:"Oli Bob", age:"12", col:"red", dob:""},
         {id:2, name:"Mary May", age:"1", col:"blue", dob:"14/05/1982"},
         {id:3, name:"Christine Lobowski", age:"42", col:"green", dob:"22/05/1982"},
         {id:4, name:"Brendon Philips", age:"125", col:"orange", dob:"01/08/1980"},
         {id:5, name:"Margret Marmajuke", age:"16", col:"yellow", dob:"31/01/1999"},
         ],
         layout:"fitColumns", //fit columns to width of table (optional)
         columns:[ //Define Table Columns
             {title:"Name", field:"name", width:150},
             {title:"Age", field:"age", hozAlign:"left", formatter:"progress"},
             {title:"Favourite Color", field:"col"},
             {title:"Date Of Birth", field:"dob", sorter:"date", hozAlign:"center"},
         ],
         rowClick:function(e, row){ //trigger an alert message when the row is clicked
             alert("Row " + row.getData().id + " Clicked!!!!");
         },
    });
    </script>', $title);
}

You can try it out by replacing the attached TD.php for your Tracy install (in the includes subfolder).

Note that you can supply two arguments to the \TD::echo method: $str and $title, just like with d() and bd()

Does that work for you ok?

TD.php