z-push 2.5.1: Heartbeat interval



  • Hi all,
    Looking at the server logs, my ping my z-push server every 5 mins. My setup is z-push 2.5.1 with Kopano on Debian 10 with apache 2.4 and php 7.3 behind HAProxy.

    According to the specs, EAS should have adaptive heartbeat interval up to 28 minutes. Mine seems to be fixed at 5 min. Is this an error in my setup?

    I have previously worked with horde and had a heartbeat of 1440 secs. with a similar setup.

    Is there any way to experience with longer heartbeats? What heartbeat duration have other people in this forum with z-push?
    Thank you,
    alex


  • Kopano

    Hi @alex1452,

    @alex1452 said in z-push 2.5.1: Heartbeat interval:

    with a similar setup.

    have you checked if timeouts in your reverse proxy (haproxy), your webserver (apache) or php are closing the connection early?



  • Hi @fbartels,

    I have the following timeouts in my haproxy.conf

    	timeout connect 10s
    	timeout client 30m
    	timeout server 30m
    	timeout http-keep-alive 30m
    

    In have deliberately not used PHP-fpm but instead mod-php with Apache 2.4 to avoid timeout issues.

    Do you have any suggestions where I should start looking for timeouts?

    Thank you,
    alex


  • Kopano

    Hi @alex1452,

    if I remember correctly Apache would log this in its error.log. Not sure where haproxy would log this.



  • Hi @fbartels,

    I have checked apache logs there are no timeouts. Will set-up more logging for HApoxy and report back.

    Thank you,
    alex



  • Hi @fbartels,

    As stated earlier, I have no errors on the apache log. However the HAProxy log hat timeouts with SSL negotiation. Therfore I have decided to try to isolate the problem and connect the client directly to the apache server without SSL (pure HTTP connection).

    So android client and apache are now on the same subnet (192.168.1.x), apache server is directly on the router so there is a direct connection: Client–>WIFI http (port 80)–>Apache2.4 with z-push. Kopano 8.7 is installed on the same computer.

    However, I still have access every 5 min (instead of a longer interval) (see below). Any idea what I can do to increase heartbeat?

    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:02:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 272 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:02:25 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 23773 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:02:27 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 318 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:02:27 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 246 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:02:30 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:07:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 272 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:07:25 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 14592 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:07:26 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 318 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:07:27 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 246 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:07:29 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:12:25 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:17:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:22:25 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:27:25 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:32:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:37:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:42:25 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:47:25 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:52:25 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:16:57:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:07:25 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 272 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:07:25 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 6435 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:07:27 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 318 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:07:27 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 246 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:08:05 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Search&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 365 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:12:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:17:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:22:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 272 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:22:25 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 37157 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:22:26 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 318 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:22:27 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 246 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:27:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:31:40 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:32:26 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:42:25 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:47:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:52:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [09/Sep/2019:23:57:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:00:02:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:00:07:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:00:12:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:00:17:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:00:22:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:00:27:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:00:32:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:00:37:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:00:42:25 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:00:46:40 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 246 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:00:46:41 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:00:46:59 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:00:47:21 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:00:47:44 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:00:48:08 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:00:52:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:00:57:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:04:10 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 318 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:04:11 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 318 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:04:12 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 246 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:02:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:04:12 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=MoveItems&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 490 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:04:14 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 272 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:04:15 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 435 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:04:15 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 318 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:04:16 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 246 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:04:18 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:07:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:12:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:17:27 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:22:25 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:27:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 272 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:27:25 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 19675 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:27:26 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 318 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:27:27 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 246 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:27:29 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:32:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:32:47 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:33:09 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:33:25 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:33:51 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:34:04 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:34:26 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:37:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    ::ffff:192.168.1.233 - *deleted* [10/Sep/2019:01:42:24 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Ping&User=*deleted*&DeviceId=*deleted*&DeviceType=Android HTTP/1.1" 200 0 "-" "*Android-device*/PPR1.180610.011"
    
    

  • Kopano

    Hi Alex,

    What are the values of PING_LOWER_BOUND_LIFETIME and PING_HIGHER_BOUND_LIFETIME in z-push.conf.php?

    Please also post WBXML level log for the this user with Ping/Sync connections.

    Manfred



  • Hi @Manfred,

    Thank you very much for getting in touch. Both values are not defined:

    define('PING_LOWER_BOUND_LIFETIME', false);
    define('PING_HIGHER_BOUND_LIFETIME', false);
    

    Below the debug file. Unfortunately the file leaks a lot of personal information (incl. full name). I hopefully have deleted all relevant instances.

    For whatever reason, the heartbeat now seem to be around 900s. However it also does not seem to go higher.

    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] -------- Start
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] cmd='Ping' devType='Android' devId='*deleted*' getUser='*deleted*' from='192.168.1.140' version='(no branch)-2.5.1' method='POST'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] Used timezone '*deleted*'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ZPush::GetBackend(): trying autoload backend 'BackendKopano'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] BackendKopano using PHP-MAPI version: 8.7.0 - PHP version: 7.3.4-2
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] Request::ProcessHeaders() ASVersion: 14.1
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ZPush::CommandNeedsProvisioning(18): false
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ZPush::CommandNeedsAuthentication(18): true
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] KopanoBackend->Logon(): Trying to authenticate user '*deleted*'..
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] FileStateMachine->GetState() read '2100' bytes from file: '/var/lib/z-push/4/2/*deleted*-devicedata'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ASDevice data loaded for user: '*deleted*'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] InterProcessData:__construct type: '*deleted*'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] TopCollector(): Initialized mutexid Resource id #23 and memid Resource id #24.
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] InterProcessData:__construct type: '*deleted*'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] LoopDetection(): Initialized mutexid Resource id #28 and memid Resource id #29.
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ZPush::HierarchyCommand(18): false
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] KopanoBackend->openMessageStore('*deleted*'): Found 'DEFAULT' store: 'Resource id #35'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] KopanoBackend->Logon(): User '*deleted*' is authenticated
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] Store supports properties containing Unicode characters.
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ZPush::CommandNeedsPlainInput(18): false
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I  <Ping:Ping>
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] FileStateMachine->GetState() read '1185' bytes from file: '/var/lib/z-push/4/2/*deleted*-633e6dee-869b-4596-9b67-203deba763f6-fd'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->UseCPO('DEFAULT')
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ZPush::GetAdditionalSyncFolderStore('15e8b53b2b3b4390bca19445cf5faf3b0e0000000000'): 'false'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncCollections->AddCollection(): Folder id 'U865ba' : ref. PolicyKey '225249625', ref. Lifetime '900', last sync at '1568167285'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncCollections->AddCollection(): Updated reference PolicyKey '225249625', reference Lifetime '900', Last sync at '1568167285'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->GetLatestSyncKey(): '{633e6dee-869b-4596-9b67-203deba763f6}15'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/4/2/*deleted*-633e6dee-869b-4596-9b67-203deba763f6-15'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] FileStateMachine->GetState() read '1154' bytes from file: '/var/lib/z-push/4/2/*deleted*-6a4053dd-2177-40c6-bbc4-c0011d97e005-fd'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->UseCPO('DEFAULT')
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ZPush::GetAdditionalSyncFolderStore('15e8b53b2b3b4390bca19445cf5faf3b110000000000'): 'false'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncCollections->AddCollection(): Folder id 'Ud5994' : ref. PolicyKey '225249625', ref. Lifetime '240', last sync at '1568108504'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->GetLatestSyncKey(): '{6a4053dd-2177-40c6-bbc4-c0011d97e005}10'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/4/2/*deleted*-6a4053dd-2177-40c6-bbc4-c0011d97e005-10'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] FileStateMachine->GetState() read '1061' bytes from file: '/var/lib/z-push/4/2/*deleted*-178f36a8-faac-432f-8116-94a6d5115be7-fd'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->UseCPO('DEFAULT')
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ZPush::GetAdditionalSyncFolderStore('15e8b53b2b3b4390bca19445cf5faf3b120000000000'): 'false'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncCollections->AddCollection(): Folder id 'U4c7b2' : ref. PolicyKey '225249625', ref. Lifetime '240', last sync at '1568108534'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->GetLatestSyncKey(): '{178f36a8-faac-432f-8116-94a6d5115be7}54'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/4/2/*deleted*-178f36a8-faac-432f-8116-94a6d5115be7-54'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] FileStateMachine->GetState() read '1059' bytes from file: '/var/lib/z-push/4/2/*deleted*-1cc60533-60ad-477c-8c1b-05f326ff4e4e-fd'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->UseCPO('DEFAULT')
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ZPush::GetAdditionalSyncFolderStore('15e8b53b2b3b4390bca19445cf5faf3b130000000000'): 'false'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncCollections->AddCollection(): Folder id 'U8df5f' : ref. PolicyKey '225249625', ref. Lifetime '240', last sync at '1568105162'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->GetLatestSyncKey(): '{1cc60533-60ad-477c-8c1b-05f326ff4e4e}11'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/4/2/*deleted*-1cc60533-60ad-477c-8c1b-05f326ff4e4e-11'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] FileStateMachine->GetState() read '1015' bytes from file: '/var/lib/z-push/4/2/*deleted*-763777ad-b568-4f39-ad49-3e6721467091-fd'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->UseCPO('DEFAULT')
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ZPush::GetAdditionalSyncFolderStore('15e8b53b2b3b4390bca19445cf5faf3b160000000000'): 'false'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncCollections->AddCollection(): Folder id 'Ufca25' : ref. PolicyKey '225249625', ref. Lifetime '240', last sync at '1568109077'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->GetLatestSyncKey(): '{763777ad-b568-4f39-ad49-3e6721467091}5'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/4/2/*deleted*-763777ad-b568-4f39-ad49-3e6721467091-5'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] FileStateMachine->GetState() read '1016' bytes from file: '/var/lib/z-push/4/2/*deleted*-3e17a2c4-93dc-486d-8042-660b5a52fb15-fd'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->UseCPO('DEFAULT')
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ZPush::GetAdditionalSyncFolderStore('15e8b53b2b3b4390bca19445cf5faf3b170000000000'): 'false'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncCollections->AddCollection(): Folder id 'U3d2c8' : ref. PolicyKey '225249625', ref. Lifetime '240', last sync at '1568108549'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->GetLatestSyncKey(): '{3e17a2c4-93dc-486d-8042-660b5a52fb15}19'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/4/2/*deleted*-3e17a2c4-93dc-486d-8042-660b5a52fb15-19'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] FileStateMachine->GetState() read '379' bytes from file: '/var/lib/z-push/4/2/*deleted*-1e7cf9cd-059f-4610-949d-12580e29ff77-fd'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->UseCPO('DEFAULT')
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncCollections->AddCollection(): Folder id '' : ref. PolicyKey '225249625', ref. Lifetime '10', last sync at '1568105131'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->GetLatestSyncKey(): '{1e7cf9cd-059f-4610-949d-12580e29ff77}1'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] StateManager->loadHierarchyCache(): '*deleted*-1e7cf9cd-059f-4610-949d-12580e29ff77-hc-1'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] FileStateMachine->GetState() read '2800' bytes from file: '/var/lib/z-push/4/2/*deleted*-1e7cf9cd-059f-4610-949d-12580e29ff77-hc-1'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/4/2/*deleted*-1e7cf9cd-059f-4610-949d-12580e29ff77-1'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] HandlePing(): reference PolicyKey for PING: 225249625
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] HandlePing(): initialization data received
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I   <Ping:LifeTime>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I    900
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I   </Ping:LifeTime>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I   <Ping:Folders>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I    <Ping:Folder>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     <Ping:ServerEntryId>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I      U865ba
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     </Ping:ServerEntryId>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     <Ping:FolderType>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I      Email
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     </Ping:FolderType>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I    </Ping:Folder>
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] HandlePing(): using saved sync state for 'Email' id 'U865ba'
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I    <Ping:Folder>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     <Ping:ServerEntryId>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I      Ud5994
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     </Ping:ServerEntryId>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     <Ping:FolderType>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I      Email
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     </Ping:FolderType>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I    </Ping:Folder>
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] HandlePing(): using saved sync state for 'Email' id 'Ud5994'
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I    <Ping:Folder>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     <Ping:ServerEntryId>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I      U4c7b2
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     </Ping:ServerEntryId>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     <Ping:FolderType>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I      Contacts
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     </Ping:FolderType>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I    </Ping:Folder>
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] HandlePing(): using saved sync state for 'Contacts' id 'U4c7b2'
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I    <Ping:Folder>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     <Ping:ServerEntryId>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I      U8df5f
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     </Ping:ServerEntryId>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     <Ping:FolderType>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I      Calendar
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     </Ping:FolderType>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I    </Ping:Folder>
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] HandlePing(): using saved sync state for 'Calendar' id 'U8df5f'
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I    <Ping:Folder>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     <Ping:ServerEntryId>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I      Ufca25
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     </Ping:ServerEntryId>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     <Ping:FolderType>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I      Notes
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     </Ping:FolderType>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I    </Ping:Folder>
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] HandlePing(): using saved sync state for 'Notes' id 'Ufca25'
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I    <Ping:Folder>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     <Ping:ServerEntryId>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I      U3d2c8
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     </Ping:ServerEntryId>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     <Ping:FolderType>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I      Tasks
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I     </Ping:FolderType>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I    </Ping:Folder>
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] HandlePing(): using saved sync state for 'Tasks' id 'U3d2c8'
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I   </Ping:Folders>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I  </Ping:Ping>
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncCollections->SaveCollection(): Data of folder 'U865ba' changed
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] FileStateMachine->SetState() written 1158 bytes on file: '/var/lib/z-push/4/2/*deleted*-633e6dee-869b-4596-9b67-203deba763f6-fd'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] DeviceManager->DoAutomaticASDeviceSaving(): save automatically: false
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] InterProcessData:__construct type: '*deleted*'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] PingTracking(): Initialized mutexid Resource id #169 and memid Resource id #170.
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] PingTracking initialised with IPC provider 'IpcSharedMemoryProvider' with type '2'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] Announce process as PUSH connection
    11/09/2019 10:01:29 [ 1463] [ INFO] [*deleted*] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 900 seconds)
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] KopanoBackend->HasChangesSink(): created - HierarchyHash: 6df56be9069dbc69df50964c9badc758
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] KopanoBackend->adviseStoreToSink(): advised store 'Resource id #35'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ZPush::GetAdditionalSyncFolderStore('15e8b53b2b3b4390bca19445cf5faf3b0e0000000000'): 'false'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] KopanoBackend->ChangesSinkInitialize(): folderid '15e8b53b2b3b4390bca19445cf5faf3b0e0000000000'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] KopanoBackend->GetFolderStat() fetched status information of 25 folders for store '*deleted*'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->IsExporterRunRequired(): false - current: 1568167284/156/32/60 - saved: 1568167284/156/32/60 - expiring: 2019-09-17 23:47:41
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ZPush::GetAdditionalSyncFolderStore('15e8b53b2b3b4390bca19445cf5faf3b110000000000'): 'false'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] KopanoBackend->ChangesSinkInitialize(): folderid '15e8b53b2b3b4390bca19445cf5faf3b110000000000'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->IsExporterRunRequired(): false - current: 1568026300/39/0/0 - saved: 1568026300/39/0/0 - expiring: 2019-09-17 13:32:48
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ZPush::GetAdditionalSyncFolderStore('15e8b53b2b3b4390bca19445cf5faf3b120000000000'): 'false'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] KopanoBackend->ChangesSinkInitialize(): folderid '15e8b53b2b3b4390bca19445cf5faf3b120000000000'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->IsExporterRunRequired(): false - current: 1567586209/417/0/38 - saved: 1567586209/417/0/38 - expiring: 2019-10-11 17:16:20
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ZPush::GetAdditionalSyncFolderStore('15e8b53b2b3b4390bca19445cf5faf3b130000000000'): 'false'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] KopanoBackend->ChangesSinkInitialize(): folderid '15e8b53b2b3b4390bca19445cf5faf3b130000000000'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->IsExporterRunRequired(): false - current: 1568087616/139/0/2 - saved: 1568087616/139/0/2 - expiring: 2019-09-24 14:19:24
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ZPush::GetAdditionalSyncFolderStore('15e8b53b2b3b4390bca19445cf5faf3b160000000000'): 'false'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] KopanoBackend->ChangesSinkInitialize(): folderid '15e8b53b2b3b4390bca19445cf5faf3b160000000000'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->IsExporterRunRequired(): false - current: 1567167004/19/0/0 - saved: 1567167004/19/0/0 - expiring: 2019-10-11 15:43:10
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ZPush::GetAdditionalSyncFolderStore('15e8b53b2b3b4390bca19445cf5faf3b170000000000'): 'false'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] KopanoBackend->ChangesSinkInitialize(): folderid '15e8b53b2b3b4390bca19445cf5faf3b170000000000'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] SyncParameters->IsExporterRunRequired(): false - current: 1568090327/87/0/0 - saved: 1568090327/87/0/0 - expiring: 2019-10-11 10:28:01
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] refpolkey:'225249625', sent polkey:'225249625'
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 11
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ExportChangesICS->Config() initialized with state: 0xecc60000f30c0000
    11/09/2019 10:01:29 [ 1463] [DEBUG] [*deleted*] ExportChangesICS->InitializeExporter() successfully. 0 changes ready to sync for 'hierarchy'.
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] -------- Start
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] cmd='Search' devType='Android' devId='*deleted*' getUser='*deleted*' from='192.168.1.140' version='(no branch)-2.5.1' method='POST'
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] Used timezone '*deleted*'
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] ZPush::GetBackend(): trying autoload backend 'BackendKopano'
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] BackendKopano using PHP-MAPI version: 8.7.0 - PHP version: 7.3.4-2
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] Request::ProcessHeaders() ASVersion: 14.1
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] ZPush::CommandNeedsProvisioning(16): true
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] FileStateMachine->GetState() read '2100' bytes from file: '/var/lib/z-push/4/2/*deleted*-devicedata'
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] ASDevice data loaded for user: '*deleted*'
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] InterProcessData:__construct type: '*deleted*'
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] TopCollector(): Initialized mutexid Resource id #21 and memid Resource id #22.
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] InterProcessData:__construct type: '*deleted*'
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] LoopDetection(): Initialized mutexid Resource id #26 and memid Resource id #27.
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] ZPush::HierarchyCommand(16): false
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] DeviceManager->ProvisioningRequired('225249625') saved device key '225249625': false
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] DeviceManager->getPolicyName(): determined policy name: 'default'
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] DeviceManager->getProvisioningPolicies(): loaded 'default' policy.
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] ZPush::CommandNeedsAuthentication(16): true
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] KopanoBackend->Logon(): Trying to authenticate user '*deleted*'..
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] KopanoBackend->openMessageStore('*deleted*'): Found 'DEFAULT' store: 'Resource id #38'
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] KopanoBackend->Logon(): User '*deleted*' is authenticated
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] Store supports properties containing Unicode characters.
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] ZPush::CommandNeedsPlainInput(16): false
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I  <Search:Search>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I   <Search:Store>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I    <Search:Name>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I     GAL
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I    </Search:Name>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I    <Search:Query>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I     *deleted*
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I    </Search:Query>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I    <Search:Options>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I     <Search:Range>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I      0-1
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I     </Search:Range>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I     <Search:Picture>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I      <Search:MaxSize>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I       102400
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I      </Search:MaxSize>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I      <Search:MaxPictures>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I       1
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I      </Search:MaxPictures>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I     </Search:Picture>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I    </Search:Options>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] I   </Search:Store>
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O  <Search:Search>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O   <Search:Status>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O   1
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O   </Search:Status>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O   <Search:Response>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O    <Search:Store>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O     <Search:Status>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O     1
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O     </Search:Status>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O     <Search:Result>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O      <Search:Properties>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O       <GAL:DisplayName>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O       *deleted*
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O       </GAL:DisplayName>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O       <GAL:Alias>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O       *deleted*
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O       </GAL:Alias>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O       <GAL:LastName>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O       *deleted*
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O       </GAL:LastName>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O       <GAL:EmailAddress>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O       *deleted*
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O       </GAL:EmailAddress>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O      </Search:Properties>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O     </Search:Result>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O     <Search:Range>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O     0-0
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O     </Search:Range>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O     <Search:Total>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O     1
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O     </Search:Total>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O    </Search:Store>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O   </Search:Response>
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] O  </Search:Search>
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] WBXMLEncoder->endTag() WBXML output completed
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] WBXML-OUT: AwFqAAAPRUwDMQABTUdMAzEAAU5PABBFA0FsZXhhbmRlciBXaWVnYW5kAAFKA2FsZXgAAUwDQWxleGFuZGVyIFdpZWdhbmQAAU8DYWxleGFuZGVyQHdpZWdhbmQuYml6AAEBAQAPSwMwLTAAAVADMQABAQEB
    11/09/2019 10:01:35 [ 1458] [WBXML] [*deleted*] WBXML-IN : AwFqAAAPRUdIA0dBTAABSQNhbGV4YW5kZXJAd2llZ2FuZC5iaXoAAUpLAzAtMQABYWIDMTAyNDAwAAFjAzEAAQEBAQE=
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] LoopDetection->ProcessLoopDetectionTerminate()
    11/09/2019 10:01:35 [ 1458] [ INFO] [*deleted*] cmd='Search' memory='2.11 MiB/2.00 MiB' time='0.23s' devType='Android' devId='*deleted*' getUser='*deleted*' from='192.168.1.140' idle='0s' version='(no branch)-2.5.1' method='POST' httpcode='200'
    11/09/2019 10:01:35 [ 1458] [DEBUG] [*deleted*] -------- End
    

  • Kopano

    Hi Alex,

    900 seconds is what your device requests:

    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I   <Ping:LifeTime>
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I    900
    11/09/2019 10:01:29 [ 1463] [WBXML] [*deleted*] I   </Ping:LifeTime>
    

    However the log is far from complete as there’s no end for the Ping command, so it’s not possible to tell if Ping terminated earlier or it really ran for 900 seconds. My experience is that the devices only increase ping lifetime if Ping command ran for the amount of time they requested.

    Manfred



  • Hi @Manfred,

    Thank you. Unfortunately I was not able to post a longer log because of message size limits. I understand that this is caused by the mobile and not z-push. Will investigate more with other phones.

    Thank you,
    Alex


Log in to reply