Error Handling and Logging

Error handling and logging are essential parts of application and infrastructure protection. When Error Handling is mentioned, it is referring to the capture of any errors in our application logic that may cause the system to crash, unless handled correctly. On the other hand, logging highlights all the operations and requests that occurred on our system. Logging not only allows the identification of all operations that have occurred, but it also helps determine what actions need to be taken to protect the system. Since attackers often attempt to remove all traces of their action by deleting logs, it’s critical that logs are centralized.

In this chapter

Error Handling

In Go, there is a built-in error type. The different values of error type indicate an abnormal state. Usually in Go, if the error value is not nil then an error has occurred. It must be dealt with in order to allow the application to recover from that state without crashing.

A simple example taken from the Go blog follows:

if err != nil {
    // handle the error
}

Not only can the built-in errors be used, we can also specify our own error types. This can be achieved by using the errors.New function. Example:

{...}
if f < 0 {
    return 0, errors.New("math: square root of negative number")
}
//If an error has occurred print it
if err != nil {
    fmt.Println(err)
}
{...}

If we need to format the string containing the invalid argument to see what caused the error, the Errorf function in the fmt package allows us to do this.

{...}
if f < 0 {
    return 0, fmt.Errorf("math: square root of negative number %g", f)
}
{...}

When dealing with error logs, developers should ensure no sensitive information is disclosed in the error responses, as well as guarantee that no error handlers leak information (e.g. debugging, or stack trace information).

In Go, there are additional error handling functions, these functions are panic, recover and defer. When an application state is panic its normal execution is interrupted, any defer statements are executed, and then the function returns to its caller. recover is usually used inside defer statements and allows the application to regain control over a panicking routine, and return to normal execution. The following snippet, based on the Go documentation explains the execution flow:

func main () {
    start()
    fmt.Println("Returned normally from start().")
}

func start () {
    defer func () {
        if r := recover(); r != nil {
            fmt.Println("Recovered in start()")
        }
    }()
    fmt.Println("Called start()")
    part2(0)
    fmt.Println("Returned normally from part2().")
}

func part2 (i int) {
    if i > 0 {
        fmt.Println("Panicking in part2()!")
        panic(fmt.Sprintf("%v", i))
    }
    defer fmt.Println("Defer in part2()")
    fmt.Println("Executing part2()")
    part2(i + 1)
}

Output:

Called start()
Executing part2()
Panicking in part2()!
Defer in part2()
Recovered in start()
Returned normally from start().

By examining the output, we can see how Go can handle panic situations and recover from them, allowing the application to resume its normal state. These functions allow for a graceful recovery from an otherwise unrecoverable failure.

It is worth noting that defer usages also include Mutex Unlocking, or loading content after the surrounding function has executed (e.g. footer).

In the log package there is also a log.Fatal. Fatal level is effectively logging the message, then calling os.Exit(1). Which means:

  • Defer statements will not be executed.
  • Buffers will not be flushed.
  • Temporary files and directories are not removed.

Considering all the previously mentioned points, we can see how log.Fatal differs from Panic and why it should be used carefully. Some examples of the possible usage of log.Fatal are:

  • Set up logging and check whether we have a healthy environment and parameters. If we don’t, then there’s no need to execute our main().
  • An error that should never occur and that we know that it’s unrecoverable.
  • If a non-interactive process encounters an error and cannot complete, there is no way to notify the user about this error. It’s best to stop the execution before additional problems can emerge from this failure.

To demonstrate, here’s an example of an initialization failure:

func initialize(i int) {
    ...
    //This is just to deliberately crash the function.
    if i < 2 {
        fmt.Printf("Var %d - initialized\n", i)
    } else {
        //This was never supposed to happen, so we'll terminate our program.
        log.Fatal("Init failure - Terminating.")
    }
}

func main() {
    i := 1
    for i < 3 {
        initialize(i)
        i++
    }
    fmt.Println("Initialized all variables successfully")
}

It’s important to assure that in case of an error associated with the security controls, its access is denied by default.

Logging

Logging should always be handled by the application and should not rely on a server configuration.

All logging should be implemented by a master routine on a trusted system, and the developers should also ensure no sensitive data is included in the logs (e.g. passwords, session information, system details, etc.), nor is there any debugging or stack trace information. Additionally, logging should cover both successful and unsuccessful security events, with an emphasis on important log event data.

