Books / Go - Secure Coding Practices / Chapter 8
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.
- Under
/log
folder, create two files:checksum
andlog
checksum
:
abf72fbe055fa68d08f31447bcd00297eb9641db5b0acd7ba052b1602b1249cd
log
:
This a sample log entry.
- 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
}