[horde] Sending HTTP 401 Unauthorized header response

Mon Jan 7 18:58:34 UTC 2019

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