[horde] Sending HTTP 401 Unauthorized header response

Arjen de Korte build+horde at de-korte.org
Tue Jan 15 10:50:31 UTC 2019

Citeren Arjen de Korte <build+horde at de-korte.org>:

> Citeren Michael J Rubinsky <mrubinsk at horde.org>:
>> Quoting Arjen de Korte <build+horde at de-korte.org>:
>>> Citeren Arjen de Korte <build+horde at de-korte.org>:
>>>> Citeren Michael J Rubinsky <mrubinsk at horde.org>:
>>>>> Quoting Arjen de Korte <build+horde at de-korte.org>:
>>>>>> Citeren Arjen de Korte <build+horde at de-korte.org>:
>>>>>>> Citeren Arjen de Korte <build+horde at de-korte.org>:
>>>>>>>> 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:
>>>>>>> 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  
>>>>>> +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  
>> 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  
             $this->_logger->notice('Sending HTTP 401 Unauthorized  
header response.');

This will at least allow me to quickly spot failed login attempts.

More information about the horde mailing list