[horde] EMERG: HORDE-BETA Missing required state object [pid 15927 on line 122 of "/usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync/Driver/Base.php"]

Tue Jan 7 16:02:01 UTC 2014

On 7 January 2014 16:10, Michael J Rubinsky <mrubinsk at horde.org> wrote:
>
> Quoting Simon B <simon.buongiorno at gmail.com>:
>
>> On 6 January 2014 19:25, Michael J Rubinsky <mrubinsk at horde.org> wrote:
>>>
>>>
>>> Quoting Simon B <simon.buongiorno at gmail.com>:
>>>
>>>> On 6 January 2014 17:47, Michael J Rubinsky <mrubinsk at horde.org> wrote:
>>>>>
>>>>>
>>>>>
>>>>> Quoting Michael J Rubinsky <mrubinsk at horde.org>:
>>>>>
>>>>>> Quoting Simon B <simon.buongiorno at gmail.com>:
>>>>>>
>>>>>>>> Horde::debug($variable_name);
>>>>>>>>
>>>>>>>> Will output the contents of said variable to horde_debug.txt in your
>>>>>>>> tmp
>>>>>>>> directory. The call on line 216 is probably the one that you are
>>>>>>>> most
>>>>>>>> interested in.
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> Hi Michael
>>>>>>>
>>>>>>> Introducing Horde::debug($username); and Horde::debug($password);
>>>>>>> after line 216 of
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> "/usr/share/git-horde5/framework/Core/lib/Horde/Core/ActiveSync/Driver.php"
>>>>>>> yields:
>>>>>>>
>>>>>>> ==> /tmp/horde_debug.txt <==
>>>>>>> 2014-01-06T08:59:32+00:00 DEBUG: Variable information:
>>>>>>> string(17) "simon at example.net"
>>>>>>>
>>>>>>> Backtrace:
>>>>>>> 1. Horde_Rpc_ActiveSync->getResponse()
>>>>>>> /usr/share/git-horde5/horde/rpc.php:156
>>>>>>> 2. Horde_ActiveSync->handleRequest()
>>>>>>> /usr/share/git-horde5/framework/Rpc/lib/Horde/Rpc/ActiveSync.php:122
>>>>>>> 3. Horde_ActiveSync->authenticate()
>>>>>>>
>>>>>>> /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php:723
>>>>>>> 4. Horde_Core_ActiveSync_Driver->authenticate()
>>>>>>>
>>>>>>> /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php:561
>>>>>>> 5. Horde::debug()
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> /usr/share/git-horde5/framework/Core/lib/Horde/Core/ActiveSync/Driver.php:217
>>>>>>>
>>>>>>> 2014-01-06T08:59:32+00:00 DEBUG: Variable information:
>>>>>>> string(18) "CorrectPassword"
>>>>>>>
>>>>>>> Backtrace:
>>>>>>> 1. Horde_Rpc_ActiveSync->getResponse()
>>>>>>> /usr/share/git-horde5/horde/rpc.php:156
>>>>>>> 2. Horde_ActiveSync->handleRequest()
>>>>>>> /usr/share/git-horde5/framework/Rpc/lib/Horde/Rpc/ActiveSync.php:122
>>>>>>> 3. Horde_ActiveSync->authenticate()
>>>>>>>
>>>>>>> /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php:723
>>>>>>> 4. Horde_Core_ActiveSync_Driver->authenticate()
>>>>>>>
>>>>>>> /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php:561
>>>>>>> 5. Horde::debug()
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> /usr/share/git-horde5/framework/Core/lib/Horde/Core/ActiveSync/Driver.php:218
>>>>>>>
>>>>>>> This tells me nothing other than than the variables being entered are
>>>>>>> actually correct (well, at least this wasn't all my fat fingers).  I
>>>>>>> still see no authentication attempt in the IMAP server logs (but then
>>>>>>> should I expect to - I mean I don't see authentication attempts for
>>>>>>> every activesync attempt, so probably not).
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> You *should* see IMAP login for each discreet ActiveSync connection.
>>>>>>
>>>>>>
>>>>>>> In an effort to attempt to look competent, I added
>>>>>>> Horde::debug($result); to
>>>>>>>
>>>>>>> /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php:561
>>>>>>> and
>>>>>>>
>>>>>>> /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php:723
>>>>>>> but neither of these resulted in extra output in horde_debug.txt
>>>>
>>>>
>>>>
>>>>>> It's not clear from your comment exactly where you placed the debug
>>>>>> call
>>>>>> in relation to the authenticate calls, but this is probably expected
>>>>>> since
>>>>>> it seems that authentication fails in the Core driver.
>>>>
>>>>
>>>>
>>>> Hi Michael
>>>>
>>>> In all instances I simply inserted a carriage return and added the
>>>> debug code on a separate line immediately below the line numbers
>>>> listed in the backtrace.
>>>>
>>>>  561         if ($result = $this->_driver->authenticate($user, $pass,
>>>> $domain)) {
>>>> So, $result immediately below it
>>>
>>>
>>>
>>> This won't show anything because the debug line won't be reached when
>>> auth
>>> fails.
>>>
>>>>
>>>>  721             return $result;
>>>> So, $result immediately below it
>>>
>>>
>>>
>>> This won't show anything because the code returns before the debug line
>>> is
>>> reached.
>>>
>>>
>>>> Looking at this after a day's worth of coffee consumption, I think
>>>> might have put it in the wrong place.  If you agree, I can put it
>>>> somewhere else.
>>>
>>>
>>>
>>>
>>> Anyway, from what you are telling me authentication is failing in Horde,
>>> so
>>> the ActiveSync library code doesn't matter. Do this to verify:
>>>
>>> In Horde_Core_ActiveSync_Driver:: on line 213 (currently blank), right
>>> before the comment about trying Basic auth, add something like
>>>
>>> Horde::debug($conf['activesync']['auth']['type']);
>>>
>>> This will output the configured activesync auth type, as well as provide
>>> a
>>> sanity check that the code is reached. Then, between line 216 and 217
>>> add:
>>>
>>> Horde::debug('Authentication failed');
>>>
>>> This will show that authentication failed when checking the horde auth
>>> backend.
>>>
>>>
>>> For completeness, add this between 231 and 232
>>>
>>> Horde::debug('Permission check failed.');
>>>
>>> This shows that the device or user was denied access based on permission
>>> settings.
>>>
>>> Then finally on line 235 add Horde::debug('So far so good.');
>>>
>>> This shows that up to that point authentication succeeded, and I have no
>>> idea wtf is going on.
>>
>>
>> Hi Michael
>>
>> Here's the horde_debug.txt
>>
>> root at mail:~# less /tmp/horde_debug.txt
>> 2014-01-07T09:10:39+00:00 DEBUG: Variable information:
>> string(5) "basic"
>>
>> Backtrace:
>> 1. Horde_Rpc_ActiveSync->getResponse()
>> /usr/share/git-horde5/horde/rpc.php:156
>> 2. Horde_ActiveSync->handleRequest()
>> /usr/share/git-horde5/framework/Rpc/lib/Horde/Rpc/ActiveSync.php:122
>> 3. Horde_ActiveSync->authenticate()
>> /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php:725
>> 4. Horde_Core_ActiveSync_Driver->authenticate()
>> /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php:561
>> 5. Horde::debug()
>>
>> /usr/share/git-horde5/framework/Core/lib/Horde/Core/ActiveSync/Driver.php:213
>>
>> 2014-01-07T09:10:39+00:00 DEBUG: Variable information:
>> string(21) "Authentication failed"
>
>
> Ok. This means that Horde's authentication backend does not accept your
> credentials. It's not ActiveSync code.

Do you have an idea where I can put the Horde::Debug() to trace this?
Is it possible that Horde is somehow caching stale data?

As a curiosity I've always had 4 password mismatch log lines in the
IMAP log every single day from the localhost (i.e. it can only be
coming from Horde) at the very time that all the logs rotate.  I
assume it's because I'm the admin user, but I've never been able to
track it down.  And it's survived the upgrade from H4 to H5 (when I
was hoping it would disappear).

>> Backtrace:
>> 1. Horde_Rpc_ActiveSync->getResponse()
>> /usr/share/git-horde5/horde/rpc.php:156
>> 2. Horde_ActiveSync->handleRequest()
>> /usr/share/git-horde5/framework/Rpc/lib/Horde/Rpc/ActiveSync.php:122
>> 3. Horde_ActiveSync->authenticate()
>> /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php:725
>> 4. Horde_Core_ActiveSync_Driver->authenticate()
>> /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php:561
>> 5. Horde::debug()
>>
>> /usr/share/git-horde5/framework/Core/lib/Horde/Core/ActiveSync/Driver.php:217
>>
>> 2014-01-07T09:10:39+00:00 DEBUG: Variable information:
>> string(17) "simon at example.net"
>
>
> Is this the correct username? I.e., do you use the full email address when
> you log in to Horde's interface?

Yes, it is.  I've always only used full email addresses (and it's
working for the web interface).

