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

Michael J Rubinsky mrubinsk at horde.org
Tue Nov 15 16:23:01 UTC 2016 

Quoting john smith <johnsmith.125696454 at gmail.com>:

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

Fist off, realize that "mail server" is ambiguous. You mention  
"postfix" - this is a SMTP server which handles outgoing email. It  
would be perfectly reasonable that such a server is running on your  
webserver to handle e.g., any email that the system generates (such as  
logs, system errors etc...) to send to the root/webmaster/postmaster  
etc...

The log you show below is showing log entries from "dovecot" - which  
is your IMAP server. This is the server that (presumably) handles  
authentication for your horde install. I'm not sure what you changed  
when you reconfigured horde to point to the right mail server.

Anyway, the actual IMAP server in use would not affect the  
connectivity of ActiveSync. This is assuming that the user could  
authenticate successfully to either one and it is also assuming that  
you are creating a new account on the ActiveSync client and not using  
one that actually existed on the client prior to switching the IMAP  
server. However, it's hard to say what's happening since you don't  
include the full sync log.


> 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.
> --
> imp mailing list
> Frequently Asked Questions: http://wiki.horde.org/FAQ
> To unsubscribe, mail: imp-unsubscribe at lists.horde.org



-- 
mike
The Horde Project
http://www.horde.org
https://www.facebook.com/hordeproject
https://www.twitter.com/hordeproject
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 2007 bytes
Desc: S/MIME Signature
URL: <https://lists.horde.org/archives/imp/attachments/20161115/9903dd24/attachment-0001.bin>

More information about the imp mailing list