[horde] ActiveSync-ERR: Problem loading mail folders from IMAP server: User is not authorized

"Michael Hübner" michael.huebner at gmx.net
Fri Jan 4 14:56:03 UTC 2013 

As in other topics similiar issues are discussed I opened this ticket, as I didn't find an open on for this topic:

http://bugs.horde.org/ticket/11933

Regards,
Michael

-------- Original-Nachricht --------
Datum: Tue, 01 Jan 2013 21:17:54 +0100
Von: "Michael Hübner" <michael.huebner at gmx.net>
An: horde at lists.horde.org
Betreff: Re: [horde] ActiveSync-ERR: Problem loading mail folders from IMAP server: User is not authorized

I enabled IMAP-Server Logging in IMPs-backends setting and get following logfile:

>> Tue, 01 Jan 2013 21:09:36 +0100
S: * OK [CAPABILITY IMAP4rev1 UIDPLUS CHILDREN NAMESPACE THREAD=ORDEREDSUBJECT THREAD=REFERENCES SORT QUOTA AUTH=PLAIN IDLE STARTTLS XMAGICTRASH] Courier-IMAP ready. C$
C: 1 STARTTLS
S: 1 OK Begin SSL/TLS negotiation now.
C: 2 CAPABILITY
S: * CAPABILITY IMAP4rev1 UIDPLUS CHILDREN NAMESPACE THREAD=ORDEREDSUBJECT THREAD=REFERENCES SORT QUOTA AUTH=PLAIN IDLE XMAGICTRASH
S: 2 OK CAPABILITY completed
C: [LOGIN Command - username: testuser]
S: 3 OK LOGIN Ok.
C: 4 CAPABILITY
S: * CAPABILITY IMAP4rev1 UIDPLUS CHILDREN NAMESPACE THREAD=ORDEREDSUBJECT THREAD=REFERENCES SORT QUOTA AUTH=PLAIN IDLE XMAGICTRASH
S: 4 OK CAPABILITY completed
C: 5 LOGOUT
S: * BYE Courier-IMAP server shutting down
S: 5 OK LOGOUT completed

Is this the correct output I should be expecting, or is my imap-server missing any capabilities?

The IMAP-Server is saying Login was okay, but horde is saying User is not authorized....

2013-01-01T21:09:35+01:00 DEBUG: Client did not provide authentication data.
2013-01-01T21:09:36+01:00 INFO: [25082] Horde_Core_ActiveSync_Driver::authenticate() attempt for testuser
2013-01-01T21:09:36+01:00 DEBUG: [1240672483] FOLDERSYNC request received for user testuser
2013-01-01T21:09:36+01:00 DEBUG: [1240672483] Device entry does not exist, creating it.
2013-01-01T21:09:36+01:00 DEBUG: [1240672483] Device entry does not exist for user testuser, creating it.
2013-01-01T21:09:36+01:00 INFO: Request being handled for device: 1240672483 Supporting protocol version: 12.0
2013-01-01T21:09:36+01:00 INFO: [1240672483] Handling FOLDERSYNC command.
2013-01-01T21:09:36+01:00 DEBUG: [1240672483] Checking policykey for device: 0 user: testuser
2013-01-01T21:09:36+01:00 DEBUG: Policykey: 0 verified.
2013-01-01T21:09:36+01:00 DEBUG: I  <FolderHierarchy:FolderSync>
2013-01-01T21:09:36+01:00 DEBUG: I   <FolderHierarchy:SyncKey>
2013-01-01T21:09:36+01:00 DEBUG: I    0
2013-01-01T21:09:36+01:00 DEBUG: I   </FolderHierarchy:SyncKey>
2013-01-01T21:09:36+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync] syncKey: 0
2013-01-01T21:09:36+01:00 DEBUG: [25082] Resetting device state.
2013-01-01T21:09:36+01:00 DEBUG: Adding new SYNC_CACHE entry for user testuser and device 1240672483: a:12:{s:18:"confirmed_synckeys";a:0:{}s:17:"lasthbsyncstarted";$
2013-01-01T21:09:36+01:00 DEBUG: I  </FolderHierarchy:FolderSync>
2013-01-01T21:09:36+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync] newSyncKey: {50e34280-2a98-46ae-adcc-61fa4e2e75c3}1
2013-01-01T21:09:36+01:00 DEBUG: [25082] Initializing folder diff engine
2013-01-01T21:09:36+01:00 DEBUG: [25082] Horde_Core_ActiveSync_Driver::getFolderList()
2013-01-01T21:09:36+01:00 DEBUG: [25082] Polling Horde_Core_ActiveSync_Driver::_getMailFolders()
2013-01-01T21:09:36+01:00 ERR: [25082] Problem loading mail folders from IMAP server: User is not authorized
2013-01-01T21:09:36+01:00 ERR: User is not authorized
2013-01-01T21:09:36+01:00 DEBUG: [25082] No folder changes found.
2013-01-01T21:09:36+01:00 DEBUG: O  <FolderHierarchy:FolderSync>
2013-01-01T21:09:36+01:00 DEBUG: O   <FolderHierarchy:Status>
2013-01-01T21:09:36+01:00 DEBUG: O    1
2013-01-01T21:09:36+01:00 DEBUG: O   <FolderHierarchy:Status/>
2013-01-01T21:09:36+01:00 DEBUG: O   <FolderHierarchy:SyncKey>
2013-01-01T21:09:36+01:00 DEBUG: O    0
2013-01-01T21:09:36+01:00 DEBUG: O   <FolderHierarchy:SyncKey/>
2013-01-01T21:09:36+01:00 DEBUG: O   <FolderHierarchy:Changes>
2013-01-01T21:09:36+01:00 DEBUG: O    <FolderHierarchy:Count>
2013-01-01T21:09:36+01:00 DEBUG: O     0
2013-01-01T21:09:36+01:00 DEBUG: O    <FolderHierarchy:Count/>
2013-01-01T21:09:36+01:00 DEBUG: O   <FolderHierarchy:Changes/>
2013-01-01T21:09:36+01:00 DEBUG: O  <FolderHierarchy:FolderSync/>
2013-01-01T21:09:36+01:00 INFO: [25082] User testuser logged off

