Better logging of page_error

This adds more logging to page_error, including the HTTP status code, the request IP address, an internal message to show the reason for the error, and a random string to help identify the error in the logs. This string is also shown on the error page to the user, to improve the chance of it being included in any screenshots from users.
mysociety · Dec 2, 2024 · c5eef33 · c5eef33
1 parent a104bc4
commit c5eef33
Show file tree

Hide file tree

Showing 21 changed files with 105 additions and 18 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -1,5 +1,9 @@
 ## Releases
 
+* Unreleased
+    - Development improvements
+        - More logging when page_error is called, to aid troubleshooting. #5279
+
 * v6.0 (14th November 2024)
     - Front end improvements:
         - Include requirements for redeeming the link in the email change confirmation mail. #4422

diff --git a/perllib/FixMyStreet/App/Controller/Auth.pm b/perllib/FixMyStreet/App/Controller/Auth.pm
@@ -465,20 +465,22 @@ sub check_csrf_token : Private {
     $c->stash->{csrf_time} = $time;
     my $gen_token = $c->forward('get_csrf_token');
     delete $c->stash->{csrf_time};
-    $c->detach('no_csrf_token')
-        unless $time
-            && $time > time() - 3600
-            && $token eq $gen_token;
+
+    my $cutoff = time() - 3600;
+    my $valid_time = $time && $time > $cutoff;
+    my $valid_token = $token eq $gen_token;
+    unless ($valid_time && $valid_token) {
+        my $msg = "Invalid CSRF token: ";
+        $msg .= "$token != $gen_token " unless $valid_token;
+        $msg .= "$time < $cutoff" unless $valid_time;
+        $c->stash->{internal_message} = $msg;
+        $c->detach('/page_error_400_bad_request', []);
+    }
 
     # Also check recaptcha if needed
     $c->cobrand->call_hook('check_recaptcha');
 }
 
-sub no_csrf_token : Private {
-    my ($self, $c) = @_;
-    $c->detach('/page_error_400_bad_request', []);
-}
-
 =item common_password
 
 Returns 1/0 depending on if password is common/breached or not.

diff --git a/perllib/FixMyStreet/App/Controller/Auth/Social.pm b/perllib/FixMyStreet/App/Controller/Auth/Social.pm
@@ -187,7 +187,10 @@ sub oidc_sign_in : Private {
     $c->detach( '/page_error_403_access_denied', [] ) if FixMyStreet->config('SIGNUPS_DISABLED');
 
     my $cfg = $c->forward('oidc_config');
-    $c->detach( '/page_error_400_bad_request', [] ) unless $cfg;
+    unless ($cfg) {
+        $c->stash->{internal_message} = 'OIDC config not found';
+        $c->detach( '/page_error_400_bad_request', [] );
+    }
 
     my $oidc = $c->forward('oidc');
     my $nonce = $self->generate_nonce();
@@ -269,7 +272,10 @@ sub oidc_callback: Path('/auth/OIDC') : Args(0) {
             $c->detach('oauth_failure');
         }
     }
-    $c->detach('/page_error_400_bad_request', []) unless $c->get_param('code') && $c->get_param('state');
+    unless ( $c->get_param('code') && $c->get_param('state') ) {
+        $c->stash->{internal_message} = "Social::oidc_callback missing code (" . $c->get_param('code') . ") or state (" . $c->get_param('state') . ")";
+        $c->detach('/page_error_400_bad_request', []) ;
+    }
 
     # After a password reset on the OIDC endpoint the user isn't properly logged
     # in, so redirect them to the usual OIDC login process.
@@ -290,7 +296,10 @@ sub oidc_callback: Path('/auth/OIDC') : Args(0) {
     }
 
     # The only other valid state param is 'login' at this point.
