davis icon indicating copy to clipboard operation
davis copied to clipboard

Published 20 hours ago • verified publisher icon tchapi

Error in prod.log after upgrading from version 1.8

Open ghtm2 opened this issue 2 years ago • 5 comments

Hi,

I've been running version 1.8.0 since release up until now, after upgrading to version 2.0.2 I get the following error in the prod.log:

[2022-07-25T17:00:26.224623+02:00] request.INFO: Matched route "dav". {"route":"dav","route_parameters":{"_route":"dav","_controller":"App\\Controller\\DAVController::dav","path":""},"request_uri":"https://<domain>/dav/","method":"PROPFIND"} []
[2022-07-25T17:00:26.224908+02:00] php.INFO: User Deprecated: Since symfony/security-guard 5.3: The "Symfony\Component\Security\Guard\Authenticator\GuardBridgeAuthenticator" class is deprecated, use the new authenticator system instead. {"exception":"[object] (ErrorException(code: 0): User Deprecated: Since symfony/security-guard 5.3: The \"Symfony\\Component\\Security\\Guard\\Authenticator\\GuardBridgeAuthenticator\" class is deprecated, use the new authenticator system instead. at /var/www/html/<domain>/vendor/symfony/security-guard/Authenticator/GuardBridgeAuthenticator.php:35)"} []
[2022-07-25T17:00:26.225496+02:00] security.DEBUG: Checking for authenticator support. {"firewall_name":"main","authenticators":1} []
[2022-07-25T17:00:26.225504+02:00] security.DEBUG: Checking support on authenticator. {"firewall_name":"main","authenticator":"Symfony\\Component\\Security\\Guard\\Authenticator\\GuardBridgeAuthenticator"} []
[2022-07-25T17:00:26.225511+02:00] security.DEBUG: Authenticator does not support the request. {"firewall_name":"main","authenticator":"Symfony\\Component\\Security\\Guard\\Authenticator\\GuardBridgeAuthenticator"} []
[2022-07-25T17:00:26.229582+02:00] app.ERROR: [401]: Sabre\DAV\Exception\NotAuthenticated - No 'Authorization: Basic' header found. Either the client didn't send one, or the server is misconfigured. Login was needed for privilege: {DAV:}read on  [{"file":"/var/www/html/<domain>/vendor/sabre/dav/lib/DAVACL/Plugin.php","line":936,"function":"checkPrivileges","class":"Sabre\\DAVACL\\Plugin","type":"->"},{"file":"/var/www/html/<domain>/vendor/sabre/event/lib/WildcardEmitterTrait.php","line":89,"function":"propFind","class":"Sabre\\DAVACL\\Plugin","type":"->"},{"file":"/var/www/html/<domain>/vendor/sabre/dav/lib/DAV/Server.php","line":1052,"function":"emit","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/<domain>/vendor/sabre/dav/lib/DAV/Server.php","line":984,"function":"getPropertiesByNode","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/<domain>/vendor/sabre/dav/lib/DAV/Server.php","line":1662,"function":"getPropertiesIteratorForPath","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/<domain>/vendor/sabre/dav/lib/DAV/Server.php","line":1647,"function":"writeMultiStatus","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/<domain>/vendor/sabre/dav/lib/DAV/CorePlugin.php","line":346,"function":"generateMultiStatus","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/<domain>/vendor/sabre/event/lib/WildcardEmitterTrait.php","line":89,"function":"httpPropFind","class":"Sabre\\DAV\\CorePlugin","type":"->"},{"file":"/var/www/html/<domain>/vendor/sabre/dav/lib/DAV/Server.php","line":472,"function":"emit","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/<domain>/vendor/sabre/dav/lib/DAV/Server.php","line":253,"function":"invokeMethod","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/<domain>/src/Controller/DAVController.php","line":294,"function":"start","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/html/<domain>/vendor/symfony/http-kernel/HttpKernel.php","line":152,"function":"dav","class":"App\\Controller\\DAVController","type":"->"},{"file":"/var/www/html/<domain>/vendor/symfony/http-kernel/HttpKernel.php","line":74,"function":"handleRaw","class":"Symfony\\Component\\HttpKernel\\HttpKernel","type":"->"},{"file":"/var/www/html/<domain>/vendor/symfony/http-kernel/Kernel.php","line":202,"function":"handle","class":"Symfony\\Component\\HttpKernel\\HttpKernel","type":"->"},{"file":"/var/www/html/<domain>/public/index.php","line":28,"function":"handle","class":"Symfony\\Component\\HttpKernel\\Kernel","type":"->"}] []

