Repository: sonatype-nexus-community/nancy (go)

Issue:
Implement logging for Nancy
Thanks for creating an issue! Please fill out this form so we can be
sure to have all the information we need, and to minimize back and forth.

* **What are you trying to do?**
Nancy could use some logging, for helping people diagnose issues like @fitzoh in https://github.com/sonatype-nexus-community/nancy/issues/71

* **What feature or behavior is this required for?**
It is just a way we can get some better detail from users when they run into issues

* **How could we solve this issue? (Not knowing is okay!)**
The suggestion is to:

- Log to `~/.ossindex`
- Provide a mechanism to specify the log location (if someone wants to log to `/tmp`, etc...
- Log debug by default to it's own file (all log levels), and then errors to an error file
- Maybe cycle logs on each request (so people don't end up with a growing log file and have no idea why)
- DO NOT LOG SENSITIVE INFO

* **Anything else?**
Have fun!?

cc @bhamail / @DarthHater


Pull request:
Initial logging
Welp, it's about time we got better about logging!

This pull request makes the following changes:
* Adds a logger package, so you can obtain a logger from anywhere
* Partially implements the logger for the IQ path (thus far)

It relates to the following issue #s:
* Fixes #76 

cc @bhamail / @DarthHater / @zendern / @fitzoh 


Patch:
diff --git a/README.md b/README.md
index fe53449..9ff2ed5 100644
--- a/README.md
+++ b/README.md
@@ -16,27 +16,33 @@
 ```
  ~ > nancy
 Usage:
+        go list -m all | nancy [options]
+        go list -m all | nancy iq [options]
         nancy [options] </path/to/Gopkg.lock>
         nancy [options] </path/to/go.sum>
-        nancy iq [options]
 
 Options:
   -clean-cache
-    	Deletes local cache directory
+        Deletes local cache directory
   -exclude-vulnerability value
-    	Comma separated list of CVEs to exclude
+        Comma separated list of CVEs to exclude
   -exclude-vulnerability-file string
         Path to a file containing newline separated CVEs to be excluded (default "./.nancy-ignore")
   -help
         provides help text on how to use nancy
   -no-color
-    	indicate output should not be colorized
+        indicate output should not be colorized
   -output string
-    	Styling for output format. ["json-pretty" "text" "csv" "json"] (default "text")
+        Styling for output format. ["json" "json-pretty" "text" "csv"] (default "text")
   -quiet
-    	indicate output should contain only packages with vulnerabilities
+        indicate output should contain only packages with vulnerabilities
+  -v    Set log level to Info
   -version
         prints current nancy version
+  -vv
+        Set log level to Debug
+  -vvv
+        Set log level to Trace
 
 $ > nancy iq
 Usage:
@@ -55,6 +61,11 @@ Options:
         Specify token/password for request (default "admin123")
   -user string
         Specify username for request (default "admin")
+  -v    Set log level to Info
+  -vv
+        Set log level to Debug
+  -vvv
+        Set log level to Trace
 ```
 
 `nancy` currently works for projects that use `dep` or `go mod` for dependencies.
diff --git a/configuration/parse.go b/configuration/parse.go
index 2c3a7ec..2878b60 100644
--- a/configuration/parse.go
+++ b/configuration/parse.go
@@ -39,6 +39,9 @@ type Configuration struct {
 	CveList    types.CveListFlag
 	Path       string
 	Formatter  logrus.Formatter
+	Info       bool
+	Debug      bool
+	Trace      bool
 }
 
 type IqConfiguration struct {
@@ -50,6 +53,9 @@ type IqConfiguration struct {
 	Application string
 	Server      string
 	MaxRetries  int
+	Info        bool
+	Debug       bool
+	Trace       bool
 }
 
 var unixComments = regexp.MustCompile(`#.*$`)
@@ -57,6 +63,9 @@ var untilComment = regexp.MustCompile(`(until=)(.*)`)
 
 func ParseIQ(args []string) (config IqConfiguration, err error) {
 	iqCommand := flag.NewFlagSet("iq", flag.ExitOnError)
+	iqCommand.BoolVar(&config.Info, "v", false, "Set log level to Info")
+	iqCommand.BoolVar(&config.Debug, "vv", false, "Set log level to Debug")
+	iqCommand.BoolVar(&config.Trace, "vvv", false, "Set log level to Trace")
 	iqCommand.StringVar(&config.User, "user", "admin", "Specify username for request")
 	iqCommand.StringVar(&config.Token, "token", "admin123", "Specify token/password for request")
 	iqCommand.StringVar(&config.Server, "server-url", "http://localhost:8070", "Specify Nexus IQ Server URL/port")
@@ -99,6 +108,9 @@ func Parse(args []string) (Configuration, error) {
 	flag.BoolVar(&config.Quiet, "quiet", false, "indicate output should contain only packages with vulnerabilities")
 	flag.BoolVar(&config.Version, "version", false, "prints current nancy version")
 	flag.BoolVar(&config.CleanCache, "clean-cache", false, "Deletes local cache directory")
+	flag.BoolVar(&config.Info, "v", false, "Set log level to Info")
+	flag.BoolVar(&config.Debug, "vv", false, "Set log level to Debug")
+	flag.BoolVar(&config.Trace, "vvv", false, "Set log level to Trace")
 	flag.Var(&config.CveList, "exclude-vulnerability", "Comma separated list of CVEs to exclude")
 	flag.StringVar(&excludeVulnerabilityFilePath, "exclude-vulnerability-file", "./.nancy-ignore", "Path to a file containing newline separated CVEs to be excluded")
 	flag.StringVar(&outputFormat, "output", "text", "Styling for output format. "+fmt.Sprintf("%+q", reflect.ValueOf(outputFormats).MapKeys()))
diff --git a/customerrors/error.go b/customerrors/error.go
index a5c842c..29bc348 100644
--- a/customerrors/error.go
+++ b/customerrors/error.go
@@ -18,6 +18,7 @@ import (
 	"os"
 
 	"github.com/sonatype-nexus-community/nancy/buildversion"
+	. "github.com/sonatype-nexus-community/nancy/logger"
 )
 
 type SwError struct {
@@ -36,7 +37,9 @@ func (sw SwError) Exit() {
 func Check(err error, message string) {
 	if err != nil {
 		myErr := SwError{Message: message, Err: err}
+		LogLady.WithField("error", err).Error(message)
 		fmt.Println(myErr.Error())
+		fmt.Printf("For more information, check the log file at %s\n", GetLogFileLocation())
 		fmt.Println("nancy version:", buildversion.BuildVersion)
 		myErr.Exit()
 	}
diff --git a/go.mod b/go.mod
index e09b562..da1e48f 100644
--- a/go.mod
+++ b/go.mod
@@ -29,7 +29,7 @@ require (
 	github.com/stretchr/testify v1.3.0
 	golang.org/x/net v0.0.0-20181220203305-927f97764cc3 // indirect
 	golang.org/x/sync v0.0.0-20181221193216-37e7f081c4d4 // indirect
-	golang.org/x/sys v0.0.0-20200202164722-d101bd2416d5 // indirect
+	golang.org/x/sys v0.0.0-20200302150141-5c8b2ff67527 // indirect
 	gopkg.in/go-playground/assert.v1 v1.2.1
 )
 
diff --git a/go.sum b/go.sum
index 282a86d..2d9cb31 100644
--- a/go.sum
+++ b/go.sum
@@ -67,8 +67,8 @@ golang.org/x/net v0.0.0-20181220203305-927f97764cc3/go.mod h1:mL1N/T3taQHkDXs73r
 golang.org/x/sync v0.0.0-20181221193216-37e7f081c4d4 h1:YUO/7uOKsKeq9UokNS62b8FYywz3ker1l1vDZRCRefw=
 golang.org/x/sync v0.0.0-20181221193216-37e7f081c4d4/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
 golang.org/x/sys v0.0.0-20190422165155-953cdadca894/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
-golang.org/x/sys v0.0.0-20200202164722-d101bd2416d5 h1:LfCXLvNmTYH9kEmVgqbnsWfruoXZIrh4YBgqVHtDvw0=
-golang.org/x/sys v0.0.0-20200202164722-d101bd2416d5/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20200302150141-5c8b2ff67527 h1:uYVVQ9WP/Ds2ROhcaGPeIdVq0RIXVLwsHlnvJ+cT1So=
+golang.org/x/sys v0.0.0-20200302150141-5c8b2ff67527/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/text v0.3.0 h1:g61tztE5qeGQ89tm6NTjjM9VPIm088od1l6aSorWRWg=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=
diff --git a/iq/iq.go b/iq/iq.go
index b9bbb87..636d885 100644
--- a/iq/iq.go
+++ b/iq/iq.go
@@ -23,9 +23,11 @@ import (
 	"net/http"
 	"time"
 
+	"github.com/sirupsen/logrus"
 	"github.com/sonatype-nexus-community/nancy/configuration"
 	"github.com/sonatype-nexus-community/nancy/customerrors"
 	"github.com/sonatype-nexus-community/nancy/cyclonedx"
+	. "github.com/sonatype-nexus-community/nancy/logger"
 	"github.com/sonatype-nexus-community/nancy/ossindex"
 	"github.com/sonatype-nexus-community/nancy/types"
 	"github.com/sonatype-nexus-community/nancy/useragent"
@@ -64,14 +66,20 @@ var statusURLResp types.StatusURLResult
 // AuditPackages accepts a slice of purls, public application ID, and configuration, and will submit these to
 // Nexus IQ Server for audit, and return a struct of StatusURLResult
 func AuditPackages(purls []string, applicationID string, config configuration.IqConfiguration) (types.StatusURLResult, error) {
+	LogLady.WithFields(logrus.Fields{
+		"purls":          purls,
+		"application_id": applicationID,
+	}).Info("Beginning audit with IQ")
 	localConfig = config
 
 	if localConfig.User == "admin" && localConfig.Token == "admin123" {
+		LogLady.Info("Warning user of questionable life choices related to username and password")
 		warnUserOfBadLifeChoices()
 	}
 
 	internalID := getInternalApplicationID(applicationID)
 	if internalID == "" {
+		LogLady.Error("Internal ID not obtained from Nexus IQ")
 		return statusURLResp, fmt.Errorf("Internal ID for %s could not be found, or Nexus IQ Server is down", applicationID)
 	}
 
@@ -79,8 +87,15 @@ func AuditPackages(purls []string, applicationID string, config configuration.Iq
 	customerrors.Check(err, "There was an issue auditing packages using OSS Index")
 
 	sbom := cyclonedx.ProcessPurlsIntoSBOM(resultsFromOssIndex)
+	LogLady.WithField("sbom", sbom).Debug("Obtained cyclonedx SBOM")
+
+	LogLady.WithFields(logrus.Fields{
+		"internal_id": internalID,
+		"sbom":        sbom,
+	}).Debug("Submitting to Third Party API")
 	statusURL := submitToThirdPartyAPI(sbom, internalID)
 	if statusURL == "" {
+		LogLady.Error("StatusURL not obtained from Third Party API")
 		return statusURLResp, fmt.Errorf("There was an issue submitting your sbom to the Nexus IQ Third Party API, sbom: %s", sbom)
 	}
 
@@ -133,9 +148,11 @@ func getInternalApplicationID(applicationID string) (internalID string) {
 }
 
 func submitToThirdPartyAPI(sbom string, internalID string) string {
+	LogLady.Debug("Beginning to submit to Third Party API")
 	client := &http.Client{}
 
 	url := fmt.Sprintf("%s%s", localConfig.Server, fmt.Sprintf("%s%s%s%s", thirdPartyAPILeft, internalID, thirdPartyAPIRight, localConfig.Stage))
+	LogLady.WithField("url", url).Debug("Crafted URL for submission to Third Party API")
 
 	req, err := http.NewRequest(
 		"POST",
@@ -154,18 +171,32 @@ func submitToThirdPartyAPI(sbom string, internalID string) string {
 
 	if resp.StatusCode == http.StatusAccepted {
 		bodyBytes, err := ioutil.ReadAll(resp.Body)
+		LogLady.WithField("body", string(bodyBytes)).Info("Request accepted")
 		customerrors.Check(err, "There was an issue submitting your sbom to the Nexus IQ Third Party API")
 
 		var response thirdPartyAPIResult
 		json.Unmarshal(bodyBytes, &response)
 		return response.StatusURL
 	}
+	bodyBytes, err := ioutil.ReadAll(resp.Body)
+	LogLady.WithFields(logrus.Fields{
+		"body":        string(bodyBytes),
+		"status_code": resp.StatusCode,
+		"status":      resp.Status,
+	}).Info("Request not accepted")
+	customerrors.Check(err, "There was an issue submitting your sbom to the Nexus IQ Third Party API")
 
 	return ""
 }
 
 func pollIQServer(statusURL string, finished chan bool, maxRetries int) {
+	LogLady.WithFields(logrus.Fields{
+		"attempt_number": tries,
+		"max_retries":    maxRetries,
+		"status_url":     statusURL,
+	}).Trace("Polling Nexus IQ for response")
 	if tries > maxRetries {
+		LogLady.Error("Maximum tries exceeded, finished polling, consider bumping up Max Retries")
 		finished <- true
 	}
 
diff --git a/logger/logger.go b/logger/logger.go
new file mode 100644
index 0000000..e8baa04
--- /dev/null
+++ b/logger/logger.go
@@ -0,0 +1,54 @@
+// Copyright 2020 Sonatype Inc.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+// Package logger has functions to obtain a logger, and helpers for setting up where the logger writes
+package logger
+
+import (
+	"fmt"
+	"os"
+	"path"
+
+	"github.com/sirupsen/logrus"
+	"github.com/sonatype-nexus-community/nancy/types"
+)
+
+// DefaultLogFile can be overriden to use a different file name for upstream consumers
+var DefaultLogFile = "nancy.combined.log"
+
+// LogLady can be obtained from outside the package, the name is a reference to the brilliant
+// actress in Twin Peaks
+var LogLady = logrus.New()
+
+func init() {
+	if len(os.Args) > 1 && os.Args[1] != "iq" && os.Args[1][:5] == "-test" {
+		DefaultLogFile = "nancy.test.log"
+	}
+	file, err := os.OpenFile(GetLogFileLocation(), os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0666)
+	if err != nil {
+		fmt.Print(err)
+	}
+
+	LogLady.Out = file
+	LogLady.Level = logrus.InfoLevel
+	LogLady.Formatter = &logrus.JSONFormatter{}
+}
+
+// GetLogFileLocation will return the location on disk of the log file
+func GetLogFileLocation() (result string) {
+	result, _ = os.UserHomeDir()
+	os.MkdirAll(path.Join(result, types.OssIndexDirName), os.ModePerm)
+	result = path.Join(result, types.OssIndexDirName, DefaultLogFile)
+	return
+}
diff --git a/main.go b/main.go
index a0c773e..1a7323b 100644
--- a/main.go
+++ b/main.go
@@ -18,13 +18,13 @@ import (
 	"errors"
 	"flag"
 	"fmt"
-	"io/ioutil"
-	"log"
 	"os"
 	"path/filepath"
 	"reflect"
 	"strings"
 
+	"github.com/sirupsen/logrus"
+	. "github.com/sonatype-nexus-community/nancy/logger"
 	"github.com/sonatype-nexus-community/nancy/types"
 
 	figure "github.com/common-nighthawk/go-figure"
@@ -40,118 +40,200 @@ import (
 )
 
 func main() {
+	LogLady.Info("Starting Nancy")
+
 	if len(os.Args) > 1 && os.Args[1] == "iq" {
+		LogLady.Info("Nancy parsing config for IQ")
 		config, err := configuration.ParseIQ(os.Args[2:])
 		if err != nil {
 			flag.Usage()
 			os.Exit(1)
 		}
+		LogLady.WithField("config", config).Info("Obtained IQ config")
 		processIQConfig(config)
+		LogLady.Info("Nancy finished parsing config for IQ")
 	} else {
+		LogLady.Info("Nancy parsing config for OSS Index")
 		ossIndexConfig, err := configuration.Parse(os.Args[1:])
 		if err != nil {
 			flag.Usage()
 			os.Exit(1)
 		}
 		processConfig(ossIndexConfig)
+		LogLady.Info("Nancy finished parsing config for OSS Index")
 	}
 }
 
 func printHeader(print bool) {
 	if print {
+		LogLady.Info("Attempting to print header")
 		figure.NewFigure("Nancy", "larry3d", true).Print()
 		figure.NewFigure("By Sonatype & Friends", "pepper", true).Print()
-		log.Println("Nancy version: " + buildversion.BuildVersion)
+
+		LogLady.WithField("version", buildversion.BuildVersion).Info("Printing Nancy version")
+		fmt.Println("Nancy version: " + buildversion.BuildVersion)
+		LogLady.Info("Finished printing header")
 	}
 }
 
 func processConfig(config configuration.Configuration) {
 	if config.Help {
+		LogLady.Info("Printing usage and exiting clean")
 		flag.Usage()
 		os.Exit(0)
 	}
 
 	if config.Version {
+		LogLady.WithFields(logrus.Fields{
+			"build_time":   buildversion.BuildTime,
+			"build_commit": buildversion.BuildCommit,
+			"version":      buildversion.BuildVersion,
+		}).Info("Printing version information and exiting clean")
+
 		fmt.Println(buildversion.BuildVersion)
 		_, _ = fmt.Printf("build time: %s\n", buildversion.BuildTime)
 		_, _ = fmt.Printf("build commit: %s\n", buildversion.BuildCommit)
 		os.Exit(0)
 	}
 
+	if config.Info {
+		LogLady.Level = logrus.InfoLevel
+	}
+	if config.Debug {
+		LogLady.Level = logrus.DebugLevel
+	}
+	if config.Trace {
+		LogLady.Level = logrus.TraceLevel
+	}
+
 	if config.CleanCache {
+		LogLady.Info("Attempting to clean cache")
 		if err := ossindex.RemoveCacheDirectory(); err != nil {
+			LogLady.WithField("error", err).Error("Error cleaning cache")
 			fmt.Printf("ERROR: cleaning cache: %v\n", err)
 			os.Exit(1)
 		}
+		LogLady.Info("Cache cleaned")
 		return
 	}
 
-	if config.Quiet {
-		log.SetOutput(ioutil.Discard)
-	}
-
 	printHeader((!config.Quiet && reflect.TypeOf(config.Formatter).String() == "*audit.AuditLogTextFormatter"))
 
 	if config.UseStdIn {
+		LogLady.Info("Parsing config for StdIn")
 		doStdInAndParse(config)
 	}
 	if !config.UseStdIn {
+		LogLady.Info("Parsing config for file based scan")
 		doCheckExistenceAndParse(config)
 	}
 }
 
 func processIQConfig(config configuration.IqConfiguration) {
+	// TODO: a lot of this code is a duplication of the OSS Index config, probably should extract some of it
 	if config.Help {
+		LogLady.Info("Printing usage and exiting clean")
 		flag.Usage()
 		os.Exit(0)
 	}
 
 	if config.Version {
+		LogLady.WithFields(logrus.Fields{
+			"build_time":   buildversion.BuildTime,
+			"build_commit": buildversion.BuildCommit,
+			"version":      buildversion.BuildVersion,
+		}).Info("Printing version information and exiting clean")
+
 		fmt.Println(buildversion.BuildVersion)
 		_, _ = fmt.Printf("build time: %s\n", buildversion.BuildTime)
 		_, _ = fmt.Printf("build commit: %s\n", buildversion.BuildCommit)
 		os.Exit(0)
 	}
 
+	if config.Info {
+		LogLady.Level = logrus.InfoLevel
+	}
+	if config.Debug {
+		LogLady.Level = logrus.DebugLevel
+	}
+	if config.Trace {
+		LogLady.Level = logrus.TraceLevel
+	}
+
 	if config.Application == "" {
+		LogLady.Info("No application specified, printing usage and exiting clean")
 		flag.Usage()
+		os.Exit(0)
 	}
 
 	printHeader(true)
 
+	LogLady.Info("Parsing IQ config for StdIn")
 	doStdInAndParseForIQ(config)
 }
 
 func doStdInAndParse(config configuration.Configuration) {
+	LogLady.Info("Beginning StdIn parse for OSS Index")
 	fi, err := os.Stdin.Stat()
 	if err != nil {
+		LogLady.WithField("error", err).Error("Error obtaining Std In")
 		panic(err)
 	}
 	if (fi.Mode() & os.ModeNamedPipe) == 0 {
+		LogLady.Error("Error obtaining StdIn, showing usage and exiting with error")
 		flag.Usage()
 		os.Exit(1)
 	} else {
+		LogLady.Info("Instantiating go.mod package")
+
 		mod := packages.Mod{}
 		scanner := bufio.NewScanner(os.Stdin)
+
+		LogLady.Info("Beginning to parse StdIn")
 		mod.ProjectList, _ = parse.GoList(scanner)
+		LogLady.WithFields(logrus.Fields{
+			"projectList": mod.ProjectList,
+		}).Debug("Obtained project list")
+
 		var purls = mod.ExtractPurlsFromManifest()
+		LogLady.WithFields(logrus.Fields{
+			"purls": purls,
+		}).Debug("Extracted purls")
+
+		LogLady.Info("Auditing purls with OSS Index")
 		checkOSSIndex(purls, nil, config)
 	}
 }
 
 func doStdInAndParseForIQ(config configuration.IqConfiguration) {
+	LogLady.Debug("Beginning StdIn parse for IQ")
 	fi, err := os.Stdin.Stat()
 	if err != nil {
+		LogLady.WithField("error", err).Error("Error obtaining Std In")
 		panic(err)
 	}
 	if (fi.Mode() & os.ModeNamedPipe) == 0 {
+		LogLady.Error("Error obtaining StdIn, showing usage and exiting with error")
 		flag.Usage()
 		os.Exit(1)
 	} else {
+		LogLady.Info("Instantiating go.mod package")
+
 		mod := packages.Mod{}
 		scanner := bufio.NewScanner(os.Stdin)
+
+		LogLady.Info("Beginning to parse StdIn")
 		mod.ProjectList, _ = parse.GoList(scanner)
+		LogLady.WithFields(logrus.Fields{
+			"projectList": mod.ProjectList,
+		}).Debug("Obtained project list")
+
 		var purls = mod.ExtractPurlsFromManifestForIQ()
+		LogLady.WithFields(logrus.Fields{
+			"purls": purls,
+		}).Debug("Extracted purls")
+
+		LogLady.Info("Auditing purls with IQ Server")
 		auditWithIQServer(purls, config.Application, config)
 	}
 }
@@ -209,19 +291,23 @@ func checkOSSIndex(purls []string, invalidpurls []string, config configuration.C
 }
 
 func auditWithIQServer(purls []string, applicationID string, config configuration.IqConfiguration) {
+	LogLady.Debug("Sending purls to be Audited by IQ Server")
 	res, err := iq.AuditPackages(purls, applicationID, config)
 	customerrors.Check(err, "Uh oh! There was an error with your request to Nexus IQ Server")
 
 	fmt.Println()
 	if res.IsError {
+		LogLady.WithField("res", res).Error("An error occurred with the request to IQ Server")
 		customerrors.Check(errors.New(res.ErrorMessage), "Uh oh! There was an error with your request to Nexus IQ Server")
 	}
 
 	if res.PolicyAction != "Failure" {
+		LogLady.WithField("res", res).Debug("Successful in communicating with IQ Server")
 		fmt.Println("Wonderbar! No policy violations reported for this audit!")
 		fmt.Println("Report URL: ", res.ReportHTMLURL)
 		os.Exit(0)
 	} else {
+		LogLady.WithField("res", res).Debug("Successful in communicating with IQ Server")
 		fmt.Println("Hi, Nancy here, you have some policy violations to clean up!")
 		fmt.Println("Report URL: ", res.ReportHTMLURL)
 		os.Exit(1)
diff --git a/ossindex/ossindex.go b/ossindex/ossindex.go
index fa084d6..0c2f086 100644
--- a/ossindex/ossindex.go
+++ b/ossindex/ossindex.go
@@ -21,15 +21,16 @@ import (
 	"flag"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"net/http"
 	"os"
 	"os/user"
+	"path"
 	"strings"
 	"time"
 
 	"github.com/dgraph-io/badger"
 	"github.com/sonatype-nexus-community/nancy/customerrors"
+	. "github.com/sonatype-nexus-community/nancy/logger"
 	"github.com/sonatype-nexus-community/nancy/types"
 	"github.com/sonatype-nexus-community/nancy/useragent"
 )
@@ -45,10 +46,20 @@ var (
 )
 
 func getDatabaseDirectory() (dbDir string) {
+	LogLady.Trace("Attempting to get database directory")
 	usr, err := user.Current()
 	customerrors.Check(err, "Error getting user home")
 
-	return usr.HomeDir + "/.ossindex"
+	LogLady.WithField("home_dir", usr.HomeDir).Trace("Obtained user directory")
+	var leftPath = path.Join(usr.HomeDir, types.OssIndexDirName)
+	var fullPath string
+	if flag.Lookup("test") == nil {
+		fullPath = path.Join(leftPath, dbValueDirName)
+	} else {
+		fullPath = path.Join(leftPath, "test-nancy")
+	}
+
+	return fullPath
 }
 
 // RemoveCacheDirectory deletes the local database directory.
@@ -64,14 +75,13 @@ func getOssIndexUrl() string {
 }
 
 func openDb(dbDir string) (db *badger.DB, err error) {
+	LogLady.Debug("Attempting to open Badger DB")
 	opts := badger.DefaultOptions
-	if flag.Lookup("test") == nil {
-		opts.Dir = dbDir + "/" + dbValueDirName
-		opts.ValueDir = dbDir + "/" + dbValueDirName
-	} else {
-		opts.Dir = dbDir + "/" + "test-nancy"
-		opts.ValueDir = dbDir + "/" + "test-nancy"
-	}
+
+	opts.Dir = getDatabaseDirectory()
+	opts.ValueDir = getDatabaseDirectory()
+	LogLady.WithField("badger_opts", opts).Debug("Set Badger Options")
+
 	db, err = badger.Open(opts)
 	return
 }
@@ -134,17 +144,19 @@ func AuditPackages(purls []string) ([]types.Coordinate, error) {
 			}
 
 			if resp.StatusCode != http.StatusOK {
+				LogLady.WithField("resp_status_code", resp.Status).Error("Error accessing OSS Index")
 				return nil, fmt.Errorf("[%s] error accessing OSS Index", resp.Status)
 			}
 
 			defer func() {
 				if err := resp.Body.Close(); err != nil {
-					log.Printf("error closing response body: %s\n", err)
+					LogLady.WithField("error", err).Error("Error closing response body")
 				}
 			}()
 
 			body, err := ioutil.ReadAll(resp.Body)
 			if err != nil {
+				LogLady.WithField("error", err).Error("Error accessing OSS Index")
 				return nil, err
 			}
 
@@ -194,6 +206,7 @@ func chunk(purls []string, chunkSize int) [][]string {
 }
 
 func setupRequest(jsonStr []byte) (req *http.Request, err error) {
+	LogLady.WithField("json_string", string(jsonStr)).Debug("Setting up new POST request to OSS Index")
 	req, err = http.NewRequest(
 		"POST",
 		getOssIndexUrl(),
diff --git a/types/types.go b/types/types.go
index 895f56d..b8d193b 100644
--- a/types/types.go
+++ b/types/types.go
@@ -21,6 +21,11 @@ import (
 	decimal "github.com/shopspring/decimal"
 )
 
+// Helpful constants to pull strings we use more than once out of code
+const (
+	OssIndexDirName = ".ossindex"
+)
+
 type Vulnerability struct {
 	Id          string
 	Title       string
diff --git a/useragent/useragent.go b/useragent/useragent.go
index 968e5bc..0154f97 100644
--- a/useragent/useragent.go
+++ b/useragent/useragent.go
@@ -21,6 +21,7 @@ import (
 	"runtime"
 
 	"github.com/sonatype-nexus-community/nancy/buildversion"
+	. "github.com/sonatype-nexus-community/nancy/logger"
 )
 
 // Variables that can be overriden (primarily for tests), or for consumers
@@ -36,6 +37,7 @@ var (
 // can be used to tell if nancy is being ran inside an orb, bitbucket pipeline, etc... that
 // we authored
 func GetUserAgent() string {
+	LogLady.Debug("Obtaining User Agent")
 	// where callTree format is:
 	// toolName__toolVersion___subToolName__subToolVersion___subSubToolName__subSubToolVersion
 	//
@@ -48,36 +50,49 @@ func GetUserAgent() string {
 	return getUserAgent("non ci usage", callTree)
 }
 
-func getUserAgentBaseAndVersion() string {
-	return fmt.Sprintf("%s/%s", CLIENTTOOL, buildversion.BuildVersion)
+func getUserAgentBaseAndVersion() (baseAgent string) {
+	LogLady.Trace("Attempting to obtain user agent and version")
+	baseAgent = fmt.Sprintf("%s/%s", CLIENTTOOL, buildversion.BuildVersion)
+	LogLady.WithField("user_agent_base", baseAgent).Trace("Obtained user agent and version")
+	return
 }
 
 func checkCIEnvironments(callTree string) string {
 	if checkForCISystem("CIRCLECI") {
+		LogLady.Trace("CircleCI usage")
 		return getUserAgent("circleci", callTree)
 	}
 	if checkForCISystem("BITBUCKET_BUILD_NUMBER") {
+		LogLady.Trace("BitBucket usage")
 		return getUserAgent("bitbucket", callTree)
 	}
 	if checkForCISystem("TRAVIS") {
+		LogLady.Trace("TravisCI usage")
 		return getUserAgent("travis-ci", callTree)
 	}
 	if checkForCISystem("GITLAB_CI") {
+		LogLady.Trace("GitLab usage")
 		return getUserAgent("gitlab-ci", callTree)
 	}
 	if checkIfJenkins() {
+		LogLady.Trace("Jenkins usage")
 		return getUserAgent("jenkins", callTree)
 	}
 	if checkIfGitHub() {
 		id := getGitHubActionID()
+		LogLady.WithField("gh_action_id", id).Trace("GitHub Actions usage")
 		return getUserAgent(fmt.Sprintf("github-action %s", id), callTree)
 	}
 
+	LogLady.Trace("Returning User Agent")
 	return getUserAgent("ci usage", callTree)
 }
 
-func getUserAgent(agent string, callTree string) string {
-	return fmt.Sprintf("%s (%s; %s %s; %s)", getUserAgentBaseAndVersion(), agent, GOOS, GOARCH, callTree)
+func getUserAgent(agent string, callTree string) (userAgent string) {
+	LogLady.Trace("Obtaining parsed User Agent string")
+	userAgent = fmt.Sprintf("%s (%s; %s %s; %s)", getUserAgentBaseAndVersion(), agent, GOOS, GOARCH, callTree)
+	LogLady.WithField("user_agent_parsed", userAgent).Trace("Obtained parsed User Agent string")
+	return
 }
 
 func checkForCIEnvironment() bool {


Test patch:
diff --git a/configuration/parse_test.go b/configuration/parse_test.go
index 914c76a..513d37e 100644
--- a/configuration/parse_test.go
+++ b/configuration/parse_test.go
@@ -86,6 +86,9 @@ func TestConfigParse(t *testing.T) {
 		"output of csv":               {args: []string{"-output=csv", "/tmp/go16.sum"}, expectedConfig: Configuration{Formatter: &audit.CsvFormatter{Quiet: &boolFalse}, Path: "/tmp/go16.sum"}, expectedErr: nil},
 		"output of text":              {args: []string{"-output=text", "/tmp/go17.sum"}, expectedConfig: Configuration{Formatter: defaultAuditLogFormatter, Path: "/tmp/go17.sum"}, expectedErr: nil},
 		"output of bad value":         {args: []string{"-output=aintgonnadoit", "/tmp/go18.sum"}, expectedConfig: Configuration{Formatter: defaultAuditLogFormatter, Path: "/tmp/go18.sum"}, expectedErr: nil},
+		"log level of info":           {args: []string{"-v"}, expectedConfig: Configuration{UseStdIn: true, Formatter: defaultAuditLogFormatter, Info: true}, expectedErr: nil},
+		"log level of debug":          {args: []string{"-vv"}, expectedConfig: Configuration{UseStdIn: true, Formatter: defaultAuditLogFormatter, Debug: true}, expectedErr: nil},
+		"log level of trace":          {args: []string{"-vvv"}, expectedConfig: Configuration{UseStdIn: true, Formatter: defaultAuditLogFormatter, Trace: true}, expectedErr: nil},
 	}
 
 	for name, test := range tests {
@@ -120,6 +123,9 @@ func TestConfigParseIQ(t *testing.T) {
 		"max-retries non default": {args: []string{"iq", "-max-retries", "200"}, expectedConfig: IqConfiguration{Help: false, Version: false, User: "admin", Token: "admin123", Stage: "develop", Server: "http://localhost:8070", MaxRetries: 200}, expectedErr: nil},
 		"stage non default":       {args: []string{"iq", "-stage", "build"}, expectedConfig: IqConfiguration{Help: false, Version: false, User: "admin", Token: "admin123", Stage: "build", Server: "http://localhost:8070", MaxRetries: 300}, expectedErr: nil},
 		"specify application":     {args: []string{"iq", "-application", "testapp"}, expectedConfig: IqConfiguration{Help: false, Version: false, User: "admin", Token: "admin123", Stage: "develop", Server: "http://localhost:8070", MaxRetries: 300, Application: "testapp"}, expectedErr: nil},
+		"log level of info":       {args: []string{"iq", "-v"}, expectedConfig: IqConfiguration{User: "admin", Token: "admin123", Stage: "develop", Server: "http://localhost:8070", MaxRetries: 300, Info: true}, expectedErr: nil},
+		"log level of debug":      {args: []string{"iq", "-vv"}, expectedConfig: IqConfiguration{User: "admin", Token: "admin123", Stage: "develop", Server: "http://localhost:8070", MaxRetries: 300, Debug: true}, expectedErr: nil},
+		"log level of trace":      {args: []string{"iq", "-vvv"}, expectedConfig: IqConfiguration{User: "admin", Token: "admin123", Stage: "develop", Server: "http://localhost:8070", MaxRetries: 300, Trace: true}, expectedErr: nil},
 	}
 
 	for name, test := range tests {
diff --git a/logger/logger_test.go b/logger/logger_test.go
new file mode 100644
index 0000000..de5449a
--- /dev/null
+++ b/logger/logger_test.go
@@ -0,0 +1,66 @@
+// Copyright 2020 Sonatype Inc.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+// Package logger has functions to obtain a logger, and helpers for setting up where the logger writes
+package logger
+
+import (
+	"encoding/json"
+	"io/ioutil"
+	"os"
+	"strings"
+	"testing"
+
+	"github.com/sirupsen/logrus"
+)
+
+func TestLogger(t *testing.T) {
+	LogLady.Level = logrus.DebugLevel
+	// Do initial write to have a file
+	LogLady.Debug("Test")
+
+	if !strings.Contains(GetLogFileLocation(), "nancy.test.log") {
+		t.Error("Nancy test file not in log file location")
+	}
+
+	err := os.Truncate(GetLogFileLocation(), 0)
+
+	LogLady.Debug("Test")
+
+	dat, err := ioutil.ReadFile(GetLogFileLocation())
+	if err != nil {
+		t.Error("Unable to open log file")
+	}
+
+	var logTest LogTest
+
+	err = json.Unmarshal(dat, &logTest)
+	if err != nil {
+		t.Error("Improperly written log, should be valid json")
+	}
+
+	if logTest.Level != "debug" {
+		t.Error("Log level not set properly")
+	}
+
+	if logTest.Msg != "Test" {
+		t.Error("Message not written to log correctly")
+	}
+}
+
+type LogTest struct {
+	Level string `json:"level"`
+	Msg   string `json:"msg"`
+	Time  string `json:"time"`
+}