I have implemented custom event subscription to SamlauthEvents::USER_SYNC as I need to do some custom checks and assignments before letting new user being created via saml login.
So in my callback I check two dates and If the dates are not equal, I want to log an error and then throw an exception and break the login and user creation.
But the log is not written to watchdog when the error is thrown.
Here's the code where the error should be logged and exception thrown
if ($event->isFirstLogin()) {
if ($dateA != $dateB) {
$this->logger->error('Denying SAML login. Date mismatch', []);
throw new \RuntimeException('Could not complete user registration');
}
}
When RuntimeException is thrown - does that somehow cancel the commit to db of the call to logger or what is going on ?
Comments
Comment #2
tbrix commentedComment #3
roderikIt would surprise me. The SamlauthEvents::USER_SYNC event is just dispatched in the middle of a long login procedure, which logs & throws exceptions for all over the place.
So yes, your log should be logged. In fact the message in your RuntimeException should always get logged too.
(The code is horrible to read because Drupal Core + Redirects == horrible side effects that need to be protected against... but... your exception should end up being passed to SamlController::handleExceptionInRenderContext(), which basically always should log the message.)
So in short, I don't know what's going on there.
Comment #4
roderikOh, what I said isn't true. If you set the 'error_throw ' / "Bypass error handling'" config to TRUE, that method doesn't log.
If that setting influences your message being logged, I'd like to know because then I need to do more testing / documenting.
(If your log only gets lost when 'error_throw' == TRUE.... then I suspect some other class having subscribed to the KernelEvents::EXCEPTION event, that is doing something strange.)
Comment #5
tbrix commentedThank you so much @rodrik for that quick response.
If I check "Bypass error handling" the effect is that the RuntimeException is not logged. But no effect on the call to error log, whether its Bypassed or not. When unchecked the exception is logged, but not the logger error.
No matter how, I cant seem to log en error in my callback with $this->logger->error, if I throw an exception afterwards.
Comment #6
roderikOK, the effect on the RuntimeException is as expected, I guess.
But this makes the weirdness more glaring. the RuntimeExcption message is logged, and that'
$this->logger->warning(), which should be completely equivalent to the log call you are doingSo why your earlier message is not logged, is even more mysterious to me.
Comment #7
iamfil commentedI just ran into this issue as well with dblog. I believe the database transaction is rolled back and the message is not saved. Switching to syslog allowed me to see my log messages from my custom code running during SamlauthEvents::USER_SYNC .
Comment #8
roderikOh, you're right! (I've learned something in the 3 years since I answered this issue.)
This classifies as a bug. But it won't be solved soon.
Workaround:
There isn't really one, besides using a non-SQL-based logging method, if you want to both log a message and throw an exception.
In the original reporter's case, I'd actually advise to just throw a
\RuntimeException('Denying SAML login. Date mismatch'). Because that is then going to be logged by this module. And not displayed to the user; the user sees a generic message (unless you explicitly turn on the "show detailed errors to the user" config, but if you want to prevent the user seeing cryptic errors, you should turn that config option off again, instead of just throwing an exception with a generic message).But that is detail. There still is a use case for logging a technical message and passing a generic error to the user (which you'd do through a
UserVisibleException, not a\RuntimeException). And that... does not work, in event subscribers.Reason:
The event is dispatched during User::save(), whose SQL implementation does a database rollback if an exception is thrown. The externalauth module (which is responsible for the user registration+login) does not have a good event to do it before User::save(). And if we dispatch the event after User::save().... the side effect of throwing an exception then would be already having a saved bogus user in your database.
Long term solution:
(Either stop using externalauth, or) refactor the externalauth module. Which I've been planning for years (I've been using two issues in its queue to dump vague plans). But it's not reached the top of my to-do list of volunteer/un-sponsored time.
Short term 'needs work':
This needs docs in the README.
Comment #9
roderikDocs are added. Guess this is a better status.