I haven't touched the nginx (1.20), php (8.0.13) or Thunderbird (102.0.3) configs, everything is the exact same. I've gone back to version 1.8 for now and no such error is produced.

Any idea what/where the problem may be?

Thanks.

ghtm2 avatar Jul 25 '22 15:07 ghtm2

Hello !

The error seems to be client-side (401): app.ERROR: [401]: Sabre\DAV\Exception\NotAuthenticated - No 'Authorization: Basic' header found.

What authentication mechanism are you using ? Digest was removed in 1.8.0 so this shouldn't be a problem but still ..

tchapi avatar Jul 25 '22 16:07 tchapi

I'm using the default AUTH_METHOD=Basic

While that is what the message seems to suggest, why would the new davis version complain about it when 1.8 doesn't? I can't seem to find any commits in neither davis nor sabre/dav that modify Basic Auth in a major way.

The only thing that I found, which may be related, was this sabre/dav issue from 2019.

ghtm2 avatar Jul 25 '22 19:07 ghtm2

I can't seem to find any commits in neither davis nor sabre/dav that modify Basic Auth in a major way.

There are none, this feature wasn't touched... I can't reproduce your error at the moment. Apart from the log, is it working properly ?

tchapi avatar Aug 01 '22 07:08 tchapi

Apart from flooding the log with those 6 lines on every authentication request it does appear to work.

I've since upgraded to 1.10.2 which doesn't exhibit this behavior. Maybe it's due to this commit?

ghtm2 avatar Aug 01 '22 15:08 ghtm2

It may but it shouldn't since this commit is specifically to extract logs from environments where we can't introspect them (Docker, etc).

I'll dig deeper later if I find the time

tchapi avatar Aug 02 '22 14:08 tchapi

Hi there 👋🏼

I've finally got to the bottom of this. It's indeed linked to the fact that logs are now correctly surfaced since https://github.com/tchapi/davis/commit/b9d2b95f6e813bcb8fe39d76dcf46372be31cb12.

The log in itself is legit: it appears for instance when you access /dav in a browser without specifying the correct credentials first; you get a 401, and it's logged, until the next request where hopefully you have provided the correct credentials (and then it doesn't appear anymore).

While I'm not going to remove it since:

  1. Accessing /dav in a browser is not the usual usage
  2. It's a good log to have in case you get DDoSed

... I have nevertheless made it less verbose in https://github.com/tchapi/davis/commit/642bce7a07d6be3e6e500ad7c275bf48afd5881e (removing the trace), since we probably don't need it.

tchapi avatar Dec 11 '22 17:12 tchapi

Hello again.

Thanks for taking a look.

This is what prod.log is swamped with on current master and Thunderbird 102.6.0:

[2022-12-14T19:30:10.561374+01:00] request.INFO: Matched route "dav". {"route":"dav","route_parameters":{"_route":"dav","_controller":"App\\Controller\\DAVController::dav","path":"principals/test/"},"request_uri":"https://<domain>/dav/principals/test/","method":"PROPFIND"} []
[2022-12-14T19:30:10.561650+01:00] php.INFO: User Deprecated: Since symfony/security-guard 5.3: The "Symfony\Component\Security\Guard\Authenticator\GuardBridgeAuthenticator" class is deprecated, use the new authenticator system instead. {"exception":"[object] (ErrorException(code: 0): User Deprecated: Since symfony/security-guard 5.3: The \"Symfony\\Component\\Security\\Guard\\Authenticator\\GuardBridgeAuthenticator\" class is deprecated, use the new authenticator system instead. at /srv/http/davis/vendor/symfony/security-guard/Authenticator/GuardBridgeAuthenticator.php:35)"} []
[2022-12-14T19:30:10.562423+01:00] security.DEBUG: Checking for authenticator support. {"firewall_name":"main","authenticators":1} []
[2022-12-14T19:30:10.562429+01:00] security.DEBUG: Checking support on authenticator. {"firewall_name":"main","authenticator":"Symfony\\Component\\Security\\Guard\\Authenticator\\GuardBridgeAuthenticator"} []
[2022-12-14T19:30:10.562434+01:00] security.DEBUG: Authenticator does not support the request. {"firewall_name":"main","authenticator":"Symfony\\Component\\Security\\Guard\\Authenticator\\GuardBridgeAuthenticator"} []
[2022-12-14T19:30:10.566800+01:00] app.ERROR: [401]: Sabre\DAV\Exception\NotAuthenticated - No 'Authorization: Basic' header found. Login was needed [] []

