Add audit logging

- Auditing for general errors in executables
- Auditing for improper messages received by WFE
- Automatic audit wlogging of software errors
- Audit logging for mis-routed messages
- Audit logging for certificate requests
- Auditing for improper messages received by WFE
- Add audit events table
- Expect more details in TestRegistration in web-front-end_test.go
- Remove "extra" debug details from web-front-end.go per Issue #174
- Improve test coverage of web-front-end.go
- WFE audit updates for revocation support rebase
- Add audit messages to RPC for Improper Messages and Error Conditions
- Also note misrouted messages

.gitignore

@@ -8,6 +8,9 @@ _obj
 _test
 bin
 
+# Test files
+test/js/node_modules
+
 # Architecture specific extensions/prefixes
 *.[568vq]
 [568vq].out

cmd/boulder-ca/main.go

@@ -28,6 +28,9 @@ func main() {
 		auditlogger, err := blog.Dial(c.Syslog.Network, c.Syslog.Server, c.Syslog.Tag, stats)
 		cmd.FailOnError(err, "Could not connect to Syslog")
 
+		// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
+		defer auditlogger.AuditPanic()
+
 		blog.SetAuditLogger(auditlogger)
 
 		cadb, err := ca.NewCertificateAuthorityDatabaseImpl(c.CA.DBDriver, c.CA.DBName)

cmd/boulder-ra/main.go

@@ -25,6 +25,9 @@ func main() {
 		auditlogger, err := blog.Dial(c.Syslog.Network, c.Syslog.Server, c.Syslog.Tag, stats)
 		cmd.FailOnError(err, "Could not connect to Syslog")
 
+		// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
+		defer auditlogger.AuditPanic()
+
 		blog.SetAuditLogger(auditlogger)
 
 		rai := ra.NewRegistrationAuthorityImpl()

cmd/boulder-sa/main.go

@@ -28,6 +28,9 @@ func main() {
 		auditlogger, err := blog.Dial(c.Syslog.Network, c.Syslog.Server, c.Syslog.Tag, stats)
 		cmd.FailOnError(err, "Could not connect to Syslog")
 
+		// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
+		defer auditlogger.AuditPanic()
+
 		blog.SetAuditLogger(auditlogger)
 
 		sai, err := sa.NewSQLStorageAuthority(c.SA.DBDriver, c.SA.DBName)

cmd/boulder-va/main.go

@@ -25,6 +25,9 @@ func main() {
 		auditlogger, err := blog.Dial(c.Syslog.Network, c.Syslog.Server, c.Syslog.Tag, stats)
 		cmd.FailOnError(err, "Could not connect to Syslog")
 
+		// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
+		defer auditlogger.AuditPanic()
+
 		blog.SetAuditLogger(auditlogger)
 
 		go cmd.ProfileCmd("VA", stats)

cmd/boulder-wfe/main.go

@@ -73,6 +73,9 @@ func main() {
 		auditlogger, err := blog.Dial(c.Syslog.Network, c.Syslog.Server, c.Syslog.Tag, stats)
 		cmd.FailOnError(err, "Could not connect to Syslog")
 
+		// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
+		defer auditlogger.AuditPanic()
+
 		blog.SetAuditLogger(auditlogger)
 
 		wfe := wfe.NewWebFrontEndImpl()

cmd/boulder/main.go

@@ -65,6 +65,9 @@ func main() {
 		auditlogger, err := blog.Dial(c.Syslog.Network, c.Syslog.Server, c.Syslog.Tag, stats)
 		cmd.FailOnError(err, "Could not connect to Syslog")
 
+		// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
+		defer auditlogger.AuditPanic()
+
 		blog.SetAuditLogger(auditlogger)
 
 		// Run StatsD profiling

cmd/shell.go

@@ -140,8 +140,8 @@ func (as *AppShell) Run() {
 // FailOnError exits and prints an error message if we encountered a problem
 func FailOnError(err error, msg string) {
 	if err != nil {
-		fmt.Fprintf(os.Stderr, "%s: %s\n", msg, err)
-		os.Exit(1)
+		// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
+		panic(fmt.Sprintf("%s: %s", msg, err))
 	}
 }
 

core/interfaces.go

@@ -68,7 +68,7 @@ type RegistrationAuthority interface {
 	RevokeCertificate(x509.Certificate) error
 
 	// [ValidationAuthority]
-	OnValidationUpdate(Authorization)
+	OnValidationUpdate(Authorization) error
 }
 
 type ValidationAuthority interface {

core/objects.go

@@ -321,7 +321,7 @@ func (jb *JsonBuffer) UnmarshalJSON(data []byte) (err error) {
 // thing exposed on the wire is the certificate itself.
 type Certificate struct {
 	RegistrationID int64 `db:"registrationID"`
-	
+
 	// The parsed version of DER. Useful for extracting things like serial number.
 	ParsedCertificate *x509.Certificate `db:"-"`
 

docs/requirements/audit_events.csv

@@ -0,0 +1,10 @@
+UUID,Shortname,CPS Reference,Description
+11917fa4-10ef-4e0d-9105-bacbe7836a3c,Certificate Requests,,"All Certificate requests – Date and time of request, type of event, and request information are automatically logged by the application. This includes Issuance, renewal, and re-key requests as well as sender/requester DN, Certificate serial number, initial application, method of request (online, in-person), source of verification, name of document presented for identity proofing, all fields verified in the application, Certificate common name, new validity period dates, date and time of response and success or failure indication are automatically logged by the application, and all associated error messages and codes. Manual interactions with participants such as telephone or in person inquiries and results of verification calls will be logged manually in a logbook or in a computer-based recording/tracking system and include date/time, description of interaction and identity provided."
+4e85d791-09c0-4ab3-a837-d3d67e945134,Revocation Requests,,"All Certificate Revocation requests – Date and time of Revocation request, sender/requester DN, Certificate serial number, subject DN of Certificate to revoke, Subscriber’s common name, Revocation reason, date and time of response and success or failure indication are automatically logged by the application; manual interactions with requestors such as telephone or in person inquiries and requests for Revocation are logged manually in a logbook or in a computer-based recording/tracking system. The date/time, description of interaction and identity provided are also recorded."
+a88fd00b-fa62-4a2f-9226-3eef27e2a50e,Certificate Updates,,"The approval or rejection of a Certificate status change request – Identity of equipment operator who initiated the request, message contents, message source, destination, and success or failure indication are automatically logged by the application."
+d510aa7e-ce9d-44ea-aa6d-4479a5652439,Software Updates and Migrations,,"Any security-relevant changes to the configuration of a component – Date and time of modification, name of modifier, description of modification, build information (i.e. size, version number) of any modified files and the reason for modification are manually logged during change management processes."
+78722466-9519-42bd-8a16-9c1ec1ca29ea,Compromise Notifications,,"All Certificate compromise notification requests – Date and time of notification, identity of person making the notification, identification of entity compromised, and a description of the compromise are logged manually by the personnel who receive the notification (e.g. Help Desk, RA Operators, etc.) and by RA/RA Operators’ system processing logs."
+9cc4d537-8534-4970-8665-4b382abe82f3,Error Conditions,,"Software error conditions – Date and time of event, and description of event are automatically logged by the application reporting the event or by the operating system."
+03806e9f-b6f3-4b29-b0a2-46fae57646d5,Software Integrity Failures,,"Software check integrity failures – Date and time of event, and description of event are automatically logged by the application reporting the event or by the operating system."
+0786b6f2-91ca-4f48-9883-842a19084c64,Improper Messages,,"Receipt of improper messages – Date and time of event, and description of event are automatically logged by the application reporting the event or by the operating system."
+f523f21f-12d2-4c31-b2eb-ee4b7d96d60e,Misrouted Messages,,"Misrouted messages – Date and time of event, and description of event are automatically logged by the application reporting the event or by the operating system."

docs/requirements/print_comment_markers

@@ -0,0 +1,2 @@
+#!/bin/bash
+cat audit_events.csv | tail +2 | awk -F "," '{print "// AUDIT[", $2, "]", $1;}'

log/audit-logger.go

@@ -27,6 +27,17 @@ var _Singleton singleton
 // The constant used to identify audit-specific messages
 const auditTag = "[AUDIT]"
 
+// Constant used to indicate an emergency exit to the executor
+const emergencyReturnValue = 13
+
+// exitFunction closes the running system
+type exitFunction func ()
+
+// Default to calling os.Exit()
+func defaultEmergencyExit() {
+	os.Exit(emergencyReturnValue)
+}
+
 // AuditLogger is a System Logger with additional audit-specific methods.
 // In addition to all the standard syslog.Writer methods from
 // http://golang.org/pkg/log/syslog/#Writer, you can also call
@@ -35,6 +46,7 @@ const auditTag = "[AUDIT]"
 type AuditLogger struct {
 	*syslog.Writer
 	Stats statsd.Statter
+	exitFunction exitFunction
 }
 
 // Dial establishes a connection to the log daemon by passing through
@@ -54,7 +66,12 @@ func NewAuditLogger(log *syslog.Writer, stats statsd.Statter) (*AuditLogger, err
 	if log == nil {
 		return nil, errors.New("Attempted to use a nil System Logger.")
 	}
-	return &AuditLogger{log, stats}, nil
+	audit := &AuditLogger{
+		log,
+		stats,
+		defaultEmergencyExit,
+	}
+	return audit, nil
 }
 
 // initializeAuditLogger should only be used in unit tests. Failures in this
@@ -96,90 +113,118 @@ func GetAuditLogger() *AuditLogger {
 	return _Singleton.log
 }
 
-// Audit sends a NOTICE-severity message that is prefixed with the
-// audit tag, for special handling at the upstream system logger.
-func (log *AuditLogger) Audit(msg string) (err error) {
-	fmt.Println(msg)
-	err = log.Notice(fmt.Sprintf("%s %s", auditTag, msg))
-
-	log.Stats.Inc("Logging.Audit", 1, 1.0)
-
+// Log the provided message at the appropriate level, writing to
+// both stdout and the Logger, as well as informing statsd.
+func (log *AuditLogger) logAtLevel(level, msg string) (err error) {
+	fmt.Printf("%s\n", msg)
+	log.Stats.Inc(level, 1, 1.0)
+
+	switch level {
+	case "Logging.Alert":
+		err = log.Writer.Alert(msg)
+	case "Logging.Crit":
+		err = log.Writer.Crit(msg)
+	case "Logging.Debug":
+		err = log.Writer.Debug(msg)
+	case "Logging.Emerg":
+		err = log.Writer.Emerg(msg)
+	case "Logging.Err":
+		err = log.Writer.Err(msg)
+	case "Logging.Info":
+		err = log.Writer.Info(msg)
+	case "Logging.Warning":
+		err = log.Writer.Warning(msg)
+	}
 	return
 }
 
-// Audit can format an error for auditing; it does so at ERR level.
-func (log *AuditLogger) AuditErr(msg error) (err error) {
-	fmt.Println(msg)
-	err = log.Err(fmt.Sprintf("%s %s", auditTag, msg))
-
+// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
+func (log *AuditLogger) auditAtLevel(level, msg string) (err error) {
+	// Submit a separate counter that marks an Audit event
 	log.Stats.Inc("Logging.Audit", 1, 1.0)
 
-	return
+	text := fmt.Sprintf("%s %s", auditTag, msg)
+	return log.logAtLevel(level, text)
 }
 
-// Warning formats an error for the Warn level.
-func (log *AuditLogger) WarningErr(msg error) (err error) {
-	fmt.Println(msg)
-	err = log.Warning(fmt.Sprintf("%s", msg))
+// AuditPanic catches panics executables. This method should be added
+// in a defer statement as early as possible
+// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
+func (log *AuditLogger) AuditPanic() {
+	if err := recover(); err != nil {
+		log.Audit(fmt.Sprintf("Panic: %v", err))
+	}
+}
 
-	return
+// WarningErr formats an error for the Warn level.
+func (log *AuditLogger) WarningErr(msg error) (err error) {
+	return log.logAtLevel("Logging.Warning", fmt.Sprintf("%s", msg))
 }
 
+// Alert level messages pass through normally.
 func (log *AuditLogger) Alert(msg string) (err error) {
-	fmt.Println(msg)
-	log.Stats.Inc("Logging.Alert", 1, 1.0)
-	return log.Writer.Alert(msg)
+	return log.logAtLevel("Logging.Alert", msg)
 }
 
+// Crit level messages are automatically marked for audit
 func (log *AuditLogger) Crit(msg string) (err error) {
-	fmt.Println(msg)
-	log.Stats.Inc("Logging.Crit", 1, 1.0)
-	return log.Writer.Crit(msg)
+	return log.auditAtLevel("Logging.Crit", msg)
 }
 
+// Debug level messages pass through normally.
 func (log *AuditLogger) Debug(msg string) (err error) {
-	fmt.Println(msg)
-	log.Stats.Inc("Logging.Debug", 1, 1.0)
-	return log.Writer.Debug(msg)
+	return log.logAtLevel("Logging.Debug", msg)
 }
 
+// Emerg level messages are automatically marked for audit
 func (log *AuditLogger) Emerg(msg string) (err error) {
-	fmt.Println(msg)
-	log.Stats.Inc("Logging.Emerg", 1, 1.0)
-	return log.Writer.Emerg(msg)
+	return log.auditAtLevel("Logging.Emerg", msg)
 }
 
+// Err level messages are automatically marked for audit
 func (log *AuditLogger) Err(msg string) (err error) {
-	fmt.Println(msg)
-	log.Stats.Inc("Logging.Err", 1, 1.0)
-	return log.Writer.Err(msg)
+	return log.auditAtLevel("Logging.Err", msg)
 }
 
+// Info level messages pass through normally.
 func (log *AuditLogger) Info(msg string) (err error) {
-	fmt.Println(msg)
-	log.Stats.Inc("Logging.Info", 1, 1.0)
-	return log.Writer.Info(msg)
+	return log.logAtLevel("Logging.Info", msg)
 }
 
+// Warning level messages pass through normally.
 func (log *AuditLogger) Warning(msg string) (err error) {
-	fmt.Println(msg)
-	log.Stats.Inc("Logging.Warning", 1, 1.0)
-	return log.Writer.Warning(msg)
+	return log.logAtLevel("Logging.Warning", msg)
 }
 
+// Notice level messages pass through normally.
 func (log *AuditLogger) Notice(msg string) (err error) {
-	fmt.Println(msg)
-	log.Stats.Inc("Logging.Notice", 1, 1.0)
-	return log.Writer.Notice(msg)
+	return log.logAtLevel("Logging.Notice", msg)
+}
+
+// Audit sends a NOTICE-severity message that is prefixed with the
+// audit tag, for special handling at the upstream system logger.
+// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
+func (log *AuditLogger) Audit(msg string) (err error) {
+	return log.auditAtLevel("Logging.Notice", msg)
 }
 
-const EMERGENCY_RETVAL = 13
+// AuditErr can format an error for auditing; it does so at ERR level.
+// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
+func (log *AuditLogger) AuditErr(msg error) (err error) {
+	return log.auditAtLevel("Logging.Err", fmt.Sprintf("%s", msg))
+}
+
+// SetEmergencyExitFunc changes the systems' behavior on an emergency exit.
+func (log *AuditLogger) SetEmergencyExitFunc(exit exitFunction) {
+	log.exitFunction = exit
+}
 
+// EmergencyExit triggers an immediate Boulder shutdown in the event of serious
+// errors. This function will provide the necessary housekeeping.
+// Currently, make an emergency log entry and exit; the Activity Monitor
+// should notice the Emerg level event and shut down all components.
+// AUDIT[ Error Conditions ] 9cc4d537-8534-4970-8665-4b382abe82f3
 func (log *AuditLogger) EmergencyExit(msg string) {
-	// Some errors may be serious enough to trigger an immediate Boulder
-	// shutdown.  This function will provide the necessary housekeeping.
-	// Currently, make an emergency log entry and exit; the Activity Monitor
-	// should notice the Emerg level event and shut down all components.
-	log.Emerg(msg)
-	os.Exit(EMERGENCY_RETVAL)
+	log.auditAtLevel("Logging.Emerg", msg)
+	log.exitFunction()
 }