>> Backtrace:
>> 1. Horde_Rpc_ActiveSync->getResponse()
>> /usr/share/git-horde5/horde/rpc.php:156
>> 2. Horde_ActiveSync->handleRequest()
>> /usr/share/git-horde5/framework/Rpc/lib/Horde/Rpc/ActiveSync.php:122
>> 3. Horde_ActiveSync->authenticate()
>> /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php:725
>> 4. Horde_Core_ActiveSync_Driver->authenticate()
>> /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php:561
>> 5. Horde::debug()
>>
>> /usr/share/git-horde5/framework/Core/lib/Horde/Core/ActiveSync/Driver.php:218
>>
>> 2014-01-07T09:10:39+00:00 DEBUG: Variable information:
>> string(18) "CorrectPassword"
>>
>> Backtrace:
>> 1. Horde_Rpc_ActiveSync->getResponse()
>> /usr/share/git-horde5/horde/rpc.php:156
>> 2. Horde_ActiveSync->handleRequest()
>> /usr/share/git-horde5/framework/Rpc/lib/Horde/Rpc/ActiveSync.php:122
>> 3. Horde_ActiveSync->authenticate()
>> /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php:725
>> 4. Horde_Core_ActiveSync_Driver->authenticate()
>> /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php:561
>> 5. Horde::debug()
>>
>> /usr/share/git-horde5/framework/Core/lib/Horde/Core/ActiveSync/Driver.php:219
>>
>> According to Horde, the authentication is failing.  And yet the
>> password is correct.  To prove this, I've copied the password in the
>> Horde_debug.txt into the Mail database  (not that I believe two
>> different devices are somehow sending it wrong) before doing the
>> authentication again.
>
>
> If the activesync library is sending the correct username and password to
> horde's authentication backend, and it is rejecting it, it is not something
> in the activesync code that is broken.
>
>> For this last attempt, I turned on mysql logging to check my theory
>> that it wasn't trying to authenticate using the wrong details (I
>> manages to isolate just my attempt to set up the account, but I'll
>> send you the log off list).  However, that proved to me that it IS
>> using the IMAP auth details and even seems to initiate a sync (the
>> time-stamps are a full 7 seconds later than the timestamps in the
>> horde_debug.txt).
>>
>> How would I roll back to the previous version (or say the version that
>> was there on the 21st of Dec when it was last known to be working?  I
>> know it's working for you, but something in the new AS code is funky
>> (at least on my system).  A git pull should overwrite any changes I've
>> made to
>> /usr/share/git-horde5/framework/Core/lib/Horde/Core/ActiveSync/Driver.php
>> and any other files, yes?
>
>
> If you are using Git, you can checkout a specific commit id that you know
> was working for you:
>
> git checkout {commit hash}
>
> you can use the commit history on github to find a commit you want to revert
> to:
>
> https://github.com/horde/horde/commits/master

Thanks.  It might be worth a try.

Simon