[horde] Sending HTTP 401 Unauthorized header response

[Arjen de Korte]

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:
>>>> 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.