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

Sat Jan 4 01:49:18 UTC 2014

Quoting Simon B <simon.buongiorno at gmail.com>:

> On 2 January 2014 18:13, Michael J Rubinsky <mrubinsk at horde.org> wrote:
>>
>> Quoting Simon B <simon.buongiorno at gmail.com>:
>>
>>> On 2 January 2014 15:58, Simon B <simon.buongiorno at gmail.com> wrote:
>>>>
>>>> On 31 December 2013 17:09, Michael J Rubinsky <mrubinsk at horde.org> wrote:
>>>>>
>>>>>
>>>>> Quoting Simon B <simon.buongiorno at gmail.com>:
>>>>>
>>>>>> On 26 December 2013 19:03, Michael J Rubinsky <mrubinsk at horde.org>
>>>>>> wrote:
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> Quoting Simon B <simon.buongiorno at gmail.com>:
>>>>>>>
>>>>>>>> On 25 December 2013 21:34, Michael J Rubinsky <mrubinsk at horde.org>
>>>>>>>> wrote:
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> Quoting Simon B <simon.buongiorno at gmail.com>:
>>>>>>>>>
>>>>>>>>>> Hi
>>>>>>>>>>
>>>>>>>>>> Since the last git pull that I did on Sunday I have this in my
>>>>>>>>>> logs..
>>>>>>>>>>
>>>>>>>>>> 2013-12-22T06:31:39+00:00 EMERG: HORDE-BETA [horde] Missing
>>>>>>>>>> required
>>>>>>>>>> state object [pid 15927 on line 122 of
>>>
>>>
>>> SNIP
>>>>>
>>>>> Ensure your ActiveSync configuration is completely up to date, and the
>>>>> storage choices make sense for your install. I.e., if you are using SQL,
>>>>> make sure the database is correct. If you are using NoSql, make sure
>>>>> that
>>>>> Mongo is setup properly.
>>>>
>>>>
>>>> Happy New Year Michael!
>>>>
>>>> I've looked at this several times - and if there's something missing
>>>> from the config I cannot find it.  As I mentioned, the admin/config
>>>> page reports the DB schema is all up-to-date (if that's what you mean
>>>> by making sure the DB is correct).  What could I do to verify that?  I
>>>> am using SQL.  Although I see no mention of storage for
>>>> ActiveSync.....
>>>>
>>>> So, on faith, I decided to let the admin/config page generate a new
>>>> config after making my config 660 (it's usually 640).
>>>>
>>>> And sure enough storage for ActiveSync now appears in the config.  I
>>>> know how this happened, but not why.
>>>>
>>>> As recounted before, my git-update script does a weekly pull on Sunday
>>>> and reruns install_dev.  Then, if things stop working I go in and see
>>>> if the config needs changing (which I have to do manually, because the
>>>> config is not writeable by Apache).  Usually, the only thing that need
>>>> changing is the $Id - but I use the show differences to make sure.
>>>> Since the update 3 days before Christmas, that hasn't been working for
>>>> me.  I get an error that says:
>>>> No available configuration data to show differences for.
>>>>
>>>> I'm not sure why that is - had that been working I would have seen
>>>> that you'd added Storage parameters for ActiveSync and made the
>>>> necessary edits.  Should the show differences code be working?  Is it
>>>> being retired?  Do you need more information from me to debug that?
>>>>
>>>> Once again, I'd like to call for a subtle UI change (in the colour of
>>>> the tabs) when new parameters have been added.  That too would have
>>>> alerted me to which area I should have been investigating (because of
>>>> course once the DB schema showed up as not needing updating, I wasn't
>>>> in a position to think it might be a storage config issue).
>>>>
>>>> Thanks for pointing me in the right direction though :)
>>>
>>>
>>> Hi Michael,
>>>
>>> So, no more errors in the log and  admin/activesync.php is available
>>> again.
>>>
>>> However, my username/password is being refused on the devices.  I've
>>> double and triple checked the input.
>>>
>>> There's no error in any of the logs - not the apache one, not the
>>> horde one and not the dovecot one.
>>>
>>> The (Android) phone says:
>>> Username/Password incorrect.  (Authentication failed.)
>>>
>>> The iPhone says:
>>> Exchange Account.  Unable to verify account information
>>>
>>> IMAP is working.
>>>
>>> Without a meaningful error, I have nowhere to look.
>>
>>
>> Do you see the requests hitting the webserver? Are the devices trying to
>> connect to ssl, and do you have ssl open etc... ?
>>
>> Needless to say, I'm having no issues.
>
> Hi Michael
>
> No, I don't - which is the weird thing.  As I said, there's no error
> in Apache or in Horde.  The devices are trying to use SSL and SSL has
> been working and I haven't changed the IMP config.
>
> In the webmail_access_log there appears (with each authentication
> attempt on an existing account):
> 109.44.3.13 - simon at example.net [03/Jan/2014:10:14:12 +0000] "OPTIONS
> /Microsoft-Server-ActiveSync HTTP/1.1" 401 2741
> 109.44.3.13 - simon at example.net [03/Jan/2014:10:14:12 +0000] "OPTIONS
> /Microsoft-Server-ActiveSync HTTP/1.1" 401 1349
>
> Trying to set up a new account, I get this.
>
> 109.44.3.13 - simon at example.net [03/Jan/2014:11:08:55 +0000] "OPTIONS
> /Microsoft-Server-ActiveSync?Cmd=OPTIONS&User=simon%40example.net&DeviceId=validate&DeviceType=Android
> HTTP/1.1" 401 2478
> 109.44.3.13 - simon at example.net [03/Jan/2014:11:09:16 +0000] "OPTIONS
> /Microsoft-Server-ActiveSync?Cmd=OPTIONS&User=simon%40example.net&DeviceId=validate&DeviceType=Android
> HTTP/1.1" 401 1090
>
> However, there's nothing in the webmail_error_log and nothing in the
> maillog (which does log password mismatches).  So, it looks to me as
> if Horde/ActiveSync is not "passing" the credentials on.
>
> maillog:
> Jan  3 10:13:34 mail dovecot: imap(simon at example.net): Disconnected:
> Logged out in=134 out=563
> ------Attempts should be here--------------
> Jan  3 10:15:56 mail dovecot: auth-worker(18251): mysql(localhost):
> Connected to database Mail
>
> maillog:
> Jan  3 11:08:35 mail dovecot: auth-worker(18637): mysql(localhost):
> Connected to database Mail
> Jan  3 11:08:35 mail dovecot: imap-login: Login:
> user=<simon at example.net>, method=PLAIN, rip=127.0.0.1, TLS
> Jan  3 11:08:35 mail dovecot: imap(simon at example.net): Disconnected:
> Logged out in=134 out=563
> ------Attempts should be here--------------
> Jan  3 11:09:21 mail postfix/smtpd[18679]: warning: hostname
> 177-139-206-235.dsl.telesp.net.br does not resolve to address
> 177.139.206.235: Name or service not known
> Jan  3 11:09:21 mail postfix/smtpd[18679]: connect from  
> unknown[177.139.206.235]
>
> Both these devices were previously working and haven't been updated,
> so I doubt it's a device error.
>
> So, I set the log-level to DEBUG and the following is generated for
> each authentication/setup attempt.
>
> 2014-01-03T11:52:53+00:00 DEBUG: HORDE-BETA Setting timeobjects
> inactive because the fileroot does not exist or the application is not
> configured yet. [pid 20297 on line 738 of
> "/usr/share/git-horde5/framework/Core/lib/Horde/Registry.php"]
> 2014-01-03T11:52:53+00:00 DEBUG: HORDE-BETA Load config file (nls.php;
> app: horde) [pid 20297 on line 402 of
> "/usr/share/git-horde5/framework/Core/lib/Horde.php"]
> 2014-01-03T11:52:53+00:00 DEBUG: HORDE-BETA [imp] Load config file
> (conf.php; app: imp) [pid 20297 on line 402 of
> "/usr/share/git-horde5/framework/Core/lib/Horde.php"]
> 2014-01-03T11:52:53+00:00 DEBUG: HORDE-BETA [imp] Load config file
> (prefs.php; app: horde) [pid 20297 on line 402 of
> "/usr/share/git-horde5/framework/Core/lib/Horde.php"]
> 2014-01-03T11:52:53+00:00 DEBUG: HORDE-BETA [imp] Load config file
> (prefs.php; app: imp) [pid 20297 on line 402 of
> "/usr/share/git-horde5/framework/Core/lib/Horde.php"]
> 2014-01-03T11:52:53+00:00 DEBUG: HORDE-BETA [imp] Load config file
> (backends.php; app: imp) [pid 20297 on line 402 of
> "/usr/share/git-horde5/framework/Core/lib/Horde.php"]
> 2014-01-03T11:52:53+00:00 DEBUG: HORDE-BETA [horde]
> Horde_Rpc::__construct complete [pid 20297 on line 47 of
> "/usr/share/git-horde5/framework/Rpc/lib/Horde/Rpc/ActiveSync.php"]
> 2014-01-03T11:52:53+00:00 DEBUG: HORDE-BETA [horde]
> Horde_Rpc_ActiveSync::getResponse() starting for OPTIONS [pid 20297 on
> line 156 of "/usr/share/git-horde5/horde/rpc.php"]
> 2014-01-03T11:52:53+00:00 NOTICE: HORDE-BETA [horde] Login failed from
> ActiveSync client for user simon at example.net. [pid 20297 on line 561

What do you have configured as the authentication method for  
ActiveSync? Is it correct for your situation?

> of "/usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php"]
> 2014-01-03T11:52:53+00:00 DEBUG: HORDE-BETA [horde] Max memory usage:
> 10747904 bytes [pid 20297 on line 598 of
> "/usr/share/git-horde5/framework/Core/lib/Horde/Registry.php"]
>
> However, trying to set up a new account generates some significant  
> other logs.

<Snip - nothing of interest in the log>

>
>  I'm concerned about this line:
>
> 2014-01-03T11:56:37+00:00 DEBUG: HORDE-BETA Horde_Registry: retrieved
> app with cache ID
> horde_registry|app|1387693513|7a33c72006bee84b640c94c5b7ca0afa [pid
> 17454 on line 2027 of
> "/usr/share/git-horde5/framework/Core/lib/Horde/Registry.php"
>
> Logging is set to per device, but device logs are not being created at
> the moment (not surprisingly as the accounts aren't being
> created/authenticated).
>
> I notice that in admin/activesync.php there is now much more
> information displayed.  However, some of this is stale and I'm not
> able to remove it.  I think this might be where the problem is.
>
> Does the 1387693513 relate to the Id: ANDROIDC1898347182 in
> admin/activesync.php?

No. That log line has nothing to do with ActiveSync. It's related to  
app api caching in the registry.

>
>
> Simon

-- 
mike

The Horde Project (www.horde.org)
mrubinsk at horde.org
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 5849 bytes
Desc: S/MIME Signature
URL: <http://lists.horde.org/archives/horde/attachments/20140103/12ed0bbe/attachment.bin>