So the error string is shorter now, but the log is still too verbose for my liking.

Is there any way to get rid of the GuardBridgeAuthenticator messages?

Alternatively, can I turn off the INFO and DEBUG messages somewhere? Just so it won't log several megabytes of quite irrelevant data every few minutes...

ghtm2 avatar Dec 14 '22 19:12 ghtm2

This is what prod.log is swamped with on current master and Thunderbird 102.6.0:

The thing is, why is Thunderbird sending a request without credentials? It shouldn't (since I guess that you indicated the correct credentials in its configuration)

tchapi avatar Dec 14 '22 19:12 tchapi

The thing is, why is Thunderbird sending a request without credentials?

Right, if the Thunderbird error console were to be believed it doesn't. There is not a single 401 logged in there.

But I've since turned on the access.log in nginx:

<IP> - - [15/Dec/2022:10:24:57 +0100] "PROPFIND /dav/calendars/test/appointments/ HTTP/2.0" 401 428 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - - [15/Dec/2022:10:24:57 +0100] "PROPFIND /dav/calendars/test/general/ HTTP/2.0" 401 423 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - - [15/Dec/2022:10:24:57 +0100] "PROPFIND /dav/calendars/test/vacations/ HTTP/2.0" 401 425 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - test [15/Dec/2022:10:24:57 +0100] "PROPFIND /dav/calendars/test/appointments/ HTTP/2.0" 207 2118 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - test [15/Dec/2022:10:24:57 +0100] "PROPFIND /dav/calendars/test/vacations/ HTTP/2.0" 207 2114 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - test [15/Dec/2022:10:24:57 +0100] "PROPFIND /dav/calendars/test/general/ HTTP/2.0" 207 2113 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - - [15/Dec/2022:10:24:57 +0100] "OPTIONS /dav/calendars/test/ HTTP/2.0" 401 415 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - - [15/Dec/2022:10:24:57 +0100] "OPTIONS /dav/calendars/test/ HTTP/2.0" 401 415 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - - [15/Dec/2022:10:24:57 +0100] "OPTIONS /dav/calendars/test/ HTTP/2.0" 401 415 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - test [15/Dec/2022:10:24:57 +0100] "OPTIONS /dav/calendars/test/ HTTP/2.0" 200 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - test [15/Dec/2022:10:24:57 +0100] "OPTIONS /dav/calendars/test/ HTTP/2.0" 200 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - test [15/Dec/2022:10:24:57 +0100] "OPTIONS /dav/calendars/test/ HTTP/2.0" 200 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - - [15/Dec/2022:10:24:57 +0100] "PROPFIND /dav/principals/test/ HTTP/2.0" 401 416 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - - [15/Dec/2022:10:24:57 +0100] "PROPFIND /dav/principals/test/ HTTP/2.0" 401 416 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - - [15/Dec/2022:10:24:57 +0100] "PROPFIND /dav/principals/test/ HTTP/2.0" 401 416 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - test [15/Dec/2022:10:24:57 +0100] "PROPFIND /dav/principals/test/ HTTP/2.0" 207 784 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - test [15/Dec/2022:10:24:57 +0100] "PROPFIND /dav/principals/test/ HTTP/2.0" 207 784 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - test [15/Dec/2022:10:24:57 +0100] "PROPFIND /dav/principals/test/ HTTP/2.0" 207 784 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - test [15/Dec/2022:10:24:57 +0100] "REPORT /dav/calendars/test/appointments/ HTTP/2.0" 207 289 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - test [15/Dec/2022:10:24:57 +0100] "REPORT /dav/calendars/test/vacations/ HTTP/2.0" 207 288 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"
<IP> - test [15/Dec/2022:10:24:57 +0100] "REPORT /dav/calendars/test/general/ HTTP/2.0" 207 289 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:102.0) Gecko/20100101 Thunderbird/102.6.0"

If I'm understanding this correctly for whatever reason some commands are first sent without credentials then retried with credentials right after. I've got no idea why it does this and I'm quite confused as to why the error console in Thunderbird doesn't show a single 401. It's basically the same error console as in Firefox which shows 401s all over the place...

