[horde] Activesync simultaneous requests
Michael J Rubinsky
mrubinsk at horde.org
Tue Jun 13 01:35:47 UTC 2017
Quoting Pascal Rigaux <pascal.rigaux at univ-paris1.fr>:
> Hi,
>
> I'm hitting a pb similar to "Activesync not closing connections"
> https://lists.horde.org/archives/horde/Week-of-Mon-20130318/047034.html .
>
> We have imapproxy + dovecot + horde5 (upgraded in 2017/01, so
> Horde_ActiveSync 2.37.4).
> For some users, there is sometime (once or twice a day for those
> users) we sometimes have the following error in dovecot logs:
>
> imap-login: Maximum number of connections from user+IP exceeded
> (mail_max_userip_connections=15)
>
> After some digging, it seems some Android really are doing many
> simultaneous requests. Below are some logs for 3 different behaviors.
> I've enabled activesync logging and looked:
> - at the concurrent ItemOperations: it was <Synchronize> <Folder> on
> different <FolderId>.
> - at the concurrent Ping, it could not find a reason for this
>
> Is it a normal behavior for ActiveSync?
Yes. The ITEMOPERATIONS requests are requesting specific data (usually
MIME parts) of an email. This can run concurrently to PING or SYNC
operations since those check for changes to the mailbox. This allows
the email data that wasn't returned in the initial SYNC response to be
downloaded while the server continues to check for changes. It also
reduces the amount of SYNC and/or PING connections the client has to
tear down and create, saving batter power.
There used to be code that closed the IMAP connection at certain
points in the request, but it was causing problems elsewhere. I'll
have to revisit this when I get the chance.
>
>
> (some info below, on each lines, there is the concurrent ActiveSync cmds):
>
> [Sun Jun 11 16:37:26 2017] 16:35:46=Ping 16:37:26=Sync
> [Sun Jun 11 16:37:26 2017] 16:35:46=Ping 16:37:26=Sync 16:37:26=Sync
> [Sun Jun 11 16:37:26 2017] 16:35:46=Ping 16:37:26=FolderSync
> 16:37:26=Sync 16:37:26=Sync
> [Sun Jun 11 16:37:26 2017] 16:35:46=Ping 16:37:26=FolderSync
> 16:37:26=Sync 16:37:26=Sync 16:37:26=Sync
> [Sun Jun 11 16:37:26 2017] 16:35:46=Ping 16:37:26=FolderSync
> 16:37:26=Sync 16:37:26=Sync 16:37:26=Sync
> [Sun Jun 11 16:37:27 2017] 16:35:46=Ping 16:37:26=FolderSync
> 16:37:26=Sync 16:37:26=Sync 16:37:27=Sync
> [Sun Jun 11 16:37:28 2017] 16:35:46=Ping 16:37:28=Sync
> [Sun Jun 11 16:37:28 2017] 16:35:46=Ping 16:37:28=Sync 16:37:28=Sync
> [Sun Jun 11 16:37:28 2017] 16:35:46=Ping 16:37:28=Sync 16:37:28=Sync
> 16:37:28=Sync
> [Sun Jun 11 16:37:31 2017] 16:35:46=Ping 16:37:31=Ping
> [Sun Jun 11 16:37:33 2017] 16:35:46=Ping 16:37:31=Ping 16:37:33=Sync
> [Sun Jun 11 16:37:34 2017] 16:35:46=Ping 16:37:31=Ping 16:37:33=Sync
> 16:37:34=FolderSync
> [Sun Jun 11 16:37:34 2017] 16:35:46=Ping 16:37:31=Ping 16:37:33=Sync
> 16:37:34=FolderSync 16:37:34=Sync
> [Sun Jun 11 16:37:34 2017] 16:35:46=Ping 16:37:31=Ping 16:37:33=Sync
> 16:37:34=FolderSync 16:37:34=Sync 16:37:34=Sync
> [Sun Jun 11 16:37:34 2017] 16:35:46=Ping 16:37:31=Ping 16:37:33=Sync
> 16:37:34=FolderSync 16:37:34=Sync 16:37:34=Sync 16:37:34=Sync
> [Sun Jun 11 16:37:34 2017] 16:35:46=Ping 16:37:31=Ping 16:37:33=Sync
> 16:37:34=FolderSync 16:37:34=Sync 16:37:34=Sync 16:37:34=Sync
> 16:37:34=Sync
> [Sun Jun 11 16:37:36 2017] 16:35:46=Ping 16:37:31=Ping 16:37:36=Sync
> [Sun Jun 11 16:37:36 2017] 16:35:46=Ping 16:37:31=Ping 16:37:36=Sync
> 16:37:36=Sync
> [Sun Jun 11 16:37:36 2017] 16:35:46=Ping 16:37:31=Ping 16:37:36=Sync
> 16:37:36=Sync
> [Sun Jun 11 16:37:36 2017] 16:35:46=Ping 16:37:31=Ping 16:37:36=Sync
> 16:37:36=Sync 16:37:36=Sync
> [Sun Jun 11 16:37:36 2017] 16:35:46=Ping 16:37:31=Ping 16:37:36=Sync
> 16:37:36=Sync 16:37:36=Sync 16:37:36=Sync
> [Sun Jun 11 16:37:38 2017] 16:35:46=Ping 16:37:31=Ping 16:37:38=Ping
> [Sun Jun 11 16:37:45 2017] 16:35:46=Ping 16:37:31=Ping 16:37:38=Ping
> 16:37:45=Sync
> [Sun Jun 11 16:37:45 2017] 16:35:46=Ping 16:37:31=Ping 16:37:38=Ping
> 16:37:45=Sync 16:37:45=Sync
> [Sun Jun 11 16:37:45 2017] 16:35:46=Ping 16:37:31=Ping 16:37:38=Ping
> 16:37:45=FolderSync 16:37:45=Sync 16:37:45=Sync
> [Sun Jun 11 16:37:45 2017] 16:35:46=Ping 16:37:31=Ping 16:37:38=Ping
> 16:37:45=FolderSync 16:37:45=Sync 16:37:45=Sync 16:37:45=Sync
> [Sun Jun 11 16:37:45 2017] 16:35:46=Ping 16:37:31=Ping 16:37:38=Ping
> 16:37:45=FolderSync 16:37:45=Sync 16:37:45=Sync 16:37:45=Sync
> 16:37:45=Sync
> [Sun Jun 11 16:37:45 2017] 16:35:46=Ping 16:37:31=Ping 16:37:38=Ping
> 16:37:45=FolderSync 16:37:45=Sync 16:37:45=Sync 16:37:45=Sync
> 16:37:45=Sync 16:37:45=Sync
>
>
> [Mon Jun 12 09:56:52 2017] 09:56:52=ItemOperations 09:56:52=Ping
> [Mon Jun 12 09:56:53 2017] 09:56:52=Ping 09:56:53=Ping
> [Mon Jun 12 09:56:53 2017] 09:56:52=Ping 09:56:53=ItemOperations
> 09:56:53=Ping
> [Mon Jun 12 09:56:54 2017] 09:56:52=Ping 09:56:53=Ping 09:56:54=Ping
> [Mon Jun 12 09:56:54 2017] 09:56:52=Ping 09:56:53=Ping
> 09:56:54=ItemOperations 09:56:54=Ping
> [Mon Jun 12 09:56:54 2017] 09:56:52=Ping 09:56:53=Ping 09:56:54=Ping
> 09:56:54=Ping
> [Mon Jun 12 09:56:55 2017] 09:56:52=Ping 09:56:53=Ping 09:56:54=Ping
> 09:56:54=Ping 09:56:55=ItemOperations
> [Mon Jun 12 09:56:55 2017] 09:56:52=Ping 09:56:53=Ping 09:56:54=Ping
> 09:56:54=Ping 09:56:55=Ping
> [Mon Jun 12 09:56:55 2017] 09:56:52=Ping 09:56:53=Ping 09:56:54=Ping
> 09:56:54=Ping 09:56:55=ItemOperations 09:56:55=Ping
> [Mon Jun 12 09:56:56 2017] 09:56:52=Ping 09:56:53=Ping 09:56:54=Ping
> 09:56:54=Ping 09:56:55=Ping 09:56:56=Ping
> [Mon Jun 12 09:56:56 2017] 09:56:52=Ping 09:56:53=Ping 09:56:54=Ping
> 09:56:54=Ping 09:56:55=Ping 09:56:56=ItemOperations 09:56:56=Ping
> [Mon Jun 12 09:56:57 2017] 09:56:52=Ping 09:56:53=Ping 09:56:54=Ping
> 09:56:54=Ping 09:56:55=Ping 09:56:56=Ping 09:56:57=ItemOperations
> [Mon Jun 12 09:56:58 2017] 09:56:52=Ping 09:56:53=Ping 09:56:54=Ping
> 09:56:54=Ping 09:56:55=Ping 09:56:56=Ping 09:56:58=Ping
> [Mon Jun 12 09:56:58 2017] 09:56:52=Ping 09:56:53=Ping 09:56:54=Ping
> 09:56:54=Ping 09:56:55=Ping 09:56:56=Ping 09:56:58=ItemOperations
> 09:56:58=Ping
> [Mon Jun 12 09:56:59 2017] 09:56:52=Ping 09:56:53=Ping 09:56:54=Ping
> 09:56:54=Ping 09:56:55=Ping 09:56:56=Ping 09:56:58=Ping
> 09:56:59=ItemOperations
> [Mon Jun 12 09:56:59 2017] 09:56:52=Ping 09:56:53=Ping 09:56:54=Ping
> 09:56:54=Ping 09:56:55=Ping 09:56:56=Ping 09:56:58=Ping
> 09:56:59=ItemOperations
> [Mon Jun 12 09:57:00 2017] 09:56:52=Ping 09:56:53=Ping 09:56:54=Ping
> 09:56:54=Ping 09:56:55=Ping 09:56:56=Ping 09:56:58=Ping
> 09:57:00=ItemOperations
> [Mon Jun 12 09:57:01 2017] 09:56:52=Ping 09:56:53=Ping 09:56:54=Ping
> 09:56:54=Ping 09:56:55=Ping 09:56:56=Ping 09:56:58=Ping
> 09:57:01=ItemOperations
> [Mon Jun 12 09:57:01 2017] 09:56:52=Ping 09:56:53=Ping 09:56:54=Ping
> 09:56:54=Ping 09:56:55=Ping 09:56:56=Ping 09:56:58=Ping
> 09:57:01=ItemOperations
> [Mon Jun 12 09:58:03 2017] 09:56:58=Ping 09:58:03=Ping
>
> [Sun Jun 11 15:16:15 2017] 15:16:15=Ping
> [Sun Jun 11 15:16:31 2017] 15:16:15=Ping 15:16:31=Sync
> [Sun Jun 11 15:16:31 2017] 15:16:15=Ping 15:16:31=Sync 15:16:31=Sync
> [Sun Jun 11 15:16:33 2017] 15:16:15=Ping 15:16:33=Ping
> [Sun Jun 11 15:16:37 2017] 15:16:15=Ping 15:16:33=Ping
> 15:16:37=ItemOperations
> [Sun Jun 11 15:16:37 2017] 15:16:15=Ping 15:16:33=Ping
> 15:16:37=ItemOperations 15:16:37=ItemOperations
> [Sun Jun 11 15:16:37 2017] 15:16:15=Ping 15:16:33=Ping
> 15:16:37=ItemOperations 15:16:37=ItemOperations
> 15:16:37=ItemOperations
> [Sun Jun 11 15:16:37 2017] 15:16:15=Ping 15:16:33=Ping
> 15:16:37=ItemOperations 15:16:37=ItemOperations
> 15:16:37=ItemOperations 15:16:37=ItemOperations
> [Sun Jun 11 15:16:37 2017] 15:16:15=Ping 15:16:33=Ping
> 15:16:37=ItemOperations 15:16:37=ItemOperations
> 15:16:37=ItemOperations 15:16:37=ItemOperations
> 15:16:37=ItemOperations
> [Sun Jun 11 15:16:37 2017] 15:16:15=Ping 15:16:33=Ping
> 15:16:37=ItemOperations 15:16:37=ItemOperations
> 15:16:37=ItemOperations
> [Sun Jun 11 15:16:38 2017] 15:16:15=Ping 15:16:33=Ping
> 15:16:38=ItemOperations
> [Sun Jun 11 15:16:38 2017] 15:16:15=Ping 15:16:33=Ping
> 15:16:38=ItemOperations 15:16:38=ItemOperations
> [Sun Jun 11 15:16:38 2017] 15:16:15=Ping 15:16:33=Ping
> 15:16:38=ItemOperations 15:16:38=ItemOperations
> 15:16:38=ItemOperations
> [Sun Jun 11 15:16:39 2017] 15:16:15=Ping 15:16:33=Ping
> 15:16:38=ItemOperations 15:16:38=ItemOperations
> 15:16:39=ItemOperations
> [Sun Jun 11 15:16:39 2017] 15:16:15=Ping 15:16:33=Ping
> 15:16:38=ItemOperations 15:16:38=ItemOperations
> 15:16:39=ItemOperations 15:16:39=ItemOperations
> ...
> [Sun Jun 11 15:16:40 2017] 15:16:15=Ping 15:16:33=Ping
> 15:16:39=ItemOperations 15:16:39=ItemOperations
> 15:16:39=ItemOperations 15:16:39=ItemOperations
> 15:16:39=ItemOperations 15:16:39=ItemOperations
> 15:16:39=ItemOperations 15:16:39=ItemOperations
> 15:16:39=ItemOperations 15:16:39=ItemOperations
> 15:16:39=ItemOperations 15:16:39=ItemOperations
> 15:16:39=ItemOperations 15:16:40=ItemOperations
> 15:16:40=ItemOperations 15:16:40=ItemOperations
> 15:16:40=ItemOperations 15:16:40=ItemOperations
> 15:16:40=ItemOperations 15:16:40=ItemOperations
> 15:16:40=ItemOperations
> [Sun Jun 11 15:16:41 2017] 15:16:15=Ping 15:16:33=Ping
> 15:16:39=ItemOperations 15:16:39=ItemOperations
> 15:16:39=ItemOperations 15:16:39=ItemOperations
> 15:16:39=ItemOperations 15:16:40=ItemOperations
> 15:16:40=ItemOperations 15:16:40=ItemOperations
> 15:16:40=ItemOperations 15:16:40=ItemOperations
> 15:16:40=ItemOperations 15:16:40=ItemOperations
> 15:16:41=ItemOperations 15:16:41=ItemOperations
> 15:16:41=ItemOperations 15:16:41=ItemOperations
> 15:16:41=ItemOperations
> [Sun Jun 11 15:16:49 2017] 15:16:33=Ping 15:16:49=Sync
> [Sun Jun 11 15:16:51 2017] 15:16:33=Ping 15:16:51=Ping
>
>
>
> Method to obtain the info above: activate apache ForensicLog, then
> process it with:
>
> #!/usr/bin/perl
> use POSIX qw(strftime);
> ($user) = @ARGV;
>
> open(my $F, "<", "/var/log/apache2/echange-forensic.log");
> while (<$F>) {
> if (($id) = /^-(.*)/) {
> delete $in{$id};
> } elsif (/User=$user/ and ($id, $cmd) = /^\+(.*?)\|.*Cmd=(\w+)/) {
> my (undef, $t, undef) = split ":", $id;
> $in{$id} = strftime("%H:%M:%S", localtime(hex($t))) . "=" . $cmd;
> my $time = localtime(hex($t));
> print "[$time] " . join(' ', sort values %in) . "\n";
> }
> }
>
>
>
>
> --
> Horde mailing list
> Frequently Asked Questions: http://horde.org/faq/
> To unsubscribe, mail: horde-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: not available
Type: application/pgp-keys
Size: 9272 bytes
Desc: PGP Public Key
URL: <https://lists.horde.org/archives/horde/attachments/20170613/12603736/attachment-0002.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 821 bytes
Desc: PGP Digital Signature
URL: <https://lists.horde.org/archives/horde/attachments/20170613/12603736/attachment-0003.bin>
More information about the horde
mailing list