From efd10fff457e3afc9fc76d79fa9f3cb13ea2ead2 Mon Sep 17 00:00:00 2001 From: Heinz Wiesinger Date: Thu, 4 Jul 2024 13:11:21 +0200 Subject: [PATCH] Logger: Handle missing queue times --- lib/InfluxDBLogger.php | 5 ++- lib/Tests/InfluxDBPerformTest.php | 52 ++++++++++++++++++++++++++----- 2 files changed, 48 insertions(+), 9 deletions(-) diff --git a/lib/InfluxDBLogger.php b/lib/InfluxDBLogger.php index 78e4eab..8dfe0b0 100644 --- 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 index 5b71768..5f82b2c 100644 --- 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')