-    $c->detach('/page_error_400_bad_request', []) unless $c->get_param('state') eq 'login';
+    unless ($c->get_param('state') eq 'login') {
+        $c->stash->{internal_message} = "Social::oidc_callback invalid state: " . $c->get_param('state');
+        $c->detach('/page_error_400_bad_request', []) ;
+    }
 
     my $token = eval {
         $oidc->get_access_token(

diff --git a/perllib/FixMyStreet/App/Controller/Form.pm b/perllib/FixMyStreet/App/Controller/Form.pm
@@ -46,6 +46,7 @@ sub load_form {
     );
 
     if (!$form->has_current_page) {
+        $c->stash->{internal_error} = "Form doesn't have current page";
         $c->detach('/page_error_400_bad_request', [ 'Bad request' ]);
     }
 
@@ -114,6 +115,7 @@ sub get_page : Private {
     my $process = $c->get_param('process') || '';
     $goto = $self->first_page($c) unless $goto || $process;
     if ($goto && $process) {
+        $c->stash->{internal_error} = "Both goto and process parameters set";
         $c->detach('/page_error_400_bad_request', [ 'Bad request' ]);
     }
 

diff --git a/perllib/FixMyStreet/App/Controller/My.pm b/perllib/FixMyStreet/App/Controller/My.pm
@@ -349,15 +349,27 @@ sub anonymize : Path('anonymize') {
         $object = $c->stash->{problem};
     } elsif ($id = $c->get_param('update')) {
         $c->stash->{update} = $object = $c->model('DB::Comment')->find({ id => $id });
-        $c->detach('/page_error_400_bad_request') unless $object;
+        unless ($object) {
+            $c->stash->{internal_error} = "No update found for ID $id";
+            $c->detach('/page_error_400_bad_request');
+        }
     } else {
         $c->detach('/page_error_404_not_found');
     }
-    $c->detach('/page_error_400_bad_request') unless $c->user->id == $object->user_id;
-    $c->detach('/page_error_400_bad_request') if $object->anonymous;
+    unless ($c->user->id == $object->user_id) {
+        $c->stash->{internal_error} = "User " . $c->user->id . " does not own this object with ID " . $object->id;
+        $c->detach('/page_error_400_bad_request');
+    }
+    if ($object->anonymous) {
+        $c->stash->{internal_error} = "Object " . $object->id . " is already anonymous";
+        $c->detach('/page_error_400_bad_request');
+    }
 
     if ($c->get_param('hide') || $c->get_param('hide_everywhere')) {
-        $c->detach('/page_error_400_bad_request') unless $c->req->method eq 'POST';
+        unless ($c->req->method eq 'POST') {
+            $c->stash->{internal_error} = "Not a POST request: " . $c->req->method;
+            $c->detach('/page_error_400_bad_request');
+        }
         $c->forward('/auth/check_csrf_token');
         if ($c->get_param('hide')) {
             $object->update({ anonymous => 1 });

diff --git a/perllib/FixMyStreet/App/Controller/Questionnaire.pm b/perllib/FixMyStreet/App/Controller/Questionnaire.pm
@@ -38,6 +38,7 @@ sub check_questionnaire : Private {
         my $problem_url = $c->cobrand->base_url_for_report( $problem ) . $problem->url;
         my $contact_url = $c->uri_for( "/contact" );
         my $message = sprintf(_("You have already answered this questionnaire. If you have a question, please <a href='%s'>get in touch</a>, or <a href='%s'>view your problem</a>.\n"), $contact_url, $problem_url);
+        $c->stash->{internal_message} = "Questionnaire ID " . $questionnaire->id;
         $c->detach('/page_error_400_bad_request', [ $message ]);
     }
 

diff --git a/perllib/FixMyStreet/App/Controller/Root.pm b/perllib/FixMyStreet/App/Controller/Root.pm
@@ -1,4 +1,6 @@
 package FixMyStreet::App::Controller::Root;
+use Digest::MD5 qw(md5_hex);
+use mySociety::Random qw(random_bytes);
 use Moose;
 use namespace::autoclean;
 
@@ -145,8 +147,17 @@ sub page_error_500_internal_error : Private {
 
 sub page_error : Private {
     my ($self, $c, $error_msg, $code) = @_;
-    $c->stash->{template}  = 'errors/generic.html';
-    $c->stash->{message} = $error_msg || _('Unknown error');
+    $c->stash->{template} = 'errors/generic.html';
+    $c->stash->{message}  = $error_msg || _('Unknown error');
+    $c->stash->{error_id} = substr(md5_hex(random_bytes(12, 1)), 0, 6);
+
+    my $addr = $c->req->address;
+    $c->log->info(
+        "page_error (HTTP $code, IP $addr, ID " .
+        $c->stash->{error_id} . "): " .
+        "User message: " . $c->stash->{message} .
+        ($c->stash->{internal_message} ? "; Internal message: " . $c->stash->{internal_message} : "")
+    );
     $c->response->status($code);
 }
 

diff --git a/t/app/controller/admin.t b/t/app/controller/admin.t
@@ -9,6 +9,9 @@ package main;
 
 use FixMyStreet::TestMech;
 
+FixMyStreet::App->log->disable('info');
+END { FixMyStreet::App->log->enable('info'); }
+
 my $mech = FixMyStreet::TestMech->new;
 
 my $user = $mech->create_user_ok('[email protected]', name => 'Test User');

diff --git a/t/app/controller/admin/triage.t b/t/app/controller/admin/triage.t
@@ -1,6 +1,9 @@
 use FixMyStreet::TestMech;
 use FixMyStreet::Script::Alerts;
 
+FixMyStreet::App->log->disable('info');
+END { FixMyStreet::App->log->enable('info'); }
+
 my $mech = FixMyStreet::TestMech->new;
 
 my $user = $mech->create_user_ok('[email protected]', name => 'Test User');

diff --git a/t/app/controller/auth_profile.t b/t/app/controller/auth_profile.t
@@ -10,6 +10,10 @@ package main;
 
 use Test::MockModule;
 use FixMyStreet::TestMech;
+
+FixMyStreet::App->log->disable('info');
+END { FixMyStreet::App->log->enable('info'); }
+
 my $mech = FixMyStreet::TestMech->new;
 
 my $resolver = Test::MockModule->new('Email::Valid');

diff --git a/t/app/controller/index.t b/t/app/controller/index.t
@@ -2,6 +2,9 @@ use FixMyStreet::TestMech;
 use DateTime;
 use Web::Scraper;
 
+FixMyStreet::App->log->disable('info');
+END { FixMyStreet::App->log->enable('info'); }
+
 my $mech = FixMyStreet::TestMech->new;
 
 use t::Mock::Nominatim;

diff --git a/t/app/controller/my.t b/t/app/controller/my.t
@@ -1,4 +1,8 @@
 use FixMyStreet::TestMech;
+
+FixMyStreet::App->log->disable('info');
+END { FixMyStreet::App->log->enable('info'); }
+
 my $mech = FixMyStreet::TestMech->new;
 
 $mech->get_ok('/my');

diff --git a/t/app/controller/my_planned.t b/t/app/controller/my_planned.t
@@ -1,4 +1,8 @@
 use FixMyStreet::TestMech;
+
+FixMyStreet::App->log->disable('info');
+END { FixMyStreet::App->log->enable('info'); }
+
 my $mech = FixMyStreet::TestMech->new;
 
 $mech->get_ok('/my/planned');

diff --git a/t/app/controller/questionnaire.t b/t/app/controller/questionnaire.t
@@ -2,6 +2,9 @@ use DateTime;
 
 use FixMyStreet::TestMech;
 
+FixMyStreet::App->log->disable('info');
+END { FixMyStreet::App->log->enable('info'); }
+
 ok( my $mech = FixMyStreet::TestMech->new, 'Created mech object' );
 
 my $user = $mech->create_user_ok('[email protected]', name => 'Test User');

diff --git a/t/app/controller/report_updates.t b/t/app/controller/report_updates.t
@@ -17,6 +17,9 @@ use Web::Scraper;
 use Path::Class;
 use DateTime;
 
+FixMyStreet::App->log->disable('info');
+END { FixMyStreet::App->log->enable('info'); }
+
 my $mech = FixMyStreet::TestMech->new;
 
 my $user = $mech->create_user_ok('[email protected]', name => 'Test User');

diff --git a/t/app/controller/waste_echo.t b/t/app/controller/waste_echo.t
@@ -2,6 +2,9 @@ use Test::MockTime qw(set_fixed_time);
 use FixMyStreet::TestMech;
 use FixMyStreet::Cobrand::Merton;
 
+FixMyStreet::App->log->disable('info');
+END { FixMyStreet::App->log->enable('info'); }
+
 my $mech = FixMyStreet::TestMech->new;
 
 $mech->create_body_ok(2500, 'Merton Council', { cobrand => 'merton' });

diff --git a/templates/web/base/errors/generic.html b/templates/web/base/errors/generic.html
@@ -9,6 +9,9 @@
 <div class="confirmation-header confirmation-header--[% header_class %]">
     <h1>[% title %]</h1>
     <p>[% message | safe %]</p>
+    [% IF error_id %]
+        <small>[% tprintf(loc('Code: %s'), error_id) %]</small>
+    [% END %]
 </div>
 
 [% INCLUDE 'footer.html' %]

diff --git a/templates/web/brent/errors/generic.html b/templates/web/brent/errors/generic.html
@@ -36,6 +36,9 @@ <h1>My Account login</h1>
     <div class="confirmation-header confirmation-header--[% header_class %]">
         <h1>[% title %]</h1>
         <p>[% message | safe %]</p>
+        [% IF error_id %]
+            <small>[% tprintf(loc('Code: %s'), error_id) %]</small>
+        [% END %]
     </div>
 [% END %]
 

diff --git a/templates/web/highwaysengland/errors/generic.html b/templates/web/highwaysengland/errors/generic.html
@@ -35,6 +35,9 @@ <h1>Single sign on login</h1>
     <div class="confirmation-header confirmation-header--failure">
         <h1>[% title %]</h1>
         <p>[% message | safe %]</p>
+        [% IF error_id %]
+            <small>[% tprintf(loc('Code: %s'), error_id) %]</small>
+        [% END %]
     </div>
 [% END %]
 

diff --git a/templates/web/tfl/errors/generic.html b/templates/web/tfl/errors/generic.html
@@ -36,6 +36,9 @@ <h1>My Account login</h1>
     <div class="confirmation-header confirmation-header--[% header_class %]">
         <h1>[% title %]</h1>
         <p>[% message | safe %]</p>
+        [% IF error_id %]
+            <small>[% tprintf(loc('Code: %s'), error_id) %]</small>
+        [% END %]
     </div>
 [% END %]
 

diff --git a/web/cobrands/sass/_base.scss b/web/cobrands/sass/_base.scss
@@ -3074,6 +3074,10 @@ a#geolocate_link {
     word-break: break-word; // It prevents screen overflow when there is a long url, when a page has not been found.
   }
 
+  &.confirmation-header--failure small {
+    color: #888888;
+  }
+
   & > :last-child {
     margin-bottom: 0;
   }