[imp] I can't add a server to iPhone

john smith johnsmith.125696454 at gmail.com
Tue Nov 15 16:06:03 UTC 2016 

I have my Horde installation working just the way I need it, except for the
mobile devices.  Something weird happened with my Horde, and I only noticed
it by chance.

My webserver is 192.168.1.14.  My mail server is 192.168.1.13.  Traffic
from outside hits the router and ports 80 and 443 are sent to the
webserver.  IMAP, SMTP etc are sent to the mail server.

I add an account on my iPhone, open ssh sessions to both my webserver and
my mail server.  But distracted by someone in the office, I run `tail -f
/var/log/maillog` on my webserver, rather than on my mail server.  Only
when I see some of my previously sent e-mails and realize that I am in fact
looking at maillog on a webserver, do I see that something is wrong.
Postfix is running on that server.  I don't even remember *installing* it
on that server, let alone telling it to run!  And I definitely know that in
the past, I have tailed the maillog on the mail server, and that my e-mails
have worked.

I stop postfix on the mail server, reconfigure the horde to consider
192.168.1.13 as the mail server, and that seems to fix it.

Now I try to add an Exchange account on an iPhone.  On the webserver, I
see:

***
Nov 14 12:07:02 www HORDE: [imp] Login success for john (XXX.XXX.XXX.XXX)
to {imap://192.168.1.13/} [pid 6958 on line 157 of
"/usr/share/horde/imp/lib/Auth.php"]
***

In the mail server logs, I see:

***
Nov 14 12:12:48 mail dovecot: imap-login: Login: user=<john>, method=PLAIN,
rip=192.168.1.14, lip=192.168.1.13, mpid=18233, TLS
Nov 14 12:12:48 mail dovecot: imap(john): Disconnected: Logged out
bytes=129/910
***

Yet on the iPhone, I see 'connection failed'.

Is there something wrong with my Active Sync settings?  If I enable
debugging, I see:

***
2016-11-14T12:28:42+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7112]
Initializing state for collection: INBOX, synckey: {5829ada8-85c8-4679-badb-
1b75c0a8010e}1
2016-11-14T12:28:42+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7112]
Loading state for synckey {5829ada8-85c8-4679-badb-1b75c0a8010e}1
2016-11-14T12:28:42+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO WARN: [7112]
Could not find state for synckey {5829ada8-85c8-4679-badb-1b75c0a8010e}1.
2016-11-14T12:28:42+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO NOTICE: [7112]
State not found for Fbc407fc0. Continuing.
2016-11-14T12:28:42+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7112] O
<Ping:Ping>
2016-11-14T12:28:42+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7112] O
<Ping:Status>
2016-11-14T12:28:42+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7112]
O    3
2016-11-14T12:28:42+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7112] O
</Ping:Status>
2016-11-14T12:28:42+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7112] O
</Ping:Ping>
2016-11-14T12:28:42+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7112]
Maximum memory usage for ActiveSync request: 20447232 bytes.
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113]
Horde_Core_ActiveSync_Driver::authenticate() attempt for john
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113] SYNC
request received for user john
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113]
Device entry exists for JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO, updating
userAgent, version, and supported.
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113]
Request being handled for device: JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO,
Supporting protocol version: 14.0, Using Horde_ActiveSync v2.37.2
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113] GET
VARIABLES: Array
(
    [User] => john
    [DeviceId] => JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO
    [DeviceType] => iPhone
    [Cmd] => Sync
)

