From build+horde at de-korte.org Tue Jan 15 10:50:31 2019 From: build+horde at de-korte.org (Arjen de Korte) Date: Tue, 15 Jan 2019 11:50:31 +0100 Subject: [horde] Sending HTTP 401 Unauthorized header response In-Reply-To: <20190107195834.Horde.OlVVf2dJSpYy5EjQFUtaHiv@mail.de-korte.org> References: <20190104152203.Horde.skNgYuZKCzv795xTmgTlnaY@mail.de-korte.org> <20190104210201.Horde.r-303ccdI28KsnOnEVNBbZh@mail.de-korte.org> <20190105121146.Horde.sK7sG58bA8Ke1656lIsHW79@mail.de-korte.org> <20190105143933.Horde.duOBfWL1gmlVtWCkEN0GuEF@tarn.theupstairsroom.com> <20190105193534.Horde.3CPL8SdLzzWjjBVWRnv2Rr5@mail.de-korte.org> <20190107092115.Horde.rExbvmQta6sKNV73K4ukcMj@mail.de-korte.org> <20190107135715.Horde.BLabnaQ3erBrDtXcSMkilay@tarn.theupstairsroom.com> <20190107195834.Horde.OlVVf2dJSpYy5EjQFUtaHiv@mail.de-korte.org> Message-ID: <20190115115031.Horde.mbcyYyIBps_8B_OFm6VPLeM@mail.de-korte.org> Citeren Arjen de Korte : > Citeren Michael J Rubinsky : > >> Quoting Arjen de Korte : >> >>> Citeren Arjen de Korte : >>> >>>> Citeren Michael J Rubinsky : >>>> >>>>> Quoting Arjen de Korte : >>>>> >>>>>> Citeren Arjen de Korte : >>>>>> >>>>>>> Citeren Arjen de Korte : >>>>>>> >>>>>>>> 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. From sca at andreasschulze.de Thu Jan 17 06:00:10 2019 From: sca at andreasschulze.de (A. Schulze) Date: Thu, 17 Jan 2019 07:00:10 +0100 Subject: [horde] db migration: sqlite to postgresql Message-ID: <20190117070010.Horde.TSUaecSpOh05wZQyUDiiQC9@andreasschulze.de> Hello, I'm planning a db migration. has anybody suggestions on readings, tools or pitfalls? Andreas From lang at b1-systems.de Thu Jan 17 06:21:25 2019 From: lang at b1-systems.de (Ralf Lang) Date: Thu, 17 Jan 2019 07:21:25 +0100 Subject: [horde] db migration: sqlite to postgresql In-Reply-To: <20190117070010.Horde.TSUaecSpOh05wZQyUDiiQC9@andreasschulze.de> References: <20190117070010.Horde.TSUaecSpOh05wZQyUDiiQC9@andreasschulze.de> Message-ID: Mind character sets and collations (UTF-8 vs US or Latin1) Am 17.01.19 um 07:00 schrieb A. Schulze: > Hello, > > I'm planning a db migration. has anybody suggestions on readings, > tools or pitfalls? > > Andreas > > -- Ralf Lang Linux Consultant / Developer Tel.: +49-170-6381563 Mail: lang at b1-systems.de B1 Systems GmbH Osterfeldstra?e 7 / 85088 Vohburg / http://www.b1-systems.de GF: Ralph Dehner / Unternehmenssitz: Vohburg / AG: Ingolstadt,HRB 3537