Oh well, that is one client, but there are unfortunately more:

<IP> - - [15/Dec/2022:10:18:05 +0100] "OPTIONS /dav/principals/test/ HTTP/2.0" 401 416 "-" "iOS/16.1.2 (20B110) dataaccessd/1.0"
<IP> - test [15/Dec/2022:10:18:05 +0100] "OPTIONS /dav/principals/test/ HTTP/2.0" 200 0 "-" "iOS/16.1.2 (20B110) dataaccessd/1.0"
<IP> - - [15/Dec/2022:10:18:05 +0100] "REPORT /dav/principals/test/ HTTP/2.0" 401 416 "-" "iOS/16.1.2 (20B110) dataaccessd/1.0"
<IP> - test [15/Dec/2022:10:18:06 +0100] "REPORT /dav/principals/test/ HTTP/2.0" 207 464 "-" "iOS/16.1.2 (20B110) dataaccessd/1.0"
<IP> - - [15/Dec/2022:10:18:06 +0100] "PROPFIND /dav/calendars/test/ HTTP/2.0" 401 415 "-" "iOS/16.1.2 (20B110) dataaccessd/1.0"
<IP> - test [15/Dec/2022:10:18:06 +0100] "PROPFIND /dav/calendars/test/ HTTP/2.0" 207 10990 "-" "iOS/16.1.2 (20B110) dataaccessd/1.0"
<IP> - - [15/Dec/2022:10:18:06 +0100] "PROPFIND /dav/calendars/test/inbox/ HTTP/2.0" 401 421 "-" "iOS/16.1.2 (20B110) dataaccessd/1.0"
<IP> - test [15/Dec/2022:10:18:06 +0100] "PROPFIND /dav/calendars/test/inbox/ HTTP/2.0" 207 376 "-" "iOS/16.1.2 (20B110) dataaccessd/1.0"
<IP> - - [15/Dec/2022:10:18:07 +0100] "PROPFIND /dav/calendars/test/inbox/ HTTP/2.0" 401 421 "-" "iOS/16.1.2 (20B110) dataaccessd/1.0"
<IP> - test [15/Dec/2022:10:18:07 +0100] "PROPFIND /dav/calendars/test/inbox/ HTTP/2.0" 207 376 "-" "iOS/16.1.2 (20B110) dataaccessd/1.0"

This is the calendar on iPhone which does the same thing, albeit not quite as verbose.

The only other client in use on my end is DAVx5, which doesn't do this:

<IP> - test [15/Dec/2022:10:21:09 +0100] "PROPFIND /dav/calendars/test/general/ HTTP/2.0" 207 1222 "-" "DAVx5/4.1.1-ose (2022/02/03; dav4jvm; okhttp/4.9.1) Android/8.0.0"
<IP> - test [15/Dec/2022:10:21:09 +0100] "PROPFIND /dav/calendars/test/appointments/ HTTP/2.0" 207 1227 "-" "DAVx5/4.1.1-ose (2022/02/03; dav4jvm; okhttp/4.9.1) Android/8.0.0"
<IP> - test [15/Dec/2022:10:21:10 +0100] "PROPFIND /dav/calendars/test/vacations/ HTTP/2.0" 207 1222 "-" "DAVx5/4.1.1-ose (2022/02/03; dav4jvm; okhttp/4.9.1) Android/8.0.0"

Unfortunately this is also the one that is used the least as you can tell by the ancient version numbers.

So, could it be, that this is "allowed behavior" according to some SPEC somewhere? Or are most clients just really bad like that?

Since it's two out of the three clients in use here I think I'm just going to revert b9d2b95f6e813bcb8fe39d76dcf46372be31cb12 and call it a day. While I could file a bug with Thunderbird and get this fixed in the next decade or ten there is really nothing I can do about the Apple clients.

ghtm2 avatar Dec 15 '22 12:12 ghtm2

Understood, thanks for the head up and the comprehensive exploration. I fear it's indeed an allowed behavior somehow.

Before you revert anything on your side, let me try to see if I can just easily find a way to exclude 401s altogether

tchapi avatar Dec 15 '22 12:12 tchapi

Tell me how https://github.com/tchapi/davis/commit/0ffee2950d34c12448a5132b1c551fff87c28ded goes for you

tchapi avatar Dec 15 '22 20:12 tchapi

That does indeed get rid of the log flooding, thank you very much!

ghtm2 avatar Dec 17 '22 10:12 ghtm2