[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"]

[Simon B]

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"

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"

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.

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?

Thanks for your help and patience, I know you have work to do.

Simon