Irrelevant failed authentication request logged in php_error.log + becoming GDPR-relevant

[GiantCrocodile]

Description

php_error.log is spammed with irrelevant messages, e. g. wrong password authentications. Furthermore it even contains sensitive information, e. g. the email address used for authentication thus this becomes GDPR-relevant.

Expected behavior
In general I think that Kirby 3 throws too many exceptions at some points and with wrong status code. The input should be validated first and then an exception thrown in case required fields are missing or there are obvious logic fails in the input. For this case it doesn't work and in most cases I ignored this but now I just noticed that even a regular invalid authentication due to wrong password typed in is being logged to the PHP logs. This is filling them quite fast with non-helpful messages and thus makes debugging harder. I think there is no benefit in this specific log to know that a single log-in failed.

To reproduce

Have a local WAMP setup and try to log-in to the panel with invalid credentials. Debug config option is enabled.

Your setup

v3.9.1-rc1

Your system (please complete the following information)
Firefox, WAMP setup

Additional context
This is the log entry in php_error.log:

[26-Jan-2023 19:38:45 UTC] Kirby\Exception\InvalidArgumentException: Falsches Passwort in […]\kirby\kirby\src\Cms\User.php:872
Stack trace:
#0 […]\kirby\kirby\src\Cms\Auth.php(534): Kirby\Cms\User->validatePassword(Object(SensitiveParameterValue))
#1 […]\kirby\kirby\src\Cms\Auth.php(402): Kirby\Cms\Auth->validatePassword('<removed>@...', Object(SensitiveParameterValue))
#2 […]\kirby\kirby\config\api\routes\auth.php(70): Kirby\Cms\Auth->login('<removed>@...', Object(SensitiveParameterValue), false)
#3 [internal function]: Kirby\Cms\Api->{closure}()
#4 […]\kirby\kirby\src\Api\Api.php(179): Closure->call(Object(Kirby\Cms\Api))
#5 […]\kirby\kirby\src\Cms\Api.php(46): Kirby\Api\Api->call('auth/login', 'POST', Array)
#6 […]\kirby\kirby\src\Api\Api.php(503): Kirby\Cms\Api->call('auth/login', 'POST', Array)
#7 […]\kirby\kirby\config\routes.php(42): Kirby\Api\Api->render('auth/login', 'POST', Array)
#8 [internal function]: Kirby\Http\Route->{closure}('auth/login')
#9 […]\kirby\kirby\src\Http\Router.php(120): Closure->call(Object(Kirby\Http\Route), 'auth/login')
#10 […]\kirby\kirby\src\Cms\App.php(341): Kirby\Http\Router->call('api/auth/login', 'POST')
#11 […]\kirby\kirby\src\Cms\App.php(1243): Kirby\Cms\App->call('api/auth/login', 'POST')
#12 […]\kirby\index.php(5): Kirby\Cms\App->render()
#13 {main}

[afbora]

We added the SensitiveParameter attribute that came with PHP 8.2 to the passwords, but I leave the comments to the other team members about applying it to the email parameters as well.

As workaround you can use zend.exception_ignore_args ini setting to exclude arguments (for all, not just sensitive ones) from stack traces:

ini_set('zend.exception_ignore_args', 1)

[GiantCrocodile]

Hi @afbora! Thank you for the information. I wasn't aware of this and I hope my previous comment doesn't sound too rude (it's more linked to missing language skills on my side...)! I will check that out. Thank you.

[lukasbestle]

None of us are lawyers, so we can only give you our personal opinion. If you need a definite answer, please seek legal advice.

But my personal opinion is that error logs are covered as "legitimate interest", especially if the logs are used to ensure security of the site.

There are tools like fail2ban and sshguard that read error logs to detect and block malicious actors. Kirby uses a similar method internally, so it's not needed to use these tools on top of Kirby. However they can still be useful if you want to null-route or block packets at a lower network level. This is primarily the reason why we don't filter error output by default. Every exception that occurs could be useful for one use case or another and we can't know that ahead of time.

What we could do in the future is to allow the system.exception hook to drop specific exceptions, e.g. by returning false. Then you could configure such a hook and use custom logic to decide whether a specific exception should be logged.

[GiantCrocodile]

Thanks for your reply @lukasbestle. I see the reason when logs are helpful and I agree that logs in general are not irrelevant or become a GDPR-issue in general. Just in this case it lacks relevant information to be used:

• Who does send the request? There's no IP address or hostname logged.
• For which user is this log-on request sent? The detail is cut-off: Too less is logged to protect the user automatically, e. g. by stopping log-ins for user xyz. On the other hand it's enough information to identify a person in case there's just a few users or the email address is quite unique.
• This information is only logged in debug mode I think. In productive systems this can't be used for logging/monitoring purposes.

Do I miss something here?

[lukasbestle]

Who does send the request? There's no IP address or hostname logged.

The stacktrace itself when printed to the error log is indeed not useful for the use case I mentioned, but with the system.exception it becomes possible to log the needed data to a separate file in whichever format is required.

For which user is this log-on request sent? The detail is cut-off: Too less is logged to protect the user automatically, e. g. by stopping log-ins for user xyz. On the other hand it's enough information to identify a person in case there's just a few users or the email address is quite unique.

The email address is always unique, there cannot be two users with the same email address in a Kirby installation.

This information is only logged in debug mode I think. In productive systems this can't be used for logging/monitoring purposes.

No, exceptions are always logged. They are just not displayed to the user in their original form when the debug mode is not active.

[GiantCrocodile]

The email address is always unique, there cannot be two users with the same email address in a Kirby installation.

That's a tiny misunderstand here: I wanted to say that email addresses like firstname.lastname@whatever could be easily related/identify real persons even when the last part of the email address might become cut off. I didn't mean 2 accounts with same email address.

[distantnative]

Picking this thread up: @lukasbestle and @bastianallgeier, in general I think over time we might want to catch more exceptions in the right places. Failed login attempts, search requests with 0 results and similar shouldn't end up in the PHP log, I'd think.

[lukasbestle]

Hm, I'd say it depends. In those two examples, it could make sense to log such errors for automated processing. E.g. with the failed login for tools like fail2ban, with search errors for content analysis (optimizing the content for what users search) etc. We cannot know that deep in the system.

[distantnative]

I can see that argument too. We need a decision here: either work on something or close the issue.

[lukasbestle]

An idea for a possible solution:

• Allow the system.exception hook to return false, which will drop the exception from being logged
• Over time refactor our code to pass more metadata to each exception, e.g. a unique exception key that identifies the specific issue (and also allows to translate all error messages while we are at it). The hook could then decide by the key whether an exception should be logged.
• If needed, we could also add a new boolean $log prop to the exception class. If disabled, Kirby would then only pass the exception to the hook but never log it.

[bastianallgeier]

@lukasbestle sounds good to me