From 40c4ade6ea7f0415687f231c0c0164c6ef538ea2 Mon Sep 17 00:00:00 2001
From: Rene Krenn <rkrenn@sipwise.com>
Date: Fri, 18 Jun 2021 13:45:23 +0200
Subject: [PATCH] TT#118802 log raw perl catalyst request time

(cherry picked from commit 05f2f1137d6d3ce1deb1880eb1427b94e409c691)

Change-Id: I6bda815d2ccf2800a0a352c0d44aaee8039ee8d5
---
 lib/NGCP/Panel/Controller/Root.pm | 2 ++
 lib/NGCP/Panel/Utils/Message.pm   | 8 ++++----
 2 files changed, 6 insertions(+), 4 deletions(-)

diff --git a/lib/NGCP/Panel/Controller/Root.pm b/lib/NGCP/Panel/Controller/Root.pm
index dd4d7e2654..ef022a00cb 100644
--- a/lib/NGCP/Panel/Controller/Root.pm
+++ b/lib/NGCP/Panel/Controller/Root.pm
@@ -28,6 +28,8 @@ __PACKAGE__->config(namespace => '');
 
 sub auto :Private {
     my($self, $c) = @_;
+    
+    $c->stash->{_request_start} = Time::HiRes::time;
 
     my $is_api_request = 0;
     $c->log->debug("Path: " . $c->request->path);
diff --git a/lib/NGCP/Panel/Utils/Message.pm b/lib/NGCP/Panel/Utils/Message.pm
index 2df0abe78a..0448e2dcfe 100644
--- a/lib/NGCP/Panel/Utils/Message.pm
+++ b/lib/NGCP/Panel/Utils/Message.pm
@@ -170,9 +170,9 @@ sub error {
         $msg = "$desc ($error)";
     }
 
-    my $logstr = 'IP=%s CALLED=%s TX=%s USER=%s DATA=%s MSG="%s" LOG="%s"';
+    my $logstr = 'IP=%s CALLED=%s TX=%s USER=%s DDATA=%s MSG="%s" LOG="%s" DURATION=%f';
     my $rc = $c->log->error(
-        sprintf $logstr, @{$log_params}{qw(r_ip called tx_id r_user data)}, $c->qs($msg), $log_msg);
+        sprintf $logstr, @{$log_params}{qw(r_ip called tx_id r_user data)}, $c->qs($msg), $log_msg, (defined $c->stash->{_request_start} ? Time::HiRes::time - $c->stash->{_request_start} : 0));
     if ($type eq 'panel') {
         if (!defined $params{flash} || $params{flash} ) {
             $c->flash(messages => [{ type => $usr_type,
@@ -230,10 +230,10 @@ sub info {
         $log_msg =~ s/\s+/ /g;
     }
 
-    my $logstr = 'IP=%s CALLED=%s TX=%s USER=%s DATA=%s MSG="%s" LOG="%s"';
+    my $logstr = 'IP=%s CALLED=%s TX=%s USER=%s DATA=%s MSG="%s" LOG="%s" DURATION=%f';
     my $rc = $c->log->info(
         sprintf $logstr,
-                @{$log_params}{qw(r_ip called tx_id r_user data)}, $msg, $log_msg);
+                @{$log_params}{qw(r_ip called tx_id r_user data)}, $msg, $log_msg, (defined $c->stash->{_request_start} ? Time::HiRes::time - $c->stash->{_request_start} : 0));
     if ($type eq 'panel') {
         #flash is on by default
         if (!defined $params{flash} || $params{flash} ) {