Re: Sending HTTP 401 Unauthorized header response
Arjen de Korte <[email protected]>
| Newsgroups | gmane.comp.horde.user |
|---|---|
| Message-ID | <[email protected]> |
Citeren Arjen de Korte <[email protected]>: > Citeren Michael J Rubinsky <[email protected]>: > >> Quoting Arjen de Korte <[email protected]>: >> >>> Citeren Arjen de Korte <[email protected]>: >>> >>>> Citeren Michael J Rubinsky <[email protected]>: >>>> >>>>> Quoting Arjen de Korte <[email protected]>: >>>>> >>>>>> Citeren Arjen de Korte <[email protected]>: >>>>>> >>>>>>> Citeren Arjen de Korte <[email protected]>: >>>>>>> >>>>>>>> Possibly more log spam: >>>>>>>> >>>>>>>> 2019-01-04T13:23:44+01:00 ERR: horde Sending HTTP 401 >>>>>>>> Unauthorized header response. [pid 1949 on line 126 of >>>>>>>> "/usr/share/php7/PEAR/Horde/Rpc/ActiveSync.php"] >>>>>>>> >>>>>>>> Dumping $serverVars just a few lines before this line, it >>>>>>>> looks like the client attempts to authenticate with type >>>>>>>> "Bearer" but there is no token. I also see requests where the >>>>>>>> same client is using Basic authentication with a base64 >>>>>>>> encoded username and password, which works fine. The client >>>>>>>> in question is the built-in Windows 10 Mail and synchronizes >>>>>>>> as usual. >>>>>>>> >>>>>>>> I've removed the account and recreated it, but the problem remains. >>>>>>> >>>>>>> It occurs with multiple accounts, all using the Windows 10 >>>>>>> Mail client. When logging the >>>>>>> $serverVars['HTTP_AUTHORIZATION'] variable, they seem to come >>>>>>> in pairs: >>>>>>> >>>>>>> 2019-01-04T19:24:10+01:00 DEBUG: Variable information: >>>>>>> string(50) "Basic XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX==" >>>>>>> >>>>>>> Backtrace: >>>>>>> 1. Horde_Rpc_ActiveSync->getResponse() >>>>>>> /srv/www/htdocs/horde/rpc.php:160 >>>>>>> 2. Horde::debug() /usr/share/php7/PEAR/Horde/Rpc/ActiveSync.php:120 >>>>>>> >>>>>>> 2019-01-04T19:24:26+01:00 DEBUG: Variable information: >>>>>>> string(6) "Bearer" >>>>>>> >>>>>>> Backtrace: >>>>>>> 1. Horde_Rpc_ActiveSync->getResponse() >>>>>>> /srv/www/htdocs/horde/rpc.php:160 >>>>>>> 2. Horde::debug() /usr/share/php7/PEAR/Horde/Rpc/ActiveSync.php:120 >>>>>>> >>>>>>> Could it somehow be that no token is sent from the server to >>>>>>> the client? Can I somehow log the token? >>>>>> >>>>>> These are weird requests. I enabled the forensics log of Apache >>>>>> and this is what it came up with for these packets: >>>>>> >>>>>> +24647:5c308a50:0|OPTIONS >>>>>> /Microsoft-Server-ActiveSync?User=xxxx&DeviceId=XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX&DeviceType=WindowsMail HTTP/1.1|Cache-Control:no-cache|Connection:Keep-Alive|Pragma:no-cache|Authorization:Basic >>>>>> XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX=|User-Agent:MSFT-WIN-3/10.0.17134|MS-ASProtocolVersion:14.1|Host:mail.example.com|Cookie:PHPSESSID=XXXXXXXXXXXXXXXXXXXXXXXXXX >>>>>> +24647:5c308b42:5|OPTIONS /Microsoft-Server-ActiveSync >>>>>> HTTP/1.1|Cache-Control:no-cache|Connection:Keep-Alive|Pragma:no-cache|Authorization:Bearer|User-Agent:MSFT-WIN-3/10.0.17134|MS-ASProtocolVersion:2.5|Host:mail.example.com >>>>>> >>>>>> The first is what I expect for ActiveSync connections, but the >>>>>> second looks like some kind of probe for the connectivity to >>>>>> the EAS server, rather than an attempt to actively exchange >>>>>> data. Look at the difference in the ASProtocolVersion and the >>>>>> absence of any identifying data. >>>>> >>>>> This looks like the initial, empty Bearer challenge that Outlook >>>>> can send when initiating OAuth authenticatie. This is used when >>>>> the client is enabled for Hybrid Modern Authentication. This is >>>>> used when Outlook is connecting with Office 365/Azure AD in >>>>> combination with a on-premise Exchange server. No clue why the >>>>> client would send those frequently. >>>> >>>> Probably because it is not getting an expected reply, although I >>>> have no idea what this would be. It looks like the present 401 is >>>> not the right one, the clients send this quite frequently (a >>>> couple of times per hour per client). >>>> >>>>> If you are seeing those often, it sounds like a client bug. >>> >>> After a bit more logging, I now see two distinct cases where an >>> empty Bearer challenge is used: >>> >>> +24860:5c30fa08:bd|POST /AutoDiscover/AutoDiscover.xml >>> HTTP/2.0|Accept:*/*|Authorization:Bearer|User-Agent:microsoft.windowscommunicationsapps|Content-Type:text/xml|Accept-Language:nl-NL,nl;q=0.5|Accept-Encoding:gzip, deflate, >>> br|Content-Length:356|Cache-Control:no-cache|Host:example.com >>> >>> and >>> >>> +24646:5c324a0e:284|OPTIONS /Microsoft-Server-ActiveSync >>> HTTP/1.1|Cache-Control:no-cache|Connection:Keep-Alive|Pragma:no-cache|Authorization:Bearer|User-Agent:MSFT-WIN-3/10.0.17134|MS-ASProtocolVersion:2.5|Host:example.com >>> >>> The first of these two is sent only when setting up a new EAS >>> account on a client, so I don't see that one very often. The >>> second is send *much* more frequently (a couple of times per hour >>> per client) and only for clients on Windows 10 (I don't have users >>> with other Windows versions) using the built-in Mail-app. None of >>> them is configured to use/require Modern Authentication. >> >> I researched this for a few hours yesterday, and I don't see >> anything else we could be sending back to the client to indicate we >> don't support Modern Authentication. My guess is that MS Mail is >> either broken, or just behaves inefficiently, trying Modern >> Authentication too frequently. The only other thing I can think of >> is that there is some undocumented value in the AUTODISCOVER >> response schema: We are sending a 401, which in addition to being >> the correct HTTP error code, MS explicitly documents in MS-ASHTTP >> 3.1.5.2.1 as indicating that the client should send an AUTODISCOVER >> request to the server. There is nothing in the protocol >> documentation which states that AUTODISCOVER returns any >> information related to authentication, other than the username and >> hostname. >> >> I also find it funny that the ASProtocolVersion is set to 2.5 in >> the OPTIONS request. While the Bearer token isn't technically a >> part of the EAS protocol, there was no support for this back when >> the current EAS version was 2.5...I'm assuming you have configured >> a recent version in your horde config and see this more recent >> version as the supported version in other "Normal" requests? > > Yes. Pretty much every client connects through 14.1 nowadays. > >> I do know that when initially provisioning desktop Outlook a >> request is actually sent to some MS Office 365 server, which then >> queries your server's Autodiscover endpoint. There is some >> undocumented (at least I couldn't find any) response schema that is >> expected by MS' server that, when missing, causes autodiscovery to >> fail and (unless a registry tweak is made) prevents provisioning >> desktop Outlook to Horde. Perhaps this is something related > > I doubt it, since all traffic originates from clients on the (W)LAN. > I do have to admit this may be going on for quite a while already, > since only recently I have lowered the logging level in Horde from > CRIT to WARN, to get some more info why Horde didn't work anymore > after upgrading to PHP 7.3. This is all fixed no, so maybe it is > time to put this to rest and increase the log level to CRIT again. After a week of forensic logging by Apache, I found that all these log lines were from Microsoft apps attempting to connect to EAS and indicating they support Modern Authentication. I silenced the noise by changing line 246 in Horde/Rpc/ActiveSync.php from $this->_logger->err('Sending HTTP 401 Unauthorized header response.'); to $this->_logger->notice('Sending HTTP 401 Unauthorized header response.'); This will at least allow me to quickly spot failed login attempts. -- Horde mailing list Frequently Asked Questions: http://horde.org/faq/ To unsubscribe, mail: [email protected]