[horde] ActiveSync/IMP error with latest GIT

Wed Feb 26 09:53:45 UTC 2014

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On Tue, 25 Feb 2014, Joerg Pulz wrote:

> ----- Message from Michael J Rubinsky <mrubinsk at horde.org> ---------
>   Date: Tue, 25 Feb 2014 10:23:03 -0500
>   From: Michael J Rubinsky <mrubinsk at horde.org>
> Reply-To: mrubinsk at horde.org
> Subject: Re: [horde] ActiveSync/IMP error with latest GIT
>     To: horde at lists.horde.org
>
>
>> Quoting Joerg Pulz <Joerg.Pulz at frm2.tum.de>:
>> 
>>> 
>>> On Sat, 22 Feb 2014, Joerg Pulz wrote:
>>> 
>>>> Hi,
>>>> 
>>>> today i updated from a completely working 5.1.6-git to a fresh
>>>> pulled 5.2.0-git.
>>>> Now ActiveSync is not working anymore for all devices.
>>>> 
>>>> The error message in the log is:
>>>> INFO: [2649] Polling Horde_Core_ActiveSync_Driver::_getMailFolders()
>>>> ERR: [2649] Problem loading mail folders from IMAP server: User is not 
>>>> authorized for imp
>>>> ERR: User is not authorized for imp
>>>> INFO: [2649] No folder changes found.
>>>> 
>>>> I can use the Horde WebUI with the same useraccount without any problems,
>>>> IMP, Kronolith, Turba, Nag, .... everything is working fine, but
>>>> ActiveSync is broken.
>>>> I updated all DB schemas and all confogurations to match the new version
>>>> 5.2.0-git.
>>>> I see no other error messages in the logs and google was no real help for
>>>> this error.
>>>> As some lines before in the log, the user and device is correctly logged,
>>>> it looks like the user is only missing when using IMP.
>>>> 
>>>> INFO: [2649] Resetting device state for device: ANDROID, user: bob, and 
>>>> collection: foldersync.
>>>> NOTICE: [2649] Clearing foldersync state from synccache.
>>>> INFO: [2649] Clearing collections data from cache.
>>>> INFO: [2649] Replacing SYNC_CACHE entry for user bob and device 
>>>> ANDROID:....
>>>> DEBUG: [2649] I  </FolderHierarchy:FolderSync>
>>>> INFO: [2649] Initializing folder diff engine
>>>> INFO: [2649] Horde_Core_ActiveSync_Driver::getFolderList()
>>>> INFO: [2649] Creating new folder uuid for @Calendar@: Aa1037f5d
>>>> INFO: [2649] Creating new folder uuid for @Contacts@: Cbf1ec0a5
>>>> INFO: [2649] Creating new folder uuid for @Tasks@: Tf76b1bc0
>>>> INFO: [2649] Creating new folder uuid for @Notes@: N2348642d
>>>> INFO: [2649] Polling Horde_Core_ActiveSync_Driver::_getMailFolders()
>>>> ERR: [2649] Problem loading mail folders from IMAP server: User is not 
>>>> authorized for imp
>>>> ERR: User is not authorized for imp
>>>> INFO: [2649] No folder changes found.
>>>> .....
>>>> INFO: [2649] Replacing SYNC_CACHE entry for user bob and device 
>>>> ANDROID:....
>>>> 
>>>> Here are the relevant ActiveSync settings:
>>>> $conf['activesync']['params']['driverconfig'] = 'horde';
>>>> $conf['activesync']['storage'] = 'Sql';
>>>> $conf['activesync']['emailsync'] = true;
>>>> $conf['activesync']['version'] = '14.1';
>>>> $conf['activesync']['auth']['type'] = 'basic';
>>>> 
>>>> We use LDAP aus auth backend and there is only one hook defined to get 
>>>> the
>>>> correct "from_addr" and "fullname" out of the LDAP directory.
>>>> 
>>>> Any clue how to debug or solve this issue?
>>>> I've quite some amount of users without working ActiveSync now.
>>>> 
>>>> Any help or hints are much appreciated.
>>> 
>>> Hi List,
>>> 
>>> here are some related additional informations regarding this problem out 
>>> of the logfile:
>>> 
>>> 2014-02-25T08:41:27+01:00 ERR: HORDE Returning HTTP 500 while handling 
>>> Sync command. [pid 22361 on line 157 of "/home/www/horde/rpc.php"]
>>> 2014-02-25T08:41:27+01:00 ERR: HORDE Error in communicating with 
>>> ActiveSync server: User is not authorized for imp [pid 22361 on line 162 
>>> of "/home/www/horde/libs/Horde/Rpc/ActiveSync.php"]
>>> 2014-02-25T08:41:27+01:00 ERR: HORDE #0 
>>> /home/www/horde/libs/Horde/Registry.php(1095): 
>>> Horde_Registry->pushApp('imp', Array)
>>> #1 /home/www/horde/libs/Horde/Registry.php(1055): 
>>> Horde_Registry->callByPackage('imp', 'favouriteRecipi...', Array)
>>> #2 /home/www/horde/libs/Horde/Registry/Caller.php(41): 
>>> Horde_Registry->call('mail/favouriteR...', Array)
>>> #3 /home/www/horde/libs/Horde/Core/ActiveSync/Connector.php(332): 
>>> Horde_Registry_Caller->__call('favouriteRecipi...', Array)
>>> #4 /home/www/horde/libs/Horde/Core/ActiveSync/Connector.php(332): 
>>> Horde_Registry_Caller->favouriteRecipients(100)
>>> #5 /home/www/horde/libs/Horde/Core/ActiveSync/Driver.php(998): 
>>> Horde_Core_ActiveSync_Connector->getRecipientCache(100)
>>> #6 /home/www/horde/libs/Horde/ActiveSync/State/Base.php(441): 
>>> Horde_Core_ActiveSync_Driver->getServerChanges(Object(Horde_ActiveSync_Folder_RI), 
>>> 0, 1393314087, 0, false, false, 100)
>>> #7 /home/www/horde/libs/Horde/ActiveSync/Collections.php(1180): 
>>> Horde_ActiveSync_State_Base->getChanges(Array)
>>> #8 /home/www/horde/libs/Horde/ActiveSync/Collections.php(1216): 
>>> Horde_ActiveSync_Collections->getCollectionChanges(false)
>>> #9 /home/www/horde/libs/Horde/ActiveSync/Request/Sync.php(399): 
>>> Horde_ActiveSync_Collections->getCollectionChangeCount()
>>> #10 /home/www/horde/libs/Horde/ActiveSync/Request/Base.php(249): 
>>> Horde_ActiveSync_Request_Sync->_handle()
>>> #11 /home/www/horde/libs/Horde/ActiveSync.php(897): 
>>> Horde_ActiveSync_Request_Base->handle()
>>> #12 /home/www/horde/libs/Horde/Rpc/ActiveSync.php(143): 
>>> Horde_ActiveSync->handleRequest('Sync', 'SEC162325CB5989...')
>>> #13 /home/www/horde/rpc.php(157): Horde_Rpc_ActiveSync->getResponse(NULL)
>>> #14 {main} [pid 22361 on line 162 of 
>>> "/home/www/horde/libs/Horde/Rpc/ActiveSync.php"]
>>> 2014-02-25T08:41:27+01:00 ERR: HORDE Buffer contents:  [pid 22361 on line 
>>> 162 of "/home/www/horde/libs/Horde/Rpc/ActiveSync.php"]
>>> 
>>> Is that of any help to find the place that needs fixing?
>> 
>> Not really.
>> 
>> 
>>> If i disable ActiveSync eMailsync, all clients can synchronize Calendar, 
>>> Contacts, Tasks and Notes successfull.
>>> If I enable ActiveSync eMailsync then nothing gets synched anymore and the 
>>> log still shows:
>>> 
>>> 2014-02-25T08:41:47+01:00 INFO: [22403] Polling 
>>> Horde_Core_ActiveSync_Driver::_getMailFolders()
>>> 2014-02-25T08:41:47+01:00 INFO: [22405] Maximum memory usage for 
>>> ActiveSync request: 22832688 bytes.
>>> 2014-02-25T08:41:47+01:00 ERR: [22403] Problem loading mail folders from 
>>> IMAP server: User is not authorized for imp
>>> 2014-02-25T08:41:47+01:00 ERR: User is not authorized for imp
>>> 
>>> This is a freshly pulled 5.2.0-git from today (some minutes ago).
>>> 
>>> Any help is much appreciated.
>> 
>> This works fine for me locally. What authentication backend do you use? Do 
>> you see the authentication attempt at the IMAP server?
>
>
> ----- End message from Michael J Rubinsky <mrubinsk at horde.org> -----
>
> Hi Michael,
>
> thanks for your response.
>
> As already said in the first eMail, we use LDAP as authentication backend.
> Just a side note, our cyrus-imap server (v2.4.17) is using the same LDAP 
> directory for authentication.
>
> There is no login attempt neither successful nor failed appearing in the logs 
> when i enable emailsync and try to sync with ActiveSync.
> Seems like imp gets never invoked by an ActiveSync sync attempt.
>
> I have no clue what parts were changed that could be relevant for this maybe 
> it's some odd side effect.
> 5.1.6-git pulled at 7th of december 2013 was working fine.
>
> Today i rechecked everything, stopped all processes, cleared all caches and 
> so on, but the error remains the same.

