ZP-1168 Log 'idle' time in INFO level.

Released under the Affero GNU General Public License (AGPL) version 3.

src/index.php

@@ -223,10 +223,11 @@ include_once(ZPUSH_CONFIG);
 
     // end gracefully
     ZLog::Write(LOGLEVEL_INFO,
-            sprintf("cmd='%s' memory='%s/%s' time='%ss' devType='%s' devId='%s' getUser='%s' from='%s' version='%s' method='%s' httpcode='%s'",
+            sprintf("cmd='%s' memory='%s/%s' time='%ss' devType='%s' devId='%s' getUser='%s' from='%s' idle='%ss' version='%s' method='%s' httpcode='%s'",
                     Request::GetCommand(), Utils::FormatBytes(memory_get_peak_usage(false)), Utils::FormatBytes(memory_get_peak_usage(true)),
                     number_format(microtime(true) - $_SERVER["REQUEST_TIME_FLOAT"], 2),
-                    Request::GetDeviceType(), Request::GetDeviceID(), Request::GetGETUser(), Request::GetRemoteAddr(), @constant('ZPUSH_VERSION'), Request::GetMethod(), http_response_code() ));
+                    Request::GetDeviceType(), Request::GetDeviceID(), Request::GetGETUser(), Request::GetRemoteAddr(),
+                    RequestProcessor::GetWaitTime(), @constant('ZPUSH_VERSION'), Request::GetMethod(), http_response_code() ));
 
     ZLog::Write(LOGLEVEL_DEBUG, "-------- End");
 

src/lib/core/synccollections.php

@@ -578,6 +578,9 @@ class SyncCollections implements Iterator {
                 ZPush::GetTopCollector()->AnnounceInformation(sprintf("Sink %d/%ds on %s", ($now-$started), $lifetime, $checkClasses));
                 $notifications = ZPush::GetBackend()->ChangesSink($nextInterval);
 
+                // how long are we waiting for changes
+                $this->waitingTime = time()-$started;
+
                 $validNotifications = false;
                 foreach ($notifications as $backendFolderId) {
                     // Check hierarchy notifications
@@ -808,6 +811,17 @@ class SyncCollections implements Iterator {
         return ($this->waitingTime > 0);
     }
 
+    /**
+     * Indicates how many seconds the process did wait in a sink, polling or before running a
+     * regular export to find changes.
+     *
+     * @access public
+     * @return array
+     */
+    public function GetWaitedSeconds() {
+        return $this->waitingTime;
+    }
+
     /**
      * Returns how the current folder should be called in the PING comment.
      *

src/lib/request/ping.php

@@ -242,6 +242,9 @@ class Ping extends RequestProcessor {
 
         self::$encoder->endTag();
 
+        // update the waittime waited
+        self::$waitTime = $sc->GetWaitedSeconds();
+
         return true;
     }
 

src/lib/request/requestprocessor.php

@@ -38,6 +38,7 @@ abstract class RequestProcessor {
     static protected $encoder;
     static protected $userIsAuthenticated;
     static protected $specialHeaders;
+    static protected $waitTime;
 
     /**
      * Authenticates the remote user
@@ -94,6 +95,7 @@ abstract class RequestProcessor {
             self::$decoder = new WBXMLDecoder(Request::GetInputStream());
 
         self::$encoder = new WBXMLEncoder(Request::GetOutputStream(), Request::GetGETAcceptMultipart());
+        self::$waitTime = 0;
     }
 
     /**
@@ -137,6 +139,16 @@ abstract class RequestProcessor {
         return self::$specialHeaders;
     }
 
+    /**
+     * Returns the amount of seconds RequestProcessor waited e.g. during Ping.
+     *
+     * @access pulic
+     * @return int
+     */
+    public static function GetWaitTime() {
+        return self::$waitTime;
+    }
+
     /**
      * Handles a command
      *

src/lib/request/sync.php

@@ -911,6 +911,9 @@ class Sync extends RequestProcessor {
             ZLog::Write(LOGLEVEL_DEBUG, sprintf("HandleSync: Processed %d folders", $sc->GetCollectionCount()));
         }
 
+        // update the waittime waited
+        self::$waitTime = $sc->GetWaitedSeconds();
+
         return true;
     }