Logger: Handle missing queue times

move-backend · Jul 4, 2024 · efd10ff · efd10ff
1 parent e777a8a
commit efd10ff
Show file tree

Hide file tree

Showing 2 changed files with 48 additions and 9 deletions.
diff --git a/lib/InfluxDBLogger.php b/lib/InfluxDBLogger.php
@@ -300,10 +300,13 @@ private static function getJobField(JobHandler $job, Throwable $e = null): array
             'end_time'       => $job->end_time,
             'pop_time'       => $job->pop_time,
             'execution_time' => $job->end_time - $job->start_time,
-            'queue_time'     => $job->pop_time - $job->payload['queue_time'],
             'job_id'         => $job->payload['id'],
         ];
 
+        if (isset($job->payload['queue_time'])) {
+            $fields['queue_time'] = $job->pop_time - $job->payload['queue_time'];
+        }
+
         if (!is_null($e)) {
             $fields['error'] = $e->getMessage();
         }

diff --git a/lib/Tests/InfluxDBPerformTest.php b/lib/Tests/InfluxDBPerformTest.php
@@ -129,8 +129,8 @@ public function testAfterPerform(): void
 
         $tags = 'class=SomeClass,queue=queue,status=finished';
         $query  = "resque,$tags start_time=1552481660.5678,end_time=1552481960.1259,";
-        $query .= 'pop_time=1552481650.1234,execution_time=299.55809998512,queue_time=1001.0889000893,';
-        $query .= 'job_id="4f181d8102ee412188728341c84a3404" 1552482605N';
+        $query .= 'pop_time=1552481650.1234,execution_time=299.55809998512,';
+        $query .= 'job_id="4f181d8102ee412188728341c84a3404",queue_time=1001.0889000893 1552482605N';
         $this->driver->expects($this->exactly(1))
                      ->method('write')
                      ->with($query);
@@ -148,6 +148,42 @@ public function testAfterPerform(): void
         InfluxDBLogger::afterPerform($job);
     }
 
+    /**
+     * Test afterPerform setting values based on payload.
+     *
+     * @covers \Resque\Logging\InfluxDBLogger::afterPerform
+     */
+    public function testAfterPerformWithoutQueueTime(): void
+    {
+        $this->driver->expects($this->exactly(1))
+                     ->method('setParameters')
+                     ->with([
+                         'url'      => 'write?db=resque&precision=n',
+                         'database' => 'resque',
+                         'method'   => 'post',
+                         'auth'     => ['envUser', 'envPass'],
+                     ]);
+
+        $tags = 'class=SomeClass,queue=queue,status=finished';
+        $query  = "resque,$tags start_time=1552481660.5678,end_time=1552481960.1259,";
+        $query .= 'pop_time=1552481650.1234,execution_time=299.55809998512,';
+        $query .= 'job_id="4f181d8102ee412188728341c84a3404" 1552482605N';
+        $this->driver->expects($this->exactly(1))
+                     ->method('write')
+                     ->with($query);
+
+        $job = new \Resque\JobHandler('queue', [
+            'class'      => 'SomeClass',
+            'id'         => '4f181d8102ee412188728341c84a3404',
+        ]);
+
+        $job->pop_time   = 1552481650.1234;
+        $job->start_time = 1552481660.5678;
+        $job->end_time   = 1552481960.1259;
+
+        InfluxDBLogger::afterPerform($job);
+    }
+
     /**
      * Test afterPerform setting values based on payload.
      *
@@ -166,8 +202,8 @@ public function testAfterPerformWithRetentionPolicy(): void
 
         $tags = 'class=SomeClass,queue=queue,status=finished';
         $query  = "resque,$tags start_time=1552481660.5678,end_time=1552481960.1259,";
-        $query .= 'pop_time=1552481650.1234,execution_time=299.55809998512,queue_time=1001.0889000893,';
-        $query .= 'job_id="4f181d8102ee412188728341c84a3404" 1552482605N';
+        $query .= 'pop_time=1552481650.1234,execution_time=299.55809998512,';
+        $query .= 'job_id="4f181d8102ee412188728341c84a3404",queue_time=1001.0889000893 1552482605N';
         $this->driver->expects($this->exactly(1))
                      ->method('write')
                      ->with($query);
@@ -206,8 +242,8 @@ public function testAfterPerformWithEnv(): void
 
         $tags = 'class=SomeClass,queue=queue,status=finished';
         $query  = "resque,$tags start_time=1552481660.5678,end_time=1552481960.1259,";
-        $query .= 'pop_time=1552481650.1234,execution_time=299.55809998512,queue_time=1001.0889000893,';
-        $query .= 'job_id="4f181d8102ee412188728341c84a3404" 1552482605N';
+        $query .= 'pop_time=1552481650.1234,execution_time=299.55809998512,';
+        $query .= 'job_id="4f181d8102ee412188728341c84a3404",queue_time=1001.0889000893 1552482605N';
         $this->driver->expects($this->exactly(1))
                      ->method('write')
                      ->with($query);
@@ -243,8 +279,8 @@ public function testOnFailure(): void
 
         $query  = 'resque,class=SomeClass,queue=queue,exception=Exception,';
         $query .= 'status=failed start_time=1552481660.5678,end_time=1552481960.1259,';
-        $query .= 'pop_time=1552481650.1234,execution_time=299.55809998512,queue_time=1001.0889000893,';
-        $query .= 'job_id="4f181d8102ee412188728341c84a3404",error="FAILURE" 1552482605N';
+        $query .= 'pop_time=1552481650.1234,execution_time=299.55809998512,';
+        $query .= 'job_id="4f181d8102ee412188728341c84a3404",queue_time=1001.0889000893,error="FAILURE" 1552482605N';
 
         $this->driver->expects($this->exactly(1))
                      ->method('write')