Regards,
Michael

-------- Original-Nachricht --------
> Datum: Fri, 28 Dec 2012 11:53:45 +0100
> Von: "Michael Hübner" <michael.huebner at gmx.net>
> An: horde at lists.horde.org
> Betreff: Re: [horde] ActiveSync-ERR: Problem loading mail folders from IMAP server: User is not authorized

> I did some more digging, and find it really confusing, courier-imap says
> login was successfull wenn doing the test with testexchangeconnectivity.com:
> 
> Dec 28 11:37:19 testserver imapd: Connection, ip=[::ffff:127.0.0.1]
> Dec 28 11:37:19 testserver authdaemond: received auth request,
> service=imap, authtype=login
> Dec 28 11:37:19 testserver authdaemond: authpam: trying this module
> Dec 28 11:37:19 testserver authdaemond: authpam: sysusername=testuser,
> sysuserid=<null>, sysgroupid=1000, homedir=/var/mail/testuser,
> address=testuser, full$
> Dec 28 11:37:19 testserver authdaemond: pam_service=imap,
> pam_username=testuser
> Dec 28 11:37:19 testserver authdaemond: dopam successful
> Dec 28 11:37:19 testserver authdaemond: Authenticated:
> sysusername=testuser, sysuserid=<null>, sysgroupid=1000, homedir=/var/mail/testuser,
> address=testuser$
> Dec 28 11:37:19 testserver imapd: LOGIN, user=testuser,
> ip=[::ffff:127.0.0.1], port=[33127], protocol=IMAP
> Dec 28 11:37:19 testserver imapd: LOGOUT, user=testuser,
> ip=[::ffff:127.0.0.1], headers=0, body=0, rcvd=24, sent=252, time=0, starttls=1
> 
> 
> Still horde-activesynclog says login was not successfull:
> 
> 2012-12-28T11:37:19+01:00 DEBUG: Client did not provide authentication
> data.
> 2012-12-28T11:37:19+01:00 INFO: [27137]
> Horde_Core_ActiveSync_Driver::authenticate() attempt for testuser
> 2012-12-28T11:37:19+01:00 DEBUG: [1589099912] FOLDERSYNC request received
> for user testuser
> 2012-12-28T11:37:19+01:00 DEBUG: [1589099912] loadDeviceInfo: testuser
> 2012-12-28T11:37:19+01:00 INFO: Request being handled for device:
> 1589099912 Supporting protocol version: 12.0
> 2012-12-28T11:37:19+01:00 INFO: [1589099912] Handling FOLDERSYNC command.
> 2012-12-28T11:37:19+01:00 DEBUG: [1589099912] Checking policykey for
> device: 0 user: testuser
> 2012-12-28T11:37:19+01:00 DEBUG: Policykey: 0 verified.
> 2012-12-28T11:37:19+01:00 DEBUG: I  <FolderHierarchy:FolderSync>
> 2012-12-28T11:37:19+01:00 DEBUG: I   <FolderHierarchy:SyncKey>
> 2012-12-28T11:37:19+01:00 DEBUG: I    0
> 2012-12-28T11:37:19+01:00 DEBUG: I   </FolderHierarchy:SyncKey>
> 2012-12-28T11:37:19+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
> syncKey: 0
> 2012-12-28T11:37:19+01:00 DEBUG: [27137] Resetting device state.
> 2012-12-28T11:37:19+01:00 DEBUG: Replacing SYNC_CACHE entry for user
> testuser and device 1589099912:
> a:12:{s:18:"confirmed_synckeys";a:0:{}s:17:"lasthbsyncstarted";b$
> 2012-12-28T11:37:19+01:00 DEBUG: I  </FolderHierarchy:FolderSync>
> 2012-12-28T11:37:19+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
> newSyncKey: {50dd765f-fd44-4682-853f-6a014e2e75c3}1
> 2012-12-28T11:37:19+01:00 DEBUG: [27137] Initializing folder diff engine
> 2012-12-28T11:37:19+01:00 DEBUG: [27137]
> Horde_Core_ActiveSync_Driver::getFolderList()
> 2012-12-28T11:37:19+01:00 DEBUG: [27137] Polling
> Horde_Core_ActiveSync_Driver::_getMailFolders()
> 2012-12-28T11:37:19+01:00 ERR: [27137] Problem loading mail folders from
> IMAP server: User is not authorized
> 2012-12-28T11:37:19+01:00 ERR: User is not authorized
> 2012-12-28T11:37:19+01:00 DEBUG: [27137] No folder changes found.
> 2012-12-28T11:37:19+01:00 DEBUG: O  <FolderHierarchy:FolderSync>
> 2012-12-28T11:37:19+01:00 DEBUG: O   <FolderHierarchy:Status>
> 2012-12-28T11:37:19+01:00 DEBUG: O    1
> 2012-12-28T11:37:19+01:00 DEBUG: O   <FolderHierarchy:Status/>
> 2012-12-28T11:37:19+01:00 DEBUG: O   <FolderHierarchy:SyncKey>
> 2012-12-28T11:37:19+01:00 DEBUG: O    0
> 2012-12-28T11:37:19+01:00 DEBUG: O   <FolderHierarchy:SyncKey/>
> 2012-12-28T11:37:19+01:00 DEBUG: O   <FolderHierarchy:Changes>
> 2012-12-28T11:37:19+01:00 DEBUG: O    <FolderHierarchy:Count>
> 2012-12-28T11:37:19+01:00 DEBUG: O     0
> 2012-12-28T11:37:19+01:00 DEBUG: O    <FolderHierarchy:Count/>
> 2012-12-28T11:37:19+01:00 DEBUG: O   <FolderHierarchy:Changes/>
> 2012-12-28T11:37:19+01:00 DEBUG: O  <FolderHierarchy:FolderSync/>
> 2012-12-28T11:37:19+01:00 INFO: [27137] User testuser logged off
> 
> I just did a pear-upgrade and got the latest update of activesync, it
> doesnt help unfortunately.
> 
> I would greatly appreciate any advice.
> 
> Regards,
> Michael
> 
> 
> -------- Original-Nachricht --------
> > Datum: Thu, 27 Dec 2012 01:03:14 +0100
> > Von: "Michael Hübner" <michael.huebner at gmx.net>
> > An: horde at lists.horde.org
> > Betreff: [horde] ActiveSync-ERR: Problem loading mail folders from IMAP
> server: User is not authorized
> 
> > Hello,
> > 
> > I hope all had a merry christmas. I'm a new user and trying to set up a
> > active-sync server with horde (fresh install from today) to connect a
> > christmas present (HTC Wildfire S) to a private (single-user)
> emailserver.
> > I am running Apache/2.2.22 (Debian) DAV/2 PHP/5.4.4-10 mod_ssl/2.2.22
> > OpenSSL/1.0.1c and managed to set up horde with imp - the web interface
> is
> > running fine. 
> > 
> > 
> > But I am not able to display any message folders on the mobile device -
> I
> > do not see any mail in the inbox. Sending e-mail with the mobile device
> and
> > the MS-Exchange profile works fine (althoug I do get an error from the
> > device as the "sent" folder doesn't get updated). 
> > 
> >  testexchangeconnectivity.com gives following error (in German - sorry):
> > 	Es wird versucht, einen OPTIONS-Befehl an den Server zu senden.
> >  	Die OPTIONS-Antwort wurde erfolgreich empfangen und ist gültig.
> > 
> > 	Es wird versucht, den Befehl 'FolderSync' in der Exchange
> > ActiveSync-Sitzung auszuführen.
> >  	Fehler beim Testen des Befehls 'FolderSync'.
> >  	
> > 	Weitere Details
> >  	Kein Posteingangsordner in der XML-Antwort gefunden.
> > 
> > I enabled error logging on my server, horde logs gives following errors:
> > DEBUG: [26431] Initializing folder diff engine
> > DEBUG: Horde_Core_ActiveSync_Driver::getFolderList()
> > DEBUG: Polling Horde_Core_ActiveSync_Driver::_getMailFolders()
> > ERR: Problem loading mail folders from IMAP server: User is not
> authorized
> > ERR: User is not authorized
> > DEBUG: [26431] No folder changes found.
> > 
> > 
> > I did read the note "RewriteRule .* -
> > [E=HTTP_MS_ASPROTOCOLVERSION:%{HTTP:Ms-Asprotocolversion}] etc." info on
> the horde-wiki but that doesnt seem to
> > help or change anything.
> > 
> > I am really struggeling where the problem could be, if anybody could
> give
> > me a hint where to look for I would be very glad, mailing list / web
> search
> > didnt help me.
> > 
> > Best regards,
> > Michael Huebner
> > 
> > -- 
> > Horde mailing list
> > Frequently Asked Questions: http://horde.org/faq/
> > To unsubscribe, mail: horde-unsubscribe at lists.horde.org
> -- 
> Horde mailing list
> Frequently Asked Questions: http://horde.org/faq/
> To unsubscribe, mail: horde-unsubscribe at lists.horde.org

More information about the horde mailing list