Re: Sending HTTP 401 Unauthorized header response

Michael J Rubinsky <[email protected]> Mon, 07 Jan 2019 13:57:15 +0000
Newsgroups	gmane.comp.horde.user
Message-ID	<20190107135715.Horde.BLabnaQ3erBrDtXcSMkilay@tarn.theupstairsroom.com>
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?

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?

-- 
mike
The Horde Project
http://www.horde.org
https://www.facebook.com/hordeproject
https://www.twitter.com/hordeproject

-- 
Horde mailing list
Frequently Asked Questions: http://horde.org/faq/
To unsubscribe, mail: [email protected]
(unnamed) (application/pgp-keys, 9.1 KB) - not displayed
signature.asc (application/pgp-signature, 821 B)