Hi,

i've done further testing.

Changed auth backend from LDAP to IMAP using the same imap server as imp 
is using -> same error: 
ERR: Problem loading mail folders from IMAP server: User is not authorized for imp
ERR: User is not authorized for imp

Changed auth backend to application and set application to imp -> other 
error:
Polling Horde_Core_ActiveSync_Driver::_getMailFolders()
Creating new folder uuid for INBOX: F8e8b9818
Creating new folder uuid for INBOX.folder1: F4d44d15e
Creating new folder uuid for INBOX.folder2: F741a1d87
Creating new folder uuid for INBOX.folder2: F114cd6c1
Creating new folder uuid for INBOX.folder2: F3d0adf72
..... and so on

Looks not so bad, at least i get a folder list now.
I've no clue why this is not working when using LDAP or IMAP as auth 
backend.

Now, when the client attempts to sync messages i get the following errors:

2014-02-26T10:31:54+01:00 INFO: [16619] Horde_Core_ActiveSync_Driver::getMessage(INBOX, 407672)
2014-02-26T10:31:54+01:00 ERR: [16619] Message gone or error reading message from server: Not Found
2014-02-26T10:31:54+01:00 INFO: [16619] Updating state during change
2014-02-26T10:31:54+01:00 INFO: [16619] Horde_Core_ActiveSync_Driver::getMessage(INBOX, 407673)
2014-02-26T10:31:54+01:00 ERR: [16619] Message gone or error reading message from server: Not Found
2014-02-26T10:31:54+01:00 INFO: [16619] Updating state during change
2014-02-26T10:31:54+01:00 INFO: [16619] Horde_Core_ActiveSync_Driver::getMessage(INBOX, 407674)
2014-02-26T10:31:54+01:00 ERR: [16619] Message gone or error reading message from server: Not Found
2014-02-26T10:31:54+01:00 INFO: [16619] Updating state during change
..... and so on

I verfied that those messages are still on the server and all appear in 
the WebUI and with other mailclients.

Something is really broken, at least for me.

Any further ideas or hints?

Kind regards
Joerg

- -- 
The beginning is the most important part of the work.
 				-Plato
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.22 (FreeBSD)

iD8DBQFTDbmsSPOsGF+KA+MRAiW4AJ0XOC+LBGMDRfo5fWQqHSDpVTW7agCeIFdC
GHazpGQZo3URDi1eLOQIB5Q=
=PGaz
-----END PGP SIGNATURE-----