store render times in access log, RT#39822

4 files changed, 19 insertions, 13 deletions

diff --git a/FS/FS/Mason/Request.pm b/FS/FS/Mason/Request.pm
index 0d9c6d448..99a8daa60 100644
--- a/FS/FS/Mason/Request.pm
+++ b/FS/FS/Mason/Request.pm
@@ -4,8 +4,8 @@ use strict;
 use warnings;
 use vars qw( $FSURL $QUERY_STRING );
 use base 'HTML::Mason::Request';
+use IO::Handle;
 use FS::Trace;
-use FS::access_user_log;
 
 $FSURL = 'http://Set/FS_Mason_Request_FSURL/in_standalone_mode/';
 $QUERY_STRING = '';
@@ -46,12 +46,11 @@ my $protect_fds;
 sub freeside_setup {
     my( $class, $filename, $mode ) = @_;
 
-    FS::Trace->log('    protecting fds');
-
     #from rt/bin/webmux.pl(.in)
     if ( !$protect_fds && $ENV{'MOD_PERL'} && exists $ENV{'MOD_PERL_API_VERSION'}
         && $ENV{'MOD_PERL_API_VERSION'} >= 2
     ) {
+        FS::Trace->log('    protecting fds');
         # under mod_perl2, STDIN and STDOUT get closed and re-opened,
         # however they are not on FD 0 and 1.  In this case, the next
         # socket that gets opened will occupy one of these FDs, and make
@@ -130,8 +129,6 @@ sub freeside_setup {
 
     }
 
-    FS::access_user_log->insert_new_path( $filename );
-
     FS::Trace->log('    done');
 
 }
diff --git a/FS/FS/Schema.pm b/FS/FS/Schema.pm
index f1c4e080d..66575fa13 100644
--- a/FS/FS/Schema.pm
+++ b/FS/FS/Schema.pm
@@ -5775,10 +5775,11 @@ sub tables_hashref {
 
     'access_user_log' => {
       'columns'      => [
-        'lognum',  'serial', '',        '', '', '',
-        'usernum',    'int', '',        '', '', '',
-        'path',   'varchar', '', 2*$char_d, '', '',
-        '_date',         @date_type,        '', '',
+        'lognum',          'serial',     '',        '', '', '',
+        'usernum',            'int',     '',        '', '', '',
+        'path',           'varchar',     '', 2*$char_d, '', '',
+        '_date',                   @date_type,          '', '',
+        'render_seconds',     'int', 'NULL',        '', '', '',
       ],
       'primary_key'  => 'lognum',
       'unique'       => [],
diff --git a/FS/FS/access_user_log.pm b/FS/FS/access_user_log.pm
index 9e7f7a00e..15437b772 100644
--- a/FS/FS/access_user_log.pm
+++ b/FS/FS/access_user_log.pm
@@ -48,6 +48,7 @@ path
 
 _date
 
+=item render_seconds
 
 =back
 
@@ -73,14 +74,15 @@ Adds a log entry for PATH for the current user and timestamp.
 =cut
 
 sub insert_new_path {
-  my( $class, $path ) = @_;
+  my( $class, $path, $render_seconds ) = @_;
 
   return '' unless defined $FS::CurrentUser::CurrentUser;
 
   my $self = $class->new( {
-    'usernum' => $FS::CurrentUser::CurrentUser->usernum,
-    'path'    => $path,
-    '_date'   => time,
+    'usernum'        => $FS::CurrentUser::CurrentUser->usernum,
+    'path'           => $path,
+    '_date'          => time,
+    'render_seconds' => $render_seconds,
   } );
 
   my $error = $self->insert;
@@ -118,6 +120,7 @@ sub check {
     || $self->ut_foreign_key('usernum', 'access_user', 'usernum')
     || $self->ut_text('path')
     || $self->ut_number('_date')
+    || $self->ut_numbern('render_seconds')
   ;
   return $error if $error;
 
diff --git a/htetc/handler.pl b/htetc/handler.pl
index 4bb214c98..920da3c97 100644
--- a/htetc/handler.pl
+++ b/htetc/handler.pl
@@ -6,6 +6,7 @@ use strict;
 use warnings;
 use FS::Mason qw( mason_interps );
 use FS::Trace;
+use FS::access_user_log;
 use FS::Conf;
 
 $FS::Conf::conf_cache_enabled = 1; # enable FS::Conf caching for performance
@@ -65,6 +66,8 @@ sub handler
     #($r) = @_;
     my $r = shift;
 
+    my $start_time = time;
+
     FS::Trace->log('protecting fds');
 
     #from rt/bin/webmux.pl(.in)
@@ -164,6 +167,8 @@ sub handler
 #       );
 #    }
 
+    FS::access_user_log->insert_new_path( $r->filename, time-$start_time );
+\
     FS::Trace->log('done');
 
     FS::Trace->dumpfile( "%%%FREESIDE_EXPORT%%%/profile/$$.".time,