299311 - need non-noisy error-logging function for logging of errors with sensitive data

Status: RESOLVED WONTFIX

(Bugzilla :: Bugzilla-General, enhancement)

Description

[A. Karl Kornel]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.7.2) Gecko/20040804 Netscape/7.2 (ax)
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.7.2) Gecko/20040804 Netscape/7.2 (ax)

As part of an authentication module I'm writing (bug 297822), I'd like to be
able to output error messages that contain potentially sensitive information
(i.e. NIS passwd entries, which contain encrypted passwords).  If a user was
logged in during the error, I could make sure that I only output this info if
the user is an admin.  However, the user is actually in the middle of the login
when the error appears, so that's not really an option.

I'd like to log the error to a file.  Bugzilla::Error does write to the file at
$datadir/errorlog (if it already exists & is writable), but it ends up
outputting lots of additional information (such as every environment variable)
along with the error.  Bugzilla::Error also records the error text that is being
displayed to the user, which might be as detailed as one would like.

I'm looking for a method like warn(), something that will log an error to a file
in $datadir, where I get to define the text to log.  The main reason why warn()
won't work is because it logs to error_log, which clutters up the log and (so
I'm told) can make Apache do strange things.

Reproducible: Always

Steps to Reproduce:




My choice of the phrase "non-noisy" is intentional.

There are also DOS concerns that should be addressed.

Comment 1

[A. Karl Kornel]

(fixed spelling error in summary)

Comment 2

[A. Karl Kornel]

Attachment: Patch v1

This is attempt #1 at a solution.  From the POD (which could probably use
editing):

=item C<QuietlyLogError>

This function is used when there is information that is worth recording, 
information that should not be displayed to the user either because the 
information is too sensitive to display, or because it may be too technical 
and/or confusing for the average user, but may be very useful to certain people
when determining the cause of the error.  This function should normally be
called just before a call to ThrowCodeError, ThrowUserError, or just before
returning an error response to the calling subroutine.

When this function is called with a non-empty string as the only parameter, the
contents of the parameter (along with the current time) is logged to the
quietlog file in the data directory.  The file must already exist, and the web
server must be able to write to it.

If the message is sucessfully logged, LOG_ERROR_OK is returned.
If the '$datadir/quietlog' file does not exist, or is not writeable,
LOG_ERROR_WRITE is returned (a non-serious error).
If the '$datadir/quietlog' file does exist, is writeable, but can not be
opened, LOG_ERROR_OPEN is returned (a potentially serious error).

QuietlyLogError can be called without parameters, or with an empty string.  In
these cases, QuietlyLogError will go through the motions of looking for and
opening the '$datadir/quietlog' file, but won't actually write anything to the
file.  This is a useful way of testing to see if quietly-logged errors are
actually being logged.

Comment 3

[A. Karl Kornel]

Comment on attachment 187963 [details] [diff] [review]
Patch v1

Patch has an error I missed.  Moving review request.

Comment 4

[A. Karl Kornel]

Attachment: Patch v1.5

attachment 187963 [details] [diff] [review] had a few errors I missed.  The docs havn't changed.

Comment 5

[A. Karl Kornel]

Comment on attachment 187983 [details] [diff] [review]
Patch v1.5

Per discussions with mkanat on IRC, I'm making a number of changes to this. 
Obsoleting this attachment & removing the review request, pending submission of
a new patch.

Comment 6

[A. Karl Kornel]

Attachment: Patch v2

Modification of attachment 187983 [details] [diff] [review] based on comments from mkanat on IRC from
04:04 to 04:43, see <http://tinyurl.com/9u5lj>.

QuietlyLogError is now known as log_error.  log_error now takes complete
responsibility for writing errors to the errorlog, taking it away from
_throw_error.  log_error also takes responsibility for writing environment
variables & CGI parameters to "$datadir/errorinfo" if it exists, and only if
errorlog exists and is written to.  Information written to errorlog is also
written to errorinfo, so that the two entries can be matched.  log_error is
perfectly happy writing to errorlog but not errorinfo (a Good Thing, as
errorinfo grows very quickly).

The POD for the function has been completely re-written to conform to the
format of DB.pm.  Some parts may be long-winded, but I think it's worth it.

Requesting review from mkanat.	Also, mkanat: what about the $vars passed to
_throw_error.  They were never logged; should they?

Comment 7

[Max Kanat-Alexander]

Comment on attachment 188013 [details] [diff] [review]
Patch v2