Important event data most commonly refers to all:

  • Input validation failures.
  • Authentication attempts, especially failures.
  • Access control failures.
  • Apparent tampering events, including unexpected changes to state data.
  • Attempts to connect with invalid or expired session tokens.
  • System exceptions.
  • Administrative functions, including changes to security configuration settings.
  • Backend TLS connection failures and cryptographic module failures.

Here’s a simple log example which illustrates this:

func main() {
    var buf bytes.Buffer
    var RoleLevel int

    logger := log.New(&buf, "logger: ", log.Lshortfile)

    fmt.Println("Please enter your user level.")
    fmt.Scanf("%d", &RoleLevel) //<--- example

    switch RoleLevel {
    case 1:
        // Log successful login
        logger.Printf("Login successful.")
        fmt.Print(&buf)
    case 2:
        // Log unsuccessful Login
        logger.Printf("Login unsuccessful - Insufficient access level.")
        fmt.Print(&buf)
     default:
        // Unspecified error
        logger.Print("Login error.")
        fmt.Print(&buf)
    }
}

It’s also good practice to implement generic error messages, or custom error pages, as a way to make sure that no information is leaked when an error occurs.


[Go’s log package][0], as per the documentation, “implements simple logging”. Some common and important features are missing, such as leveled logging (e.g. debug, info, warn, error, fatal, panic) and formatters support (e.g. logstash). These are two important features to make logs usable (e.g. for integration with a Security Information and Event Management system).

Most, if not all third-party logging packages offer these and other features. The ones below are some of the most popular third-party logging packages:

  • Logrus - https://github.com/Sirupsen/logrus
  • glog - https://github.com/golang/glog
  • loggo - https://github.com/juju/loggo

Here’s an important note regarding Go’s log package: Fatal and Panic functions have different behaviors after logging: Panic functions call panic but Fatal functions call os.Exit(1) that may terminate the program preventing deferred statements to run, buffers to be flushed, and/or temporary data to be removed.


From the perspective of log access, only authorized individuals should have access to the logs. Developers should also make sure that a mechanism that allows for log analysis is set in place, as well as guarantee that no untrusted data will be executed as code in the intended log viewing software or interface.

Regarding allocated memory cleanup, Go has a built-in Garbage Collector for this very purpose.

As a final step to guarantee log validity and integrity, a cryptographic hash function should be used as an additional step to ensure no log tampering has taken place.

{...}
// Get our known Log checksum from checksum file.
logChecksum, err := ioutil.ReadFile("log/checksum")
str := string(logChecksum) // convert content to a 'string'

// Compute our current log's SHA256 hash
b, err := ComputeSHA256("log/log")
if err != nil {
  fmt.Printf("Err: %v", err)
} else {
  hash := hex.EncodeToString(b)
  // Compare our calculated hash with our stored hash
  if str == hash {
    // Ok the checksums match.
    fmt.Println("Log integrity OK.")
  } else {
    // The file integrity has been compromised...
    fmt.Println("File Tampering detected.")
  }
}
{...}

Note: The ComputeSHA256() function calculates a file’s SHA256. It’s also important to note that the log-file hashes must be stored in a safe place, and compared with the current log hash to verify integrity before any updates to the log. Working source code is below.

  1. Under /log folder, create two files: checksum and log

checksum:

abf72fbe055fa68d08f31447bcd00297eb9641db5b0acd7ba052b1602b1249cd

log:

This a sample log entry.
  1. Then use the following script log-integrity.go:
package main

import (
	"crypto/sha256"
	"encoding/hex"
	"fmt"
	"io"
	"io/ioutil"
	"os"
)

func main() {
	logChecksum, err := ioutil.ReadFile("log/checksum")
	if err != nil {
		fmt.Println(err)
	}

	str := string(logChecksum) // convert content to a 'string'

	if b, err := ComputeSHA256("log/log"); err != nil {
		fmt.Printf("Err: %v", err)
	} else {
		hash := hex.EncodeToString(b)
		if str == hash {
			fmt.Println("Log integrity OK.")
		} else {
			fmt.Println("File Tampering detected.")
		}
	}
}

func ComputeSHA256(filePath string) ([]byte, error) {
	var result []byte
	file, err := os.Open(filePath)
	if err != nil {
		return result, err
	}
	defer file.Close()

	hash := sha256.New()
	if _, err := io.Copy(hash, file); err != nil {
		return result, err
	}

	return hash.Sum(result), nil
}

Licenses and Attributions


Speak Your Mind