Navigation

    Kopano
    • Register
    • Login
    • Search
    • Categories
    • Get Official Kopano Support
    • Recent
    Statement regarding the closure of the Kopano community forum and the end of the community edition

    z-push 2.5.1: Heartbeat interval

    General usage of Z-Push
    3
    10
    843
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • alex1452
      alex1452 last edited by

      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

      1 Reply Last reply Reply Quote 0
      • fbartels
        fbartels Kopano last edited by

        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?

        Regards Felix

        Resources:
        https://kopano.com/blog/how-to-get-kopano/
        https://documentation.kopano.io/
        https://kb.kopano.io/

        Support overview:
        https://kopano.com/support/

        1 Reply Last reply Reply Quote 0
        • alex1452
          alex1452 last edited by

          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

          fbartels 1 Reply Last reply Reply Quote 0
          • fbartels
            fbartels Kopano @alex1452 last edited by

            Hi @alex1452,

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

            Regards Felix

            Resources:
            https://kopano.com/blog/how-to-get-kopano/
            https://documentation.kopano.io/
            https://kb.kopano.io/

            Support overview:
            https://kopano.com/support/

            1 Reply Last reply Reply Quote 0
            • alex1452
              alex1452 last edited by alex1452

              Hi @fbartels,

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

              Thank you,
              alex

              1 Reply Last reply Reply Quote 0
              • alex1452
                alex1452 last edited by

                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"
                1 Reply Last reply Reply Quote 0
                • Manfred
                  Manfred Kopano last edited by

                  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

                  1 Reply Last reply Reply Quote 0
                  • alex1452
                    alex1452 last edited by

                    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
                    1 Reply Last reply Reply Quote 0
                    • Manfred
                      Manfred Kopano last edited by

                      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

                      1 Reply Last reply Reply Quote 0
                      • alex1452
                        alex1452 last edited by

                        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

                        1 Reply Last reply Reply Quote 0
                        • First post
                          Last post