>+    LOG_OK LOG_ERROR_OPEN LOG_ERROR_WRITE

  I don't think we need this many diagnostics for log_error. It can just return
true if it wrote anything, and false if it didn't.

>Index: Error.pm

>+sub log_error {
>+    my ($msg) = @_;
>+    my ($msg_result, $info_result);
>+
>+    # The Bugzilla PID, date/time, Bugzilla user login, IP, and message.
>+    # This is what goes out to errorlog.  It's also put into errorinfo
>+    # (if only 1 error can be generated in a single second, a timestamp
>+    #  could be used instead in errorinfo)
>+    my $stamp = "\n[$$] (" . time2str("%D %H:%M:%S", time()) . ') ';
>+    $stamp .= Bugzilla->user->login || '???';
>+    $stamp .= '/';
>+    $stamp .= $ENV{REMOTE_ADDR} || '???';
>+    $stamp .= "\n  $msg\n";
>+
>+    # First, write the error message given to us
>+    if (-w "$datadir/errorlog") {
>+        open(ERRORLOGFID, ">>$datadir/errorlog")
>+            || return (LOG_ERROR_OPEN, undef);
>+
>+        # Don't print anything anywhere if we're not given a message to print
>+        if ((defined $msg) && (length($msg) > 0)) {
>+            print ERRORLOGFID $stamp;
>+        }
>+        close ERRORLOGFID;
>+        $msg_result = LOG_OK;

>+    } else {
>+        return (LOG_ERROR_WRITE, undef);
>+    }

  No need to return immediately here. I think we should allow people to write
to errorinfo even if errorlog doesn't exist, if they want to do that for some
strange reason.

>+    return ($msg_result, $info_result);

  And we only need one return value.


> =head1 DESCRIPTION
> 
> Various places throughout the Bugzilla codebase need to report errors to the
>-user. The C<Throw*Error> family of functions allow this to be done in a
>-generic and localisable manner.
>+user. C<log_error> and the C<Throw*Error> family of functions allow this to be 
>+done in a generic and localisable manner.

  You don't need to modify this message. log_error isn't localizable, as far as
I know, right?

>+ Note:        This subroutine is particularly useful if you are about to throw 
>+                  an error, and you have information that should not be shown 
>+                  to the user but could still be useful in the determining the 
>+                  cause of the error.
>+              The errrolog and errorinfo files are never created automatically, 
>+                  they must be created by someone with appropriate permissions.
>+              In addition to writing $msg to the errorlog file, the Bugzilla 
>+                  process ID is written, along with the date & time that the 
>+                  message was logged, the clients IP address (if available), 
>+                  and the login of the user that generated the error (if 
>+                  available).
>+              The errorinfo file is only written to if a message is written in 
>+                  the errorlog file.  Everything written to errorlog is also 
>+                  written to errorinfo, along with the values of every 
>+                  environment variable and CGI parameter.

  Nit: OK, call this "Details" instead of "Note," I think. I agree that it's
useful information.

Comment 8

[Max Kanat-Alexander]

Oh, nevermind, do call it "Note." That's what we call it in other places.

Comment 9

[A. Karl Kornel]

Attachment: Patch v3

Modification of attachment 188013 [details] [diff] [review] with respect to comment 7:
>   I don't think we need this many diagnostics for log_error. It can just 
> return true if it wrote anything, and false if it didn't.

Removed.

> 
>   No need to return immediately here. I think we should allow people to write

> to errorinfo even if errorlog doesn't exist, if they want to do that for some

> strange reason.

Updated.

>   And we only need one return value.

Modified.  Returns 1 if anything is logged, 0 if not, and undef on file open
error.

Comment 10

[A. Karl Kornel]

bug 165589 will be adding documentation on error logging, which will need to be
updated (or created) if this lands.

Comment 11

[A. Karl Kornel]

drat

Comment 12

[A. Karl Kornel]

Comment on attachment 188079 [details] [diff] [review]
Patch v3

drat again

Comment 13

[A. Karl Kornel]

Attachment: Patch v3.1

Unbitrotted version of attachment 188079 [details] [diff] [review].

Comment 14

[Max Kanat-Alexander]

karl: Ask somebody else for review; I think I won't be able to get to this.

Comment 15

[Max Kanat-Alexander]

Really, I don't think we actually need this. I just re-write Auth, which is the only place I could imagine needing this, and I didn't see anywhere where we'd need this.