[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:
>>>>>>> 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.
More information about the horde
mailing list