2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113]
Handling SYNC command.
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113]
Checking policykey for device: JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO user: john
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113]
Stored key: 8111332433
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113]
Policykey: 8111332433 verified.
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113]
Creating new Horde_ActiveSync_SyncCache.
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113] I
<Synchronize>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113] I
<Folders>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I    <Folder>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I     <SyncKey>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I       0
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I     </SyncKey>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I     <FolderId>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I       Fbc407fc0
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I     </FolderId>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I     <Options>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I      <FilterType>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I        5
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I      </FilterType>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I      <MIMETruncation>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I        1
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I      </MIMETruncation>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I      <MIMESupport>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I        0
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I      </MIMESupport>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I      <AirSyncBase:BodyPreference>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I       <AirSyncBase:Type>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I         1
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I       </AirSyncBase:Type>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I       <AirSyncBase:TruncationSize>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I         500
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I       </AirSyncBase:TruncationSize>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I      </AirSyncBase:BodyPreference>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I     </Options>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
I    </Folder>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113]
Obtaining collection class of Email for collection id Fbc407fc0
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113]
Collection added to collection handler: collection: INBOX, synckey: NONE.
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113] I
</Folders>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113] I
</Synchronize>
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113]
Loading default OPTIONS for Fbc407fc0 collection.
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113]
Clearing all collection synckeys from the cache.
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: Have
syncable collections
2016-11-14T12:28:50+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113]
Replacing SYNC_CACHE entry for user john and device
JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO: a:11:{s:18:"confirmed_
synckeys";a:0:{}s:17:"lasthbsyncstarted";i:1479126522;s:17:"
lastsyncendnormal";i:1479126440;s:9:"timestamp";s:
10:"1479126530";s:4:"wait";b:0;s:10:"hbinterval";s:3:"900";
s:7:"folders";a:16:{s:9:"Te619e3f6";a:3:{s:5:"class";s:
5:"Tasks";s:8:"serverid";s:7:"@Tasks@";s:4:"type";i:7;}s:2:"
RI";a:3:{s:5:"class";s:5:"Email";s:8:"serverid";s:2:"RI"
;s:4:"type";i:19;}s:6:"OUTBOX";a:3:{s:5:"class";s:5:"Email";
s:8:"serverid";s:6:"OUTBOX";s:4:"type";i:6;}s:9:"N63d01f40";
a:3:{s:5:"class";s:5:"Notes";s:8:"serverid";s:7:"@Notes@";
s:4:"type";i:10;}s:9:"Ffe2f65fa";a:3:{s:5:"class";s:
5:"Email";s:8:"serverid";s:5:"Trash";s:4:"type";i:4;}s:9:"
Ff0dc4f87";a:3:{s:5:"class";s:5:"Email";s:8:"serverid";s:4:"
Sent";s:4:"type";i:5;}s:9:"Fd3ba223e";a:3:{s:5:"class";s:
5:"Email";s:8:"serverid";s:9:"Templates";s:4:"type";i:12;}s:
9:"Fbc407fc0";a:3:{s:5:"class";s:5:"Email";s:8:"serverid";s:
5:"INBOX";s:4:"type";i:2;}s:9:"Fb917ad3a";a:3:{s:5:"class";
s:5:"Email";s:8:"serverid";s:7:"Archive";s:4:"type";i:12;}
s:9:"Fa4cf7a2c";a:3:{s:5:"class";s:5:"Email";s:8:"serverid";s:13:"Sent
Messages";s:4:"type";i:12;}s:9:"F8392d0cd";a:3:{s:5:"class"
;s:5:"Email";s:8:"serverid";s:16:"Deleted Messages";s:4:"type";i:12;}s:
9:"F794fff62";a:3:{s:5:"class";s:5:"Email";s:8:"serverid";s:
6:"Drafts";s:4:"type";i:3;}s:9:"F32c45cf3";a:3:{s:5:"class"
;s:5:"Email";s:8:"serverid";s:4:"Junk";s:4:"type";i:12;}s:9:
"F0ea4b8ea";a:3:{s:5:"class";s:5:"Email";s:8:"serverid";s:
8:"Unwanted";s:4:"type";i:12;}s:9:"C1e5db894";a:3:{s:5:"
class";s:8:"Contacts";s:8:"serverid";s:10:"@Contacts@";s:
4:"type";i:9;}s:9:"Ad8208445";a:3:{s:5:"class";s:8:"
Calendar";s:8:"serverid";s:10:"@Calendar@";s:4:"type";i:8;}}
s:9:"hierarchy";s:39:"{58297605-f860-4ba0-a568-15cac0a8010e}1";s:11:"
collections";a:5:{s:9:"Fbc407fc0";a:11:{s:5:"class";
s:5:"Email";s:10:"windowsize";i:100;s:10:"filtertype";s:1:"
5";s:11:"mimesupport";s:1:"0";s:14:"mimetruncation";i:4096;
s:8:"conflict";i:1;s:9:"bodyprefs";a:1:{i:1;a:2:{s:4:"type";s:1:"1";s:14:"
truncationsize";s:3:"500";}}s:8:"serverid";s:5:"INBOX";s:11:
"lastsynckey";s:39:"{5829ada8-85c8-4679-badb-1b75c0a8010e}1"
;s:8:"pingable";b:1;s:7:"synckey";s:1:"0";}s:9:"
Ad8208445";a:9:{s:5:"class";s:8:"Calendar";s:10:"windowsize"
;s:2:"25";s:10:"filtertype";s:1:"5";s:11:"mimesupport";i:0;
s:8:"conflict";i:1;s:9:"bodyprefs";a:1:{i:1;a:2:{s:4:"type";s:1:"1";s:14:"
truncationsize";s:5:"32768";}}s:8:"serverid";s:10:"@Calendar@
";s:11:"lastsynckey";s:39:"{58297607-43b0-4a61-88b5-15d4c0a8010e}4";s:8:"
pingable";b:1;}s:9:"N63d01f40";a:9:{s:5:"class";s:5:"Notes";
s:10:"windowsize";s:2:"25";s:10:"filtertype";s:1:"0";s:11:"
mimesupport";i:0;s:8:"conflict";i:1;s:9:"bodyprefs";
a:1:{i:2;a:2:{s:4:"type";s:1:"2";s:14:"truncationsize";s:5:"
32768";}}s:8:"serverid";s:7:"@Notes@";s:11:"lastsynckey";s:
39:"{58297608-07ec-4c92-a8de-15d2c0a8010e}2";s:8:"pingable"
;b:1;}s:9:"Ff0dc4f87";a:10:{s:5:"class";s:5:"Email";s:10:"
windowsize";s:2:"25";s:10:"filtertype";s:1:"5";s:11:"
mimesupport";s:1:"0";s:14:"mimetruncation";i:4096;s:8:"
conflict";i:1;s:9:"bodyprefs";a:1:{i:1;a:2:{s:4:"type";s:1:"
1";s:14:"truncationsize";s:3:"500";}}s:8:"serverid";s:4:"
Sent";s:11:"lastsynckey";s:39:"{5829ada5-7168-497d-9122-
1b75c0a8010e}1";s:8:"pingable";b:1;}s:9:"Te619e3f6";a:9:{s:
5:"class";s:5:"Tasks";s:10:"windowsize";s:2:"25";s:10:"
filtertype";s:1:"0";s:11:"mimesupport";i:0;s:8:"
conflict";i:1;s:9:"bodyprefs";a:1:{i:1;a:2:{s:4:"type";s:1:"
1";s:14:"truncationsize";s:5:"32768";}}s:8:"serverid";s:7:"@Tasks@
";s:11:"lastsynckey";s:40:"{5829760b-a690-47b7-b881-15c7c0a8010e}12";s:8:"
pingable";b:1;}}s:13:"pingheartbeat";b:0;s:14:"synckeycounter";a:0:{}}
2016-11-14T12:28:51+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113] All
synckeys confirmed. Continuing with SYNC
2016-11-14T12:28:51+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113]
Completed parsing incoming request. Peak memory usage: 20447232.
2016-11-14T12:28:51+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113] O
<Synchronize>
2016-11-14T12:28:51+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113] O
<Status>
2016-11-14T12:28:51+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113]
O    1
2016-11-14T12:28:51+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO DEBUG: [7113] O
</Status>
2016-11-14T12:28:51+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO INFO: [7113]
Initializing state for collection: INBOX, synckey: 0
2016-11-14T12:28:51+00:00 JKKVXXXXXXXXXXXXXXXL8GTFGNQD5DO NOTICE: [7113]
Horde_ActiveSync_State_Base::loadState: clearing folder
***

That looks to me like the request is actually succeeding.  But I cannot get
e-mail (although calendar and tasks work).

Please help.

More information about the imp mailing list