execute_hook: Improve logging

[clayne]

• Provide per-hook entry and exit logging around each hook called. This came out of a debugging experience where client code was adding the same hook twice at different stages of execution but it wasn't immediately apparent from debugging output to even look in that direction.

Example output:

core @2019-07-25 17:04:06> Entering hook core.app.before_request [CODE(0x55f96d8dbac0)] in (eval 221) l. 1
core @2019-07-25 17:04:06> Exited hook core.app.before_request [CODE(0x55f96d8dbac0)] in (eval 221) l. 1

[tomhukins]

Having information such as CODE(0x55f96d8dbac0) in log files seems unhelpful to me. Why do you consider this change an improvement?

[clayne]

Having information such as CODE(0x55f96d8dbac0) in log files seems unhelpful to me. Why do you consider this change an improvement?

Because that's the only pragmatically "id" we have accessible to us to even determine what code ref is being executed at the time without making more extensive changes to all the hook code to store some kind of surrogate id or Carp style line origination data (which is significantly more work and probably overkill). I do agree the implicit stringification part is a bit of a hack though.

Additionally, this is only logged at the core debugging level, so it's not exactly something that's even going to be present in the normal case. If you have better ideas, I'm all ears, but what I do know is that the current code completely masks logging for multiple hooks registered for the same hook type.

[cromedome]

@tomhukins, @clayne - I see your respective points.

@clayne if you can provide a minimal test case or example wrapped up in a .t file, I can spend a little time noodling on this to see if I can come up with a solution that works for everyone.

Thanks!