How to build a (hacky) Hook Recorder

[bernhard]

Ever wondered when certain hooks get executed? Which hooks got fired along the request?

Open /wire/core/WireHooks.php, find the method "runHooks" and paste this at the very top of this method:

		$logfile = wire()->config->paths->root . 'hooks.txt';
		$tooOld = is_file($logfile) && filemtime($logfile) < time() - 5;
		if ($tooOld) unlink($logfile);
        $logData = get_class($object) . "::$method\n";
		file_put_contents($logfile, $logData, FILE_APPEND);

This will write a log of all hookable methods to hooks.txt and it will probably begin like this:

ProcessWire\FileCompiler::compile
ProcessWire\FileCompiler::compile
ProcessWire\FileCompiler::compile
ProcessWire\FileCompiler::compile
ProcessWire\Fields::load
ProcessWire\Fieldgroups::load
ProcessWire\Templates::load
ProcessWire\Fieldgroup::setQuietly
ProcessWire\Fieldgroup::callUnknown
(maaaany more lines)

And it will most likely end with "ProcessWire\ProcessWire::finished" 🙂 

Now you can play around with this logfile and view different pages. For example when opening a page for editing you will have a portion of this in the log (ProcessPageEdit::buildForm...):

ProcessWire\ProcessPageEdit::breadcrumb
ProcessWire\JqueryCore::use
ProcessWire\JqueryUI::use
ProcessWire\ProcessPageEdit::execute
ProcessWire\HutPage::setEditor
ProcessWire\ProcessPageEdit::buildForm
ProcessWire\ProcessPageEdit::buildFormContent
ProcessWire\Field::getInputfield
ProcessWire\Field::getInputfield
ProcessWire\Field::getInputfield
ProcessWire\Field::getInputfield
ProcessWire\Field::getInputfield
ProcessWire\Field::getInputfield
ProcessWire\Field::getInputfield
ProcessWire\Field::changed
ProcessWire\Field::changed
ProcessWire\Field::getInputfield
ProcessWire\Field::changed
ProcessWire\Field::getInputfield
ProcessWire\Field::getInputfield
ProcessWire\Field::getInputfield
ProcessWire\HutPage::viewable
ProcessWire\Pages::find
ProcessWire\PageFinder::find
ProcessWire\PageFinder::getQuery
ProcessWire\HutPage::addable
ProcessWire\ProcessPageEdit::buildFormChildren
ProcessWire\WireInputData::int
ProcessWire\WireInputData::callUnknown
ProcessWire\WireInputData::int
ProcessWire\WireInputData::callUnknown

You can also use grep to find the hooks you are looking for, for example:

cat hooks.txt | grep ProcessWire::

ProcessWire\ProcessWire::init
ProcessWire\ProcessWire::ready
ProcessWire\ProcessWire::finished
ProcessWire\ProcessWire::finished

This has helped me today to find the correct spot to hook into. Maybe it also helps anyone else. Have fun!

PS: Don't forget to remove this once you are done with inspecting, of course!

[Jonathan Lahijani]

38 minutes ago, bernhard said:

Ever wondered when certain hooks get executed?

I've literally thinking about that these past few weeks.  What a timely post!

[Jan Romero]

Neat. FWIW Tracy also shows hooks that were triggered during the request (in the debug panel). If you, like me, usually define your hook methods as closures, it’ll just say “{closure}”, but it does link to the source, so that’s nice! On the other hand it seems to show all hooks that were defined and doesn’t say whether they actually ran.

[bernhard]

Hey @Jan Romero that's true, but it shows it in a totally different way. I wanted to have a list of all methods that I can hook into, in the order of execution! I don't know how tracy sorts the list of added hooks, but it's definitely not execution order.

On the other hand tracy debugger adds nice links to the hooks and shows some more information, like for RockFrontend:

after	RockFrontend::addAlfredStyles()	AdminStyleRock::addAlfredStyles()	class method	100.0

And that line does not show up in my hooks log:

cat hooks.txt | grep RockFrontend

ProcessWire\RockFrontend::addLiveReload
ProcessWire\RockFrontend::render
ProcessWire\RockFrontend::loadLatte
ProcessWire\RockFrontend::addLiveReload
RockFrontend\StylesArray::renderAssets
RockFrontend\ScriptsArray::renderAssets

Oh... that actually makes sense, because I have not had an ALFRED call on that page yet, so obviously the hookable method does not get called! 😄 I added it and boom, there it is:

cat hooks.txt | grep RockFrontend

ProcessWire\RockFrontend::addLiveReload
ProcessWire\RockFrontend::render
ProcessWire\RockFrontend::loadLatte
ProcessWire\RockFrontend::getIcons
ProcessWire\RockFrontend::addLiveReload
ProcessWire\RockFrontend::addAlfredStyles
RockFrontend\StylesArray::renderAssets
RockFrontend\StylesArray::renderAssets
RockFrontend\ScriptsArray::renderAssets
RockFrontend\ScriptsArray::renderAssets

Another one. I saved a page from the backend and the grep for "::save" looks like this:

cat hooks.txt | grep ::save

ProcessWire\Pages::save
ProcessWire\Pages::saveReady
ProcessWire\Pages::savePageOrFieldReady
ProcessWire\Pages::saved
ProcessWire\Pages::savedPageOrField

I think this is really neat!

Maybe @adrian has an idea how we could integrate this into Tracydebugger and maybe get the best of both worlds (tracy current implementation + my hacky one)? I think it would need a modification in the core, but that should not be a big deal for @ryan.

[adrian]

The hooks info that Tracy shows is basically a copy of what is shown in PW's Debug Mode Tools (using getHooks()) and AFAIK it's only hooks that are triggered by AddHookAfter/Before calls. From what I can tell what Bernhard is showing is all hooks that are run as PW is booting up - there are lots of entries missing in that list. Not saying that it's not a useful list, but they are very different things.

Unfortunately it seems that Tracy isn't available at the point that runHooks() is called, so I couldn't replace your log file approach with a bd() call so at the moment it will need Ryan's input to make it possible to display this list in Tracy.