Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Keep a copy of triggered event names for better debugging #13594

Closed
wants to merge 1 commit into from

Conversation

tsteur
Copy link
Member

@tsteur tsteur commented Oct 11, 2018

Sometimes you are in a method that can be triggered through many different events and you want to know which event triggered the method or which events happened before this as the event might be triggered by another event etc. Not keeping any params re possible memory issues.

Might be even useful to log like the last X occurred events in some places on top of a backtrace or so... (be something maybe for another PR). Refs DEV-1456

Sometimes you are in a method that can be triggered through many different events and you want to know which event triggered the method or which events happened before this as the event might be triggered by another event etc. Not keeping any params re possible memory issues.

Might be even useful to log like the last X occurred events in some places on top of a backtrace or so... (be something maybe for another PR)
@tsteur tsteur added the Needs Review PRs that need a code review label Oct 11, 2018
@tsteur tsteur added this to the 3.7.0 milestone Oct 11, 2018
@diosmosis
Copy link
Member

Is this needed because we don't have access to the event name in a shared event handler? Like in this example:

public function getListHooksRegistered()
{
    return [
        'event1' => 'myEventHandler',
        'event2' => 'myEventHandler',
        'event3' => 'myEventHandler',
        ...
    ];
}

public function myEventHandler()
{
    $logger->info("myEventHandler() triggered by ???");
}

? Or are there other reasons (or maybe this isn't a reason)?

@tsteur
Copy link
Member Author

tsteur commented Oct 15, 2018

yes for example this.

sometimes there might be also APIs that call other APIs that call other APIs and you want to get a trace of how we ended up there to understand what happened. Eg in a API.TagManager.addContainer which may be triggered by a SitesManager.addSite.end which may be triggered by ... etc

@diosmosis
Copy link
Member

For the first case, would it be simpler to just have separate event handlers? For the other use case, would a backtrace work too? Eg debug_backtrace(IGNORE_ARGS_OR_WHATEVER_ITS_CALLED).

Think this could be useful for fatal error emails, but if we save our logs (to eg, cloudwatch or on a server), you could simply look up the logs for the request in either case. Eg, we could log in EventDispatcher and the event handlers (or maybe just in EventDispatcher like invoking event handler for event MyEvent: MyPlugin.myEventHandler). Or maybe I'm missing another use case?

@tsteur
Copy link
Member Author

tsteur commented Oct 15, 2018

Backtrace wouldn't be too helpful as it contains too much info and is not needed in this case. In my case the event handlers give a very good summary of what happened in the system to lead up to this point. Separate handlers is not really possible in this case. Eg think of CustomPiwikJs.trackerChanged (not sure exact name), this event could be triggered in various ways eg when a user creates a heatmap, or when a component is updated, or core is updated, or ...

@diosmosis
Copy link
Member

diosmosis commented Oct 15, 2018

Couldn't you just have a log in EventDispatcher like:

$logger->info("Dispatching event $eventName to handler $pluginName.$methodName");

? You wouldn't need to save and later process the events in memory in this case, you would just need to look at the logs. And you would be able to see what events are triggered (ie CustomPiwikJs.trackerChanged and what event handlers are triggered (Heatmap.handleTrackerChanged or whatever it's called).

EDIT: this just seems like a simpler solution than saving the event names and printing them somewhere else, and would give insight into all requests not just the requests that end up using that specific method.

@tsteur
Copy link
Member Author

tsteur commented Oct 15, 2018

In debug level that might be at some point useful too. For my case it is way too much noise and would log way too much. Also I can't log to file without also logging it to the user which would be a problem as I need it always on.

In my case, when something specific happens, I need to log this info to a specific place, eg to error_log. I'm actually only interested in like the last 5 events. So if memory is a problem, we could always keep max 50 events in there or so? Looking at logs doesn't work for me, as I need this info with the actual log message in a different log file. It happens like once a week or few times a week that it gets logged and then looking through many GB of other regular logs wouldn't work for me to find the matching info.

Eg it allows me to
cat my.log | grep "my error message" | cut -d' ' -f1 | sort | uniq -c | sort -n

and I can see the top reasons why some specific error or event occurred, including the last 3 or 5 events that occurred before that.

like

134343 my error message, events: Foo.Bar, X.Baz, Y.Baz
43434 my error message, events: Bar.Baz, A.Baz, B.Baz
2323 my error message, events: Hello.Bar, X.Baz, B.Baz

@diosmosis
Copy link
Member

For my case it is way too much noise and would log way too much. Also I can't log to file without also logging it to the user which would be a problem as I need it always on.

Could always log as info, default the logger to NullLogger, then supply a special logger through DI that sends it to error_log(). Or something along those lines.

It happens like once a week or few times a week that it gets logged and then looking through many GB of other regular logs wouldn't work for me to find the matching info.

Perhaps it might be a good idea to look into something like cloudwatch/sumologic/etc.

To me memory usage isn't really the issue, and I can see that it could be useful, but you can get the same thing from just logging (if you can get the request ID for the request you are looking for more info for, then grep for those logs then grep for the event log message, you'd get the same info). This just seems like unneeded code.

@diosmosis
Copy link
Member

Could also wrap EventDispatcher through DI so this code isn't in core.

@tsteur
Copy link
Member Author

tsteur commented Oct 15, 2018

I'll just close the PR. Getting bit too complicated. I'll log the messages in my plugin without any extra info.

@tsteur tsteur closed this Oct 15, 2018
@tsteur tsteur deleted the triggeredeventnames branch October 15, 2018 20:56
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Needs Review PRs that need a code review
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants