[horde] Activesync simultaneous requests

[Pascal Rigaux]

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?


(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";
     }
}