diff --git a/.github/stale.yml b/.github/stale.yml new file mode 100644 index 000000000..27c3cf9d4 --- /dev/null +++ b/.github/stale.yml @@ -0,0 +1,20 @@ +# Number of days of inactivity before an issue becomes stale +daysUntilStale: 60 +# Number of days of inactivity before a stale issue is closed +daysUntilClose: 14 +# Issues with these labels will never be considered stale +exemptLabels: + - question + - bug + - documentation +# Label to use when marking an issue as stale +staleLabel: stale +# Comment to post when marking an issue as stale. Set to `false` to disable +markComment: > + This issue has been automatically marked as stale because it has not had + recent activity. It will be closed if no further activity occurs. Thank you + for your contributions. +# Comment to post when closing a stale issue. Set to `false` to disable +closeComment: false +# Only mark issues as stale for now until we go through backlog of PRs +only: issues diff --git a/.gitignore b/.gitignore index 66be63a00..1fb13abeb 100644 --- a/.gitignore +++ b/.gitignore @@ -1 +1,4 @@ logrus +vendor + +.idea/ diff --git a/.golangci.yml b/.golangci.yml new file mode 100644 index 000000000..65dc28503 --- /dev/null +++ b/.golangci.yml @@ -0,0 +1,40 @@ +run: + # do not run on test files yet + tests: false + +# all available settings of specific linters +linters-settings: + errcheck: + # report about not checking of errors in type assetions: `a := b.(MyStruct)`; + # default is false: such cases aren't reported by default. + check-type-assertions: false + + # report about assignment of errors to blank identifier: `num, _ := strconv.Atoi(numStr)`; + # default is false: such cases aren't reported by default. + check-blank: false + + lll: + line-length: 100 + tab-width: 4 + + prealloc: + simple: false + range-loops: false + for-loops: false + + whitespace: + multi-if: false # Enforces newlines (or comments) after every multi-line if statement + multi-func: false # Enforces newlines (or comments) after every multi-line function signature + +linters: + enable: + - megacheck + - govet + disable: + - maligned + - prealloc + disable-all: false + presets: + - bugs + - unused + fast: false diff --git a/.travis.yml b/.travis.yml index 2d8c08661..5e20aa414 100644 --- a/.travis.yml +++ b/.travis.yml @@ -1,8 +1,17 @@ language: go -go: - - 1.2 - - 1.3 - - 1.4 - - tip +go_import_path: github.com/sirupsen/logrus +git: + depth: 1 +env: + - GO111MODULE=on +go: [1.13.x, 1.14.x] +os: [linux, osx] install: - - go get -t ./... + - ./travis/install.sh +script: + - ./travis/cross_build.sh + - ./travis/lint.sh + - export GOMAXPROCS=4 + - export GORACE=halt_on_error=1 + - go test -race -v ./... + - if [[ "$TRAVIS_OS_NAME" == "linux" ]]; then go test -race -v -tags appengine ./... ; fi diff --git a/CHANGELOG.md b/CHANGELOG.md new file mode 100644 index 000000000..584026d67 --- /dev/null +++ b/CHANGELOG.md @@ -0,0 +1,223 @@ +# 1.6.0 +Fixes: + * end of line cleanup + * revert the entry concurrency bug fix whic leads to deadlock under some circumstances + * update dependency on go-windows-terminal-sequences to fix a crash with go 1.14 + +Features: + * add an option to the `TextFormatter` to completely disable fields quoting + +# 1.5.0 +Code quality: + * add golangci linter run on travis + +Fixes: + * add mutex for hooks concurrent access on `Entry` data + * caller function field for go1.14 + * fix build issue for gopherjs target + +Feature: + * add an hooks/writer sub-package whose goal is to split output on different stream depending on the trace level + * add a `DisableHTMLEscape` option in the `JSONFormatter` + * add `ForceQuote` and `PadLevelText` options in the `TextFormatter` + +# 1.4.2 + * Fixes build break for plan9, nacl, solaris +# 1.4.1 +This new release introduces: + * Enhance TextFormatter to not print caller information when they are empty (#944) + * Remove dependency on golang.org/x/crypto (#932, #943) + +Fixes: + * Fix Entry.WithContext method to return a copy of the initial entry (#941) + +# 1.4.0 +This new release introduces: + * Add `DeferExitHandler`, similar to `RegisterExitHandler` but prepending the handler to the list of handlers (semantically like `defer`) (#848). + * Add `CallerPrettyfier` to `JSONFormatter` and `TextFormatter` (#909, #911) + * Add `Entry.WithContext()` and `Entry.Context`, to set a context on entries to be used e.g. in hooks (#919). + +Fixes: + * Fix wrong method calls `Logger.Print` and `Logger.Warningln` (#893). + * Update `Entry.Logf` to not do string formatting unless the log level is enabled (#903) + * Fix infinite recursion on unknown `Level.String()` (#907) + * Fix race condition in `getCaller` (#916). + + +# 1.3.0 +This new release introduces: + * Log, Logf, Logln functions for Logger and Entry that take a Level + +Fixes: + * Building prometheus node_exporter on AIX (#840) + * Race condition in TextFormatter (#468) + * Travis CI import path (#868) + * Remove coloured output on Windows (#862) + * Pointer to func as field in JSONFormatter (#870) + * Properly marshal Levels (#873) + +# 1.2.0 +This new release introduces: + * A new method `SetReportCaller` in the `Logger` to enable the file, line and calling function from which the trace has been issued + * A new trace level named `Trace` whose level is below `Debug` + * A configurable exit function to be called upon a Fatal trace + * The `Level` object now implements `encoding.TextUnmarshaler` interface + +# 1.1.1 +This is a bug fix release. + * fix the build break on Solaris + * don't drop a whole trace in JSONFormatter when a field param is a function pointer which can not be serialized + +# 1.1.0 +This new release introduces: + * several fixes: + * a fix for a race condition on entry formatting + * proper cleanup of previously used entries before putting them back in the pool + * the extra new line at the end of message in text formatter has been removed + * a new global public API to check if a level is activated: IsLevelEnabled + * the following methods have been added to the Logger object + * IsLevelEnabled + * SetFormatter + * SetOutput + * ReplaceHooks + * introduction of go module + * an indent configuration for the json formatter + * output colour support for windows + * the field sort function is now configurable for text formatter + * the CLICOLOR and CLICOLOR\_FORCE environment variable support in text formater + +# 1.0.6 + +This new release introduces: + * a new api WithTime which allows to easily force the time of the log entry + which is mostly useful for logger wrapper + * a fix reverting the immutability of the entry given as parameter to the hooks + a new configuration field of the json formatter in order to put all the fields + in a nested dictionnary + * a new SetOutput method in the Logger + * a new configuration of the textformatter to configure the name of the default keys + * a new configuration of the text formatter to disable the level truncation + +# 1.0.5 + +* Fix hooks race (#707) +* Fix panic deadlock (#695) + +# 1.0.4 + +* Fix race when adding hooks (#612) +* Fix terminal check in AppEngine (#635) + +# 1.0.3 + +* Replace example files with testable examples + +# 1.0.2 + +* bug: quote non-string values in text formatter (#583) +* Make (*Logger) SetLevel a public method + +# 1.0.1 + +* bug: fix escaping in text formatter (#575) + +# 1.0.0 + +* Officially changed name to lower-case +* bug: colors on Windows 10 (#541) +* bug: fix race in accessing level (#512) + +# 0.11.5 + +* feature: add writer and writerlevel to entry (#372) + +# 0.11.4 + +* bug: fix undefined variable on solaris (#493) + +# 0.11.3 + +* formatter: configure quoting of empty values (#484) +* formatter: configure quoting character (default is `"`) (#484) +* bug: fix not importing io correctly in non-linux environments (#481) + +# 0.11.2 + +* bug: fix windows terminal detection (#476) + +# 0.11.1 + +* bug: fix tty detection with custom out (#471) + +# 0.11.0 + +* performance: Use bufferpool to allocate (#370) +* terminal: terminal detection for app-engine (#343) +* feature: exit handler (#375) + +# 0.10.0 + +* feature: Add a test hook (#180) +* feature: `ParseLevel` is now case-insensitive (#326) +* feature: `FieldLogger` interface that generalizes `Logger` and `Entry` (#308) +* performance: avoid re-allocations on `WithFields` (#335) + +# 0.9.0 + +* logrus/text_formatter: don't emit empty msg +* logrus/hooks/airbrake: move out of main repository +* logrus/hooks/sentry: move out of main repository +* logrus/hooks/papertrail: move out of main repository +* logrus/hooks/bugsnag: move out of main repository +* logrus/core: run tests with `-race` +* logrus/core: detect TTY based on `stderr` +* logrus/core: support `WithError` on logger +* logrus/core: Solaris support + +# 0.8.7 + +* logrus/core: fix possible race (#216) +* logrus/doc: small typo fixes and doc improvements + + +# 0.8.6 + +* hooks/raven: allow passing an initialized client + +# 0.8.5 + +* logrus/core: revert #208 + +# 0.8.4 + +* formatter/text: fix data race (#218) + +# 0.8.3 + +* logrus/core: fix entry log level (#208) +* logrus/core: improve performance of text formatter by 40% +* logrus/core: expose `LevelHooks` type +* logrus/core: add support for DragonflyBSD and NetBSD +* formatter/text: print structs more verbosely + +# 0.8.2 + +* logrus: fix more Fatal family functions + +# 0.8.1 + +* logrus: fix not exiting on `Fatalf` and `Fatalln` + +# 0.8.0 + +* logrus: defaults to stderr instead of stdout +* hooks/sentry: add special field for `*http.Request` +* formatter/text: ignore Windows for colors + +# 0.7.3 + +* formatter/\*: allow configuration of timestamp layout + +# 0.7.2 + +* formatter/text: Add configuration option for time format (#158) diff --git a/README.md b/README.md index e755e7c18..5796706db 100644 --- a/README.md +++ b/README.md @@ -1,18 +1,46 @@ -# Logrus :walrus: [![Build Status](https://travis-ci.org/Sirupsen/logrus.svg?branch=master)](https://travis-ci.org/Sirupsen/logrus) [![godoc reference](https://godoc.org/github.com/Sirupsen/logrus?status.png)][godoc] +# Logrus :walrus: [![Build Status](https://travis-ci.org/sirupsen/logrus.svg?branch=master)](https://travis-ci.org/sirupsen/logrus) [![GoDoc](https://godoc.org/github.com/sirupsen/logrus?status.svg)](https://godoc.org/github.com/sirupsen/logrus) Logrus is a structured logger for Go (golang), completely API compatible with -the standard library logger. [Godoc][godoc]. **Please note the Logrus API is not -yet stable (pre 1.0). Logrus itself is completely stable and has been used in -many large deployments. The core API is unlikely to change much but please -version control your Logrus to make sure you aren't fetching latest `master` on -every build.** +the standard library logger. + +**Logrus is in maintenance-mode.** We will not be introducing new features. It's +simply too hard to do in a way that won't break many people's projects, which is +the last thing you want from your Logging library (again...). + +This does not mean Logrus is dead. Logrus will continue to be maintained for +security, (backwards compatible) bug fixes, and performance (where we are +limited by the interface). + +I believe Logrus' biggest contribution is to have played a part in today's +widespread use of structured logging in Golang. There doesn't seem to be a +reason to do a major, breaking iteration into Logrus V2, since the fantastic Go +community has built those independently. Many fantastic alternatives have sprung +up. Logrus would look like those, had it been re-designed with what we know +about structured logging in Go today. Check out, for example, +[Zerolog][zerolog], [Zap][zap], and [Apex][apex]. + +[zerolog]: https://github.com/rs/zerolog +[zap]: https://github.com/uber-go/zap +[apex]: https://github.com/apex/log + +**Seeing weird case-sensitive problems?** It's in the past been possible to +import Logrus as both upper- and lower-case. Due to the Go package environment, +this caused issues in the community and we needed a standard. Some environments +experienced problems with the upper-case variant, so the lower-case was decided. +Everything using `logrus` will need to use the lower-case: +`github.com/sirupsen/logrus`. Any package that isn't, should be changed. + +To fix Glide, see [these +comments](https://github.com/sirupsen/logrus/issues/553#issuecomment-306591437). +For an in-depth explanation of the casing issue, see [this +comment](https://github.com/sirupsen/logrus/issues/570#issuecomment-313933276). Nicely color-coded in development (when a TTY is attached, otherwise just plain text): ![Colored](http://i.imgur.com/PY7qMwd.png) -With `log.Formatter = new(logrus.JSONFormatter)`, for easy parsing by logstash +With `log.SetFormatter(&log.JSONFormatter{})`, for easy parsing by logstash or Splunk: ```json @@ -32,17 +60,56 @@ ocean","size":10,"time":"2014-03-10 19:57:38.562264131 -0400 EDT"} "time":"2014-03-10 19:57:38.562543128 -0400 EDT"} ``` -With the default `log.Formatter = new(logrus.TextFormatter)` when a TTY is not +With the default `log.SetFormatter(&log.TextFormatter{})` when a TTY is not attached, the output is compatible with the [logfmt](http://godoc.org/github.com/kr/logfmt) format: ```text -time="2014-04-20 15:36:23.830442383 -0400 EDT" level="info" msg="A group of walrus emerges from the ocean" animal="walrus" size=10 -time="2014-04-20 15:36:23.830584199 -0400 EDT" level="warning" msg="The group's number increased tremendously!" omg=true number=122 -time="2014-04-20 15:36:23.830596521 -0400 EDT" level="info" msg="A giant walrus appears!" animal="walrus" size=10 -time="2014-04-20 15:36:23.830611837 -0400 EDT" level="info" msg="Tremendously sized cow enters the ocean." animal="walrus" size=9 -time="2014-04-20 15:36:23.830626464 -0400 EDT" level="fatal" msg="The ice breaks!" omg=true number=100 +time="2015-03-26T01:27:38-04:00" level=debug msg="Started observing beach" animal=walrus number=8 +time="2015-03-26T01:27:38-04:00" level=info msg="A group of walrus emerges from the ocean" animal=walrus size=10 +time="2015-03-26T01:27:38-04:00" level=warning msg="The group's number increased tremendously!" number=122 omg=true +time="2015-03-26T01:27:38-04:00" level=debug msg="Temperature changes" temperature=-4 +time="2015-03-26T01:27:38-04:00" level=panic msg="It's over 9000!" animal=orca size=9009 +time="2015-03-26T01:27:38-04:00" level=fatal msg="The ice breaks!" err=&{0x2082280c0 map[animal:orca size:9009] 2015-03-26 01:27:38.441574009 -0400 EDT panic It's over 9000!} number=100 omg=true ``` +To ensure this behaviour even if a TTY is attached, set your formatter as follows: + +```go + log.SetFormatter(&log.TextFormatter{ + DisableColors: true, + FullTimestamp: true, + }) +``` + +#### Logging Method Name + +If you wish to add the calling method as a field, instruct the logger via: +```go +log.SetReportCaller(true) +``` +This adds the caller as 'method' like so: + +```json +{"animal":"penguin","level":"fatal","method":"github.com/sirupsen/arcticcreatures.migrate","msg":"a penguin swims by", +"time":"2014-03-10 19:57:38.562543129 -0400 EDT"} +``` + +```text +time="2015-03-26T01:27:38-04:00" level=fatal method=github.com/sirupsen/arcticcreatures.migrate msg="a penguin swims by" animal=penguin +``` +Note that this does add measurable overhead - the cost will depend on the version of Go, but is +between 20 and 40% in recent tests with 1.6 and 1.7. You can validate this in your +environment via benchmarks: +``` +go test -bench=.*CallerTracing +``` + + +#### Case-sensitivity + +The organization's name was changed to lower-case--and this will not be changed +back. If you are getting import conflicts due to case sensitivity, please use +the lower-case import: `github.com/sirupsen/logrus`. #### Example @@ -52,7 +119,7 @@ The simplest way to use Logrus is simply the package-level exported logger: package main import ( - log "github.com/Sirupsen/logrus" + log "github.com/sirupsen/logrus" ) func main() { @@ -63,7 +130,7 @@ func main() { ``` Note that it's completely api-compatible with the stdlib logger, so you can -replace your `log` imports everywhere with `log "github.com/Sirupsen/logrus"` +replace your `log` imports everywhere with `log "github.com/sirupsen/logrus"` and you'll now have the flexibility of Logrus. You can customize it all you want: @@ -72,20 +139,16 @@ package main import ( "os" - log "github.com/Sirupsen/logrus" - "github.com/Sirupsen/logrus/hooks/airbrake" + log "github.com/sirupsen/logrus" ) func init() { // Log as JSON instead of the default ASCII formatter. log.SetFormatter(&log.JSONFormatter{}) - // Use the Airbrake hook to report errors that have Error severity or above to - // an exception tracker. You can create custom hooks, see the Hooks section. - log.AddHook(&logrus_airbrake.AirbrakeHook{}) - - // Output to stderr instead of stdout, could also be a file. - log.SetOutput(os.Stderr) + // Output to stdout instead of the default stderr + // Can be any io.Writer, see below for File example + log.SetOutput(os.Stdout) // Only log the warning severity or above. log.SetLevel(log.WarnLevel) @@ -106,6 +169,16 @@ func main() { "omg": true, "number": 100, }).Fatal("The ice breaks!") + + // A common pattern is to re-use fields between logging statements by re-using + // the logrus.Entry returned from WithFields() + contextLogger := log.WithFields(log.Fields{ + "common": "this is a common field", + "other": "I also should be logged always", + }) + + contextLogger.Info("I'll be logged with common and other field") + contextLogger.Info("Me too") } ``` @@ -116,7 +189,8 @@ application, you can also create an instance of the `logrus` Logger: package main import ( - "github.com/Sirupsen/logrus" + "os" + "github.com/sirupsen/logrus" ) // Create a new instance of the logger. You can have any number of instances. @@ -125,7 +199,15 @@ var log = logrus.New() func main() { // The API for setting attributes is a little different than the package level // exported logger. See Godoc. - log.Out = os.Stderr + log.Out = os.Stdout + + // You could set this to any `io.Writer` such as a file + // file, err := os.OpenFile("logrus.log", os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0666) + // if err == nil { + // log.Out = file + // } else { + // log.Info("Failed to log to file, using default stderr") + // } log.WithFields(logrus.Fields{ "animal": "walrus", @@ -136,7 +218,7 @@ func main() { #### Fields -Logrus encourages careful, structured logging though logging fields instead of +Logrus encourages careful, structured logging through logging fields instead of long, unparseable error messages. For example, instead of: `log.Fatalf("Failed to send event %s to topic %s with key %d")`, you should log the much more discoverable: @@ -158,60 +240,42 @@ In general, with Logrus using any of the `printf`-family functions should be seen as a hint you should add a field, however, you can still use the `printf`-family functions with Logrus. -#### Hooks +#### Default Fields -You can add hooks for logging levels. For example to send errors to an exception -tracking service on `Error`, `Fatal` and `Panic`, info to StatsD or log to -multiple places simultaneously, e.g. syslog. +Often it's helpful to have fields _always_ attached to log statements in an +application or parts of one. For example, you may want to always log the +`request_id` and `user_ip` in the context of a request. Instead of writing +`log.WithFields(log.Fields{"request_id": request_id, "user_ip": user_ip})` on +every line, you can create a `logrus.Entry` to pass around instead: ```go -// Not the real implementation of the Airbrake hook. Just a simple sample. -import ( - log "github.com/Sirupsen/logrus" -) - -func init() { - log.AddHook(new(AirbrakeHook)) -} - -type AirbrakeHook struct{} - -// `Fire()` takes the entry that the hook is fired for. `entry.Data[]` contains -// the fields for the entry. See the Fields section of the README. -func (hook *AirbrakeHook) Fire(entry *logrus.Entry) error { - err := airbrake.Notify(entry.Data["error"].(error)) - if err != nil { - log.WithFields(log.Fields{ - "source": "airbrake", - "endpoint": airbrake.Endpoint, - }).Info("Failed to send error to Airbrake") - } +requestLogger := log.WithFields(log.Fields{"request_id": request_id, "user_ip": user_ip}) +requestLogger.Info("something happened on that request") # will log request_id and user_ip +requestLogger.Warn("something not great happened") +``` - return nil -} +#### Hooks -// `Levels()` returns a slice of `Levels` the hook is fired for. -func (hook *AirbrakeHook) Levels() []log.Level { - return []log.Level{ - log.ErrorLevel, - log.FatalLevel, - log.PanicLevel, - } -} -``` +You can add hooks for logging levels. For example to send errors to an exception +tracking service on `Error`, `Fatal` and `Panic`, info to StatsD or log to +multiple places simultaneously, e.g. syslog. -Logrus comes with built-in hooks. Add those, or your custom hook, in `init`: +Logrus comes with [built-in hooks](hooks/). Add those, or your custom hook, in +`init`: ```go import ( - log "github.com/Sirupsen/logrus" - "github.com/Sirupsen/logrus/hooks/airbrake" - "github.com/Sirupsen/logrus/hooks/syslog" + log "github.com/sirupsen/logrus" + "gopkg.in/gemnasium/logrus-airbrake-hook.v2" // the package is named "airbrake" + logrus_syslog "github.com/sirupsen/logrus/hooks/syslog" "log/syslog" ) func init() { - log.AddHook(new(logrus_airbrake.AirbrakeHook)) + + // Use the Airbrake hook to report errors that have Error severity or above to + // an exception tracker. You can create custom hooks, see the Hooks section. + log.AddHook(airbrake.NewHook(123, "xyz", "production")) hook, err := logrus_syslog.NewSyslogHook("udp", "localhost:514", syslog.LOG_INFO, "") if err != nil { @@ -221,35 +285,17 @@ func init() { } } ``` +Note: Syslog hook also support connecting to local syslog (Ex. "/dev/log" or "/var/run/syslog" or "/var/run/log"). For the detail, please check the [syslog hook README](hooks/syslog/README.md). -* [`github.com/Sirupsen/logrus/hooks/airbrake`](https://github.com/Sirupsen/logrus/blob/master/hooks/airbrake/airbrake.go) - Send errors to an exception tracking service compatible with the Airbrake API. - Uses [`airbrake-go`](https://github.com/tobi/airbrake-go) behind the scenes. - -* [`github.com/Sirupsen/logrus/hooks/papertrail`](https://github.com/Sirupsen/logrus/blob/master/hooks/papertrail/papertrail.go) - Send errors to the Papertrail hosted logging service via UDP. - -* [`github.com/Sirupsen/logrus/hooks/syslog`](https://github.com/Sirupsen/logrus/blob/master/hooks/syslog/syslog.go) - Send errors to remote syslog server. - Uses standard library `log/syslog` behind the scenes. - -* [`github.com/nubo/hiprus`](https://github.com/nubo/hiprus) - Send errors to a channel in hipchat. - -* [`github.com/sebest/logrusly`](https://github.com/sebest/logrusly) - Send logs to Loggly (https://www.loggly.com/) +A list of currently known service hooks can be found in this wiki [page](https://github.com/sirupsen/logrus/wiki/Hooks) -* [`github.com/johntdyer/slackrus`](https://github.com/johntdyer/slackrus) - Hook for Slack chat. - -* [`github.com/wercker/journalhook`](https://github.com/wercker/journalhook). - Hook for logging to `systemd-journald`. #### Level logging -Logrus has six logging levels: Debug, Info, Warning, Error, Fatal and Panic. +Logrus has seven logging levels: Trace, Debug, Info, Warning, Error, Fatal and Panic. ```go +log.Trace("Something very low level.") log.Debug("Useful debugging information.") log.Info("Something noteworthy happened!") log.Warn("You should probably take a look at this.") @@ -292,17 +338,17 @@ could do: ```go import ( - log "github.com/Sirupsen/logrus" + log "github.com/sirupsen/logrus" ) init() { // do something here to set environment depending on an environment variable // or command-line flag if Environment == "production" { - log.SetFormatter(logrus.JSONFormatter) + log.SetFormatter(&log.JSONFormatter{}) } else { // The TextFormatter is default, you don't actually have to do this. - log.SetFormatter(logrus.TextFormatter) + log.SetFormatter(&log.TextFormatter{}) } } ``` @@ -319,12 +365,25 @@ The built-in logging formatters are: without colors. * *Note:* to force colored output when there is no TTY, set the `ForceColors` field to `true`. To force no colored output even if there is a TTY set the - `DisableColors` field to `true` + `DisableColors` field to `true`. For Windows, see + [github.com/mattn/go-colorable](https://github.com/mattn/go-colorable). + * When colors are enabled, levels are truncated to 4 characters by default. To disable + truncation set the `DisableLevelTruncation` field to `true`. + * When outputting to a TTY, it's often helpful to visually scan down a column where all the levels are the same width. Setting the `PadLevelText` field to `true` enables this behavior, by adding padding to the level text. + * All options are listed in the [generated docs](https://godoc.org/github.com/sirupsen/logrus#TextFormatter). * `logrus.JSONFormatter`. Logs fields as JSON. + * All options are listed in the [generated docs](https://godoc.org/github.com/sirupsen/logrus#JSONFormatter). Third party logging formatters: -* [`zalgo`](https://github.com/aybabtme/logzalgo): invoking the P͉̫o̳̼̊w̖͈̰͎e̬͔̭͂r͚̼̹̲ ̫͓͉̳͈ō̠͕͖̚f̝͍̠ ͕̲̞͖͑Z̖̫̤̫ͪa͉̬͈̗l͖͎g̳̥o̰̥̅!̣͔̲̻͊̄ ̙̘̦̹̦. +* [`FluentdFormatter`](https://github.com/joonix/log). Formats entries that can be parsed by Kubernetes and Google Container Engine. +* [`GELF`](https://github.com/fabienm/go-logrus-formatters). Formats entries so they comply to Graylog's [GELF 1.1 specification](http://docs.graylog.org/en/2.4/pages/gelf.html). +* [`logstash`](https://github.com/bshuster-repo/logrus-logstash-hook). Logs fields as [Logstash](http://logstash.net) Events. +* [`prefixed`](https://github.com/x-cray/logrus-prefixed-formatter). Displays log entry source along with alternative layout. +* [`zalgo`](https://github.com/aybabtme/logzalgo). Invoking the Power of Zalgo. +* [`nested-logrus-formatter`](https://github.com/antonfisher/nested-logrus-formatter). Converts logrus fields to a nested structure. +* [`powerful-logrus-formatter`](https://github.com/zput/zxcTool). get fileName, log's line number and the latest function's name when print log; Sava log to files. +* [`caption-json-formatter`](https://github.com/nolleh/caption_json_formatter). logrus's message json formatter with human-readable caption added. You can define your formatter by implementing the `Formatter` interface, requiring a `Format` method. `Format` takes an `*Entry`. `entry.Data` is a @@ -337,7 +396,7 @@ type MyJSONFormatter struct { log.SetFormatter(new(MyJSONFormatter)) -func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { +func (f *MyJSONFormatter) Format(entry *Entry) ([]byte, error) { // Note this doesn't include Time, Level and Message which are available on // the Entry. Consult `godoc` on information about those fields or read the // source of the official loggers. @@ -351,7 +410,7 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { #### Logger as an `io.Writer` -Logrus can be transormed into an `io.Writer`. That writer is the end of an `io.Pipe` and it is your responsibility to close it. +Logrus can be transformed into an `io.Writer`. That writer is the end of an `io.Pipe` and it is your responsibility to close it. ```go w := logger.Writer() @@ -367,11 +426,88 @@ srv := http.Server{ Each line written to that writer will be printed the usual way, using formatters and hooks. The level for those entries is `info`. +This means that we can override the standard library logger easily: + +```go +logger := logrus.New() +logger.Formatter = &logrus.JSONFormatter{} + +// Use logrus for standard log output +// Note that `log` here references stdlib's log +// Not logrus imported under the name `log`. +log.SetOutput(logger.Writer()) +``` + #### Rotation Log rotation is not provided with Logrus. Log rotation should be done by an external program (like `logrotate(8)`) that can compress and delete old log entries. It should not be a feature of the application-level logger. +#### Tools + +| Tool | Description | +| ---- | ----------- | +|[Logrus Mate](https://github.com/gogap/logrus_mate)|Logrus mate is a tool for Logrus to manage loggers, you can initial logger's level, hook and formatter by config file, the logger will be generated with different configs in different environments.| +|[Logrus Viper Helper](https://github.com/heirko/go-contrib/tree/master/logrusHelper)|An Helper around Logrus to wrap with spf13/Viper to load configuration with fangs! And to simplify Logrus configuration use some behavior of [Logrus Mate](https://github.com/gogap/logrus_mate). [sample](https://github.com/heirko/iris-contrib/blob/master/middleware/logrus-logger/example) | + +#### Testing + +Logrus has a built in facility for asserting the presence of log messages. This is implemented through the `test` hook and provides: + +* decorators for existing logger (`test.NewLocal` and `test.NewGlobal`) which basically just adds the `test` hook +* a test logger (`test.NewNullLogger`) that just records log messages (and does not output any): + +```go +import( + "github.com/sirupsen/logrus" + "github.com/sirupsen/logrus/hooks/test" + "github.com/stretchr/testify/assert" + "testing" +) + +func TestSomething(t*testing.T){ + logger, hook := test.NewNullLogger() + logger.Error("Helloerror") + + assert.Equal(t, 1, len(hook.Entries)) + assert.Equal(t, logrus.ErrorLevel, hook.LastEntry().Level) + assert.Equal(t, "Helloerror", hook.LastEntry().Message) + + hook.Reset() + assert.Nil(t, hook.LastEntry()) +} +``` + +#### Fatal handlers + +Logrus can register one or more functions that will be called when any `fatal` +level message is logged. The registered handlers will be executed before +logrus performs an `os.Exit(1)`. This behavior may be helpful if callers need +to gracefully shutdown. Unlike a `panic("Something went wrong...")` call which can be intercepted with a deferred `recover` a call to `os.Exit(1)` can not be intercepted. + +``` +... +handler := func() { + // gracefully shutdown something... +} +logrus.RegisterExitHandler(handler) +... +``` + +#### Thread safety + +By default, Logger is protected by a mutex for concurrent writes. The mutex is held when calling hooks and writing logs. +If you are sure such locking is not needed, you can call logger.SetNoLock() to disable the locking. + +Situation when locking is not needed includes: + +* You have no hooks registered, or hooks calling is already thread-safe. + +* Writing to logger.Out is already thread-safe, for example: + + 1) logger.Out is protected by locks. + + 2) logger.Out is an os.File handler opened with `O_APPEND` flag, and every write is smaller than 4k. (This allows multi-thread/multi-process writing) -[godoc]: https://godoc.org/github.com/Sirupsen/logrus + (Refer to http://www.notthewizard.com/2014/06/17/are-files-appends-really-atomic/) diff --git a/alt_exit.go b/alt_exit.go new file mode 100644 index 000000000..8fd189e1c --- /dev/null +++ b/alt_exit.go @@ -0,0 +1,76 @@ +package logrus + +// The following code was sourced and modified from the +// https://github.com/tebeka/atexit package governed by the following license: +// +// Copyright (c) 2012 Miki Tebeka . +// +// Permission is hereby granted, free of charge, to any person obtaining a copy of +// this software and associated documentation files (the "Software"), to deal in +// the Software without restriction, including without limitation the rights to +// use, copy, modify, merge, publish, distribute, sublicense, and/or sell copies of +// the Software, and to permit persons to whom the Software is furnished to do so, +// subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in all +// copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, FITNESS +// FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR +// COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER +// IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN +// CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. + +import ( + "fmt" + "os" +) + +var handlers = []func(){} + +func runHandler(handler func()) { + defer func() { + if err := recover(); err != nil { + fmt.Fprintln(os.Stderr, "Error: Logrus exit handler error:", err) + } + }() + + handler() +} + +func runHandlers() { + for _, handler := range handlers { + runHandler(handler) + } +} + +// Exit runs all the Logrus atexit handlers and then terminates the program using os.Exit(code) +func Exit(code int) { + runHandlers() + os.Exit(code) +} + +// RegisterExitHandler appends a Logrus Exit handler to the list of handlers, +// call logrus.Exit to invoke all handlers. The handlers will also be invoked when +// any Fatal log entry is made. +// +// This method is useful when a caller wishes to use logrus to log a fatal +// message but also needs to gracefully shutdown. An example usecase could be +// closing database connections, or sending a alert that the application is +// closing. +func RegisterExitHandler(handler func()) { + handlers = append(handlers, handler) +} + +// DeferExitHandler prepends a Logrus Exit handler to the list of handlers, +// call logrus.Exit to invoke all handlers. The handlers will also be invoked when +// any Fatal log entry is made. +// +// This method is useful when a caller wishes to use logrus to log a fatal +// message but also needs to gracefully shutdown. An example usecase could be +// closing database connections, or sending a alert that the application is +// closing. +func DeferExitHandler(handler func()) { + handlers = append([]func(){handler}, handlers...) +} diff --git a/alt_exit_test.go b/alt_exit_test.go new file mode 100644 index 000000000..54d503cb4 --- /dev/null +++ b/alt_exit_test.go @@ -0,0 +1,151 @@ +package logrus + +import ( + "io/ioutil" + "log" + "os" + "os/exec" + "path/filepath" + "runtime" + "strings" + "testing" + "time" +) + +func TestRegister(t *testing.T) { + current := len(handlers) + + var results []string + + h1 := func() { results = append(results, "first") } + h2 := func() { results = append(results, "second") } + + RegisterExitHandler(h1) + RegisterExitHandler(h2) + + if len(handlers) != current+2 { + t.Fatalf("expected %d handlers, got %d", current+2, len(handlers)) + } + + runHandlers() + + if len(results) != 2 { + t.Fatalf("expected 2 handlers to be run, ran %d", len(results)) + } + + if results[0] != "first" { + t.Fatal("expected handler h1 to be run first, but it wasn't") + } + + if results[1] != "second" { + t.Fatal("expected handler h2 to be run second, but it wasn't") + } +} + +func TestDefer(t *testing.T) { + current := len(handlers) + + var results []string + + h1 := func() { results = append(results, "first") } + h2 := func() { results = append(results, "second") } + + DeferExitHandler(h1) + DeferExitHandler(h2) + + if len(handlers) != current+2 { + t.Fatalf("expected %d handlers, got %d", current+2, len(handlers)) + } + + runHandlers() + + if len(results) != 2 { + t.Fatalf("expected 2 handlers to be run, ran %d", len(results)) + } + + if results[0] != "second" { + t.Fatal("expected handler h2 to be run first, but it wasn't") + } + + if results[1] != "first" { + t.Fatal("expected handler h1 to be run second, but it wasn't") + } +} + +func TestHandler(t *testing.T) { + testprog := testprogleader + testprog = append(testprog, getPackage()...) + testprog = append(testprog, testprogtrailer...) + tempDir, err := ioutil.TempDir("", "test_handler") + if err != nil { + log.Fatalf("can't create temp dir. %q", err) + } + defer os.RemoveAll(tempDir) + + gofile := filepath.Join(tempDir, "gofile.go") + if err := ioutil.WriteFile(gofile, testprog, 0666); err != nil { + t.Fatalf("can't create go file. %q", err) + } + + outfile := filepath.Join(tempDir, "outfile.out") + arg := time.Now().UTC().String() + err = exec.Command("go", "run", gofile, outfile, arg).Run() + if err == nil { + t.Fatalf("completed normally, should have failed") + } + + data, err := ioutil.ReadFile(outfile) + if err != nil { + t.Fatalf("can't read output file %s. %q", outfile, err) + } + + if string(data) != arg { + t.Fatalf("bad data. Expected %q, got %q", data, arg) + } +} + +// getPackage returns the name of the current package, which makes running this +// test in a fork simpler +func getPackage() []byte { + pc, _, _, _ := runtime.Caller(0) + fullFuncName := runtime.FuncForPC(pc).Name() + idx := strings.LastIndex(fullFuncName, ".") + return []byte(fullFuncName[:idx]) // trim off function details +} + +var testprogleader = []byte(` +// Test program for atexit, gets output file and data as arguments and writes +// data to output file in atexit handler. +package main + +import ( + "`) +var testprogtrailer = []byte( + `" + "flag" + "fmt" + "io/ioutil" +) + +var outfile = "" +var data = "" + +func handler() { + ioutil.WriteFile(outfile, []byte(data), 0666) +} + +func badHandler() { + n := 0 + fmt.Println(1/n) +} + +func main() { + flag.Parse() + outfile = flag.Arg(0) + data = flag.Arg(1) + + logrus.RegisterExitHandler(handler) + logrus.RegisterExitHandler(badHandler) + logrus.Fatal("Bye bye") +} +`) diff --git a/appveyor.yml b/appveyor.yml new file mode 100644 index 000000000..df9d65c3a --- /dev/null +++ b/appveyor.yml @@ -0,0 +1,14 @@ +version: "{build}" +platform: x64 +clone_folder: c:\gopath\src\github.com\sirupsen\logrus +environment: + GOPATH: c:\gopath +branches: + only: + - master +install: + - set PATH=%GOPATH%\bin;c:\go\bin;%PATH% + - go version +build_script: + - go get -t + - go test diff --git a/buffer_pool.go b/buffer_pool.go new file mode 100644 index 000000000..4545dec07 --- /dev/null +++ b/buffer_pool.go @@ -0,0 +1,52 @@ +package logrus + +import ( + "bytes" + "sync" +) + +var ( + bufferPool BufferPool +) + +type BufferPool interface { + Put(*bytes.Buffer) + Get() *bytes.Buffer +} + +type defaultPool struct { + pool *sync.Pool +} + +func (p *defaultPool) Put(buf *bytes.Buffer) { + p.pool.Put(buf) +} + +func (p *defaultPool) Get() *bytes.Buffer { + return p.pool.Get().(*bytes.Buffer) +} + +func getBuffer() *bytes.Buffer { + return bufferPool.Get() +} + +func putBuffer(buf *bytes.Buffer) { + buf.Reset() + bufferPool.Put(buf) +} + +// SetBufferPool allows to replace the default logrus buffer pool +// to better meets the specific needs of an application. +func SetBufferPool(bp BufferPool) { + bufferPool = bp +} + +func init() { + SetBufferPool(&defaultPool{ + pool: &sync.Pool{ + New: func() interface{} { + return new(bytes.Buffer) + }, + }, + }) +} diff --git a/doc.go b/doc.go new file mode 100644 index 000000000..da67aba06 --- /dev/null +++ b/doc.go @@ -0,0 +1,26 @@ +/* +Package logrus is a structured logger for Go, completely API compatible with the standard library logger. + + +The simplest way to use Logrus is simply the package-level exported logger: + + package main + + import ( + log "github.com/sirupsen/logrus" + ) + + func main() { + log.WithFields(log.Fields{ + "animal": "walrus", + "number": 1, + "size": 10, + }).Info("A walrus appears") + } + +Output: + time="2015-09-07T08:48:33Z" level=info msg="A walrus appears" animal=walrus number=1 size=10 + +For a full guide visit https://github.com/sirupsen/logrus +*/ +package logrus diff --git a/entry.go b/entry.go index 17fe6f707..71b7120c6 100644 --- a/entry.go +++ b/entry.go @@ -2,16 +2,45 @@ package logrus import ( "bytes" + "context" "fmt" - "io" "os" + "reflect" + "runtime" + "strings" + "sync" "time" ) +var ( + + // qualified package name, cached at first use + logrusPackage string + + // Positions in the call stack when tracing to report the calling method + minimumCallerDepth int + + // Used for caller information initialisation + callerInitOnce sync.Once +) + +const ( + maximumCallerDepth int = 25 + knownLogrusFrames int = 4 +) + +func init() { + // start at the bottom of the stack before the package-name cache is primed + minimumCallerDepth = 1 +} + +// Defines the key when adding errors using WithError. +var ErrorKey = "error" + // An entry is the final or intermediate Logrus logging entry. It contains all -// the fields passed with WithField{,s}. It's finally logged when Debug, Info, -// Warn, Error, Fatal or Panic is called on it. These objects can be reused and -// passed around as much as you wish to avoid field duplication. +// the fields passed with WithField{,s}. It's finally logged when Trace, Debug, +// Info, Warn, Error, Fatal or Panic is called on it. These objects can be +// reused and passed around as much as you wish to avoid field duplication. type Entry struct { Logger *Logger @@ -21,36 +50,75 @@ type Entry struct { // Time at which the log entry was created Time time.Time - // Level the log entry was logged at: Debug, Info, Warn, Error, Fatal or Panic + // Level the log entry was logged at: Trace, Debug, Info, Warn, Error, Fatal or Panic + // This field will be set on entry firing and the value will be equal to the one in Logger struct field. Level Level - // Message passed to Debug, Info, Warn, Error, Fatal or Panic + // Calling method, with package name + Caller *runtime.Frame + + // Message passed to Trace, Debug, Info, Warn, Error, Fatal or Panic Message string + + // When formatter is called in entry.log(), a Buffer may be set to entry + Buffer *bytes.Buffer + + // Contains the context set by the user. Useful for hook processing etc. + Context context.Context + + // err may contain a field formatting error + err string } func NewEntry(logger *Logger) *Entry { return &Entry{ Logger: logger, - // Default is three fields, give a little extra room - Data: make(Fields, 5), + // Default is three fields, plus one optional. Give a little extra room. + Data: make(Fields, 6), } } -// Returns a reader for the entry, which is a proxy to the formatter. -func (entry *Entry) Reader() (*bytes.Buffer, error) { - serialized, err := entry.Logger.Formatter.Format(entry) - return bytes.NewBuffer(serialized), err +// Returns the bytes representation of this entry from the formatter. +func (entry *Entry) Bytes() ([]byte, error) { + return entry.Logger.Formatter.Format(entry) } // Returns the string representation from the reader and ultimately the // formatter. func (entry *Entry) String() (string, error) { - reader, err := entry.Reader() + serialized, err := entry.Bytes() if err != nil { return "", err } + str := string(serialized) + return str, nil +} + +// Add a caller field to the Entry. +func (entry *Entry) WithCaller() *Entry { + frame := getCaller() + if frame != nil { + return entry.WithFields(Fields{ + FieldKeyFile: fmt.Sprintf("%s:%d", frame.File, frame.Line), + FieldKeyFunc: frame.Function, + }) + } + + return entry +} + +// Add an error as single field (using the key defined in ErrorKey) to the Entry. +func (entry *Entry) WithError(err error) *Entry { + return entry.WithField(ErrorKey, err) +} - return reader.String(), err +// Add a context to the Entry. +func (entry *Entry) WithContext(ctx context.Context) *Entry { + dataCopy := make(Fields, len(entry.Data)) + for k, v := range entry.Data { + dataCopy[k] = v + } + return &Entry{Logger: entry.Logger, Data: dataCopy, Time: entry.Time, err: entry.err, Context: ctx} } // Add a single field to the Entry. @@ -60,54 +128,181 @@ func (entry *Entry) WithField(key string, value interface{}) *Entry { // Add a map of fields to the Entry. func (entry *Entry) WithFields(fields Fields) *Entry { - data := Fields{} + data := make(Fields, len(entry.Data)+len(fields)) for k, v := range entry.Data { data[k] = v } + fieldErr := entry.err for k, v := range fields { - data[k] = v + isErrField := false + if t := reflect.TypeOf(v); t != nil { + switch t.Kind() { + case reflect.Func: + isErrField = true + case reflect.Ptr: + isErrField = t.Elem().Kind() == reflect.Func + } + } + if isErrField { + tmp := fmt.Sprintf("can not add field %q", k) + if fieldErr != "" { + fieldErr = entry.err + ", " + tmp + } else { + fieldErr = tmp + } + } else { + data[k] = v + } + } + return &Entry{Logger: entry.Logger, Data: data, Time: entry.Time, err: fieldErr, Context: entry.Context} +} + +// Overrides the time of the Entry. +func (entry *Entry) WithTime(t time.Time) *Entry { + dataCopy := make(Fields, len(entry.Data)) + for k, v := range entry.Data { + dataCopy[k] = v } - return &Entry{Logger: entry.Logger, Data: data} + return &Entry{Logger: entry.Logger, Data: dataCopy, Time: t, err: entry.err, Context: entry.Context} +} + +// getPackageName reduces a fully qualified function name to the package name +// There really ought to be to be a better way... +func getPackageName(f string) string { + for { + lastPeriod := strings.LastIndex(f, ".") + lastSlash := strings.LastIndex(f, "/") + if lastPeriod > lastSlash { + f = f[:lastPeriod] + } else { + break + } + } + + return f +} + +// getCaller retrieves the name of the first non-logrus calling function +func getCaller() *runtime.Frame { + // cache this package's fully-qualified name + callerInitOnce.Do(func() { + pcs := make([]uintptr, maximumCallerDepth) + _ = runtime.Callers(0, pcs) + + // dynamic get the package name and the minimum caller depth + for i := 0; i < maximumCallerDepth; i++ { + funcName := runtime.FuncForPC(pcs[i]).Name() + if strings.Contains(funcName, "getCaller") { + logrusPackage = getPackageName(funcName) + break + } + } + + minimumCallerDepth = knownLogrusFrames + }) + + // Restrict the lookback frames to avoid runaway lookups + pcs := make([]uintptr, maximumCallerDepth) + depth := runtime.Callers(minimumCallerDepth, pcs) + frames := runtime.CallersFrames(pcs[:depth]) + + for f, again := frames.Next(); again; f, again = frames.Next() { + pkg := getPackageName(f.Function) + + // If the caller isn't part of this package, we're done + if pkg != logrusPackage { + return &f //nolint:scopelint + } + } + + // if we got here, we failed to find the caller's context + return nil } -func (entry *Entry) log(level Level, msg string) { - entry.Time = time.Now() +func (entry Entry) HasCaller() (has bool) { + return entry.Logger != nil && + entry.Logger.ReportCaller && + entry.Caller != nil +} + +// This function is not declared with a pointer value because otherwise +// race conditions will occur when using multiple goroutines +func (entry Entry) log(level Level, msg string) { + var buffer *bytes.Buffer + + // Default to now, but allow users to override if they want. + // + // We don't have to worry about polluting future calls to Entry#log() + // with this assignment because this function is declared with a + // non-pointer receiver. + if entry.Time.IsZero() { + entry.Time = time.Now() + } + entry.Level = level entry.Message = msg + entry.Logger.mu.Lock() + if entry.Logger.ReportCaller { + entry.Caller = getCaller() + } + entry.Logger.mu.Unlock() - if err := entry.Logger.Hooks.Fire(level, entry); err != nil { - entry.Logger.mu.Lock() - fmt.Fprintf(os.Stderr, "Failed to fire hook: %v\n", err) - entry.Logger.mu.Unlock() + entry.fireHooks() + + buffer = getBuffer() + defer func() { + entry.Buffer = nil + putBuffer(buffer) + }() + buffer.Reset() + entry.Buffer = buffer + + entry.write() + + entry.Buffer = nil + + // To avoid Entry#log() returning a value that only would make sense for + // panic() to use in Entry#Panic(), we avoid the allocation by checking + // directly here. + if level <= PanicLevel { + panic(&entry) } +} - reader, err := entry.Reader() +func (entry *Entry) fireHooks() { + entry.Logger.mu.Lock() + defer entry.Logger.mu.Unlock() + err := entry.Logger.Hooks.Fire(entry.Level, entry) if err != nil { - entry.Logger.mu.Lock() - fmt.Fprintf(os.Stderr, "Failed to obtain reader, %v\n", err) - entry.Logger.mu.Unlock() + fmt.Fprintf(os.Stderr, "Failed to fire hook: %v\n", err) } +} +func (entry *Entry) write() { entry.Logger.mu.Lock() defer entry.Logger.mu.Unlock() - - _, err = io.Copy(entry.Logger.Out, reader) + serialized, err := entry.Logger.Formatter.Format(entry) if err != nil { + fmt.Fprintf(os.Stderr, "Failed to obtain reader, %v\n", err) + return + } + if _, err = entry.Logger.Out.Write(serialized); err != nil { fmt.Fprintf(os.Stderr, "Failed to write to log, %v\n", err) } +} - // To avoid Entry#log() returning a value that only would make sense for - // panic() to use in Entry#Panic(), we avoid the allocation by checking - // directly here. - if level <= PanicLevel { - panic(entry) +func (entry *Entry) Log(level Level, args ...interface{}) { + if entry.Logger.IsLevelEnabled(level) { + entry.log(level, fmt.Sprint(args...)) } } +func (entry *Entry) Trace(args ...interface{}) { + entry.Log(TraceLevel, args...) +} + func (entry *Entry) Debug(args ...interface{}) { - if entry.Logger.Level >= DebugLevel { - entry.log(DebugLevel, fmt.Sprint(args...)) - } + entry.Log(DebugLevel, args...) } func (entry *Entry) Print(args ...interface{}) { @@ -115,15 +310,11 @@ func (entry *Entry) Print(args ...interface{}) { } func (entry *Entry) Info(args ...interface{}) { - if entry.Logger.Level >= InfoLevel { - entry.log(InfoLevel, fmt.Sprint(args...)) - } + entry.Log(InfoLevel, args...) } func (entry *Entry) Warn(args ...interface{}) { - if entry.Logger.Level >= WarnLevel { - entry.log(WarnLevel, fmt.Sprint(args...)) - } + entry.Log(WarnLevel, args...) } func (entry *Entry) Warning(args ...interface{}) { @@ -131,37 +322,37 @@ func (entry *Entry) Warning(args ...interface{}) { } func (entry *Entry) Error(args ...interface{}) { - if entry.Logger.Level >= ErrorLevel { - entry.log(ErrorLevel, fmt.Sprint(args...)) - } + entry.Log(ErrorLevel, args...) } func (entry *Entry) Fatal(args ...interface{}) { - if entry.Logger.Level >= FatalLevel { - entry.log(FatalLevel, fmt.Sprint(args...)) - } - os.Exit(1) + entry.Log(FatalLevel, args...) + entry.Logger.Exit(1) } func (entry *Entry) Panic(args ...interface{}) { - if entry.Logger.Level >= PanicLevel { - entry.log(PanicLevel, fmt.Sprint(args...)) - } + entry.Log(PanicLevel, args...) panic(fmt.Sprint(args...)) } // Entry Printf family functions -func (entry *Entry) Debugf(format string, args ...interface{}) { - if entry.Logger.Level >= DebugLevel { - entry.Debug(fmt.Sprintf(format, args...)) +func (entry *Entry) Logf(level Level, format string, args ...interface{}) { + if entry.Logger.IsLevelEnabled(level) { + entry.Log(level, fmt.Sprintf(format, args...)) } } +func (entry *Entry) Tracef(format string, args ...interface{}) { + entry.Logf(TraceLevel, format, args...) +} + +func (entry *Entry) Debugf(format string, args ...interface{}) { + entry.Logf(DebugLevel, format, args...) +} + func (entry *Entry) Infof(format string, args ...interface{}) { - if entry.Logger.Level >= InfoLevel { - entry.Info(fmt.Sprintf(format, args...)) - } + entry.Logf(InfoLevel, format, args...) } func (entry *Entry) Printf(format string, args ...interface{}) { @@ -169,9 +360,7 @@ func (entry *Entry) Printf(format string, args ...interface{}) { } func (entry *Entry) Warnf(format string, args ...interface{}) { - if entry.Logger.Level >= WarnLevel { - entry.Warn(fmt.Sprintf(format, args...)) - } + entry.Logf(WarnLevel, format, args...) } func (entry *Entry) Warningf(format string, args ...interface{}) { @@ -179,35 +368,36 @@ func (entry *Entry) Warningf(format string, args ...interface{}) { } func (entry *Entry) Errorf(format string, args ...interface{}) { - if entry.Logger.Level >= ErrorLevel { - entry.Error(fmt.Sprintf(format, args...)) - } + entry.Logf(ErrorLevel, format, args...) } func (entry *Entry) Fatalf(format string, args ...interface{}) { - if entry.Logger.Level >= FatalLevel { - entry.Fatal(fmt.Sprintf(format, args...)) - } + entry.Logf(FatalLevel, format, args...) + entry.Logger.Exit(1) } func (entry *Entry) Panicf(format string, args ...interface{}) { - if entry.Logger.Level >= PanicLevel { - entry.Panic(fmt.Sprintf(format, args...)) - } + entry.Logf(PanicLevel, format, args...) } // Entry Println family functions -func (entry *Entry) Debugln(args ...interface{}) { - if entry.Logger.Level >= DebugLevel { - entry.Debug(entry.sprintlnn(args...)) +func (entry *Entry) Logln(level Level, args ...interface{}) { + if entry.Logger.IsLevelEnabled(level) { + entry.Log(level, entry.sprintlnn(args...)) } } +func (entry *Entry) Traceln(args ...interface{}) { + entry.Logln(TraceLevel, args...) +} + +func (entry *Entry) Debugln(args ...interface{}) { + entry.Logln(DebugLevel, args...) +} + func (entry *Entry) Infoln(args ...interface{}) { - if entry.Logger.Level >= InfoLevel { - entry.Info(entry.sprintlnn(args...)) - } + entry.Logln(InfoLevel, args...) } func (entry *Entry) Println(args ...interface{}) { @@ -215,9 +405,7 @@ func (entry *Entry) Println(args ...interface{}) { } func (entry *Entry) Warnln(args ...interface{}) { - if entry.Logger.Level >= WarnLevel { - entry.Warn(entry.sprintlnn(args...)) - } + entry.Logln(WarnLevel, args...) } func (entry *Entry) Warningln(args ...interface{}) { @@ -225,21 +413,16 @@ func (entry *Entry) Warningln(args ...interface{}) { } func (entry *Entry) Errorln(args ...interface{}) { - if entry.Logger.Level >= ErrorLevel { - entry.Error(entry.sprintlnn(args...)) - } + entry.Logln(ErrorLevel, args...) } func (entry *Entry) Fatalln(args ...interface{}) { - if entry.Logger.Level >= FatalLevel { - entry.Fatal(entry.sprintlnn(args...)) - } + entry.Logln(FatalLevel, args...) + entry.Logger.Exit(1) } func (entry *Entry) Panicln(args ...interface{}) { - if entry.Logger.Level >= PanicLevel { - entry.Panic(entry.sprintlnn(args...)) - } + entry.Logln(PanicLevel, args...) } // Sprintlnn => Sprint no newline. This is to get the behavior of how diff --git a/entry_test.go b/entry_test.go index 98717df49..b98e14ad6 100644 --- a/entry_test.go +++ b/entry_test.go @@ -2,12 +2,127 @@ package logrus import ( "bytes" + "context" "fmt" "testing" + "time" "github.com/stretchr/testify/assert" ) +func TestEntryWithError(t *testing.T) { + + assert := assert.New(t) + + defer func() { + ErrorKey = "error" + }() + + err := fmt.Errorf("kaboom at layer %d", 4711) + + assert.Equal(err, WithError(err).Data["error"]) + + logger := New() + logger.Out = &bytes.Buffer{} + entry := NewEntry(logger) + + assert.Equal(err, entry.WithError(err).Data["error"]) + + ErrorKey = "err" + + assert.Equal(err, entry.WithError(err).Data["err"]) + +} + +func TestEntryWithContext(t *testing.T) { + assert := assert.New(t) + ctx := context.WithValue(context.Background(), "foo", "bar") + + assert.Equal(ctx, WithContext(ctx).Context) + + logger := New() + logger.Out = &bytes.Buffer{} + entry := NewEntry(logger) + + assert.Equal(ctx, entry.WithContext(ctx).Context) +} + +func TestEntryWithContextCopiesData(t *testing.T) { + assert := assert.New(t) + + // Initialize a parent Entry object with a key/value set in its Data map + logger := New() + logger.Out = &bytes.Buffer{} + parentEntry := NewEntry(logger).WithField("parentKey", "parentValue") + + // Create two children Entry objects from the parent in different contexts + ctx1 := context.WithValue(context.Background(), "foo", "bar") + childEntry1 := parentEntry.WithContext(ctx1) + assert.Equal(ctx1, childEntry1.Context) + + ctx2 := context.WithValue(context.Background(), "bar", "baz") + childEntry2 := parentEntry.WithContext(ctx2) + assert.Equal(ctx2, childEntry2.Context) + assert.NotEqual(ctx1, ctx2) + + // Ensure that data set in the parent Entry are preserved to both children + assert.Equal("parentValue", childEntry1.Data["parentKey"]) + assert.Equal("parentValue", childEntry2.Data["parentKey"]) + + // Modify data stored in the child entry + childEntry1.Data["childKey"] = "childValue" + + // Verify that data is successfully stored in the child it was set on + val, exists := childEntry1.Data["childKey"] + assert.True(exists) + assert.Equal("childValue", val) + + // Verify that the data change to child 1 has not affected its sibling + val, exists = childEntry2.Data["childKey"] + assert.False(exists) + assert.Empty(val) + + // Verify that the data change to child 1 has not affected its parent + val, exists = parentEntry.Data["childKey"] + assert.False(exists) + assert.Empty(val) +} + +func TestEntryWithTimeCopiesData(t *testing.T) { + assert := assert.New(t) + + // Initialize a parent Entry object with a key/value set in its Data map + logger := New() + logger.Out = &bytes.Buffer{} + parentEntry := NewEntry(logger).WithField("parentKey", "parentValue") + + // Create two children Entry objects from the parent with two different times + childEntry1 := parentEntry.WithTime(time.Now().AddDate(0, 0, 1)) + childEntry2 := parentEntry.WithTime(time.Now().AddDate(0, 0, 2)) + + // Ensure that data set in the parent Entry are preserved to both children + assert.Equal("parentValue", childEntry1.Data["parentKey"]) + assert.Equal("parentValue", childEntry2.Data["parentKey"]) + + // Modify data stored in the child entry + childEntry1.Data["childKey"] = "childValue" + + // Verify that data is successfully stored in the child it was set on + val, exists := childEntry1.Data["childKey"] + assert.True(exists) + assert.Equal("childValue", val) + + // Verify that the data change to child 1 has not affected its sibling + val, exists = childEntry2.Data["childKey"] + assert.False(exists) + assert.Empty(val) + + // Verify that the data change to child 1 has not affected its parent + val, exists = parentEntry.Data["childKey"] + assert.False(exists) + assert.Empty(val) +} + func TestEntryPanicln(t *testing.T) { errBoom := fmt.Errorf("boom time") @@ -51,3 +166,91 @@ func TestEntryPanicf(t *testing.T) { entry := NewEntry(logger) entry.WithField("err", errBoom).Panicf("kaboom %v", true) } + +const ( + badMessage = "this is going to panic" + panicMessage = "this is broken" +) + +type panickyHook struct{} + +func (p *panickyHook) Levels() []Level { + return []Level{InfoLevel} +} + +func (p *panickyHook) Fire(entry *Entry) error { + if entry.Message == badMessage { + panic(panicMessage) + } + + return nil +} + +func TestEntryHooksPanic(t *testing.T) { + logger := New() + logger.Out = &bytes.Buffer{} + logger.Level = InfoLevel + logger.Hooks.Add(&panickyHook{}) + + defer func() { + p := recover() + assert.NotNil(t, p) + assert.Equal(t, panicMessage, p) + + entry := NewEntry(logger) + entry.Info("another message") + }() + + entry := NewEntry(logger) + entry.Info(badMessage) +} + +func TestEntryWithIncorrectField(t *testing.T) { + assert := assert.New(t) + + fn := func() {} + + e := Entry{} + eWithFunc := e.WithFields(Fields{"func": fn}) + eWithFuncPtr := e.WithFields(Fields{"funcPtr": &fn}) + + assert.Equal(eWithFunc.err, `can not add field "func"`) + assert.Equal(eWithFuncPtr.err, `can not add field "funcPtr"`) + + eWithFunc = eWithFunc.WithField("not_a_func", "it is a string") + eWithFuncPtr = eWithFuncPtr.WithField("not_a_func", "it is a string") + + assert.Equal(eWithFunc.err, `can not add field "func"`) + assert.Equal(eWithFuncPtr.err, `can not add field "funcPtr"`) + + eWithFunc = eWithFunc.WithTime(time.Now()) + eWithFuncPtr = eWithFuncPtr.WithTime(time.Now()) + + assert.Equal(eWithFunc.err, `can not add field "func"`) + assert.Equal(eWithFuncPtr.err, `can not add field "funcPtr"`) +} + +func TestEntryLogfLevel(t *testing.T) { + logger := New() + buffer := &bytes.Buffer{} + logger.Out = buffer + logger.SetLevel(InfoLevel) + entry := NewEntry(logger) + + entry.Logf(DebugLevel, "%s", "debug") + assert.NotContains(t, buffer.String(), "debug") + + entry.Logf(WarnLevel, "%s", "warn") + assert.Contains(t, buffer.String(), "warn") +} + +func TestEntryReportCallerRace(t *testing.T) { + logger := New() + entry := NewEntry(logger) + go func() { + logger.SetReportCaller(true) + }() + go func() { + entry.Info("should not race") + }() +} diff --git a/example_basic_test.go b/example_basic_test.go new file mode 100644 index 000000000..9ff56555b --- /dev/null +++ b/example_basic_test.go @@ -0,0 +1,77 @@ +package logrus_test + +import ( + "os" + + "github.com/sirupsen/logrus" +) + +func Example_basic() { + var log = logrus.New() + log.Formatter = new(logrus.JSONFormatter) + log.Formatter = new(logrus.TextFormatter) //default + log.Formatter.(*logrus.TextFormatter).DisableColors = true // remove colors + log.Formatter.(*logrus.TextFormatter).DisableTimestamp = true // remove timestamp from test output + log.Level = logrus.TraceLevel + log.Out = os.Stdout + + // file, err := os.OpenFile("logrus.log", os.O_CREATE|os.O_WRONLY, 0666) + // if err == nil { + // log.Out = file + // } else { + // log.Info("Failed to log to file, using default stderr") + // } + + defer func() { + err := recover() + if err != nil { + entry := err.(*logrus.Entry) + log.WithFields(logrus.Fields{ + "omg": true, + "err_animal": entry.Data["animal"], + "err_size": entry.Data["size"], + "err_level": entry.Level, + "err_message": entry.Message, + "number": 100, + }).Error("The ice breaks!") // or use Fatal() to force the process to exit with a nonzero code + } + }() + + log.WithFields(logrus.Fields{ + "animal": "walrus", + "number": 0, + }).Trace("Went to the beach") + + log.WithFields(logrus.Fields{ + "animal": "walrus", + "number": 8, + }).Debug("Started observing beach") + + log.WithFields(logrus.Fields{ + "animal": "walrus", + "size": 10, + }).Info("A group of walrus emerges from the ocean") + + log.WithFields(logrus.Fields{ + "omg": true, + "number": 122, + }).Warn("The group's number increased tremendously!") + + log.WithFields(logrus.Fields{ + "temperature": -4, + }).Debug("Temperature changes") + + log.WithFields(logrus.Fields{ + "animal": "orca", + "size": 9009, + }).Panic("It's over 9000!") + + // Output: + // level=trace msg="Went to the beach" animal=walrus number=0 + // level=debug msg="Started observing beach" animal=walrus number=8 + // level=info msg="A group of walrus emerges from the ocean" animal=walrus size=10 + // level=warning msg="The group's number increased tremendously!" number=122 omg=true + // level=debug msg="Temperature changes" temperature=-4 + // level=panic msg="It's over 9000!" animal=orca size=9009 + // level=error msg="The ice breaks!" err_animal=orca err_level=panic err_message="It's over 9000!" err_size=9009 number=100 omg=true +} diff --git a/example_custom_caller_test.go b/example_custom_caller_test.go new file mode 100644 index 000000000..6749effbc --- /dev/null +++ b/example_custom_caller_test.go @@ -0,0 +1,28 @@ +package logrus_test + +import ( + "os" + "path" + "runtime" + "strings" + + "github.com/sirupsen/logrus" +) + +func ExampleJSONFormatter_CallerPrettyfier() { + l := logrus.New() + l.SetReportCaller(true) + l.Out = os.Stdout + l.Formatter = &logrus.JSONFormatter{ + DisableTimestamp: true, + CallerPrettyfier: func(f *runtime.Frame) (string, string) { + s := strings.Split(f.Function, ".") + funcname := s[len(s)-1] + _, filename := path.Split(f.File) + return funcname, filename + }, + } + l.Info("example of custom format caller") + // Output: + // {"file":"example_custom_caller_test.go","func":"ExampleJSONFormatter_CallerPrettyfier","level":"info","msg":"example of custom format caller"} +} diff --git a/example_default_field_value_test.go b/example_default_field_value_test.go new file mode 100644 index 000000000..e7edd1a8a --- /dev/null +++ b/example_default_field_value_test.go @@ -0,0 +1,31 @@ +package logrus_test + +import ( + "os" + + "github.com/sirupsen/logrus" +) + +type DefaultFieldHook struct { + GetValue func() string +} + +func (h *DefaultFieldHook) Levels() []logrus.Level { + return logrus.AllLevels +} + +func (h *DefaultFieldHook) Fire(e *logrus.Entry) error { + e.Data["aDefaultField"] = h.GetValue() + return nil +} + +func ExampleDefaultFieldHook() { + l := logrus.New() + l.Out = os.Stdout + l.Formatter = &logrus.TextFormatter{DisableTimestamp: true, DisableColors: true} + + l.AddHook(&DefaultFieldHook{GetValue: func() string { return "with its default value" }}) + l.Info("first log") + // Output: + // level=info msg="first log" aDefaultField="with its default value" +} diff --git a/example_function_test.go b/example_function_test.go new file mode 100644 index 000000000..dda890d83 --- /dev/null +++ b/example_function_test.go @@ -0,0 +1,31 @@ +package logrus_test + +import ( + "testing" + + log "github.com/sirupsen/logrus" + "github.com/stretchr/testify/assert" +) + +func TestLogger_LogFn(t *testing.T) { + log.SetFormatter(&log.JSONFormatter{}) + log.SetLevel(log.WarnLevel) + + notCalled := 0 + log.InfoFn(func() []interface{} { + notCalled++ + return []interface{}{ + "Hello", + } + }) + assert.Equal(t, 0, notCalled) + + called := 0 + log.ErrorFn(func() []interface{} { + called++ + return []interface{}{ + "Oopsi", + } + }) + assert.Equal(t, 1, called) +} diff --git a/example_global_hook_test.go b/example_global_hook_test.go new file mode 100644 index 000000000..ff7b2559f --- /dev/null +++ b/example_global_hook_test.go @@ -0,0 +1,37 @@ +package logrus_test + +import ( + "os" + + "github.com/sirupsen/logrus" +) + +var ( + mystring string +) + +type GlobalHook struct { +} + +func (h *GlobalHook) Levels() []logrus.Level { + return logrus.AllLevels +} + +func (h *GlobalHook) Fire(e *logrus.Entry) error { + e.Data["mystring"] = mystring + return nil +} + +func ExampleGlobalHook() { + l := logrus.New() + l.Out = os.Stdout + l.Formatter = &logrus.TextFormatter{DisableTimestamp: true, DisableColors: true} + l.AddHook(&GlobalHook{}) + mystring = "first value" + l.Info("first log") + mystring = "another value" + l.Info("second log") + // Output: + // level=info msg="first log" mystring="first value" + // level=info msg="second log" mystring="another value" +} diff --git a/example_hook_test.go b/example_hook_test.go new file mode 100644 index 000000000..dc0e69f19 --- /dev/null +++ b/example_hook_test.go @@ -0,0 +1,43 @@ +// +build !windows + +package logrus_test + +import ( + "log/syslog" + "os" + + "github.com/sirupsen/logrus" + slhooks "github.com/sirupsen/logrus/hooks/syslog" +) + +// An example on how to use a hook +func Example_hook() { + var log = logrus.New() + log.Formatter = new(logrus.TextFormatter) // default + log.Formatter.(*logrus.TextFormatter).DisableColors = true // remove colors + log.Formatter.(*logrus.TextFormatter).DisableTimestamp = true // remove timestamp from test output + if sl, err := slhooks.NewSyslogHook("udp", "localhost:514", syslog.LOG_INFO, ""); err == nil { + log.Hooks.Add(sl) + } + log.Out = os.Stdout + + log.WithFields(logrus.Fields{ + "animal": "walrus", + "size": 10, + }).Info("A group of walrus emerges from the ocean") + + log.WithFields(logrus.Fields{ + "omg": true, + "number": 122, + }).Warn("The group's number increased tremendously!") + + log.WithFields(logrus.Fields{ + "omg": true, + "number": 100, + }).Error("The ice breaks!") + + // Output: + // level=info msg="A group of walrus emerges from the ocean" animal=walrus size=10 + // level=warning msg="The group's number increased tremendously!" number=122 omg=true + // level=error msg="The ice breaks!" number=100 omg=true +} diff --git a/examples/basic/basic.go b/examples/basic/basic.go deleted file mode 100644 index a1623ec00..000000000 --- a/examples/basic/basic.go +++ /dev/null @@ -1,50 +0,0 @@ -package main - -import ( - "github.com/Sirupsen/logrus" -) - -var log = logrus.New() - -func init() { - log.Formatter = new(logrus.JSONFormatter) - log.Formatter = new(logrus.TextFormatter) // default - log.Level = logrus.DebugLevel -} - -func main() { - defer func() { - err := recover() - if err != nil { - log.WithFields(logrus.Fields{ - "omg": true, - "err": err, - "number": 100, - }).Fatal("The ice breaks!") - } - }() - - log.WithFields(logrus.Fields{ - "animal": "walrus", - "number": 8, - }).Debug("Started observing beach") - - log.WithFields(logrus.Fields{ - "animal": "walrus", - "size": 10, - }).Info("A group of walrus emerges from the ocean") - - log.WithFields(logrus.Fields{ - "omg": true, - "number": 122, - }).Warn("The group's number increased tremendously!") - - log.WithFields(logrus.Fields{ - "temperature": -4, - }).Debug("Temperature changes") - - log.WithFields(logrus.Fields{ - "animal": "orca", - "size": 9009, - }).Panic("It's over 9000!") -} diff --git a/examples/hook/hook.go b/examples/hook/hook.go deleted file mode 100644 index 42e7a4c98..000000000 --- a/examples/hook/hook.go +++ /dev/null @@ -1,35 +0,0 @@ -package main - -import ( - "github.com/Sirupsen/logrus" - "github.com/Sirupsen/logrus/hooks/airbrake" - "github.com/tobi/airbrake-go" -) - -var log = logrus.New() - -func init() { - log.Formatter = new(logrus.TextFormatter) // default - log.Hooks.Add(new(logrus_airbrake.AirbrakeHook)) -} - -func main() { - airbrake.Endpoint = "https://exceptions.whatever.com/notifier_api/v2/notices.xml" - airbrake.ApiKey = "whatever" - airbrake.Environment = "production" - - log.WithFields(logrus.Fields{ - "animal": "walrus", - "size": 10, - }).Info("A group of walrus emerges from the ocean") - - log.WithFields(logrus.Fields{ - "omg": true, - "number": 122, - }).Warn("The group's number increased tremendously!") - - log.WithFields(logrus.Fields{ - "omg": true, - "number": 100, - }).Fatal("The ice breaks!") -} diff --git a/exported.go b/exported.go index a67e1b802..017c30ce6 100644 --- a/exported.go +++ b/exported.go @@ -1,7 +1,9 @@ package logrus import ( + "context" "io" + "time" ) var ( @@ -15,37 +17,48 @@ func StandardLogger() *Logger { // SetOutput sets the standard logger output. func SetOutput(out io.Writer) { - std.mu.Lock() - defer std.mu.Unlock() - std.Out = out + std.SetOutput(out) } // SetFormatter sets the standard logger formatter. func SetFormatter(formatter Formatter) { - std.mu.Lock() - defer std.mu.Unlock() - std.Formatter = formatter + std.SetFormatter(formatter) +} + +// SetReportCaller sets whether the standard logger will include the calling +// method as a field. +func SetReportCaller(include bool) { + std.SetReportCaller(include) } // SetLevel sets the standard logger level. func SetLevel(level Level) { - std.mu.Lock() - defer std.mu.Unlock() - std.Level = level + std.SetLevel(level) } // GetLevel returns the standard logger level. func GetLevel() Level { - std.mu.Lock() - defer std.mu.Unlock() - return std.Level + return std.GetLevel() +} + +// IsLevelEnabled checks if the log level of the standard logger is greater than the level param +func IsLevelEnabled(level Level) bool { + return std.IsLevelEnabled(level) } // AddHook adds a hook to the standard logger hooks. func AddHook(hook Hook) { - std.mu.Lock() - defer std.mu.Unlock() - std.Hooks.Add(hook) + std.AddHook(hook) +} + +// WithError creates an entry from the standard logger and adds an error to it, using the value defined in ErrorKey as key. +func WithError(err error) *Entry { + return std.WithField(ErrorKey, err) +} + +// WithContext creates an entry from the standard logger and adds a context to it. +func WithContext(ctx context.Context) *Entry { + return std.WithContext(ctx) } // WithField creates an entry from the standard logger and adds a field to @@ -67,6 +80,20 @@ func WithFields(fields Fields) *Entry { return std.WithFields(fields) } +// WithTime creates an entry from the standard logger and overrides the time of +// logs generated with it. +// +// Note that it doesn't log until you call Debug, Print, Info, Warn, Fatal +// or Panic on the Entry it returns. +func WithTime(t time.Time) *Entry { + return std.WithTime(t) +} + +// Trace logs a message at level Trace on the standard logger. +func Trace(args ...interface{}) { + std.Trace(args...) +} + // Debug logs a message at level Debug on the standard logger. func Debug(args ...interface{}) { std.Debug(args...) @@ -102,11 +129,61 @@ func Panic(args ...interface{}) { std.Panic(args...) } -// Fatal logs a message at level Fatal on the standard logger. +// Fatal logs a message at level Fatal on the standard logger then the process will exit with status set to 1. func Fatal(args ...interface{}) { std.Fatal(args...) } +// TraceFn logs a message from a func at level Trace on the standard logger. +func TraceFn(fn LogFunction) { + std.TraceFn(fn) +} + +// DebugFn logs a message from a func at level Debug on the standard logger. +func DebugFn(fn LogFunction) { + std.DebugFn(fn) +} + +// PrintFn logs a message from a func at level Info on the standard logger. +func PrintFn(fn LogFunction) { + std.PrintFn(fn) +} + +// InfoFn logs a message from a func at level Info on the standard logger. +func InfoFn(fn LogFunction) { + std.InfoFn(fn) +} + +// WarnFn logs a message from a func at level Warn on the standard logger. +func WarnFn(fn LogFunction) { + std.WarnFn(fn) +} + +// WarningFn logs a message from a func at level Warn on the standard logger. +func WarningFn(fn LogFunction) { + std.WarningFn(fn) +} + +// ErrorFn logs a message from a func at level Error on the standard logger. +func ErrorFn(fn LogFunction) { + std.ErrorFn(fn) +} + +// PanicFn logs a message from a func at level Panic on the standard logger. +func PanicFn(fn LogFunction) { + std.PanicFn(fn) +} + +// FatalFn logs a message from a func at level Fatal on the standard logger then the process will exit with status set to 1. +func FatalFn(fn LogFunction) { + std.FatalFn(fn) +} + +// Tracef logs a message at level Trace on the standard logger. +func Tracef(format string, args ...interface{}) { + std.Tracef(format, args...) +} + // Debugf logs a message at level Debug on the standard logger. func Debugf(format string, args ...interface{}) { std.Debugf(format, args...) @@ -142,11 +219,16 @@ func Panicf(format string, args ...interface{}) { std.Panicf(format, args...) } -// Fatalf logs a message at level Fatal on the standard logger. +// Fatalf logs a message at level Fatal on the standard logger then the process will exit with status set to 1. func Fatalf(format string, args ...interface{}) { std.Fatalf(format, args...) } +// Traceln logs a message at level Trace on the standard logger. +func Traceln(args ...interface{}) { + std.Traceln(args...) +} + // Debugln logs a message at level Debug on the standard logger. func Debugln(args ...interface{}) { std.Debugln(args...) @@ -182,7 +264,7 @@ func Panicln(args ...interface{}) { std.Panicln(args...) } -// Fatalln logs a message at level Fatal on the standard logger. +// Fatalln logs a message at level Fatal on the standard logger then the process will exit with status set to 1. func Fatalln(args ...interface{}) { std.Fatalln(args...) } diff --git a/formatter.go b/formatter.go index 038ce9fd2..408883773 100644 --- a/formatter.go +++ b/formatter.go @@ -1,5 +1,18 @@ package logrus +import "time" + +// Default key names for the default fields +const ( + defaultTimestampFormat = time.RFC3339 + FieldKeyMsg = "msg" + FieldKeyLevel = "level" + FieldKeyTime = "time" + FieldKeyLogrusError = "logrus_error" + FieldKeyFunc = "func" + FieldKeyFile = "file" +) + // The Formatter interface is used to implement a custom Formatter. It takes an // `Entry`. It exposes all the fields, including the default ones: // @@ -14,7 +27,7 @@ type Formatter interface { Format(*Entry) ([]byte, error) } -// This is to not silently overwrite `time`, `msg` and `level` fields when +// This is to not silently overwrite `time`, `msg`, `func` and `level` fields when // dumping it. If this code wasn't there doing: // // logrus.WithField("level", 1).Info("hello") @@ -26,19 +39,40 @@ type Formatter interface { // // It's not exported because it's still using Data in an opinionated way. It's to // avoid code duplication between the two default formatters. -func prefixFieldClashes(data Fields) { - _, ok := data["time"] - if ok { - data["fields.time"] = data["time"] +func prefixFieldClashes(data Fields, fieldMap FieldMap, reportCaller bool) { + timeKey := fieldMap.resolve(FieldKeyTime) + if t, ok := data[timeKey]; ok { + data["fields."+timeKey] = t + delete(data, timeKey) + } + + msgKey := fieldMap.resolve(FieldKeyMsg) + if m, ok := data[msgKey]; ok { + data["fields."+msgKey] = m + delete(data, msgKey) + } + + levelKey := fieldMap.resolve(FieldKeyLevel) + if l, ok := data[levelKey]; ok { + data["fields."+levelKey] = l + delete(data, levelKey) } - _, ok = data["msg"] - if ok { - data["fields.msg"] = data["msg"] + logrusErrKey := fieldMap.resolve(FieldKeyLogrusError) + if l, ok := data[logrusErrKey]; ok { + data["fields."+logrusErrKey] = l + delete(data, logrusErrKey) } - _, ok = data["level"] - if ok { - data["fields.level"] = data["level"] + // If reportCaller is not set, 'func' will not conflict. + if reportCaller { + funcKey := fieldMap.resolve(FieldKeyFunc) + if l, ok := data[funcKey]; ok { + data["fields."+funcKey] = l + } + fileKey := fieldMap.resolve(FieldKeyFile) + if l, ok := data[fileKey]; ok { + data["fields."+fileKey] = l + } } } diff --git a/formatter_bench_test.go b/formatter_bench_test.go index 77989da62..d9481589f 100644 --- a/formatter_bench_test.go +++ b/formatter_bench_test.go @@ -1,6 +1,7 @@ package logrus import ( + "fmt" "testing" "time" ) @@ -45,6 +46,15 @@ var largeFields = Fields{ "entries": "yeah", } +var errorFields = Fields{ + "foo": fmt.Errorf("bar"), + "baz": fmt.Errorf("qux"), +} + +func BenchmarkErrorTextFormatter(b *testing.B) { + doBenchmark(b, &TextFormatter{DisableColors: true}, errorFields) +} + func BenchmarkSmallTextFormatter(b *testing.B) { doBenchmark(b, &TextFormatter{DisableColors: true}, smallFields) } @@ -70,11 +80,14 @@ func BenchmarkLargeJSONFormatter(b *testing.B) { } func doBenchmark(b *testing.B, formatter Formatter, fields Fields) { + logger := New() + entry := &Entry{ Time: time.Time{}, Level: InfoLevel, Message: "message", Data: fields, + Logger: logger, } var d []byte var err error diff --git a/go.mod b/go.mod new file mode 100644 index 000000000..b3919d5ea --- /dev/null +++ b/go.mod @@ -0,0 +1,10 @@ +module github.com/sirupsen/logrus + +require ( + github.com/davecgh/go-spew v1.1.1 // indirect + github.com/pmezard/go-difflib v1.0.0 // indirect + github.com/stretchr/testify v1.2.2 + golang.org/x/sys v0.0.0-20191026070338-33540a1f6037 +) + +go 1.13 diff --git a/go.sum b/go.sum new file mode 100644 index 000000000..1edc143be --- /dev/null +++ b/go.sum @@ -0,0 +1,10 @@ +github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= +github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= +github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= +github.com/stretchr/testify v1.2.2 h1:bSDNvY7ZPG5RlJ8otE/7V6gMiyenm9RtJ7IUVIAoJ1w= +github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs= +golang.org/x/sys v0.0.0-20190422165155-953cdadca894 h1:Cz4ceDQGXuKRnVBDTS23GTn/pU5OE2C0WrNTOYK1Uuc= +golang.org/x/sys v0.0.0-20190422165155-953cdadca894/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= +golang.org/x/sys v0.0.0-20191026070338-33540a1f6037 h1:YyJpGZS1sBuBCzLAR1VEpK193GlqGZbnPFnPV/5Rsb4= +golang.org/x/sys v0.0.0-20191026070338-33540a1f6037/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= diff --git a/hook_test.go b/hook_test.go index 13f34cb6f..b5cf077b1 100644 --- a/hook_test.go +++ b/hook_test.go @@ -1,9 +1,16 @@ -package logrus +package logrus_test import ( + "bytes" + "encoding/json" + "sync" "testing" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + . "github.com/sirupsen/logrus" + . "github.com/sirupsen/logrus/internal/testutils" ) type TestHook struct { @@ -17,6 +24,7 @@ func (hook *TestHook) Fire(entry *Entry) error { func (hook *TestHook) Levels() []Level { return []Level{ + TraceLevel, DebugLevel, InfoLevel, WarnLevel, @@ -49,6 +57,7 @@ func (hook *ModifyHook) Fire(entry *Entry) error { func (hook *ModifyHook) Levels() []Level { return []Level{ + TraceLevel, DebugLevel, InfoLevel, WarnLevel, @@ -84,6 +93,46 @@ func TestCanFireMultipleHooks(t *testing.T) { }) } +type SingleLevelModifyHook struct { + ModifyHook +} + +func (h *SingleLevelModifyHook) Levels() []Level { + return []Level{InfoLevel} +} + +func TestHookEntryIsPristine(t *testing.T) { + l := New() + b := &bytes.Buffer{} + l.Formatter = &JSONFormatter{} + l.Out = b + l.AddHook(&SingleLevelModifyHook{}) + + l.Error("error message") + data := map[string]string{} + err := json.Unmarshal(b.Bytes(), &data) + require.NoError(t, err) + _, ok := data["wow"] + require.False(t, ok) + b.Reset() + + l.Info("error message") + data = map[string]string{} + err = json.Unmarshal(b.Bytes(), &data) + require.NoError(t, err) + _, ok = data["wow"] + require.True(t, ok) + b.Reset() + + l.Error("error message") + data = map[string]string{} + err = json.Unmarshal(b.Bytes(), &data) + require.NoError(t, err) + _, ok = data["wow"] + require.False(t, ok) + b.Reset() +} + type ErrorHook struct { Fired bool } @@ -120,3 +169,50 @@ func TestErrorHookShouldFireOnError(t *testing.T) { assert.Equal(t, hook.Fired, true) }) } + +func TestAddHookRace(t *testing.T) { + var wg sync.WaitGroup + wg.Add(2) + hook := new(ErrorHook) + LogAndAssertJSON(t, func(log *Logger) { + go func() { + defer wg.Done() + log.AddHook(hook) + }() + go func() { + defer wg.Done() + log.Error("test") + }() + wg.Wait() + }, func(fields Fields) { + // the line may have been logged + // before the hook was added, so we can't + // actually assert on the hook + }) +} + +type HookCallFunc struct { + F func() +} + +func (h *HookCallFunc) Levels() []Level { + return AllLevels +} + +func (h *HookCallFunc) Fire(e *Entry) error { + h.F() + return nil +} + +func TestHookFireOrder(t *testing.T) { + checkers := []string{} + h := LevelHooks{} + h.Add(&HookCallFunc{F: func() { checkers = append(checkers, "first hook") }}) + h.Add(&HookCallFunc{F: func() { checkers = append(checkers, "second hook") }}) + h.Add(&HookCallFunc{F: func() { checkers = append(checkers, "third hook") }}) + + if err := h.Fire(InfoLevel, &Entry{}); err != nil { + t.Error("unexpected error:", err) + } + require.Equal(t, []string{"first hook", "second hook", "third hook"}, checkers) +} diff --git a/hooks.go b/hooks.go index 0da2b3653..3f151cdc3 100644 --- a/hooks.go +++ b/hooks.go @@ -11,11 +11,11 @@ type Hook interface { } // Internal type for storing the hooks on a logger instance. -type levelHooks map[Level][]Hook +type LevelHooks map[Level][]Hook // Add a hook to an instance of logger. This is called with // `log.Hooks.Add(new(MyHook))` where `MyHook` implements the `Hook` interface. -func (hooks levelHooks) Add(hook Hook) { +func (hooks LevelHooks) Add(hook Hook) { for _, level := range hook.Levels() { hooks[level] = append(hooks[level], hook) } @@ -23,7 +23,7 @@ func (hooks levelHooks) Add(hook Hook) { // Fire all the hooks for the passed level. Used by `entry.log` to fire // appropriate hooks for a log entry. -func (hooks levelHooks) Fire(level Level, entry *Entry) error { +func (hooks LevelHooks) Fire(level Level, entry *Entry) error { for _, hook := range hooks[level] { if err := hook.Fire(entry); err != nil { return err diff --git a/hooks/airbrake/airbrake.go b/hooks/airbrake/airbrake.go deleted file mode 100644 index 75f4db151..000000000 --- a/hooks/airbrake/airbrake.go +++ /dev/null @@ -1,54 +0,0 @@ -package logrus_airbrake - -import ( - "github.com/Sirupsen/logrus" - "github.com/tobi/airbrake-go" -) - -// AirbrakeHook to send exceptions to an exception-tracking service compatible -// with the Airbrake API. You must set: -// * airbrake.Endpoint -// * airbrake.ApiKey -// * airbrake.Environment -// -// Before using this hook, to send an error. Entries that trigger an Error, -// Fatal or Panic should now include an "error" field to send to Airbrake. -type AirbrakeHook struct{} - -func (hook *AirbrakeHook) Fire(entry *logrus.Entry) error { - if entry.Data["error"] == nil { - entry.Logger.WithFields(logrus.Fields{ - "source": "airbrake", - "endpoint": airbrake.Endpoint, - }).Warn("Exceptions sent to Airbrake must have an 'error' key with the error") - return nil - } - - err, ok := entry.Data["error"].(error) - if !ok { - entry.Logger.WithFields(logrus.Fields{ - "source": "airbrake", - "endpoint": airbrake.Endpoint, - }).Warn("Exceptions sent to Airbrake must have an `error` key of type `error`") - return nil - } - - airErr := airbrake.Notify(err) - if airErr != nil { - entry.Logger.WithFields(logrus.Fields{ - "source": "airbrake", - "endpoint": airbrake.Endpoint, - "error": airErr, - }).Warn("Failed to send error to Airbrake") - } - - return nil -} - -func (hook *AirbrakeHook) Levels() []logrus.Level { - return []logrus.Level{ - logrus.ErrorLevel, - logrus.FatalLevel, - logrus.PanicLevel, - } -} diff --git a/hooks/airbrake/airbrake_test.go b/hooks/airbrake/airbrake_test.go deleted file mode 100644 index d2fd61dad..000000000 --- a/hooks/airbrake/airbrake_test.go +++ /dev/null @@ -1,57 +0,0 @@ -package logrus_airbrake - -import ( - "encoding/xml" - "errors" - "net/http" - "net/http/httptest" - "testing" - "time" - - "github.com/Sirupsen/logrus" - "github.com/tobi/airbrake-go" -) - -type notice struct { - Error struct { - Message string `xml:"message"` - } `xml:"error"` -} - -func TestNoticeReceived(t *testing.T) { - msg := make(chan string, 1) - expectedMsg := "foo" - - ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - var notice notice - if err := xml.NewDecoder(r.Body).Decode(¬ice); err != nil { - t.Error(err) - } - r.Body.Close() - - msg <- notice.Error.Message - })) - defer ts.Close() - - hook := &AirbrakeHook{} - - airbrake.Environment = "production" - airbrake.Endpoint = ts.URL - airbrake.ApiKey = "foo" - - log := logrus.New() - log.Hooks.Add(hook) - - log.WithFields(logrus.Fields{ - "error": errors.New(expectedMsg), - }).Error("Airbrake will not see this string") - - select { - case received := <-msg: - if received != expectedMsg { - t.Errorf("Unexpected message received: %s", received) - } - case <-time.After(time.Second): - t.Error("Timed out; no notice received by Airbrake API") - } -} diff --git a/hooks/papertrail/README.md b/hooks/papertrail/README.md deleted file mode 100644 index ae61e9229..000000000 --- a/hooks/papertrail/README.md +++ /dev/null @@ -1,28 +0,0 @@ -# Papertrail Hook for Logrus :walrus: - -[Papertrail](https://papertrailapp.com) provides hosted log management. Once stored in Papertrail, you can [group](http://help.papertrailapp.com/kb/how-it-works/groups/) your logs on various dimensions, [search](http://help.papertrailapp.com/kb/how-it-works/search-syntax) them, and trigger [alerts](http://help.papertrailapp.com/kb/how-it-works/alerts). - -In most deployments, you'll want to send logs to Papertrail via their [remote_syslog](http://help.papertrailapp.com/kb/configuration/configuring-centralized-logging-from-text-log-files-in-unix/) daemon, which requires no application-specific configuration. This hook is intended for relatively low-volume logging, likely in managed cloud hosting deployments where installing `remote_syslog` is not possible. - -## Usage - -You can find your Papertrail UDP port on your [Papertrail account page](https://papertrailapp.com/account/destinations). Substitute it below for `YOUR_PAPERTRAIL_UDP_PORT`. - -For `YOUR_APP_NAME`, substitute a short string that will readily identify your application or service in the logs. - -```go -import ( - "log/syslog" - "github.com/Sirupsen/logrus" - "github.com/Sirupsen/logrus/hooks/papertrail" -) - -func main() { - log := logrus.New() - hook, err := logrus_papertrail.NewPapertrailHook("logs.papertrailapp.com", YOUR_PAPERTRAIL_UDP_PORT, YOUR_APP_NAME) - - if err == nil { - log.Hooks.Add(hook) - } -} -``` diff --git a/hooks/papertrail/papertrail.go b/hooks/papertrail/papertrail.go deleted file mode 100644 index c0f10c1bd..000000000 --- a/hooks/papertrail/papertrail.go +++ /dev/null @@ -1,55 +0,0 @@ -package logrus_papertrail - -import ( - "fmt" - "net" - "os" - "time" - - "github.com/Sirupsen/logrus" -) - -const ( - format = "Jan 2 15:04:05" -) - -// PapertrailHook to send logs to a logging service compatible with the Papertrail API. -type PapertrailHook struct { - Host string - Port int - AppName string - UDPConn net.Conn -} - -// NewPapertrailHook creates a hook to be added to an instance of logger. -func NewPapertrailHook(host string, port int, appName string) (*PapertrailHook, error) { - conn, err := net.Dial("udp", fmt.Sprintf("%s:%d", host, port)) - return &PapertrailHook{host, port, appName, conn}, err -} - -// Fire is called when a log event is fired. -func (hook *PapertrailHook) Fire(entry *logrus.Entry) error { - date := time.Now().Format(format) - msg, _ := entry.String() - payload := fmt.Sprintf("<22> %s %s: %s", date, hook.AppName, msg) - - bytesWritten, err := hook.UDPConn.Write([]byte(payload)) - if err != nil { - fmt.Fprintf(os.Stderr, "Unable to send log line to Papertrail via UDP. Wrote %d bytes before error: %v", bytesWritten, err) - return err - } - - return nil -} - -// Levels returns the available logging levels. -func (hook *PapertrailHook) Levels() []logrus.Level { - return []logrus.Level{ - logrus.PanicLevel, - logrus.FatalLevel, - logrus.ErrorLevel, - logrus.WarnLevel, - logrus.InfoLevel, - logrus.DebugLevel, - } -} diff --git a/hooks/papertrail/papertrail_test.go b/hooks/papertrail/papertrail_test.go deleted file mode 100644 index 96318d003..000000000 --- a/hooks/papertrail/papertrail_test.go +++ /dev/null @@ -1,26 +0,0 @@ -package logrus_papertrail - -import ( - "fmt" - "testing" - - "github.com/Sirupsen/logrus" - "github.com/stvp/go-udp-testing" -) - -func TestWritingToUDP(t *testing.T) { - port := 16661 - udp.SetAddr(fmt.Sprintf(":%d", port)) - - hook, err := NewPapertrailHook("localhost", port, "test") - if err != nil { - t.Errorf("Unable to connect to local UDP server.") - } - - log := logrus.New() - log.Hooks.Add(hook) - - udp.ShouldReceive(t, "foo", func() { - log.Info("foo") - }) -} diff --git a/hooks/sentry/README.md b/hooks/sentry/README.md deleted file mode 100644 index 19e58bb45..000000000 --- a/hooks/sentry/README.md +++ /dev/null @@ -1,61 +0,0 @@ -# Sentry Hook for Logrus :walrus: - -[Sentry](https://getsentry.com) provides both self-hosted and hosted -solutions for exception tracking. -Both client and server are -[open source](https://github.com/getsentry/sentry). - -## Usage - -Every sentry application defined on the server gets a different -[DSN](https://www.getsentry.com/docs/). In the example below replace -`YOUR_DSN` with the one created for your application. - -```go -import ( - "github.com/Sirupsen/logrus" - "github.com/Sirupsen/logrus/hooks/sentry" -) - -func main() { - log := logrus.New() - hook, err := logrus_sentry.NewSentryHook(YOUR_DSN, []logrus.Level{ - logrus.PanicLevel, - logrus.FatalLevel, - logrus.ErrorLevel, - }) - - if err == nil { - log.Hooks.Add(hook) - } -} -``` - -## Special fields - -Some logrus fields have a special meaning in this hook, -these are server_name and logger. -When logs are sent to sentry these fields are treated differently. -- server_name (also known as hostname) is the name of the server which -is logging the event (hostname.example.com) -- logger is the part of the application which is logging the event. -In go this usually means setting it to the name of the package. - -## Timeout - -`Timeout` is the time the sentry hook will wait for a response -from the sentry server. - -If this time elapses with no response from -the server an error will be returned. - -If `Timeout` is set to 0 the SentryHook will not wait for a reply -and will assume a correct delivery. - -The SentryHook has a default timeout of `100 milliseconds` when created -with a call to `NewSentryHook`. This can be changed by assigning a value to the `Timeout` field: - -```go -hook, _ := logrus_sentry.NewSentryHook(...) -hook.Timeout = 20*time.Second -``` diff --git a/hooks/sentry/sentry.go b/hooks/sentry/sentry.go deleted file mode 100644 index 379f281c5..000000000 --- a/hooks/sentry/sentry.go +++ /dev/null @@ -1,100 +0,0 @@ -package logrus_sentry - -import ( - "fmt" - "time" - - "github.com/Sirupsen/logrus" - "github.com/getsentry/raven-go" -) - -var ( - severityMap = map[logrus.Level]raven.Severity{ - logrus.DebugLevel: raven.DEBUG, - logrus.InfoLevel: raven.INFO, - logrus.WarnLevel: raven.WARNING, - logrus.ErrorLevel: raven.ERROR, - logrus.FatalLevel: raven.FATAL, - logrus.PanicLevel: raven.FATAL, - } -) - -func getAndDel(d logrus.Fields, key string) (string, bool) { - var ( - ok bool - v interface{} - val string - ) - if v, ok = d[key]; !ok { - return "", false - } - - if val, ok = v.(string); !ok { - return "", false - } - delete(d, key) - return val, true -} - -// SentryHook delivers logs to a sentry server. -type SentryHook struct { - // Timeout sets the time to wait for a delivery error from the sentry server. - // If this is set to zero the server will not wait for any response and will - // consider the message correctly sent - Timeout time.Duration - - client *raven.Client - levels []logrus.Level -} - -// NewSentryHook creates a hook to be added to an instance of logger -// and initializes the raven client. -// This method sets the timeout to 100 milliseconds. -func NewSentryHook(DSN string, levels []logrus.Level) (*SentryHook, error) { - client, err := raven.NewClient(DSN, nil) - if err != nil { - return nil, err - } - return &SentryHook{100 * time.Millisecond, client, levels}, nil -} - -// Called when an event should be sent to sentry -// Special fields that sentry uses to give more information to the server -// are extracted from entry.Data (if they are found) -// These fields are: logger and server_name -func (hook *SentryHook) Fire(entry *logrus.Entry) error { - packet := &raven.Packet{ - Message: entry.Message, - Timestamp: raven.Timestamp(entry.Time), - Level: severityMap[entry.Level], - Platform: "go", - } - - d := entry.Data - - if logger, ok := getAndDel(d, "logger"); ok { - packet.Logger = logger - } - if serverName, ok := getAndDel(d, "server_name"); ok { - packet.ServerName = serverName - } - packet.Extra = map[string]interface{}(d) - - _, errCh := hook.client.Capture(packet, nil) - timeout := hook.Timeout - if timeout != 0 { - timeoutCh := time.After(timeout) - select { - case err := <-errCh: - return err - case <-timeoutCh: - return fmt.Errorf("no response from sentry server in %s", timeout) - } - } - return nil -} - -// Levels returns the available logging levels. -func (hook *SentryHook) Levels() []logrus.Level { - return hook.levels -} diff --git a/hooks/sentry/sentry_test.go b/hooks/sentry/sentry_test.go deleted file mode 100644 index 45f18d170..000000000 --- a/hooks/sentry/sentry_test.go +++ /dev/null @@ -1,97 +0,0 @@ -package logrus_sentry - -import ( - "encoding/json" - "fmt" - "io/ioutil" - "net/http" - "net/http/httptest" - "strings" - "testing" - - "github.com/Sirupsen/logrus" - "github.com/getsentry/raven-go" -) - -const ( - message = "error message" - server_name = "testserver.internal" - logger_name = "test.logger" -) - -func getTestLogger() *logrus.Logger { - l := logrus.New() - l.Out = ioutil.Discard - return l -} - -func WithTestDSN(t *testing.T, tf func(string, <-chan *raven.Packet)) { - pch := make(chan *raven.Packet, 1) - s := httptest.NewServer(http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) { - defer req.Body.Close() - d := json.NewDecoder(req.Body) - p := &raven.Packet{} - err := d.Decode(p) - if err != nil { - t.Fatal(err.Error()) - } - - pch <- p - })) - defer s.Close() - - fragments := strings.SplitN(s.URL, "://", 2) - dsn := fmt.Sprintf( - "%s://public:secret@%s/sentry/project-id", - fragments[0], - fragments[1], - ) - tf(dsn, pch) -} - -func TestSpecialFields(t *testing.T) { - WithTestDSN(t, func(dsn string, pch <-chan *raven.Packet) { - logger := getTestLogger() - - hook, err := NewSentryHook(dsn, []logrus.Level{ - logrus.ErrorLevel, - }) - - if err != nil { - t.Fatal(err.Error()) - } - logger.Hooks.Add(hook) - logger.WithFields(logrus.Fields{ - "server_name": server_name, - "logger": logger_name, - }).Error(message) - - packet := <-pch - if packet.Logger != logger_name { - t.Errorf("logger should have been %s, was %s", logger_name, packet.Logger) - } - - if packet.ServerName != server_name { - t.Errorf("server_name should have been %s, was %s", server_name, packet.ServerName) - } - }) -} - -func TestSentryHandler(t *testing.T) { - WithTestDSN(t, func(dsn string, pch <-chan *raven.Packet) { - logger := getTestLogger() - hook, err := NewSentryHook(dsn, []logrus.Level{ - logrus.ErrorLevel, - }) - if err != nil { - t.Fatal(err.Error()) - } - logger.Hooks.Add(hook) - - logger.Error(message) - packet := <-pch - if packet.Message != message { - t.Errorf("message should have been %s, was %s", message, packet.Message) - } - }) -} diff --git a/hooks/syslog/README.md b/hooks/syslog/README.md index 4dbb8e729..1bbc0f72d 100644 --- a/hooks/syslog/README.md +++ b/hooks/syslog/README.md @@ -5,13 +5,32 @@ ```go import ( "log/syslog" - "github.com/Sirupsen/logrus" - logrus_syslog "github.com/Sirupsen/logrus/hooks/syslog" + "github.com/sirupsen/logrus" + lSyslog "github.com/sirupsen/logrus/hooks/syslog" ) func main() { log := logrus.New() - hook, err := logrus_syslog.NewSyslogHook("udp", "localhost:514", syslog.LOG_INFO, "") + hook, err := lSyslog.NewSyslogHook("udp", "localhost:514", syslog.LOG_INFO, "") + + if err == nil { + log.Hooks.Add(hook) + } +} +``` + +If you want to connect to local syslog (Ex. "/dev/log" or "/var/run/syslog" or "/var/run/log"). Just assign empty string to the first two parameters of `NewSyslogHook`. It should look like the following. + +```go +import ( + "log/syslog" + "github.com/sirupsen/logrus" + lSyslog "github.com/sirupsen/logrus/hooks/syslog" +) + +func main() { + log := logrus.New() + hook, err := lSyslog.NewSyslogHook("", "", syslog.LOG_INFO, "") if err == nil { log.Hooks.Add(hook) diff --git a/hooks/syslog/syslog.go b/hooks/syslog/syslog.go index b6fa37462..02b8df380 100644 --- a/hooks/syslog/syslog.go +++ b/hooks/syslog/syslog.go @@ -1,10 +1,13 @@ -package logrus_syslog +// +build !windows,!nacl,!plan9 + +package syslog import ( "fmt" - "github.com/Sirupsen/logrus" "log/syslog" "os" + + "github.com/sirupsen/logrus" ) // SyslogHook to send logs via syslog. @@ -40,7 +43,7 @@ func (hook *SyslogHook) Fire(entry *logrus.Entry) error { return hook.Writer.Warning(line) case logrus.InfoLevel: return hook.Writer.Info(line) - case logrus.DebugLevel: + case logrus.DebugLevel, logrus.TraceLevel: return hook.Writer.Debug(line) default: return nil @@ -48,12 +51,5 @@ func (hook *SyslogHook) Fire(entry *logrus.Entry) error { } func (hook *SyslogHook) Levels() []logrus.Level { - return []logrus.Level{ - logrus.PanicLevel, - logrus.FatalLevel, - logrus.ErrorLevel, - logrus.WarnLevel, - logrus.InfoLevel, - logrus.DebugLevel, - } + return logrus.AllLevels } diff --git a/hooks/syslog/syslog_test.go b/hooks/syslog/syslog_test.go index 42762dc10..bec6efd5a 100644 --- a/hooks/syslog/syslog_test.go +++ b/hooks/syslog/syslog_test.go @@ -1,9 +1,12 @@ -package logrus_syslog +// +build !windows,!nacl,!plan9 + +package syslog import ( - "github.com/Sirupsen/logrus" "log/syslog" "testing" + + "github.com/sirupsen/logrus" ) func TestLocalhostAddAndPrint(t *testing.T) { diff --git a/hooks/test/test.go b/hooks/test/test.go new file mode 100644 index 000000000..b16d06654 --- /dev/null +++ b/hooks/test/test.go @@ -0,0 +1,91 @@ +// The Test package is used for testing logrus. +// It provides a simple hooks which register logged messages. +package test + +import ( + "io/ioutil" + "sync" + + "github.com/sirupsen/logrus" +) + +// Hook is a hook designed for dealing with logs in test scenarios. +type Hook struct { + // Entries is an array of all entries that have been received by this hook. + // For safe access, use the AllEntries() method, rather than reading this + // value directly. + Entries []logrus.Entry + mu sync.RWMutex +} + +// NewGlobal installs a test hook for the global logger. +func NewGlobal() *Hook { + + hook := new(Hook) + logrus.AddHook(hook) + + return hook + +} + +// NewLocal installs a test hook for a given local logger. +func NewLocal(logger *logrus.Logger) *Hook { + + hook := new(Hook) + logger.Hooks.Add(hook) + + return hook + +} + +// NewNullLogger creates a discarding logger and installs the test hook. +func NewNullLogger() (*logrus.Logger, *Hook) { + + logger := logrus.New() + logger.Out = ioutil.Discard + + return logger, NewLocal(logger) + +} + +func (t *Hook) Fire(e *logrus.Entry) error { + t.mu.Lock() + defer t.mu.Unlock() + t.Entries = append(t.Entries, *e) + return nil +} + +func (t *Hook) Levels() []logrus.Level { + return logrus.AllLevels +} + +// LastEntry returns the last entry that was logged or nil. +func (t *Hook) LastEntry() *logrus.Entry { + t.mu.RLock() + defer t.mu.RUnlock() + i := len(t.Entries) - 1 + if i < 0 { + return nil + } + return &t.Entries[i] +} + +// AllEntries returns all entries that were logged. +func (t *Hook) AllEntries() []*logrus.Entry { + t.mu.RLock() + defer t.mu.RUnlock() + // Make a copy so the returned value won't race with future log requests + entries := make([]*logrus.Entry, len(t.Entries)) + for i := 0; i < len(t.Entries); i++ { + // Make a copy, for safety + entries[i] = &t.Entries[i] + } + return entries +} + +// Reset removes all Entries from this test hook. +func (t *Hook) Reset() { + t.mu.Lock() + defer t.mu.Unlock() + t.Entries = make([]logrus.Entry, 0) +} diff --git a/hooks/test/test_test.go b/hooks/test/test_test.go new file mode 100644 index 000000000..636bad512 --- /dev/null +++ b/hooks/test/test_test.go @@ -0,0 +1,85 @@ +package test + +import ( + "math/rand" + "sync" + "testing" + "time" + + "github.com/sirupsen/logrus" + "github.com/stretchr/testify/assert" +) + +func TestAllHooks(t *testing.T) { + assert := assert.New(t) + + logger, hook := NewNullLogger() + assert.Nil(hook.LastEntry()) + assert.Equal(0, len(hook.Entries)) + + logger.Error("Hello error") + assert.Equal(logrus.ErrorLevel, hook.LastEntry().Level) + assert.Equal("Hello error", hook.LastEntry().Message) + assert.Equal(1, len(hook.Entries)) + + logger.Warn("Hello warning") + assert.Equal(logrus.WarnLevel, hook.LastEntry().Level) + assert.Equal("Hello warning", hook.LastEntry().Message) + assert.Equal(2, len(hook.Entries)) + + hook.Reset() + assert.Nil(hook.LastEntry()) + assert.Equal(0, len(hook.Entries)) + + hook = NewGlobal() + + logrus.Error("Hello error") + assert.Equal(logrus.ErrorLevel, hook.LastEntry().Level) + assert.Equal("Hello error", hook.LastEntry().Message) + assert.Equal(1, len(hook.Entries)) +} + +func TestLoggingWithHooksRace(t *testing.T) { + + rand.Seed(time.Now().Unix()) + unlocker := rand.Int() % 100 + + assert := assert.New(t) + logger, hook := NewNullLogger() + + var wgOne, wgAll sync.WaitGroup + wgOne.Add(1) + wgAll.Add(100) + + for i := 0; i < 100; i++ { + go func(i int) { + logger.Info("info") + wgAll.Done() + if i == unlocker { + wgOne.Done() + } + }(i) + } + + wgOne.Wait() + + assert.Equal(logrus.InfoLevel, hook.LastEntry().Level) + assert.Equal("info", hook.LastEntry().Message) + + wgAll.Wait() + + entries := hook.AllEntries() + assert.Equal(100, len(entries)) +} + +func TestFatalWithAlternateExit(t *testing.T) { + assert := assert.New(t) + + logger, hook := NewNullLogger() + logger.ExitFunc = func(code int) {} + + logger.Fatal("something went very wrong") + assert.Equal(logrus.FatalLevel, hook.LastEntry().Level) + assert.Equal("something went very wrong", hook.LastEntry().Message) + assert.Equal(1, len(hook.Entries)) +} diff --git a/hooks/writer/README.md b/hooks/writer/README.md new file mode 100644 index 000000000..69676309f --- /dev/null +++ b/hooks/writer/README.md @@ -0,0 +1,43 @@ +# Writer Hooks for Logrus + +Send logs of given levels to any object with `io.Writer` interface. + +## Usage + +If you want for example send high level logs to `Stderr` and +logs of normal execution to `Stdout`, you could do it like this: + +```go +package main + +import ( + "io/ioutil" + "os" + + log "github.com/sirupsen/logrus" + "github.com/sirupsen/logrus/hooks/writer" +) + +func main() { + log.SetOutput(ioutil.Discard) // Send all logs to nowhere by default + + log.AddHook(&writer.Hook{ // Send logs with level higher than warning to stderr + Writer: os.Stderr, + LogLevels: []log.Level{ + log.PanicLevel, + log.FatalLevel, + log.ErrorLevel, + log.WarnLevel, + }, + }) + log.AddHook(&writer.Hook{ // Send info and debug logs to stdout + Writer: os.Stdout, + LogLevels: []log.Level{ + log.InfoLevel, + log.DebugLevel, + }, + }) + log.Info("This will go to stdout") + log.Warn("This will go to stderr") +} +``` diff --git a/hooks/writer/writer.go b/hooks/writer/writer.go new file mode 100644 index 000000000..1160c790e --- /dev/null +++ b/hooks/writer/writer.go @@ -0,0 +1,29 @@ +package writer + +import ( + "io" + + log "github.com/sirupsen/logrus" +) + +// Hook is a hook that writes logs of specified LogLevels to specified Writer +type Hook struct { + Writer io.Writer + LogLevels []log.Level +} + +// Fire will be called when some logging function is called with current hook +// It will format log entry to string and write it to appropriate writer +func (hook *Hook) Fire(entry *log.Entry) error { + line, err := entry.Bytes() + if err != nil { + return err + } + _, err = hook.Writer.Write(line) + return err +} + +// Levels define on which log levels this hook would trigger +func (hook *Hook) Levels() []log.Level { + return hook.LogLevels +} diff --git a/hooks/writer/writer_test.go b/hooks/writer/writer_test.go new file mode 100644 index 000000000..a30d3b01a --- /dev/null +++ b/hooks/writer/writer_test.go @@ -0,0 +1,38 @@ +package writer + +import ( + "bytes" + "io/ioutil" + "testing" + + log "github.com/sirupsen/logrus" + "github.com/stretchr/testify/assert" +) + +func TestDifferentLevelsGoToDifferentWriters(t *testing.T) { + var a, b bytes.Buffer + + log.SetFormatter(&log.TextFormatter{ + DisableTimestamp: true, + DisableColors: true, + }) + log.SetOutput(ioutil.Discard) // Send all logs to nowhere by default + + log.AddHook(&Hook{ + Writer: &a, + LogLevels: []log.Level{ + log.WarnLevel, + }, + }) + log.AddHook(&Hook{ // Send info and debug logs to stdout + Writer: &b, + LogLevels: []log.Level{ + log.InfoLevel, + }, + }) + log.Warn("send to a") + log.Info("send to b") + + assert.Equal(t, a.String(), "level=warning msg=\"send to a\"\n") + assert.Equal(t, b.String(), "level=info msg=\"send to b\"\n") +} diff --git a/internal/testutils/testutils.go b/internal/testutils/testutils.go new file mode 100644 index 000000000..6e3a6203e --- /dev/null +++ b/internal/testutils/testutils.go @@ -0,0 +1,58 @@ +package testutils + +import ( + "bytes" + "encoding/json" + "strconv" + "strings" + "testing" + + . "github.com/sirupsen/logrus" + + "github.com/stretchr/testify/require" +) + +func LogAndAssertJSON(t *testing.T, log func(*Logger), assertions func(fields Fields)) { + var buffer bytes.Buffer + var fields Fields + + logger := New() + logger.Out = &buffer + logger.Formatter = new(JSONFormatter) + + log(logger) + + err := json.Unmarshal(buffer.Bytes(), &fields) + require.Nil(t, err) + + assertions(fields) +} + +func LogAndAssertText(t *testing.T, log func(*Logger), assertions func(fields map[string]string)) { + var buffer bytes.Buffer + + logger := New() + logger.Out = &buffer + logger.Formatter = &TextFormatter{ + DisableColors: true, + } + + log(logger) + + fields := make(map[string]string) + for _, kv := range strings.Split(strings.TrimRight(buffer.String(), "\n"), " ") { + if !strings.Contains(kv, "=") { + continue + } + kvArr := strings.Split(kv, "=") + key := strings.TrimSpace(kvArr[0]) + val := kvArr[1] + if kvArr[1][0] == '"' { + var err error + val, err = strconv.Unquote(val) + require.NoError(t, err) + } + fields[key] = val + } + assertions(fields) +} diff --git a/json_formatter.go b/json_formatter.go index 0e38a6191..ba7f23711 100644 --- a/json_formatter.go +++ b/json_formatter.go @@ -1,32 +1,125 @@ package logrus import ( + "bytes" "encoding/json" "fmt" - "time" + "runtime" ) -type JSONFormatter struct{} +type fieldKey string +// FieldMap allows customization of the key names for default fields. +type FieldMap map[fieldKey]string + +func (f FieldMap) resolve(key fieldKey) string { + if k, ok := f[key]; ok { + return k + } + + return string(key) +} + +// JSONFormatter formats logs into parsable json +type JSONFormatter struct { + // TimestampFormat sets the format used for marshaling timestamps. + TimestampFormat string + + // DisableTimestamp allows disabling automatic timestamps in output + DisableTimestamp bool + + // DisableHTMLEscape allows disabling html escaping in output + DisableHTMLEscape bool + + // DataKey allows users to put all the log entry parameters into a nested dictionary at a given key. + DataKey string + + // FieldMap allows users to customize the names of keys for default fields. + // As an example: + // formatter := &JSONFormatter{ + // FieldMap: FieldMap{ + // FieldKeyTime: "@timestamp", + // FieldKeyLevel: "@level", + // FieldKeyMsg: "@message", + // FieldKeyFunc: "@caller", + // }, + // } + FieldMap FieldMap + + // CallerPrettyfier can be set by the user to modify the content + // of the function and file keys in the json data when ReportCaller is + // activated. If any of the returned value is the empty string the + // corresponding key will be removed from json fields. + CallerPrettyfier func(*runtime.Frame) (function string, file string) + + // PrettyPrint will indent all json logs + PrettyPrint bool +} + +// Format renders a single log entry func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { - data := make(Fields, len(entry.Data)+3) + data := make(Fields, len(entry.Data)+4) for k, v := range entry.Data { - // Otherwise errors are ignored by `encoding/json` - // https://github.com/Sirupsen/logrus/issues/137 - if err, ok := v.(error); ok { - data[k] = err.Error() - } else { + switch v := v.(type) { + case error: + // Otherwise errors are ignored by `encoding/json` + // https://github.com/sirupsen/logrus/issues/137 + data[k] = v.Error() + default: data[k] = v } } - prefixFieldClashes(data) - data["time"] = entry.Time.Format(time.RFC3339) - data["msg"] = entry.Message - data["level"] = entry.Level.String() - serialized, err := json.Marshal(data) - if err != nil { - return nil, fmt.Errorf("Failed to marshal fields to JSON, %v", err) + if f.DataKey != "" { + newData := make(Fields, 4) + newData[f.DataKey] = data + data = newData } - return append(serialized, '\n'), nil + + prefixFieldClashes(data, f.FieldMap, entry.HasCaller()) + + timestampFormat := f.TimestampFormat + if timestampFormat == "" { + timestampFormat = defaultTimestampFormat + } + + if entry.err != "" { + data[f.FieldMap.resolve(FieldKeyLogrusError)] = entry.err + } + if !f.DisableTimestamp { + data[f.FieldMap.resolve(FieldKeyTime)] = entry.Time.Format(timestampFormat) + } + data[f.FieldMap.resolve(FieldKeyMsg)] = entry.Message + data[f.FieldMap.resolve(FieldKeyLevel)] = entry.Level.String() + if entry.HasCaller() { + funcVal := entry.Caller.Function + fileVal := fmt.Sprintf("%s:%d", entry.Caller.File, entry.Caller.Line) + if f.CallerPrettyfier != nil { + funcVal, fileVal = f.CallerPrettyfier(entry.Caller) + } + if funcVal != "" { + data[f.FieldMap.resolve(FieldKeyFunc)] = funcVal + } + if fileVal != "" { + data[f.FieldMap.resolve(FieldKeyFile)] = fileVal + } + } + + var b *bytes.Buffer + if entry.Buffer != nil { + b = entry.Buffer + } else { + b = &bytes.Buffer{} + } + + encoder := json.NewEncoder(b) + encoder.SetEscapeHTML(!f.DisableHTMLEscape) + if f.PrettyPrint { + encoder.SetIndent("", " ") + } + if err := encoder.Encode(data); err != nil { + return nil, fmt.Errorf("failed to marshal fields to JSON, %v", err) + } + + return b.Bytes(), nil } diff --git a/json_formatter_test.go b/json_formatter_test.go index 1d7087325..7a48f2dc6 100644 --- a/json_formatter_test.go +++ b/json_formatter_test.go @@ -3,7 +3,9 @@ package logrus import ( "encoding/json" "errors" - + "fmt" + "runtime" + "strings" "testing" ) @@ -106,6 +108,102 @@ func TestFieldClashWithLevel(t *testing.T) { } } +func TestFieldClashWithRemappedFields(t *testing.T) { + formatter := &JSONFormatter{ + FieldMap: FieldMap{ + FieldKeyTime: "@timestamp", + FieldKeyLevel: "@level", + FieldKeyMsg: "@message", + }, + } + + b, err := formatter.Format(WithFields(Fields{ + "@timestamp": "@timestamp", + "@level": "@level", + "@message": "@message", + "timestamp": "timestamp", + "level": "level", + "msg": "msg", + })) + if err != nil { + t.Fatal("Unable to format entry: ", err) + } + + entry := make(map[string]interface{}) + err = json.Unmarshal(b, &entry) + if err != nil { + t.Fatal("Unable to unmarshal formatted entry: ", err) + } + + for _, field := range []string{"timestamp", "level", "msg"} { + if entry[field] != field { + t.Errorf("Expected field %v to be untouched; got %v", field, entry[field]) + } + + remappedKey := fmt.Sprintf("fields.%s", field) + if remapped, ok := entry[remappedKey]; ok { + t.Errorf("Expected %s to be empty; got %v", remappedKey, remapped) + } + } + + for _, field := range []string{"@timestamp", "@level", "@message"} { + if entry[field] == field { + t.Errorf("Expected field %v to be mapped to an Entry value", field) + } + + remappedKey := fmt.Sprintf("fields.%s", field) + if remapped, ok := entry[remappedKey]; ok { + if remapped != field { + t.Errorf("Expected field %v to be copied to %s; got %v", field, remappedKey, remapped) + } + } else { + t.Errorf("Expected field %v to be copied to %s; was absent", field, remappedKey) + } + } +} + +func TestFieldsInNestedDictionary(t *testing.T) { + formatter := &JSONFormatter{ + DataKey: "args", + } + + logEntry := WithFields(Fields{ + "level": "level", + "test": "test", + }) + logEntry.Level = InfoLevel + + b, err := formatter.Format(logEntry) + if err != nil { + t.Fatal("Unable to format entry: ", err) + } + + entry := make(map[string]interface{}) + err = json.Unmarshal(b, &entry) + if err != nil { + t.Fatal("Unable to unmarshal formatted entry: ", err) + } + + args := entry["args"].(map[string]interface{}) + + for _, field := range []string{"test", "level"} { + if value, present := args[field]; !present || value != field { + t.Errorf("Expected field %v to be present under 'args'; untouched", field) + } + } + + for _, field := range []string{"test", "fields.level"} { + if _, present := entry[field]; present { + t.Errorf("Expected field %v not to be present at top level", field) + } + } + + // with nested object, "level" shouldn't clash + if entry["level"] != "info" { + t.Errorf("Expected 'level' field to contain 'info'") + } +} + func TestJSONEntryEndsWithNewline(t *testing.T) { formatter := &JSONFormatter{} @@ -118,3 +216,157 @@ func TestJSONEntryEndsWithNewline(t *testing.T) { t.Fatal("Expected JSON log entry to end with a newline") } } + +func TestJSONMessageKey(t *testing.T) { + formatter := &JSONFormatter{ + FieldMap: FieldMap{ + FieldKeyMsg: "message", + }, + } + + b, err := formatter.Format(&Entry{Message: "oh hai"}) + if err != nil { + t.Fatal("Unable to format entry: ", err) + } + s := string(b) + if !(strings.Contains(s, "message") && strings.Contains(s, "oh hai")) { + t.Fatal("Expected JSON to format message key") + } +} + +func TestJSONLevelKey(t *testing.T) { + formatter := &JSONFormatter{ + FieldMap: FieldMap{ + FieldKeyLevel: "somelevel", + }, + } + + b, err := formatter.Format(WithField("level", "something")) + if err != nil { + t.Fatal("Unable to format entry: ", err) + } + s := string(b) + if !strings.Contains(s, "somelevel") { + t.Fatal("Expected JSON to format level key") + } +} + +func TestJSONTimeKey(t *testing.T) { + formatter := &JSONFormatter{ + FieldMap: FieldMap{ + FieldKeyTime: "timeywimey", + }, + } + + b, err := formatter.Format(WithField("level", "something")) + if err != nil { + t.Fatal("Unable to format entry: ", err) + } + s := string(b) + if !strings.Contains(s, "timeywimey") { + t.Fatal("Expected JSON to format time key") + } +} + +func TestFieldDoesNotClashWithCaller(t *testing.T) { + SetReportCaller(false) + formatter := &JSONFormatter{} + + b, err := formatter.Format(WithField("func", "howdy pardner")) + if err != nil { + t.Fatal("Unable to format entry: ", err) + } + + entry := make(map[string]interface{}) + err = json.Unmarshal(b, &entry) + if err != nil { + t.Fatal("Unable to unmarshal formatted entry: ", err) + } + + if entry["func"] != "howdy pardner" { + t.Fatal("func field replaced when ReportCaller=false") + } +} + +func TestFieldClashWithCaller(t *testing.T) { + SetReportCaller(true) + formatter := &JSONFormatter{} + e := WithField("func", "howdy pardner") + e.Caller = &runtime.Frame{Function: "somefunc"} + b, err := formatter.Format(e) + if err != nil { + t.Fatal("Unable to format entry: ", err) + } + + entry := make(map[string]interface{}) + err = json.Unmarshal(b, &entry) + if err != nil { + t.Fatal("Unable to unmarshal formatted entry: ", err) + } + + if entry["fields.func"] != "howdy pardner" { + t.Fatalf("fields.func not set to original func field when ReportCaller=true (got '%s')", + entry["fields.func"]) + } + + if entry["func"] != "somefunc" { + t.Fatalf("func not set as expected when ReportCaller=true (got '%s')", + entry["func"]) + } + + SetReportCaller(false) // return to default value +} + +func TestJSONDisableTimestamp(t *testing.T) { + formatter := &JSONFormatter{ + DisableTimestamp: true, + } + + b, err := formatter.Format(WithField("level", "something")) + if err != nil { + t.Fatal("Unable to format entry: ", err) + } + s := string(b) + if strings.Contains(s, FieldKeyTime) { + t.Error("Did not prevent timestamp", s) + } +} + +func TestJSONEnableTimestamp(t *testing.T) { + formatter := &JSONFormatter{} + + b, err := formatter.Format(WithField("level", "something")) + if err != nil { + t.Fatal("Unable to format entry: ", err) + } + s := string(b) + if !strings.Contains(s, FieldKeyTime) { + t.Error("Timestamp not present", s) + } +} + +func TestJSONDisableHTMLEscape(t *testing.T) { + formatter := &JSONFormatter{DisableHTMLEscape: true} + + b, err := formatter.Format(&Entry{Message: "& < >"}) + if err != nil { + t.Fatal("Unable to format entry: ", err) + } + s := string(b) + if !strings.Contains(s, "& < >") { + t.Error("Message should not be HTML escaped", s) + } +} + +func TestJSONEnableHTMLEscape(t *testing.T) { + formatter := &JSONFormatter{} + + b, err := formatter.Format(&Entry{Message: "& < >"}) + if err != nil { + t.Fatal("Unable to format entry: ", err) + } + s := string(b) + if !(strings.Contains(s, "u0026") && strings.Contains(s, "u003e") && strings.Contains(s, "u003c")) { + t.Error("Message should be HTML escaped", s) + } +} diff --git a/level_test.go b/level_test.go new file mode 100644 index 000000000..78915c4f2 --- /dev/null +++ b/level_test.go @@ -0,0 +1,62 @@ +package logrus_test + +import ( + "bytes" + "encoding/json" + "testing" + + "github.com/sirupsen/logrus" + "github.com/stretchr/testify/require" +) + +func TestLevelJsonEncoding(t *testing.T) { + type X struct { + Level logrus.Level + } + + var x X + x.Level = logrus.WarnLevel + var buf bytes.Buffer + enc := json.NewEncoder(&buf) + require.NoError(t, enc.Encode(x)) + dec := json.NewDecoder(&buf) + var y X + require.NoError(t, dec.Decode(&y)) +} + +func TestLevelUnmarshalText(t *testing.T) { + var u logrus.Level + for _, level := range logrus.AllLevels { + t.Run(level.String(), func(t *testing.T) { + require.NoError(t, u.UnmarshalText([]byte(level.String()))) + require.Equal(t, level, u) + }) + } + t.Run("invalid", func(t *testing.T) { + require.Error(t, u.UnmarshalText([]byte("invalid"))) + }) +} + +func TestLevelMarshalText(t *testing.T) { + levelStrings := []string{ + "panic", + "fatal", + "error", + "warning", + "info", + "debug", + "trace", + } + for idx, val := range logrus.AllLevels { + level := val + t.Run(level.String(), func(t *testing.T) { + var cmp logrus.Level + b, err := level.MarshalText() + require.NoError(t, err) + require.Equal(t, levelStrings[idx], string(b)) + err = cmp.UnmarshalText(b) + require.NoError(t, err) + require.Equal(t, level, cmp) + }) + } +} diff --git a/logger.go b/logger.go index da928a375..dbf627c97 100644 --- a/logger.go +++ b/logger.go @@ -1,20 +1,28 @@ package logrus import ( + "context" "io" "os" "sync" + "sync/atomic" + "time" ) +// LogFunction For big messages, it can be more efficient to pass a function +// and only call it if the log level is actually enables rather than +// generating the log message and then checking if the level is enabled +type LogFunction func()[]interface{} + type Logger struct { // The logs are `io.Copy`'d to this in a mutex. It's common to set this to a - // file, or leave it default which is `os.Stdout`. You can also set this to - // something more adventorous, such as logging to Kafka. + // file, or leave it default which is `os.Stderr`. You can also set this to + // something more adventurous, such as logging to Kafka. Out io.Writer // Hooks for the logger instance. These allow firing events based on logging // levels and log entries. For example, to send errors to an error tracking // service, log to StatsD or dump the core on fatal errors. - Hooks levelHooks + Hooks LevelHooks // All log entries pass through the formatter before logged to Out. The // included formatters are `TextFormatter` and `JSONFormatter` for which // TextFormatter is the default. In development (when a TTY is attached) it @@ -22,182 +30,375 @@ type Logger struct { // own that implements the `Formatter` interface, see the `README` or included // formatters for examples. Formatter Formatter + + // Flag for whether to log caller info (off by default) + ReportCaller bool + // The logging level the logger should log at. This is typically (and defaults // to) `logrus.Info`, which allows Info(), Warn(), Error() and Fatal() to be - // logged. `logrus.Debug` is useful in + // logged. Level Level - // Used to sync writing to the log. - mu sync.Mutex + // Used to sync writing to the log. Locking is enabled by Default + mu MutexWrap + // Reusable empty entry + entryPool sync.Pool + // Function to exit the application, defaults to `os.Exit()` + ExitFunc exitFunc +} + +type exitFunc func(int) + +type MutexWrap struct { + lock sync.Mutex + disabled bool +} + +func (mw *MutexWrap) Lock() { + if !mw.disabled { + mw.lock.Lock() + } +} + +func (mw *MutexWrap) Unlock() { + if !mw.disabled { + mw.lock.Unlock() + } +} + +func (mw *MutexWrap) Disable() { + mw.disabled = true } // Creates a new logger. Configuration should be set by changing `Formatter`, // `Out` and `Hooks` directly on the default logger instance. You can also just // instantiate your own: // -// var log = &Logger{ +// var log = &logrus.Logger{ // Out: os.Stderr, -// Formatter: new(JSONFormatter), -// Hooks: make(levelHooks), +// Formatter: new(logrus.TextFormatter), +// Hooks: make(logrus.LevelHooks), // Level: logrus.DebugLevel, // } // // It's recommended to make this a global instance called `log`. func New() *Logger { return &Logger{ - Out: os.Stdout, - Formatter: new(TextFormatter), - Hooks: make(levelHooks), - Level: InfoLevel, + Out: os.Stderr, + Formatter: new(TextFormatter), + Hooks: make(LevelHooks), + Level: InfoLevel, + ExitFunc: os.Exit, + ReportCaller: false, + } +} + +func (logger *Logger) newEntry() *Entry { + entry, ok := logger.entryPool.Get().(*Entry) + if ok { + return entry } + return NewEntry(logger) +} + +func (logger *Logger) releaseEntry(entry *Entry) { + entry.Data = map[string]interface{}{} + logger.entryPool.Put(entry) } -// Adds a field to the log entry, note that you it doesn't log until you call -// Debug, Print, Info, Warn, Fatal or Panic. It only creates a log entry. -// Ff you want multiple fields, use `WithFields`. +// WithField allocates a new entry and adds a field to it. +// Debug, Print, Info, Warn, Error, Fatal or Panic must be then applied to +// this new returned entry. +// If you want multiple fields, use `WithFields`. func (logger *Logger) WithField(key string, value interface{}) *Entry { - return NewEntry(logger).WithField(key, value) + entry := logger.newEntry() + defer logger.releaseEntry(entry) + return entry.WithField(key, value) } // Adds a struct of fields to the log entry. All it does is call `WithField` for // each `Field`. func (logger *Logger) WithFields(fields Fields) *Entry { - return NewEntry(logger).WithFields(fields) + entry := logger.newEntry() + defer logger.releaseEntry(entry) + return entry.WithFields(fields) } -func (logger *Logger) Debugf(format string, args ...interface{}) { - if logger.Level >= DebugLevel { - NewEntry(logger).Debugf(format, args...) +// Add an error as single field to the log entry. All it does is call +// `WithError` for the given `error`. +func (logger *Logger) WithError(err error) *Entry { + entry := logger.newEntry() + defer logger.releaseEntry(entry) + return entry.WithError(err) +} + +// Add a context to the log entry. +func (logger *Logger) WithContext(ctx context.Context) *Entry { + entry := logger.newEntry() + defer logger.releaseEntry(entry) + return entry.WithContext(ctx) +} + +// Overrides the time of the log entry. +func (logger *Logger) WithTime(t time.Time) *Entry { + entry := logger.newEntry() + defer logger.releaseEntry(entry) + return entry.WithTime(t) +} + +func (logger *Logger) Logf(level Level, format string, args ...interface{}) { + if logger.IsLevelEnabled(level) { + entry := logger.newEntry() + entry.Logf(level, format, args...) + logger.releaseEntry(entry) } } +func (logger *Logger) Tracef(format string, args ...interface{}) { + logger.Logf(TraceLevel, format, args...) +} + +func (logger *Logger) Debugf(format string, args ...interface{}) { + logger.Logf(DebugLevel, format, args...) +} + func (logger *Logger) Infof(format string, args ...interface{}) { - if logger.Level >= InfoLevel { - NewEntry(logger).Infof(format, args...) - } + logger.Logf(InfoLevel, format, args...) } func (logger *Logger) Printf(format string, args ...interface{}) { - NewEntry(logger).Printf(format, args...) + entry := logger.newEntry() + entry.Printf(format, args...) + logger.releaseEntry(entry) } func (logger *Logger) Warnf(format string, args ...interface{}) { - if logger.Level >= WarnLevel { - NewEntry(logger).Warnf(format, args...) - } + logger.Logf(WarnLevel, format, args...) } func (logger *Logger) Warningf(format string, args ...interface{}) { - if logger.Level >= WarnLevel { - NewEntry(logger).Warnf(format, args...) - } + logger.Warnf(format, args...) } func (logger *Logger) Errorf(format string, args ...interface{}) { - if logger.Level >= ErrorLevel { - NewEntry(logger).Errorf(format, args...) - } + logger.Logf(ErrorLevel, format, args...) } func (logger *Logger) Fatalf(format string, args ...interface{}) { - if logger.Level >= FatalLevel { - NewEntry(logger).Fatalf(format, args...) - } + logger.Logf(FatalLevel, format, args...) + logger.Exit(1) } func (logger *Logger) Panicf(format string, args ...interface{}) { - if logger.Level >= PanicLevel { - NewEntry(logger).Panicf(format, args...) + logger.Logf(PanicLevel, format, args...) +} + +func (logger *Logger) Log(level Level, args ...interface{}) { + if logger.IsLevelEnabled(level) { + entry := logger.newEntry() + entry.Log(level, args...) + logger.releaseEntry(entry) } } -func (logger *Logger) Debug(args ...interface{}) { - if logger.Level >= DebugLevel { - NewEntry(logger).Debug(args...) +func (logger *Logger) LogFn(level Level, fn LogFunction) { + if logger.IsLevelEnabled(level) { + entry := logger.newEntry() + entry.Log(level, fn()...) + logger.releaseEntry(entry) } } +func (logger *Logger) Trace(args ...interface{}) { + logger.Log(TraceLevel, args...) +} + +func (logger *Logger) Debug(args ...interface{}) { + logger.Log(DebugLevel, args...) +} + func (logger *Logger) Info(args ...interface{}) { - if logger.Level >= InfoLevel { - NewEntry(logger).Info(args...) - } + logger.Log(InfoLevel, args...) } func (logger *Logger) Print(args ...interface{}) { - NewEntry(logger).Info(args...) + entry := logger.newEntry() + entry.Print(args...) + logger.releaseEntry(entry) } func (logger *Logger) Warn(args ...interface{}) { - if logger.Level >= WarnLevel { - NewEntry(logger).Warn(args...) - } + logger.Log(WarnLevel, args...) } func (logger *Logger) Warning(args ...interface{}) { - if logger.Level >= WarnLevel { - NewEntry(logger).Warn(args...) - } + logger.Warn(args...) } func (logger *Logger) Error(args ...interface{}) { - if logger.Level >= ErrorLevel { - NewEntry(logger).Error(args...) - } + logger.Log(ErrorLevel, args...) } func (logger *Logger) Fatal(args ...interface{}) { - if logger.Level >= FatalLevel { - NewEntry(logger).Fatal(args...) - } + logger.Log(FatalLevel, args...) + logger.Exit(1) } func (logger *Logger) Panic(args ...interface{}) { - if logger.Level >= PanicLevel { - NewEntry(logger).Panic(args...) + logger.Log(PanicLevel, args...) +} + +func (logger *Logger) TraceFn(fn LogFunction) { + logger.LogFn(TraceLevel, fn) +} + +func (logger *Logger) DebugFn(fn LogFunction) { + logger.LogFn(DebugLevel, fn) +} + +func (logger *Logger) InfoFn(fn LogFunction) { + logger.LogFn(InfoLevel, fn) +} + +func (logger *Logger) PrintFn(fn LogFunction) { + entry := logger.newEntry() + entry.Print(fn()...) + logger.releaseEntry(entry) +} + +func (logger *Logger) WarnFn(fn LogFunction) { + logger.LogFn(WarnLevel, fn) +} + +func (logger *Logger) WarningFn(fn LogFunction) { + logger.WarnFn(fn) +} + +func (logger *Logger) ErrorFn(fn LogFunction) { + logger.LogFn(ErrorLevel, fn) +} + +func (logger *Logger) FatalFn(fn LogFunction) { + logger.LogFn(FatalLevel, fn) + logger.Exit(1) +} + +func (logger *Logger) PanicFn(fn LogFunction) { + logger.LogFn(PanicLevel, fn) +} + +func (logger *Logger) Logln(level Level, args ...interface{}) { + if logger.IsLevelEnabled(level) { + entry := logger.newEntry() + entry.Logln(level, args...) + logger.releaseEntry(entry) } } +func (logger *Logger) Traceln(args ...interface{}) { + logger.Logln(TraceLevel, args...) +} + func (logger *Logger) Debugln(args ...interface{}) { - if logger.Level >= DebugLevel { - NewEntry(logger).Debugln(args...) - } + logger.Logln(DebugLevel, args...) } func (logger *Logger) Infoln(args ...interface{}) { - if logger.Level >= InfoLevel { - NewEntry(logger).Infoln(args...) - } + logger.Logln(InfoLevel, args...) } func (logger *Logger) Println(args ...interface{}) { - NewEntry(logger).Println(args...) + entry := logger.newEntry() + entry.Println(args...) + logger.releaseEntry(entry) } func (logger *Logger) Warnln(args ...interface{}) { - if logger.Level >= WarnLevel { - NewEntry(logger).Warnln(args...) - } + logger.Logln(WarnLevel, args...) } func (logger *Logger) Warningln(args ...interface{}) { - if logger.Level >= WarnLevel { - NewEntry(logger).Warnln(args...) - } + logger.Warnln(args...) } func (logger *Logger) Errorln(args ...interface{}) { - if logger.Level >= ErrorLevel { - NewEntry(logger).Errorln(args...) - } + logger.Logln(ErrorLevel, args...) } func (logger *Logger) Fatalln(args ...interface{}) { - if logger.Level >= FatalLevel { - NewEntry(logger).Fatalln(args...) - } + logger.Logln(FatalLevel, args...) + logger.Exit(1) } func (logger *Logger) Panicln(args ...interface{}) { - if logger.Level >= PanicLevel { - NewEntry(logger).Panicln(args...) + logger.Logln(PanicLevel, args...) +} + +func (logger *Logger) Exit(code int) { + runHandlers() + if logger.ExitFunc == nil { + logger.ExitFunc = os.Exit } + logger.ExitFunc(code) +} + +//When file is opened with appending mode, it's safe to +//write concurrently to a file (within 4k message on Linux). +//In these cases user can choose to disable the lock. +func (logger *Logger) SetNoLock() { + logger.mu.Disable() +} + +func (logger *Logger) level() Level { + return Level(atomic.LoadUint32((*uint32)(&logger.Level))) +} + +// SetLevel sets the logger level. +func (logger *Logger) SetLevel(level Level) { + atomic.StoreUint32((*uint32)(&logger.Level), uint32(level)) +} + +// GetLevel returns the logger level. +func (logger *Logger) GetLevel() Level { + return logger.level() +} + +// AddHook adds a hook to the logger hooks. +func (logger *Logger) AddHook(hook Hook) { + logger.mu.Lock() + defer logger.mu.Unlock() + logger.Hooks.Add(hook) +} + +// IsLevelEnabled checks if the log level of the logger is greater than the level param +func (logger *Logger) IsLevelEnabled(level Level) bool { + return logger.level() >= level +} + +// SetFormatter sets the logger formatter. +func (logger *Logger) SetFormatter(formatter Formatter) { + logger.mu.Lock() + defer logger.mu.Unlock() + logger.Formatter = formatter +} + +// SetOutput sets the logger output. +func (logger *Logger) SetOutput(output io.Writer) { + logger.mu.Lock() + defer logger.mu.Unlock() + logger.Out = output +} + +func (logger *Logger) SetReportCaller(reportCaller bool) { + logger.mu.Lock() + defer logger.mu.Unlock() + logger.ReportCaller = reportCaller +} + +// ReplaceHooks replaces the logger hooks and returns the old ones +func (logger *Logger) ReplaceHooks(hooks LevelHooks) LevelHooks { + logger.mu.Lock() + oldHooks := logger.Hooks + logger.Hooks = hooks + logger.mu.Unlock() + return oldHooks } diff --git a/logger_bench_test.go b/logger_bench_test.go new file mode 100644 index 000000000..1699af5aa --- /dev/null +++ b/logger_bench_test.go @@ -0,0 +1,77 @@ +package logrus + +import ( + "io/ioutil" + "os" + "testing" +) + +func BenchmarkDummyLogger(b *testing.B) { + nullf, err := os.OpenFile("/dev/null", os.O_WRONLY, 0666) + if err != nil { + b.Fatalf("%v", err) + } + defer nullf.Close() + doLoggerBenchmark(b, nullf, &TextFormatter{DisableColors: true}, smallFields) +} + +func BenchmarkDummyLoggerNoLock(b *testing.B) { + nullf, err := os.OpenFile("/dev/null", os.O_WRONLY|os.O_APPEND, 0666) + if err != nil { + b.Fatalf("%v", err) + } + defer nullf.Close() + doLoggerBenchmarkNoLock(b, nullf, &TextFormatter{DisableColors: true}, smallFields) +} + +func doLoggerBenchmark(b *testing.B, out *os.File, formatter Formatter, fields Fields) { + logger := Logger{ + Out: out, + Level: InfoLevel, + Formatter: formatter, + } + entry := logger.WithFields(fields) + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + entry.Info("aaa") + } + }) +} + +func doLoggerBenchmarkNoLock(b *testing.B, out *os.File, formatter Formatter, fields Fields) { + logger := Logger{ + Out: out, + Level: InfoLevel, + Formatter: formatter, + } + logger.SetNoLock() + entry := logger.WithFields(fields) + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + entry.Info("aaa") + } + }) +} + +func BenchmarkLoggerJSONFormatter(b *testing.B) { + doLoggerBenchmarkWithFormatter(b, &JSONFormatter{}) +} + +func BenchmarkLoggerTextFormatter(b *testing.B) { + doLoggerBenchmarkWithFormatter(b, &TextFormatter{}) +} + +func doLoggerBenchmarkWithFormatter(b *testing.B, f Formatter) { + b.SetParallelism(100) + log := New() + log.Formatter = f + log.Out = ioutil.Discard + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + log. + WithField("foo1", "bar1"). + WithField("foo2", "bar2"). + Info("this is a dummy log") + } + }) +} diff --git a/logger_test.go b/logger_test.go new file mode 100644 index 000000000..f12a04e74 --- /dev/null +++ b/logger_test.go @@ -0,0 +1,69 @@ +package logrus + +import ( + "bytes" + "encoding/json" + "fmt" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestFieldValueError(t *testing.T) { + buf := &bytes.Buffer{} + l := &Logger{ + Out: buf, + Formatter: new(JSONFormatter), + Hooks: make(LevelHooks), + Level: DebugLevel, + } + l.WithField("func", func() {}).Info("test") + fmt.Println(buf.String()) + var data map[string]interface{} + if err := json.Unmarshal(buf.Bytes(), &data); err != nil { + t.Error("unexpected error", err) + } + _, ok := data[FieldKeyLogrusError] + require.True(t, ok) +} + +func TestNoFieldValueError(t *testing.T) { + buf := &bytes.Buffer{} + l := &Logger{ + Out: buf, + Formatter: new(JSONFormatter), + Hooks: make(LevelHooks), + Level: DebugLevel, + } + l.WithField("str", "str").Info("test") + fmt.Println(buf.String()) + var data map[string]interface{} + if err := json.Unmarshal(buf.Bytes(), &data); err != nil { + t.Error("unexpected error", err) + } + _, ok := data[FieldKeyLogrusError] + require.False(t, ok) +} + +func TestWarninglnNotEqualToWarning(t *testing.T) { + buf := &bytes.Buffer{} + bufln := &bytes.Buffer{} + + formatter := new(TextFormatter) + formatter.DisableTimestamp = true + formatter.DisableLevelTruncation = true + + l := &Logger{ + Out: buf, + Formatter: formatter, + Hooks: make(LevelHooks), + Level: DebugLevel, + } + l.Warning("hello,", "world") + + l.SetOutput(bufln) + l.Warningln("hello,", "world") + + assert.NotEqual(t, buf.String(), bufln.String(), "Warning() and Wantingln() should not be equal") +} diff --git a/logrus.go b/logrus.go index 43ee12e90..2f16224cb 100644 --- a/logrus.go +++ b/logrus.go @@ -3,37 +3,27 @@ package logrus import ( "fmt" "log" + "strings" ) // Fields type, used to pass to `WithFields`. type Fields map[string]interface{} // Level type -type Level uint8 +type Level uint32 // Convert the Level to a string. E.g. PanicLevel becomes "panic". func (level Level) String() string { - switch level { - case DebugLevel: - return "debug" - case InfoLevel: - return "info" - case WarnLevel: - return "warning" - case ErrorLevel: - return "error" - case FatalLevel: - return "fatal" - case PanicLevel: - return "panic" + if b, err := level.MarshalText(); err == nil { + return string(b) + } else { + return "unknown" } - - return "unknown" } // ParseLevel takes a string level and returns the Logrus log level constant. func ParseLevel(lvl string) (Level, error) { - switch lvl { + switch strings.ToLower(lvl) { case "panic": return PanicLevel, nil case "fatal": @@ -46,19 +36,65 @@ func ParseLevel(lvl string) (Level, error) { return InfoLevel, nil case "debug": return DebugLevel, nil + case "trace": + return TraceLevel, nil } var l Level return l, fmt.Errorf("not a valid logrus Level: %q", lvl) } +// UnmarshalText implements encoding.TextUnmarshaler. +func (level *Level) UnmarshalText(text []byte) error { + l, err := ParseLevel(string(text)) + if err != nil { + return err + } + + *level = l + + return nil +} + +func (level Level) MarshalText() ([]byte, error) { + switch level { + case TraceLevel: + return []byte("trace"), nil + case DebugLevel: + return []byte("debug"), nil + case InfoLevel: + return []byte("info"), nil + case WarnLevel: + return []byte("warning"), nil + case ErrorLevel: + return []byte("error"), nil + case FatalLevel: + return []byte("fatal"), nil + case PanicLevel: + return []byte("panic"), nil + } + + return nil, fmt.Errorf("not a valid logrus level %d", level) +} + +// A constant exposing all logging levels +var AllLevels = []Level{ + PanicLevel, + FatalLevel, + ErrorLevel, + WarnLevel, + InfoLevel, + DebugLevel, + TraceLevel, +} + // These are the different logging levels. You can set the logging level to log // on your instance of logger, obtained with `logrus.New()`. const ( // PanicLevel level, highest level of severity. Logs and then calls panic with the // message passed to Debug, Info, ... PanicLevel Level = iota - // FatalLevel level. Logs and then calls `os.Exit(1)`. It will exit even if the + // FatalLevel level. Logs and then calls `logger.Exit(1)`. It will exit even if the // logging level is set to Panic. FatalLevel // ErrorLevel level. Logs. Used for errors that should definitely be noted. @@ -71,10 +107,16 @@ const ( InfoLevel // DebugLevel level. Usually only enabled when debugging. Very verbose logging. DebugLevel + // TraceLevel level. Designates finer-grained informational events than the Debug. + TraceLevel ) // Won't compile if StdLogger can't be realized by a log.Logger -var _ StdLogger = &log.Logger{} +var ( + _ StdLogger = &log.Logger{} + _ StdLogger = &Entry{} + _ StdLogger = &Logger{} +) // StdLogger is what your logrus-enabled library should take, that way // it'll accept a stdlib logger and a logrus logger. There's no standard @@ -92,3 +134,53 @@ type StdLogger interface { Panicf(string, ...interface{}) Panicln(...interface{}) } + +// The FieldLogger interface generalizes the Entry and Logger types +type FieldLogger interface { + WithField(key string, value interface{}) *Entry + WithFields(fields Fields) *Entry + WithError(err error) *Entry + + Debugf(format string, args ...interface{}) + Infof(format string, args ...interface{}) + Printf(format string, args ...interface{}) + Warnf(format string, args ...interface{}) + Warningf(format string, args ...interface{}) + Errorf(format string, args ...interface{}) + Fatalf(format string, args ...interface{}) + Panicf(format string, args ...interface{}) + + Debug(args ...interface{}) + Info(args ...interface{}) + Print(args ...interface{}) + Warn(args ...interface{}) + Warning(args ...interface{}) + Error(args ...interface{}) + Fatal(args ...interface{}) + Panic(args ...interface{}) + + Debugln(args ...interface{}) + Infoln(args ...interface{}) + Println(args ...interface{}) + Warnln(args ...interface{}) + Warningln(args ...interface{}) + Errorln(args ...interface{}) + Fatalln(args ...interface{}) + Panicln(args ...interface{}) + + // IsDebugEnabled() bool + // IsInfoEnabled() bool + // IsWarnEnabled() bool + // IsErrorEnabled() bool + // IsFatalEnabled() bool + // IsPanicEnabled() bool +} + +// Ext1FieldLogger (the first extension to FieldLogger) is superfluous, it is +// here for consistancy. Do not use. Use Logger or Entry instead. +type Ext1FieldLogger interface { + FieldLogger + Tracef(format string, args ...interface{}) + Trace(args ...interface{}) + Traceln(args ...interface{}) +} diff --git a/logrus_test.go b/logrus_test.go index d85dba4dc..9c3c920de 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -1,67 +1,117 @@ -package logrus +package logrus_test import ( "bytes" "encoding/json" - "strconv" - "strings" + "fmt" + "io/ioutil" + "os" + "path/filepath" + "runtime" "sync" "testing" + "time" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + . "github.com/sirupsen/logrus" + . "github.com/sirupsen/logrus/internal/testutils" ) -func LogAndAssertJSON(t *testing.T, log func(*Logger), assertions func(fields Fields)) { +// TestReportCaller verifies that when ReportCaller is set, the 'func' field +// is added, and when it is unset it is not set or modified +// Verify that functions within the Logrus package aren't considered when +// discovering the caller. +func TestReportCallerWhenConfigured(t *testing.T) { + LogAndAssertJSON(t, func(log *Logger) { + log.ReportCaller = false + log.Print("testNoCaller") + }, func(fields Fields) { + assert.Equal(t, "testNoCaller", fields["msg"]) + assert.Equal(t, "info", fields["level"]) + assert.Equal(t, nil, fields["func"]) + }) + + LogAndAssertJSON(t, func(log *Logger) { + log.ReportCaller = true + log.Print("testWithCaller") + }, func(fields Fields) { + assert.Equal(t, "testWithCaller", fields["msg"]) + assert.Equal(t, "info", fields["level"]) + assert.Equal(t, + "github.com/sirupsen/logrus_test.TestReportCallerWhenConfigured.func3", fields[FieldKeyFunc]) + }) + + LogAndAssertJSON(t, func(log *Logger) { + log.ReportCaller = true + log.Formatter.(*JSONFormatter).CallerPrettyfier = func(f *runtime.Frame) (string, string) { + return "somekindoffunc", "thisisafilename" + } + log.Print("testWithCallerPrettyfier") + }, func(fields Fields) { + assert.Equal(t, "somekindoffunc", fields[FieldKeyFunc]) + assert.Equal(t, "thisisafilename", fields[FieldKeyFile]) + }) + + LogAndAssertText(t, func(log *Logger) { + log.ReportCaller = true + log.Formatter.(*TextFormatter).CallerPrettyfier = func(f *runtime.Frame) (string, string) { + return "somekindoffunc", "thisisafilename" + } + log.Print("testWithCallerPrettyfier") + }, func(fields map[string]string) { + assert.Equal(t, "somekindoffunc", fields[FieldKeyFunc]) + assert.Equal(t, "thisisafilename", fields[FieldKeyFile]) + }) +} + +func logSomething(t *testing.T, message string) Fields { var buffer bytes.Buffer var fields Fields logger := New() logger.Out = &buffer logger.Formatter = new(JSONFormatter) + logger.ReportCaller = true + + entry := logger.WithFields(Fields{ + "foo": "bar", + }) - log(logger) + entry.Info(message) err := json.Unmarshal(buffer.Bytes(), &fields) assert.Nil(t, err) - assertions(fields) + return fields } -func LogAndAssertText(t *testing.T, log func(*Logger), assertions func(fields map[string]string)) { - var buffer bytes.Buffer +// TestReportCallerHelperDirect - verify reference when logging from a regular function +func TestReportCallerHelperDirect(t *testing.T) { + fields := logSomething(t, "direct") - logger := New() - logger.Out = &buffer - logger.Formatter = &TextFormatter{ - DisableColors: true, - } + assert.Equal(t, "direct", fields["msg"]) + assert.Equal(t, "info", fields["level"]) + assert.Regexp(t, "github.com/.*/logrus_test.logSomething", fields["func"]) +} - log(logger) +// TestReportCallerHelperDirect - verify reference when logging from a function called via pointer +func TestReportCallerHelperViaPointer(t *testing.T) { + fptr := logSomething + fields := fptr(t, "via pointer") - fields := make(map[string]string) - for _, kv := range strings.Split(buffer.String(), " ") { - if !strings.Contains(kv, "=") { - continue - } - kvArr := strings.Split(kv, "=") - key := strings.TrimSpace(kvArr[0]) - val := kvArr[1] - if kvArr[1][0] == '"' { - var err error - val, err = strconv.Unquote(val) - assert.NoError(t, err) - } - fields[key] = val - } - assertions(fields) + assert.Equal(t, "via pointer", fields["msg"]) + assert.Equal(t, "info", fields["level"]) + assert.Regexp(t, "github.com/.*/logrus_test.logSomething", fields["func"]) } func TestPrint(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Print("test") }, func(fields Fields) { - assert.Equal(t, fields["msg"], "test") - assert.Equal(t, fields["level"], "info") + assert.Equal(t, "test", fields["msg"]) + assert.Equal(t, "info", fields["level"]) }) } @@ -69,8 +119,8 @@ func TestInfo(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Info("test") }, func(fields Fields) { - assert.Equal(t, fields["msg"], "test") - assert.Equal(t, fields["level"], "info") + assert.Equal(t, "test", fields["msg"]) + assert.Equal(t, "info", fields["level"]) }) } @@ -78,8 +128,17 @@ func TestWarn(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Warn("test") }, func(fields Fields) { - assert.Equal(t, fields["msg"], "test") - assert.Equal(t, fields["level"], "warning") + assert.Equal(t, "test", fields["msg"]) + assert.Equal(t, "warning", fields["level"]) + }) +} + +func TestLog(t *testing.T) { + LogAndAssertJSON(t, func(log *Logger) { + log.Log(WarnLevel, "test") + }, func(fields Fields) { + assert.Equal(t, "test", fields["msg"]) + assert.Equal(t, "warning", fields["level"]) }) } @@ -87,7 +146,7 @@ func TestInfolnShouldAddSpacesBetweenStrings(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Infoln("test", "test") }, func(fields Fields) { - assert.Equal(t, fields["msg"], "test test") + assert.Equal(t, "test test", fields["msg"]) }) } @@ -95,7 +154,7 @@ func TestInfolnShouldAddSpacesBetweenStringAndNonstring(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Infoln("test", 10) }, func(fields Fields) { - assert.Equal(t, fields["msg"], "test 10") + assert.Equal(t, "test 10", fields["msg"]) }) } @@ -103,7 +162,7 @@ func TestInfolnShouldAddSpacesBetweenTwoNonStrings(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Infoln(10, 10) }, func(fields Fields) { - assert.Equal(t, fields["msg"], "10 10") + assert.Equal(t, "10 10", fields["msg"]) }) } @@ -111,7 +170,7 @@ func TestInfoShouldAddSpacesBetweenTwoNonStrings(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Infoln(10, 10) }, func(fields Fields) { - assert.Equal(t, fields["msg"], "10 10") + assert.Equal(t, "10 10", fields["msg"]) }) } @@ -119,7 +178,7 @@ func TestInfoShouldNotAddSpacesBetweenStringAndNonstring(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Info("test", 10) }, func(fields Fields) { - assert.Equal(t, fields["msg"], "test10") + assert.Equal(t, "test10", fields["msg"]) }) } @@ -127,7 +186,7 @@ func TestInfoShouldNotAddSpacesBetweenStrings(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.Info("test", "test") }, func(fields Fields) { - assert.Equal(t, fields["msg"], "testtest") + assert.Equal(t, "testtest", fields["msg"]) }) } @@ -165,7 +224,7 @@ func TestUserSuppliedFieldDoesNotOverwriteDefaults(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.WithField("msg", "hello").Info("test") }, func(fields Fields) { - assert.Equal(t, fields["msg"], "test") + assert.Equal(t, "test", fields["msg"]) }) } @@ -173,8 +232,8 @@ func TestUserSuppliedMsgFieldHasPrefix(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.WithField("msg", "hello").Info("test") }, func(fields Fields) { - assert.Equal(t, fields["msg"], "test") - assert.Equal(t, fields["fields.msg"], "hello") + assert.Equal(t, "test", fields["msg"]) + assert.Equal(t, "hello", fields["fields.msg"]) }) } @@ -182,7 +241,7 @@ func TestUserSuppliedTimeFieldHasPrefix(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.WithField("time", "hello").Info("test") }, func(fields Fields) { - assert.Equal(t, fields["fields.time"], "hello") + assert.Equal(t, "hello", fields["fields.time"]) }) } @@ -190,8 +249,8 @@ func TestUserSuppliedLevelFieldHasPrefix(t *testing.T) { LogAndAssertJSON(t, func(log *Logger) { log.WithField("level", 1).Info("test") }, func(fields Fields) { - assert.Equal(t, fields["level"], "info") - assert.Equal(t, fields["fields.level"], 1) + assert.Equal(t, "info", fields["level"]) + assert.Equal(t, 1.0, fields["fields.level"]) // JSON has floats only }) } @@ -209,6 +268,65 @@ func TestDefaultFieldsAreNotPrefixed(t *testing.T) { }) } +func TestWithTimeShouldOverrideTime(t *testing.T) { + now := time.Now().Add(24 * time.Hour) + + LogAndAssertJSON(t, func(log *Logger) { + log.WithTime(now).Info("foobar") + }, func(fields Fields) { + assert.Equal(t, fields["time"], now.Format(time.RFC3339)) + }) +} + +func TestWithTimeShouldNotOverrideFields(t *testing.T) { + now := time.Now().Add(24 * time.Hour) + + LogAndAssertJSON(t, func(log *Logger) { + log.WithField("herp", "derp").WithTime(now).Info("blah") + }, func(fields Fields) { + assert.Equal(t, fields["time"], now.Format(time.RFC3339)) + assert.Equal(t, fields["herp"], "derp") + }) +} + +func TestWithFieldShouldNotOverrideTime(t *testing.T) { + now := time.Now().Add(24 * time.Hour) + + LogAndAssertJSON(t, func(log *Logger) { + log.WithTime(now).WithField("herp", "derp").Info("blah") + }, func(fields Fields) { + assert.Equal(t, fields["time"], now.Format(time.RFC3339)) + assert.Equal(t, fields["herp"], "derp") + }) +} + +func TestTimeOverrideMultipleLogs(t *testing.T) { + var buffer bytes.Buffer + var firstFields, secondFields Fields + + logger := New() + logger.Out = &buffer + formatter := new(JSONFormatter) + formatter.TimestampFormat = time.StampMilli + logger.Formatter = formatter + + llog := logger.WithField("herp", "derp") + llog.Info("foo") + + err := json.Unmarshal(buffer.Bytes(), &firstFields) + assert.NoError(t, err, "should have decoded first message") + + buffer.Reset() + + time.Sleep(10 * time.Millisecond) + llog.Info("bar") + + err = json.Unmarshal(buffer.Bytes(), &secondFields) + assert.NoError(t, err, "should have decoded second message") + + assert.NotEqual(t, firstFields["time"], secondFields["time"], "timestamps should not be equal") +} + func TestDoubleLoggingDoesntPrefixPreviousFields(t *testing.T) { var buffer bytes.Buffer @@ -235,13 +353,119 @@ func TestDoubleLoggingDoesntPrefixPreviousFields(t *testing.T) { err = json.Unmarshal(buffer.Bytes(), &fields) assert.NoError(t, err, "should have decoded second message") assert.Equal(t, len(fields), 4, "should only have msg/time/level/context fields") - assert.Equal(t, fields["msg"], "omg it is!") - assert.Equal(t, fields["context"], "eating raw fish") + assert.Equal(t, "omg it is!", fields["msg"]) + assert.Equal(t, "eating raw fish", fields["context"]) assert.Nil(t, fields["fields.msg"], "should not have prefixed previous `msg` entry") } +func TestNestedLoggingReportsCorrectCaller(t *testing.T) { + var buffer bytes.Buffer + var fields Fields + + logger := New() + logger.Out = &buffer + logger.Formatter = new(JSONFormatter) + logger.ReportCaller = true + + llog := logger.WithField("context", "eating raw fish") + + llog.Info("looks delicious") + _, _, line, _ := runtime.Caller(0) + + err := json.Unmarshal(buffer.Bytes(), &fields) + require.NoError(t, err, "should have decoded first message") + assert.Equal(t, 6, len(fields), "should have msg/time/level/func/context fields") + assert.Equal(t, "looks delicious", fields["msg"]) + assert.Equal(t, "eating raw fish", fields["context"]) + assert.Equal(t, + "github.com/sirupsen/logrus_test.TestNestedLoggingReportsCorrectCaller", fields["func"]) + cwd, err := os.Getwd() + require.NoError(t, err) + assert.Equal(t, filepath.ToSlash(fmt.Sprintf("%s/logrus_test.go:%d", cwd, line-1)), filepath.ToSlash(fields["file"].(string))) + + buffer.Reset() + + logger.WithFields(Fields{ + "Clyde": "Stubblefield", + }).WithFields(Fields{ + "Jab'o": "Starks", + }).WithFields(Fields{ + "uri": "https://www.youtube.com/watch?v=V5DTznu-9v0", + }).WithFields(Fields{ + "func": "y drummer", + }).WithFields(Fields{ + "James": "Brown", + }).Print("The hardest workin' man in show business") + _, _, line, _ = runtime.Caller(0) + + err = json.Unmarshal(buffer.Bytes(), &fields) + assert.NoError(t, err, "should have decoded second message") + assert.Equal(t, 11, len(fields), "should have all builtin fields plus foo,bar,baz,...") + assert.Equal(t, "Stubblefield", fields["Clyde"]) + assert.Equal(t, "Starks", fields["Jab'o"]) + assert.Equal(t, "https://www.youtube.com/watch?v=V5DTznu-9v0", fields["uri"]) + assert.Equal(t, "y drummer", fields["fields.func"]) + assert.Equal(t, "Brown", fields["James"]) + assert.Equal(t, "The hardest workin' man in show business", fields["msg"]) + assert.Nil(t, fields["fields.msg"], "should not have prefixed previous `msg` entry") + assert.Equal(t, + "github.com/sirupsen/logrus_test.TestNestedLoggingReportsCorrectCaller", fields["func"]) + require.NoError(t, err) + assert.Equal(t, filepath.ToSlash(fmt.Sprintf("%s/logrus_test.go:%d", cwd, line-1)), filepath.ToSlash(fields["file"].(string))) + + logger.ReportCaller = false // return to default value +} + +func logLoop(iterations int, reportCaller bool) { + var buffer bytes.Buffer + + logger := New() + logger.Out = &buffer + logger.Formatter = new(JSONFormatter) + logger.ReportCaller = reportCaller + + for i := 0; i < iterations; i++ { + logger.Infof("round %d of %d", i, iterations) + } +} + +// Assertions for upper bounds to reporting overhead +func TestCallerReportingOverhead(t *testing.T) { + iterations := 5000 + before := time.Now() + logLoop(iterations, false) + during := time.Now() + logLoop(iterations, true) + after := time.Now() + + elapsedNotReporting := during.Sub(before).Nanoseconds() + elapsedReporting := after.Sub(during).Nanoseconds() + + maxDelta := 1 * time.Second + assert.WithinDuration(t, during, before, maxDelta, + "%d log calls without caller name lookup takes less than %d second(s) (was %d nanoseconds)", + iterations, maxDelta.Seconds(), elapsedNotReporting) + assert.WithinDuration(t, after, during, maxDelta, + "%d log calls without caller name lookup takes less than %d second(s) (was %d nanoseconds)", + iterations, maxDelta.Seconds(), elapsedReporting) +} + +// benchmarks for both with and without caller-function reporting +func BenchmarkWithoutCallerTracing(b *testing.B) { + for i := 0; i < b.N; i++ { + logLoop(1000, false) + } +} + +func BenchmarkWithCallerTracing(b *testing.B) { + for i := 0; i < b.N; i++ { + logLoop(1000, true) + } +} + func TestConvertLevelToString(t *testing.T) { + assert.Equal(t, "trace", TraceLevel.String()) assert.Equal(t, "debug", DebugLevel.String()) assert.Equal(t, "info", InfoLevel.String()) assert.Equal(t, "warning", WarnLevel.String()) @@ -255,34 +479,77 @@ func TestParseLevel(t *testing.T) { assert.Nil(t, err) assert.Equal(t, PanicLevel, l) + l, err = ParseLevel("PANIC") + assert.Nil(t, err) + assert.Equal(t, PanicLevel, l) + l, err = ParseLevel("fatal") assert.Nil(t, err) assert.Equal(t, FatalLevel, l) + l, err = ParseLevel("FATAL") + assert.Nil(t, err) + assert.Equal(t, FatalLevel, l) + l, err = ParseLevel("error") assert.Nil(t, err) assert.Equal(t, ErrorLevel, l) + l, err = ParseLevel("ERROR") + assert.Nil(t, err) + assert.Equal(t, ErrorLevel, l) + l, err = ParseLevel("warn") assert.Nil(t, err) assert.Equal(t, WarnLevel, l) + l, err = ParseLevel("WARN") + assert.Nil(t, err) + assert.Equal(t, WarnLevel, l) + l, err = ParseLevel("warning") assert.Nil(t, err) assert.Equal(t, WarnLevel, l) + l, err = ParseLevel("WARNING") + assert.Nil(t, err) + assert.Equal(t, WarnLevel, l) + l, err = ParseLevel("info") assert.Nil(t, err) assert.Equal(t, InfoLevel, l) + l, err = ParseLevel("INFO") + assert.Nil(t, err) + assert.Equal(t, InfoLevel, l) + l, err = ParseLevel("debug") assert.Nil(t, err) assert.Equal(t, DebugLevel, l) - l, err = ParseLevel("invalid") + l, err = ParseLevel("DEBUG") + assert.Nil(t, err) + assert.Equal(t, DebugLevel, l) + + l, err = ParseLevel("trace") + assert.Nil(t, err) + assert.Equal(t, TraceLevel, l) + + l, err = ParseLevel("TRACE") + assert.Nil(t, err) + assert.Equal(t, TraceLevel, l) + + _, err = ParseLevel("invalid") assert.Equal(t, "not a valid logrus Level: \"invalid\"", err.Error()) } +func TestLevelString(t *testing.T) { + var loggerlevel Level + loggerlevel = 32000 + + _ = loggerlevel.String() +} + func TestGetSetLevelRace(t *testing.T) { wg := sync.WaitGroup{} for i := 0; i < 100; i++ { @@ -299,3 +566,200 @@ func TestGetSetLevelRace(t *testing.T) { } wg.Wait() } + +func TestLoggingRace(t *testing.T) { + logger := New() + + var wg sync.WaitGroup + wg.Add(100) + + for i := 0; i < 100; i++ { + go func() { + logger.Info("info") + wg.Done() + }() + } + wg.Wait() +} + +func TestLoggingRaceWithHooksOnEntry(t *testing.T) { + logger := New() + hook := new(ModifyHook) + logger.AddHook(hook) + entry := logger.WithField("context", "clue") + + var wg sync.WaitGroup + wg.Add(100) + + for i := 0; i < 100; i++ { + go func() { + entry.Info("info") + wg.Done() + }() + } + wg.Wait() +} + +func TestReplaceHooks(t *testing.T) { + old, cur := &TestHook{}, &TestHook{} + + logger := New() + logger.SetOutput(ioutil.Discard) + logger.AddHook(old) + + hooks := make(LevelHooks) + hooks.Add(cur) + replaced := logger.ReplaceHooks(hooks) + + logger.Info("test") + + assert.Equal(t, old.Fired, false) + assert.Equal(t, cur.Fired, true) + + logger.ReplaceHooks(replaced) + logger.Info("test") + assert.Equal(t, old.Fired, true) +} + +// Compile test +func TestLogrusInterfaces(t *testing.T) { + var buffer bytes.Buffer + // This verifies FieldLogger and Ext1FieldLogger work as designed. + // Please don't use them. Use Logger and Entry directly. + fn := func(xl Ext1FieldLogger) { + var l FieldLogger = xl + b := l.WithField("key", "value") + b.Debug("Test") + } + // test logger + logger := New() + logger.Out = &buffer + fn(logger) + + // test Entry + e := logger.WithField("another", "value") + fn(e) +} + +// Implements io.Writer using channels for synchronization, so we can wait on +// the Entry.Writer goroutine to write in a non-racey way. This does assume that +// there is a single call to Logger.Out for each message. +type channelWriter chan []byte + +func (cw channelWriter) Write(p []byte) (int, error) { + cw <- p + return len(p), nil +} + +func TestEntryWriter(t *testing.T) { + cw := channelWriter(make(chan []byte, 1)) + log := New() + log.Out = cw + log.Formatter = new(JSONFormatter) + _, err := log.WithField("foo", "bar").WriterLevel(WarnLevel).Write([]byte("hello\n")) + if err != nil { + t.Error("unexecpted error", err) + } + + bs := <-cw + var fields Fields + err = json.Unmarshal(bs, &fields) + assert.Nil(t, err) + assert.Equal(t, fields["foo"], "bar") + assert.Equal(t, fields["level"], "warning") +} + +func TestLogLevelEnabled(t *testing.T) { + log := New() + log.SetLevel(PanicLevel) + assert.Equal(t, true, log.IsLevelEnabled(PanicLevel)) + assert.Equal(t, false, log.IsLevelEnabled(FatalLevel)) + assert.Equal(t, false, log.IsLevelEnabled(ErrorLevel)) + assert.Equal(t, false, log.IsLevelEnabled(WarnLevel)) + assert.Equal(t, false, log.IsLevelEnabled(InfoLevel)) + assert.Equal(t, false, log.IsLevelEnabled(DebugLevel)) + assert.Equal(t, false, log.IsLevelEnabled(TraceLevel)) + + log.SetLevel(FatalLevel) + assert.Equal(t, true, log.IsLevelEnabled(PanicLevel)) + assert.Equal(t, true, log.IsLevelEnabled(FatalLevel)) + assert.Equal(t, false, log.IsLevelEnabled(ErrorLevel)) + assert.Equal(t, false, log.IsLevelEnabled(WarnLevel)) + assert.Equal(t, false, log.IsLevelEnabled(InfoLevel)) + assert.Equal(t, false, log.IsLevelEnabled(DebugLevel)) + assert.Equal(t, false, log.IsLevelEnabled(TraceLevel)) + + log.SetLevel(ErrorLevel) + assert.Equal(t, true, log.IsLevelEnabled(PanicLevel)) + assert.Equal(t, true, log.IsLevelEnabled(FatalLevel)) + assert.Equal(t, true, log.IsLevelEnabled(ErrorLevel)) + assert.Equal(t, false, log.IsLevelEnabled(WarnLevel)) + assert.Equal(t, false, log.IsLevelEnabled(InfoLevel)) + assert.Equal(t, false, log.IsLevelEnabled(DebugLevel)) + assert.Equal(t, false, log.IsLevelEnabled(TraceLevel)) + + log.SetLevel(WarnLevel) + assert.Equal(t, true, log.IsLevelEnabled(PanicLevel)) + assert.Equal(t, true, log.IsLevelEnabled(FatalLevel)) + assert.Equal(t, true, log.IsLevelEnabled(ErrorLevel)) + assert.Equal(t, true, log.IsLevelEnabled(WarnLevel)) + assert.Equal(t, false, log.IsLevelEnabled(InfoLevel)) + assert.Equal(t, false, log.IsLevelEnabled(DebugLevel)) + assert.Equal(t, false, log.IsLevelEnabled(TraceLevel)) + + log.SetLevel(InfoLevel) + assert.Equal(t, true, log.IsLevelEnabled(PanicLevel)) + assert.Equal(t, true, log.IsLevelEnabled(FatalLevel)) + assert.Equal(t, true, log.IsLevelEnabled(ErrorLevel)) + assert.Equal(t, true, log.IsLevelEnabled(WarnLevel)) + assert.Equal(t, true, log.IsLevelEnabled(InfoLevel)) + assert.Equal(t, false, log.IsLevelEnabled(DebugLevel)) + assert.Equal(t, false, log.IsLevelEnabled(TraceLevel)) + + log.SetLevel(DebugLevel) + assert.Equal(t, true, log.IsLevelEnabled(PanicLevel)) + assert.Equal(t, true, log.IsLevelEnabled(FatalLevel)) + assert.Equal(t, true, log.IsLevelEnabled(ErrorLevel)) + assert.Equal(t, true, log.IsLevelEnabled(WarnLevel)) + assert.Equal(t, true, log.IsLevelEnabled(InfoLevel)) + assert.Equal(t, true, log.IsLevelEnabled(DebugLevel)) + assert.Equal(t, false, log.IsLevelEnabled(TraceLevel)) + + log.SetLevel(TraceLevel) + assert.Equal(t, true, log.IsLevelEnabled(PanicLevel)) + assert.Equal(t, true, log.IsLevelEnabled(FatalLevel)) + assert.Equal(t, true, log.IsLevelEnabled(ErrorLevel)) + assert.Equal(t, true, log.IsLevelEnabled(WarnLevel)) + assert.Equal(t, true, log.IsLevelEnabled(InfoLevel)) + assert.Equal(t, true, log.IsLevelEnabled(DebugLevel)) + assert.Equal(t, true, log.IsLevelEnabled(TraceLevel)) +} + +func TestReportCallerOnTextFormatter(t *testing.T) { + l := New() + + l.Formatter.(*TextFormatter).ForceColors = true + l.Formatter.(*TextFormatter).DisableColors = false + l.WithFields(Fields{"func": "func", "file": "file"}).Info("test") + + l.Formatter.(*TextFormatter).ForceColors = false + l.Formatter.(*TextFormatter).DisableColors = true + l.WithFields(Fields{"func": "func", "file": "file"}).Info("test") +} + +func TestSetReportCallerRace(t *testing.T) { + l := New() + l.Out = ioutil.Discard + l.SetReportCaller(true) + + var wg sync.WaitGroup + wg.Add(100) + + for i := 0; i < 100; i++ { + go func() { + l.Error("Some Error") + wg.Done() + }() + } + wg.Wait() +} diff --git a/terminal_check_appengine.go b/terminal_check_appengine.go new file mode 100644 index 000000000..2403de981 --- /dev/null +++ b/terminal_check_appengine.go @@ -0,0 +1,11 @@ +// +build appengine + +package logrus + +import ( + "io" +) + +func checkIfTerminal(w io.Writer) bool { + return true +} diff --git a/terminal_check_bsd.go b/terminal_check_bsd.go new file mode 100644 index 000000000..499789984 --- /dev/null +++ b/terminal_check_bsd.go @@ -0,0 +1,13 @@ +// +build darwin dragonfly freebsd netbsd openbsd +// +build !js + +package logrus + +import "golang.org/x/sys/unix" + +const ioctlReadTermios = unix.TIOCGETA + +func isTerminal(fd int) bool { + _, err := unix.IoctlGetTermios(fd, ioctlReadTermios) + return err == nil +} diff --git a/terminal_check_js.go b/terminal_check_js.go new file mode 100644 index 000000000..ebdae3ec6 --- /dev/null +++ b/terminal_check_js.go @@ -0,0 +1,7 @@ +// +build js + +package logrus + +func isTerminal(fd int) bool { + return false +} diff --git a/terminal_check_no_terminal.go b/terminal_check_no_terminal.go new file mode 100644 index 000000000..97af92c68 --- /dev/null +++ b/terminal_check_no_terminal.go @@ -0,0 +1,11 @@ +// +build js nacl plan9 + +package logrus + +import ( + "io" +) + +func checkIfTerminal(w io.Writer) bool { + return false +} diff --git a/terminal_check_notappengine.go b/terminal_check_notappengine.go new file mode 100644 index 000000000..3293fb3ca --- /dev/null +++ b/terminal_check_notappengine.go @@ -0,0 +1,17 @@ +// +build !appengine,!js,!windows,!nacl,!plan9 + +package logrus + +import ( + "io" + "os" +) + +func checkIfTerminal(w io.Writer) bool { + switch v := w.(type) { + case *os.File: + return isTerminal(int(v.Fd())) + default: + return false + } +} diff --git a/terminal_check_solaris.go b/terminal_check_solaris.go new file mode 100644 index 000000000..f6710b3bd --- /dev/null +++ b/terminal_check_solaris.go @@ -0,0 +1,11 @@ +package logrus + +import ( + "golang.org/x/sys/unix" +) + +// IsTerminal returns true if the given file descriptor is a terminal. +func isTerminal(fd int) bool { + _, err := unix.IoctlGetTermio(fd, unix.TCGETA) + return err == nil +} diff --git a/terminal_check_unix.go b/terminal_check_unix.go new file mode 100644 index 000000000..cc4fe6e31 --- /dev/null +++ b/terminal_check_unix.go @@ -0,0 +1,13 @@ +// +build linux aix +// +build !js + +package logrus + +import "golang.org/x/sys/unix" + +const ioctlReadTermios = unix.TCGETS + +func isTerminal(fd int) bool { + _, err := unix.IoctlGetTermios(fd, ioctlReadTermios) + return err == nil +} diff --git a/terminal_check_windows.go b/terminal_check_windows.go new file mode 100644 index 000000000..2879eb50e --- /dev/null +++ b/terminal_check_windows.go @@ -0,0 +1,27 @@ +// +build !appengine,!js,windows + +package logrus + +import ( + "io" + "os" + + "golang.org/x/sys/windows" +) + +func checkIfTerminal(w io.Writer) bool { + switch v := w.(type) { + case *os.File: + handle := windows.Handle(v.Fd()) + var mode uint32 + if err := windows.GetConsoleMode(handle, &mode); err != nil { + return false + } + mode |= windows.ENABLE_VIRTUAL_TERMINAL_PROCESSING + if err := windows.SetConsoleMode(handle, mode); err != nil { + return false + } + return true + } + return false +} diff --git a/terminal_darwin.go b/terminal_darwin.go deleted file mode 100644 index 8fe02a4ae..000000000 --- a/terminal_darwin.go +++ /dev/null @@ -1,12 +0,0 @@ -// Based on ssh/terminal: -// Copyright 2013 The Go Authors. All rights reserved. -// Use of this source code is governed by a BSD-style -// license that can be found in the LICENSE file. - -package logrus - -import "syscall" - -const ioctlReadTermios = syscall.TIOCGETA - -type Termios syscall.Termios diff --git a/terminal_freebsd.go b/terminal_freebsd.go deleted file mode 100644 index 0428ee5d5..000000000 --- a/terminal_freebsd.go +++ /dev/null @@ -1,20 +0,0 @@ -/* - Go 1.2 doesn't include Termios for FreeBSD. This should be added in 1.3 and this could be merged with terminal_darwin. -*/ -package logrus - -import ( - "syscall" -) - -const ioctlReadTermios = syscall.TIOCGETA - -type Termios struct { - Iflag uint32 - Oflag uint32 - Cflag uint32 - Lflag uint32 - Cc [20]uint8 - Ispeed uint32 - Ospeed uint32 -} diff --git a/terminal_linux.go b/terminal_linux.go deleted file mode 100644 index a2c0b40db..000000000 --- a/terminal_linux.go +++ /dev/null @@ -1,12 +0,0 @@ -// Based on ssh/terminal: -// Copyright 2013 The Go Authors. All rights reserved. -// Use of this source code is governed by a BSD-style -// license that can be found in the LICENSE file. - -package logrus - -import "syscall" - -const ioctlReadTermios = syscall.TCGETS - -type Termios syscall.Termios diff --git a/terminal_notwindows.go b/terminal_notwindows.go deleted file mode 100644 index b8bebc13e..000000000 --- a/terminal_notwindows.go +++ /dev/null @@ -1,21 +0,0 @@ -// Based on ssh/terminal: -// Copyright 2011 The Go Authors. All rights reserved. -// Use of this source code is governed by a BSD-style -// license that can be found in the LICENSE file. - -// +build linux darwin freebsd openbsd - -package logrus - -import ( - "syscall" - "unsafe" -) - -// IsTerminal returns true if the given file descriptor is a terminal. -func IsTerminal() bool { - fd := syscall.Stdout - var termios Termios - _, _, err := syscall.Syscall6(syscall.SYS_IOCTL, uintptr(fd), ioctlReadTermios, uintptr(unsafe.Pointer(&termios)), 0, 0, 0) - return err == 0 -} diff --git a/terminal_openbsd.go b/terminal_openbsd.go deleted file mode 100644 index d238bfa0b..000000000 --- a/terminal_openbsd.go +++ /dev/null @@ -1,8 +0,0 @@ - -package logrus - -import "syscall" - -const ioctlReadTermios = syscall.TIOCGETA - -type Termios syscall.Termios diff --git a/terminal_windows.go b/terminal_windows.go deleted file mode 100644 index 2e09f6f7e..000000000 --- a/terminal_windows.go +++ /dev/null @@ -1,27 +0,0 @@ -// Based on ssh/terminal: -// Copyright 2011 The Go Authors. All rights reserved. -// Use of this source code is governed by a BSD-style -// license that can be found in the LICENSE file. - -// +build windows - -package logrus - -import ( - "syscall" - "unsafe" -) - -var kernel32 = syscall.NewLazyDLL("kernel32.dll") - -var ( - procGetConsoleMode = kernel32.NewProc("GetConsoleMode") -) - -// IsTerminal returns true if the given file descriptor is a terminal. -func IsTerminal() bool { - fd := syscall.Stdout - var st uint32 - r, _, e := syscall.Syscall(procGetConsoleMode.Addr(), 2, uintptr(fd), uintptr(unsafe.Pointer(&st)), 0) - return r != 0 && e == 0 -} diff --git a/text_formatter.go b/text_formatter.go index 71dcb6617..3c28b54ca 100644 --- a/text_formatter.go +++ b/text_formatter.go @@ -3,36 +3,30 @@ package logrus import ( "bytes" "fmt" - "regexp" + "os" + "runtime" "sort" + "strconv" "strings" + "sync" "time" + "unicode/utf8" ) const ( - nocolor = 0 - red = 31 - green = 32 - yellow = 33 - blue = 34 - gray = 37 + red = 31 + yellow = 33 + blue = 36 + gray = 37 ) -var ( - baseTimestamp time.Time - isTerminal bool - noQuoteNeeded *regexp.Regexp -) +var baseTimestamp time.Time func init() { baseTimestamp = time.Now() - isTerminal = IsTerminal() -} - -func miniTS() int { - return int(time.Since(baseTimestamp) / time.Second) } +// TextFormatter formats logs into text type TextFormatter struct { // Set to true to bypass checking for a TTY before outputting colors. ForceColors bool @@ -40,6 +34,17 @@ type TextFormatter struct { // Force disabling colors. DisableColors bool + // Force quoting of all values + ForceQuote bool + + // DisableQuote disables quoting for all values. + // DisableQuote will have a lower priority than ForceQuote. + // If both of them are set to true, quote will be forced on all values. + DisableQuote bool + + // Override coloring based on CLICOLOR and CLICOLOR_FORCE. - https://bixense.com/clicolors/ + EnvironmentOverrideColors bool + // Disable timestamp logging. useful when output is redirected to logging // system that already adds timestamps. DisableTimestamp bool @@ -48,38 +53,172 @@ type TextFormatter struct { // the time passed since beginning of execution. FullTimestamp bool + // TimestampFormat to use for display when a full timestamp is printed + TimestampFormat string + // The fields are sorted by default for a consistent output. For applications // that log extremely frequently and don't use the JSON formatter this may not // be desired. DisableSorting bool + + // The keys sorting function, when uninitialized it uses sort.Strings. + SortingFunc func([]string) + + // Disables the truncation of the level text to 4 characters. + DisableLevelTruncation bool + + // PadLevelText Adds padding the level text so that all the levels output at the same length + // PadLevelText is a superset of the DisableLevelTruncation option + PadLevelText bool + + // QuoteEmptyFields will wrap empty fields in quotes if true + QuoteEmptyFields bool + + // Whether the logger's out is to a terminal + isTerminal bool + + // FieldMap allows users to customize the names of keys for default fields. + // As an example: + // formatter := &TextFormatter{ + // FieldMap: FieldMap{ + // FieldKeyTime: "@timestamp", + // FieldKeyLevel: "@level", + // FieldKeyMsg: "@message"}} + FieldMap FieldMap + + // CallerPrettyfier can be set by the user to modify the content + // of the function and file keys in the data when ReportCaller is + // activated. If any of the returned value is the empty string the + // corresponding key will be removed from fields. + CallerPrettyfier func(*runtime.Frame) (function string, file string) + + terminalInitOnce sync.Once + + // The max length of the level text, generated dynamically on init + levelTextMaxLength int } +func (f *TextFormatter) init(entry *Entry) { + if entry.Logger != nil { + f.isTerminal = checkIfTerminal(entry.Logger.Out) + } + // Get the max length of the level text + for _, level := range AllLevels { + levelTextLength := utf8.RuneCount([]byte(level.String())) + if levelTextLength > f.levelTextMaxLength { + f.levelTextMaxLength = levelTextLength + } + } +} + +func (f *TextFormatter) isColored() bool { + isColored := f.ForceColors || (f.isTerminal && (runtime.GOOS != "windows")) + + if f.EnvironmentOverrideColors { + switch force, ok := os.LookupEnv("CLICOLOR_FORCE"); { + case ok && force != "0": + isColored = true + case ok && force == "0", os.Getenv("CLICOLOR") == "0": + isColored = false + } + } + + return isColored && !f.DisableColors +} + +// Format renders a single log entry func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { - var keys []string = make([]string, 0, len(entry.Data)) - for k := range entry.Data { + data := make(Fields) + for k, v := range entry.Data { + data[k] = v + } + prefixFieldClashes(data, f.FieldMap, entry.HasCaller()) + keys := make([]string, 0, len(data)) + for k := range data { keys = append(keys, k) } - if !f.DisableSorting { - sort.Strings(keys) + var funcVal, fileVal string + + fixedKeys := make([]string, 0, 4+len(data)) + if !f.DisableTimestamp { + fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyTime)) + } + fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyLevel)) + if entry.Message != "" { + fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyMsg)) + } + if entry.err != "" { + fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyLogrusError)) + } + if entry.HasCaller() { + if f.CallerPrettyfier != nil { + funcVal, fileVal = f.CallerPrettyfier(entry.Caller) + } else { + funcVal = entry.Caller.Function + fileVal = fmt.Sprintf("%s:%d", entry.Caller.File, entry.Caller.Line) + } + + if funcVal != "" { + fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyFunc)) + } + if fileVal != "" { + fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyFile)) + } } - b := &bytes.Buffer{} + if !f.DisableSorting { + if f.SortingFunc == nil { + sort.Strings(keys) + fixedKeys = append(fixedKeys, keys...) + } else { + if !f.isColored() { + fixedKeys = append(fixedKeys, keys...) + f.SortingFunc(fixedKeys) + } else { + f.SortingFunc(keys) + } + } + } else { + fixedKeys = append(fixedKeys, keys...) + } - prefixFieldClashes(entry.Data) + var b *bytes.Buffer + if entry.Buffer != nil { + b = entry.Buffer + } else { + b = &bytes.Buffer{} + } - isColored := (f.ForceColors || isTerminal) && !f.DisableColors + f.terminalInitOnce.Do(func() { f.init(entry) }) - if isColored { - f.printColored(b, entry, keys) + timestampFormat := f.TimestampFormat + if timestampFormat == "" { + timestampFormat = defaultTimestampFormat + } + if f.isColored() { + f.printColored(b, entry, keys, data, timestampFormat) } else { - if !f.DisableTimestamp { - f.appendKeyValue(b, "time", entry.Time.Format(time.RFC3339)) - } - f.appendKeyValue(b, "level", entry.Level.String()) - f.appendKeyValue(b, "msg", entry.Message) - for _, key := range keys { - f.appendKeyValue(b, key, entry.Data[key]) + + for _, key := range fixedKeys { + var value interface{} + switch { + case key == f.FieldMap.resolve(FieldKeyTime): + value = entry.Time.Format(timestampFormat) + case key == f.FieldMap.resolve(FieldKeyLevel): + value = entry.Level.String() + case key == f.FieldMap.resolve(FieldKeyMsg): + value = entry.Message + case key == f.FieldMap.resolve(FieldKeyLogrusError): + value = entry.err + case key == f.FieldMap.resolve(FieldKeyFunc) && entry.HasCaller(): + value = funcVal + case key == f.FieldMap.resolve(FieldKeyFile) && entry.HasCaller(): + value = fileVal + default: + value = data[key] + } + f.appendKeyValue(b, key, value) } } @@ -87,10 +226,10 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { return b.Bytes(), nil } -func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []string) { +func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []string, data Fields, timestampFormat string) { var levelColor int switch entry.Level { - case DebugLevel: + case DebugLevel, TraceLevel: levelColor = gray case WarnLevel: levelColor = yellow @@ -100,46 +239,96 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []strin levelColor = blue } - levelText := strings.ToUpper(entry.Level.String())[0:4] + levelText := strings.ToUpper(entry.Level.String()) + if !f.DisableLevelTruncation && !f.PadLevelText { + levelText = levelText[0:4] + } + if f.PadLevelText { + // Generates the format string used in the next line, for example "%-6s" or "%-7s". + // Based on the max level text length. + formatString := "%-" + strconv.Itoa(f.levelTextMaxLength) + "s" + // Formats the level text by appending spaces up to the max length, for example: + // - "INFO " + // - "WARNING" + levelText = fmt.Sprintf(formatString, levelText) + } - if !f.FullTimestamp { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%04d] %-44s ", levelColor, levelText, miniTS(), entry.Message) - } else { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s] %-44s ", levelColor, levelText, entry.Time.Format(time.RFC3339), entry.Message) + // Remove a single newline if it already exists in the message to keep + // the behavior of logrus text_formatter the same as the stdlib log package + entry.Message = strings.TrimSuffix(entry.Message, "\n") + + caller := "" + if entry.HasCaller() { + funcVal := fmt.Sprintf("%s()", entry.Caller.Function) + fileVal := fmt.Sprintf("%s:%d", entry.Caller.File, entry.Caller.Line) + + if f.CallerPrettyfier != nil { + funcVal, fileVal = f.CallerPrettyfier(entry.Caller) + } + + if fileVal == "" { + caller = funcVal + } else if funcVal == "" { + caller = fileVal + } else { + caller = fileVal + " " + funcVal + } + } + + switch { + case f.DisableTimestamp: + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m%s %-44s ", levelColor, levelText, caller, entry.Message) + case !f.FullTimestamp: + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%04d]%s %-44s ", levelColor, levelText, int(entry.Time.Sub(baseTimestamp)/time.Second), caller, entry.Message) + default: + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s]%s %-44s ", levelColor, levelText, entry.Time.Format(timestampFormat), caller, entry.Message) } for _, k := range keys { - v := entry.Data[k] - fmt.Fprintf(b, " \x1b[%dm%s\x1b[0m=%v", levelColor, k, v) + v := data[k] + fmt.Fprintf(b, " \x1b[%dm%s\x1b[0m=", levelColor, k) + f.appendValue(b, v) } } -func needsQuoting(text string) bool { +func (f *TextFormatter) needsQuoting(text string) bool { + if f.ForceQuote { + return true + } + if f.QuoteEmptyFields && len(text) == 0 { + return true + } + if f.DisableQuote { + return false + } for _, ch := range text { if !((ch >= 'a' && ch <= 'z') || (ch >= 'A' && ch <= 'Z') || (ch >= '0' && ch <= '9') || - ch == '-' || ch == '.') { - return false + ch == '-' || ch == '.' || ch == '_' || ch == '/' || ch == '@' || ch == '^' || ch == '+') { + return true } } - return true + return false } -func (f *TextFormatter) appendKeyValue(b *bytes.Buffer, key, value interface{}) { - switch value.(type) { - case string: - if needsQuoting(value.(string)) { - fmt.Fprintf(b, "%v=%s ", key, value) - } else { - fmt.Fprintf(b, "%v=%q ", key, value) - } - case error: - if needsQuoting(value.(error).Error()) { - fmt.Fprintf(b, "%v=%s ", key, value) - } else { - fmt.Fprintf(b, "%v=%q ", key, value) - } - default: - fmt.Fprintf(b, "%v=%v ", key, value) +func (f *TextFormatter) appendKeyValue(b *bytes.Buffer, key string, value interface{}) { + if b.Len() > 0 { + b.WriteByte(' ') + } + b.WriteString(key) + b.WriteByte('=') + f.appendValue(b, value) +} + +func (f *TextFormatter) appendValue(b *bytes.Buffer, value interface{}) { + stringVal, ok := value.(string) + if !ok { + stringVal = fmt.Sprint(value) + } + + if !f.needsQuoting(stringVal) { + b.WriteString(stringVal) + } else { + b.WriteString(fmt.Sprintf("%q", stringVal)) } } diff --git a/text_formatter_test.go b/text_formatter_test.go index 28a949907..5b1cc0ab5 100644 --- a/text_formatter_test.go +++ b/text_formatter_test.go @@ -3,17 +3,44 @@ package logrus import ( "bytes" "errors" - + "fmt" + "os" + "runtime" + "sort" + "strings" "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" ) +func TestFormatting(t *testing.T) { + tf := &TextFormatter{DisableColors: true} + + testCases := []struct { + value string + expected string + }{ + {`foo`, "time=\"0001-01-01T00:00:00Z\" level=panic test=foo\n"}, + } + + for _, tc := range testCases { + b, _ := tf.Format(WithField("test", tc.value)) + + if string(b) != tc.expected { + t.Errorf("formatting expected for %q (result was %q instead of %q)", tc.value, string(b), tc.expected) + } + } +} + func TestQuoting(t *testing.T) { tf := &TextFormatter{DisableColors: true} checkQuoting := func(q bool, value interface{}) { b, _ := tf.Format(WithField("test", value)) idx := bytes.Index(b, ([]byte)("test=")) - cont := bytes.Contains(b[idx+5:], []byte{'"'}) + cont := bytes.Contains(b[idx+5:], []byte("\"")) if cont != q { if q { t.Errorf("quoting expected for: %#v", value) @@ -23,15 +50,551 @@ func TestQuoting(t *testing.T) { } } + checkQuoting(false, "") checkQuoting(false, "abcd") checkQuoting(false, "v1.0") checkQuoting(false, "1234567890") - checkQuoting(true, "/foobar") + checkQuoting(false, "/foobar") + checkQuoting(false, "foo_bar") + checkQuoting(false, "foo@bar") + checkQuoting(false, "foobar^") + checkQuoting(false, "+/-_^@f.oobar") + checkQuoting(true, "foo\n\rbar") + checkQuoting(true, "foobar$") + checkQuoting(true, "&foobar") checkQuoting(true, "x y") checkQuoting(true, "x,y") checkQuoting(false, errors.New("invalid")) checkQuoting(true, errors.New("invalid argument")) + + // Test for quoting empty fields. + tf.QuoteEmptyFields = true + checkQuoting(true, "") + checkQuoting(false, "abcd") + checkQuoting(true, "foo\n\rbar") + checkQuoting(true, errors.New("invalid argument")) + + // Test forcing quotes. + tf.ForceQuote = true + checkQuoting(true, "") + checkQuoting(true, "abcd") + checkQuoting(true, "foo\n\rbar") + checkQuoting(true, errors.New("invalid argument")) + + // Test forcing quotes when also disabling them. + tf.DisableQuote = true + checkQuoting(true, "") + checkQuoting(true, "abcd") + checkQuoting(true, "foo\n\rbar") + checkQuoting(true, errors.New("invalid argument")) + + // Test disabling quotes + tf.ForceQuote = false + tf.QuoteEmptyFields = false + checkQuoting(false, "") + checkQuoting(false, "abcd") + checkQuoting(false, "foo\n\rbar") + checkQuoting(false, errors.New("invalid argument")) +} + +func TestEscaping(t *testing.T) { + tf := &TextFormatter{DisableColors: true} + + testCases := []struct { + value string + expected string + }{ + {`ba"r`, `ba\"r`}, + {`ba'r`, `ba'r`}, + } + + for _, tc := range testCases { + b, _ := tf.Format(WithField("test", tc.value)) + if !bytes.Contains(b, []byte(tc.expected)) { + t.Errorf("escaping expected for %q (result was %q instead of %q)", tc.value, string(b), tc.expected) + } + } +} + +func TestEscaping_Interface(t *testing.T) { + tf := &TextFormatter{DisableColors: true} + + ts := time.Now() + + testCases := []struct { + value interface{} + expected string + }{ + {ts, fmt.Sprintf("\"%s\"", ts.String())}, + {errors.New("error: something went wrong"), "\"error: something went wrong\""}, + } + + for _, tc := range testCases { + b, _ := tf.Format(WithField("test", tc.value)) + if !bytes.Contains(b, []byte(tc.expected)) { + t.Errorf("escaping expected for %q (result was %q instead of %q)", tc.value, string(b), tc.expected) + } + } +} + +func TestTimestampFormat(t *testing.T) { + checkTimeStr := func(format string) { + customFormatter := &TextFormatter{DisableColors: true, TimestampFormat: format} + customStr, _ := customFormatter.Format(WithField("test", "test")) + timeStart := bytes.Index(customStr, ([]byte)("time=")) + timeEnd := bytes.Index(customStr, ([]byte)("level=")) + timeStr := customStr[timeStart+5+len("\"") : timeEnd-1-len("\"")] + if format == "" { + format = time.RFC3339 + } + _, e := time.Parse(format, (string)(timeStr)) + if e != nil { + t.Errorf("time string \"%s\" did not match provided time format \"%s\": %s", timeStr, format, e) + } + } + + checkTimeStr("2006-01-02T15:04:05.000000000Z07:00") + checkTimeStr("Mon Jan _2 15:04:05 2006") + checkTimeStr("") +} + +func TestDisableLevelTruncation(t *testing.T) { + entry := &Entry{ + Time: time.Now(), + Message: "testing", + } + keys := []string{} + timestampFormat := "Mon Jan 2 15:04:05 -0700 MST 2006" + checkDisableTruncation := func(disabled bool, level Level) { + tf := &TextFormatter{DisableLevelTruncation: disabled} + var b bytes.Buffer + entry.Level = level + tf.printColored(&b, entry, keys, nil, timestampFormat) + logLine := (&b).String() + if disabled { + expected := strings.ToUpper(level.String()) + if !strings.Contains(logLine, expected) { + t.Errorf("level string expected to be %s when truncation disabled", expected) + } + } else { + expected := strings.ToUpper(level.String()) + if len(level.String()) > 4 { + if strings.Contains(logLine, expected) { + t.Errorf("level string %s expected to be truncated to %s when truncation is enabled", expected, expected[0:4]) + } + } else { + if !strings.Contains(logLine, expected) { + t.Errorf("level string expected to be %s when truncation is enabled and level string is below truncation threshold", expected) + } + } + } + } + + checkDisableTruncation(true, DebugLevel) + checkDisableTruncation(true, InfoLevel) + checkDisableTruncation(false, ErrorLevel) + checkDisableTruncation(false, InfoLevel) } -// TODO add tests for sorting etc., this requires a parser for the text -// formatter output. +func TestPadLevelText(t *testing.T) { + // A note for future maintainers / committers: + // + // This test denormalizes the level text as a part of its assertions. + // Because of that, its not really a "unit test" of the PadLevelText functionality. + // So! Many apologies to the potential future person who has to rewrite this test + // when they are changing some completely unrelated functionality. + params := []struct { + name string + level Level + paddedLevelText string + }{ + { + name: "PanicLevel", + level: PanicLevel, + paddedLevelText: "PANIC ", // 2 extra spaces + }, + { + name: "FatalLevel", + level: FatalLevel, + paddedLevelText: "FATAL ", // 2 extra spaces + }, + { + name: "ErrorLevel", + level: ErrorLevel, + paddedLevelText: "ERROR ", // 2 extra spaces + }, + { + name: "WarnLevel", + level: WarnLevel, + // WARNING is already the max length, so we don't need to assert a paddedLevelText + }, + { + name: "DebugLevel", + level: DebugLevel, + paddedLevelText: "DEBUG ", // 2 extra spaces + }, + { + name: "TraceLevel", + level: TraceLevel, + paddedLevelText: "TRACE ", // 2 extra spaces + }, + { + name: "InfoLevel", + level: InfoLevel, + paddedLevelText: "INFO ", // 3 extra spaces + }, + } + + // We create a "default" TextFormatter to do a control test. + // We also create a TextFormatter with PadLevelText, which is the parameter we want to do our most relevant assertions against. + tfDefault := TextFormatter{} + tfWithPadding := TextFormatter{PadLevelText: true} + + for _, val := range params { + t.Run(val.name, func(t *testing.T) { + // TextFormatter writes into these bytes.Buffers, and we make assertions about their contents later + var bytesDefault bytes.Buffer + var bytesWithPadding bytes.Buffer + + // The TextFormatter instance and the bytes.Buffer instance are different here + // all the other arguments are the same. We also initialize them so that they + // fill in the value of levelTextMaxLength. + tfDefault.init(&Entry{}) + tfDefault.printColored(&bytesDefault, &Entry{Level: val.level}, []string{}, nil, "") + tfWithPadding.init(&Entry{}) + tfWithPadding.printColored(&bytesWithPadding, &Entry{Level: val.level}, []string{}, nil, "") + + // turn the bytes back into a string so that we can actually work with the data + logLineDefault := (&bytesDefault).String() + logLineWithPadding := (&bytesWithPadding).String() + + // Control: the level text should not be padded by default + if val.paddedLevelText != "" && strings.Contains(logLineDefault, val.paddedLevelText) { + t.Errorf("log line %q should not contain the padded level text %q by default", logLineDefault, val.paddedLevelText) + } + + // Assertion: the level text should still contain the string representation of the level + if !strings.Contains(strings.ToLower(logLineWithPadding), val.level.String()) { + t.Errorf("log line %q should contain the level text %q when padding is enabled", logLineWithPadding, val.level.String()) + } + + // Assertion: the level text should be in its padded form now + if val.paddedLevelText != "" && !strings.Contains(logLineWithPadding, val.paddedLevelText) { + t.Errorf("log line %q should contain the padded level text %q when padding is enabled", logLineWithPadding, val.paddedLevelText) + } + + }) + } +} + +func TestDisableTimestampWithColoredOutput(t *testing.T) { + tf := &TextFormatter{DisableTimestamp: true, ForceColors: true} + + b, _ := tf.Format(WithField("test", "test")) + if strings.Contains(string(b), "[0000]") { + t.Error("timestamp not expected when DisableTimestamp is true") + } +} + +func TestNewlineBehavior(t *testing.T) { + tf := &TextFormatter{ForceColors: true} + + // Ensure a single new line is removed as per stdlib log + e := NewEntry(StandardLogger()) + e.Message = "test message\n" + b, _ := tf.Format(e) + if bytes.Contains(b, []byte("test message\n")) { + t.Error("first newline at end of Entry.Message resulted in unexpected 2 newlines in output. Expected newline to be removed.") + } + + // Ensure a double new line is reduced to a single new line + e = NewEntry(StandardLogger()) + e.Message = "test message\n\n" + b, _ = tf.Format(e) + if bytes.Contains(b, []byte("test message\n\n")) { + t.Error("Double newline at end of Entry.Message resulted in unexpected 2 newlines in output. Expected single newline") + } + if !bytes.Contains(b, []byte("test message\n")) { + t.Error("Double newline at end of Entry.Message did not result in a single newline after formatting") + } +} + +func TestTextFormatterFieldMap(t *testing.T) { + formatter := &TextFormatter{ + DisableColors: true, + FieldMap: FieldMap{ + FieldKeyMsg: "message", + FieldKeyLevel: "somelevel", + FieldKeyTime: "timeywimey", + }, + } + + entry := &Entry{ + Message: "oh hi", + Level: WarnLevel, + Time: time.Date(1981, time.February, 24, 4, 28, 3, 100, time.UTC), + Data: Fields{ + "field1": "f1", + "message": "messagefield", + "somelevel": "levelfield", + "timeywimey": "timeywimeyfield", + }, + } + + b, err := formatter.Format(entry) + if err != nil { + t.Fatal("Unable to format entry: ", err) + } + + assert.Equal(t, + `timeywimey="1981-02-24T04:28:03Z" `+ + `somelevel=warning `+ + `message="oh hi" `+ + `field1=f1 `+ + `fields.message=messagefield `+ + `fields.somelevel=levelfield `+ + `fields.timeywimey=timeywimeyfield`+"\n", + string(b), + "Formatted output doesn't respect FieldMap") +} + +func TestTextFormatterIsColored(t *testing.T) { + params := []struct { + name string + expectedResult bool + isTerminal bool + disableColor bool + forceColor bool + envColor bool + clicolorIsSet bool + clicolorForceIsSet bool + clicolorVal string + clicolorForceVal string + }{ + // Default values + { + name: "testcase1", + expectedResult: false, + isTerminal: false, + disableColor: false, + forceColor: false, + envColor: false, + clicolorIsSet: false, + clicolorForceIsSet: false, + }, + // Output on terminal + { + name: "testcase2", + expectedResult: true, + isTerminal: true, + disableColor: false, + forceColor: false, + envColor: false, + clicolorIsSet: false, + clicolorForceIsSet: false, + }, + // Output on terminal with color disabled + { + name: "testcase3", + expectedResult: false, + isTerminal: true, + disableColor: true, + forceColor: false, + envColor: false, + clicolorIsSet: false, + clicolorForceIsSet: false, + }, + // Output not on terminal with color disabled + { + name: "testcase4", + expectedResult: false, + isTerminal: false, + disableColor: true, + forceColor: false, + envColor: false, + clicolorIsSet: false, + clicolorForceIsSet: false, + }, + // Output not on terminal with color forced + { + name: "testcase5", + expectedResult: true, + isTerminal: false, + disableColor: false, + forceColor: true, + envColor: false, + clicolorIsSet: false, + clicolorForceIsSet: false, + }, + // Output on terminal with clicolor set to "0" + { + name: "testcase6", + expectedResult: false, + isTerminal: true, + disableColor: false, + forceColor: false, + envColor: true, + clicolorIsSet: true, + clicolorForceIsSet: false, + clicolorVal: "0", + }, + // Output on terminal with clicolor set to "1" + { + name: "testcase7", + expectedResult: true, + isTerminal: true, + disableColor: false, + forceColor: false, + envColor: true, + clicolorIsSet: true, + clicolorForceIsSet: false, + clicolorVal: "1", + }, + // Output not on terminal with clicolor set to "0" + { + name: "testcase8", + expectedResult: false, + isTerminal: false, + disableColor: false, + forceColor: false, + envColor: true, + clicolorIsSet: true, + clicolorForceIsSet: false, + clicolorVal: "0", + }, + // Output not on terminal with clicolor set to "1" + { + name: "testcase9", + expectedResult: false, + isTerminal: false, + disableColor: false, + forceColor: false, + envColor: true, + clicolorIsSet: true, + clicolorForceIsSet: false, + clicolorVal: "1", + }, + // Output not on terminal with clicolor set to "1" and force color + { + name: "testcase10", + expectedResult: true, + isTerminal: false, + disableColor: false, + forceColor: true, + envColor: true, + clicolorIsSet: true, + clicolorForceIsSet: false, + clicolorVal: "1", + }, + // Output not on terminal with clicolor set to "0" and force color + { + name: "testcase11", + expectedResult: false, + isTerminal: false, + disableColor: false, + forceColor: true, + envColor: true, + clicolorIsSet: true, + clicolorForceIsSet: false, + clicolorVal: "0", + }, + // Output not on terminal with clicolor_force set to "1" + { + name: "testcase12", + expectedResult: true, + isTerminal: false, + disableColor: false, + forceColor: false, + envColor: true, + clicolorIsSet: false, + clicolorForceIsSet: true, + clicolorForceVal: "1", + }, + // Output not on terminal with clicolor_force set to "0" + { + name: "testcase13", + expectedResult: false, + isTerminal: false, + disableColor: false, + forceColor: false, + envColor: true, + clicolorIsSet: false, + clicolorForceIsSet: true, + clicolorForceVal: "0", + }, + // Output on terminal with clicolor_force set to "0" + { + name: "testcase14", + expectedResult: false, + isTerminal: true, + disableColor: false, + forceColor: false, + envColor: true, + clicolorIsSet: false, + clicolorForceIsSet: true, + clicolorForceVal: "0", + }, + } + + cleanenv := func() { + os.Unsetenv("CLICOLOR") + os.Unsetenv("CLICOLOR_FORCE") + } + + defer cleanenv() + + for _, val := range params { + t.Run("textformatter_"+val.name, func(subT *testing.T) { + tf := TextFormatter{ + isTerminal: val.isTerminal, + DisableColors: val.disableColor, + ForceColors: val.forceColor, + EnvironmentOverrideColors: val.envColor, + } + cleanenv() + if val.clicolorIsSet { + os.Setenv("CLICOLOR", val.clicolorVal) + } + if val.clicolorForceIsSet { + os.Setenv("CLICOLOR_FORCE", val.clicolorForceVal) + } + res := tf.isColored() + if runtime.GOOS == "windows" && !tf.ForceColors && !val.clicolorForceIsSet { + assert.Equal(subT, false, res) + } else { + assert.Equal(subT, val.expectedResult, res) + } + }) + } +} + +func TestCustomSorting(t *testing.T) { + formatter := &TextFormatter{ + DisableColors: true, + SortingFunc: func(keys []string) { + sort.Slice(keys, func(i, j int) bool { + if keys[j] == "prefix" { + return false + } + if keys[i] == "prefix" { + return true + } + return strings.Compare(keys[i], keys[j]) == -1 + }) + }, + } + + entry := &Entry{ + Message: "Testing custom sort function", + Time: time.Now(), + Level: InfoLevel, + Data: Fields{ + "test": "testvalue", + "prefix": "the application prefix", + "blablabla": "blablabla", + }, + } + b, err := formatter.Format(entry) + require.NoError(t, err) + require.True(t, strings.HasPrefix(string(b), "prefix="), "format output is %q", string(b)) +} diff --git a/travis/cross_build.sh b/travis/cross_build.sh new file mode 100755 index 000000000..5254435ca --- /dev/null +++ b/travis/cross_build.sh @@ -0,0 +1,5 @@ +#!/bin/bash + +if [[ "$TRAVIS_GO_VERSION" =~ ^1\.13\. ]] && [[ "$TRAVIS_OS_NAME" == "linux" ]] && [[ "$GO111MODULE" == "on" ]]; then + $(go env GOPATH)/bin/gox -build-lib +fi diff --git a/travis/install.sh b/travis/install.sh new file mode 100755 index 000000000..5fc40dd81 --- /dev/null +++ b/travis/install.sh @@ -0,0 +1,22 @@ +#!/bin/bash + +set -e + +# Install golanci 1.21.0 +if [[ "$TRAVIS_GO_VERSION" =~ ^1\.13\. ]]; then + curl -sfL https://raw.githubusercontent.com/golangci/golangci-lint/master/install.sh| sh -s -- -b $(go env GOPATH)/bin v1.21.0 +fi + +# Only do this for go1.12 when modules are on so that it doesn't need to be done when modules are off as well. +if [[ "$TRAVIS_GO_VERSION" =~ ^1\.13\. ]] && [[ "$TRAVIS_OS_NAME" == "linux" ]] && [[ "$GO111MODULE" == "on" ]]; then + GO111MODULE=off go get github.com/dgsb/gox +fi + +if [[ "$GO111MODULE" == "on" ]]; then + go mod download +fi + +if [[ "$GO111MODULE" == "off" ]]; then + # Should contain all regular (not indirect) modules from go.mod + go get github.com/stretchr/testify golang.org/x/sys/unix golang.org/x/sys/windows +fi diff --git a/travis/lint.sh b/travis/lint.sh new file mode 100755 index 000000000..0ed1d7c74 --- /dev/null +++ b/travis/lint.sh @@ -0,0 +1,5 @@ +#!/bin/bash + +if [[ "$TRAVIS_GO_VERSION" =~ ^1\.13\. ]] && [[ "$TRAVIS_OS_NAME" == "linux" ]] && [[ "$GO111MODULE" == "on" ]]; then + $(go env GOPATH)/bin/golangci-lint run ./... +fi diff --git a/writer.go b/writer.go index 90d3e01b4..72e8e3a1b 100644 --- a/writer.go +++ b/writer.go @@ -6,22 +6,61 @@ import ( "runtime" ) -func (logger *Logger) Writer() (*io.PipeWriter) { +// Writer at INFO level. See WriterLevel for details. +func (logger *Logger) Writer() *io.PipeWriter { + return logger.WriterLevel(InfoLevel) +} + +// WriterLevel returns an io.Writer that can be used to write arbitrary text to +// the logger at the given log level. Each line written to the writer will be +// printed in the usual way using formatters and hooks. The writer is part of an +// io.Pipe and it is the callers responsibility to close the writer when done. +// This can be used to override the standard library logger easily. +func (logger *Logger) WriterLevel(level Level) *io.PipeWriter { + return NewEntry(logger).WriterLevel(level) +} + +func (entry *Entry) Writer() *io.PipeWriter { + return entry.WriterLevel(InfoLevel) +} + +func (entry *Entry) WriterLevel(level Level) *io.PipeWriter { reader, writer := io.Pipe() - go logger.writerScanner(reader) + var printFunc func(args ...interface{}) + + switch level { + case TraceLevel: + printFunc = entry.Trace + case DebugLevel: + printFunc = entry.Debug + case InfoLevel: + printFunc = entry.Info + case WarnLevel: + printFunc = entry.Warn + case ErrorLevel: + printFunc = entry.Error + case FatalLevel: + printFunc = entry.Fatal + case PanicLevel: + printFunc = entry.Panic + default: + printFunc = entry.Print + } + + go entry.writerScanner(reader, printFunc) runtime.SetFinalizer(writer, writerFinalizer) return writer } -func (logger *Logger) writerScanner(reader *io.PipeReader) { +func (entry *Entry) writerScanner(reader *io.PipeReader, printFunc func(args ...interface{})) { scanner := bufio.NewScanner(reader) for scanner.Scan() { - logger.Print(scanner.Text()) + printFunc(scanner.Text()) } if err := scanner.Err(); err != nil { - logger.Errorf("Error while reading from Writer: %s", err) + entry.Errorf("Error while reading from Writer: %s", err) } reader.Close() } diff --git a/writer_test.go b/writer_test.go new file mode 100644 index 000000000..5c34927da --- /dev/null +++ b/writer_test.go @@ -0,0 +1,34 @@ +package logrus_test + +import ( + "log" + "net/http" + + "github.com/sirupsen/logrus" +) + +func ExampleLogger_Writer_httpServer() { + logger := logrus.New() + w := logger.Writer() + defer w.Close() + + srv := http.Server{ + // create a stdlib log.Logger that writes to + // logrus.Logger. + ErrorLog: log.New(w, "", 0), + } + + if err := srv.ListenAndServe(); err != nil { + logger.Fatal(err) + } +} + +func ExampleLogger_Writer_stdlib() { + logger := logrus.New() + logger.Formatter = &logrus.JSONFormatter{} + + // Use logrus for standard log output + // Note that `log` here references stdlib's log + // Not logrus imported under the name `log`. + log.SetOutput(logger.Writer()) +}