[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 08:57:07 UTC 2014

On 4 Jan 2014 02:49, "Michael J Rubinsky" <mrubinsk at horde.org> wrote:
>
>
> 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?

Eventually I'd like to move to http basic with certificates, but for now
I'm just using http-basic.

Simon

>> 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