Documentation
¶
Overview ¶
Package log is an important part of the application and having a consistent logging mechanism and structure is mandatory. With several teams writing different components that talk to each other, being able to read each others logs could be the difference between finding bugs quickly or wasting hours.
Loggers ¶
With the log package in the standard library, we have the ability to create custom loggers that can be configured to write to one or many devices. Since we use syslog to send logging output to a central log repository, our logger can be configured to just write to stdout. This not only simplifies things for us, but will keep each log trace in correct sequence.
Logging levels ¶
This package does not included logging levels. Everything needs to be logged to help trace the code and find bugs. There is no such thing as over logging. By the time you decide to change the logging level, it is always too late. The question of performance comes up quite a bit. If the only performance issue we see is coming from logging, we are doing very well. I have had these opinions for a long time, but if you want more clarity on the subject listen to this recent podcast:
Jon Gifford On Logging And Logging Infrastructure:
http://www.se-radio.net/2015/02/episode-220-jon-gifford-on-logging-and-logging-infrastructure
Robert Blumen talks to Jon Gifford of Loggly about logging and logging infrastructure. Topics include logging defined, purposes of logging, uses of logging in understanding the run-time behavior of programs, who produces logs, who consumes logs and for what reasons, software as the consumer of logs, log formats (structured versus free form), log meta-data, logging APIs, logging as coding, logging and frameworks, the massive hairball of log file management, modern logging infrastructure in which log records are stored and indexed in a search engine, how searchable logs have transformed the uses of log data, log data and analytics, leveraging the log database for statistical insights, performance and resource issues of logging, are logs really different than other data that systems record in databases, and how log visualization gives users insights into their system. The show wraps up with a discussion of open source logging platforms versus commercial SAAS providers.
Tracing Formats ¶
There are two types of tracing lines we need to log. One is a trace line that describes where the program is, what it is doing and any data associated with that trace. The second is formatted data such as a JSON document or binary dump of data. Each serve a different purpose but they both exists within the same scope of space and time.
The format of each trace line needs to be consistent and helpful or else the logging will just be noise and ultimately useless.
PREFIX[PID]: YYYY/MM/DD HH:MM:SS.ZZZ: file.go:LN: Context: Func: Tag: Var[value]: Message
Here is a breakdown of each section and a sample value:
PREFIX The application or service name. Set on Init. Ex. CHADWICK [PID]: The process id for the running program. YYYY/MM/DD Date of the trace log line in UTC. Ex. 2015/03/23 HH:MM:SS.ZZZZZZ Time of the trace log line with microsecond in UTC. Ex. 14:02:42.123 file.go:LN: The name of the source code file and line number. Ex. main.go:15: Context: This could be a userid, session or something that maintains a context across multiple trace lines. There is no way to get a goroutine id Func: The name of the function writing the trace log. Ex. GetResponse or context.GetSession Tag: The tag of trace line. Started: Start of a function/method call. Completed: Return of a function/method call. Completed ERROR: Return of a function/method call with error. ERROR: Error trace. Warning: Warning trace. Info: General information. DATA: A dump of data Query: Any query that can be copied/pasted and run. Var[value]: Optional, Data values, parameters or return values. Ex. ID[1234] Messages: Optional, Any extended information with proper grammar. Ex. Waiting on SMSC to acknowledge request.
Here are examples of how trace lines would show in the log:
CHADWICK[69910]: 2015/03/23 14:02:42.123: rule.go:82: 5567: Get: Started: ID[1234] CHADWICK[69910]: 2015/03/23 14:02:42.423: rule.go:85: 5567: Get: Query: sp_Get 1234 CHADWICK[69910]: 2015/03/23 14:02:42.523: rule.go:90: 5567: Get: Completed: Found[1] CHADWICK[69910]: 2015/03/23 14:02:42.123: rule.go:82: 5567: Get: Started: ID[1234] CHADWICK[69910]: 2015/03/23 14:02:42.423: rule.go:85: 5567: Get: Query: sp_Get 1234 CHADWICK[69910]: 2015/03/23 14:02:42.523: rule.go:90: 5567: Get: Completed: ERROR: Not Found
In the end, we want to see the flow of most functions starting and completing so we can follow the code in the logs. We want to quickly see and filter errors, which can be accomplished by using a capitalized version of the word ERROR.
The context is an important value. The context allows us to extract trace lines for one context over others. Maybe in this case 8890 represents a user id.
CHADWICK[69910]: 2015/03/23 14:02:42.123: rule.go:82: 5567: Get: Started: ID[1234] <- 5567 CHADWICK[69910]: 2015/03/23 14:02:42.423: rule.go:85: 5567: Get: Query: sp_Get 1234 <- 5567 CHADWICK[69910]: 2015/03/23 14:02:43.235: rule.go:82: 8890: Get: Started: ID[4123] <- 8890 CHADWICK[69910]: 2015/03/23 14:02:43.523: rule.go:90: 5567: Get: Completed: Found[1] <- 5567 CHADWICK[69910]: 2015/03/23 14:02:43.626: rule.go:85: 8890: Get: Query: sp_Get 4123 <- 8890 CHADWICK[69910]: 2015/03/23 14:02:44.694: rule.go:90: 8890: Get: Completed: Found[1] <- 8890
When there is a need to dump formatted data into the logs, there are three approaches. If the data can be represented as key/value pairs, you can write each pair on their own line with the DATA tag:
CHADWICK[69910]: 2015/03/23 14:02:42.123: dsmcc.go:123: 5567: DsmccDump: DATA: Protocol Discriminator: 17 CHADWICK[69910]: 2015/03/23 14:02:42.123: dsmcc.go:123: 5567: DsmccDump: DATA: DSMCC Type: 2 CHADWICK[69910]: 2015/03/23 14:02:42.123: dsmcc.go:123: 5567: DsmccDump: DATA: Message ID: 0x4021 (ClientReleaseConfirm) CHADWICK[69910]: 2015/03/23 14:02:42.123: dsmcc.go:123: 5567: DsmccDump: DATA: Transaction ID: 0x00000003 CHADWICK[69910]: 2015/03/23 14:02:42.123: dsmcc.go:123: 5567: DsmccDump: DATA: Reserved: 0xFF CHADWICK[69910]: 2015/03/23 14:02:42.123: dsmcc.go:123: 5567: DsmccDump: DATA: Adaptation Length: 0 bytes CHADWICK[69910]: 2015/03/23 14:02:42.123: dsmcc.go:123: 5567: DsmccDump: DATA: Message Length: 16 = 0x0010 CHADWICK[69910]: 2015/03/23 14:02:42.123: dsmcc.go:123: 5567: DsmccDump: DATA: Message Bytes: (0x0000) EE 6E 11 00 00 00 3E EA DE 18 00 00 00 00 00 00 CHADWICK[69910]: 2015/03/23 14:02:42.123: dsmcc.go:123: 5567: DsmccDump: DATA: Session ID CHADWICK[69910]: 2015/03/23 14:02:42.123: dsmcc.go:123: 5567: DsmccDump: DATA: Device ID: ee6e11000000 CHADWICK[69910]: 2015/03/23 14:02:42.123: dsmcc.go:123: 5567: DsmccDump: DATA: Session Number: 0x3EEADE18 CHADWICK[69910]: 2015/03/23 14:02:42.123: dsmcc.go:123: 5567: DsmccDump: DATA: Response: 0x0000 = 0 CHADWICK[69910]: 2015/03/23 14:02:42.123: dsmcc.go:123: 5567: DsmccDump: DATA: UU Data Count: 0 bytes CHADWICK[69910]: 2015/03/23 14:02:42.123: dsmcc.go:123: 5567: DsmccDump: DATA: Private Data Count: 0 bytes
When there is a single block of data to dump, then it can be written as a single multi-line trace:
CHADWICK: 2015/03/23 14:02:42.123: cgwp.go:567: 5567: Teardown: DATA: XML CHADWICK: 2015/03/23 14:02:42.123: cgwp.go:567: 5567: Teardown: DATA: <?xml version="1.0" encoding="utf-8"?> CHADWICK: 2015/03/23 14:02:42.123: cgwp.go:567: 5567: Teardown: DATA: <TeardownSession CHADWICK: 2015/03/23 14:02:42.123: cgwp.go:567: 5567: Teardown: DATA: xmlns="urn:com:comcast:ngsrm:s1:2010:12:03" CHADWICK: 2015/03/23 14:02:42.123: cgwp.go:567: 5567: Teardown: DATA: onDemandSessionId="7591a2ebfa574133bce831163356ccb2" CHADWICK: 2015/03/23 14:02:42.123: cgwp.go:567: 5567: Teardown: DATA: reasonCode="200" CHADWICK: 2015/03/23 14:02:42.123: cgwp.go:567: 5567: Teardown: DATA: clientReasonCode="0x1" CHADWICK: 2015/03/23 14:02:42.123: cgwp.go:567: 5567: Teardown: DATA: > CHADWICK: 2015/03/23 14:02:42.123: cgwp.go:567: 5567: Teardown: DATA: </TeardownSession>
When special block formatting required, the Stringer interface can be implemented to format data in custom ways:
CHADWICK[69910]: 2009/11/10 20:00:00.000: dsmcc.go:155: 5567: Data_String: Started: CHADWICK[69910]: 2009/11/10 20:00:00.000: dsmcc.go:162: 5567: Data_String: DATA: Message Bytes: (0x0000) EE 6E 11 00 00 00 3E EA DE 18 00 00 2D 00 00 00 CHADWICK[69910]: 2009/11/10 20:00:00.000: dsmcc.go:162: 5567: Data_String: DATA: (0x0010) 3E EA DE CHADWICK[69910]: 2009/11/10 20:00:00.000: dsmcc.go:164: 5567: Data_String: Completed:
API Documentation and Examples ¶
The API for the log package is focused on initializing the logger and then provides function abstractions for the different tags we have defined.
Index ¶
- func Complete(context interface{})
- func CompleteErr(err error, context interface{})
- func CompleteErrf(err error, context interface{}, format string, a ...interface{})
- func Completef(context interface{}, format string, a ...interface{})
- func DataBlock(context interface{}, key string, block interface{})
- func DataKV(context interface{}, key string, value interface{})
- func DataString(context interface{}, message string)
- func DataTrace(context interface{}, formatters ...Formatter)
- func Err(err error, context interface{})
- func ErrFatal(err error, context interface{})
- func ErrFatalf(err error, context interface{}, format string, a ...interface{})
- func Errf(err error, context interface{}, format string, a ...interface{})
- func Info(context interface{}, msg string)
- func Infof(context interface{}, format string, a ...interface{})
- func Init(prefix string, w ...io.Writer)
- func InitTest(prefix string, w ...io.Writer)
- func Queryf(context interface{}, format string, a ...interface{})
- func Start(context interface{})
- func Startf(context interface{}, format string, a ...interface{})
- func Warnf(context interface{}, format string, a ...interface{})
- type Formatter
- type Uplevel
- func (lvl Uplevel) Complete(context interface{}, function string)
- func (lvl Uplevel) CompleteErr(err error, context interface{}, function string)
- func (lvl Uplevel) CompleteErrf(err error, context interface{}, function string, format string, ...)
- func (lvl Uplevel) Completef(context interface{}, function string, format string, a ...interface{})
- func (lvl Uplevel) DataBlock(context interface{}, function string, key string, block interface{})
- func (lvl Uplevel) DataKV(context interface{}, function string, key string, value interface{})
- func (lvl Uplevel) DataString(context interface{}, function string, message string)
- func (lvl Uplevel) DataTrace(context interface{}, function string, formatters ...Formatter)
- func (lvl Uplevel) Err(err error, context interface{}, function string)
- func (lvl Uplevel) ErrFatal(err error, context interface{}, function string)
- func (lvl Uplevel) ErrFatalf(err error, context interface{}, function string, format string, ...)
- func (lvl Uplevel) Errf(err error, context interface{}, function string, format string, ...)
- func (lvl Uplevel) Info(context interface{}, function string, msg string)
- func (lvl Uplevel) Infof(context interface{}, function string, format string, a ...interface{})
- func (lvl Uplevel) Queryf(context interface{}, function string, format string, a ...interface{})
- func (lvl Uplevel) Start(context interface{}, function string)
- func (lvl Uplevel) Startf(context interface{}, function string, format string, a ...interface{})
- func (lvl Uplevel) Warnf(context interface{}, function string, format string, a ...interface{})
Examples ¶
Constants ¶
This section is empty.
Variables ¶
This section is empty.
Functions ¶
func CompleteErr ¶
func CompleteErr(err error, context interface{})
CompleteErr is used to write an error with complete into the trace.
func CompleteErrf ¶
CompleteErrf is used to write an error with complete into the trace with a formatted message.
func Completef ¶
func Completef(context interface{}, format string, a ...interface{})
Completef is used for the exit of a function with a formatted message.
func DataBlock ¶
func DataBlock(context interface{}, key string, block interface{})
DataBlock is used to write a block of data into the trace.
Example ¶
ExampleDataBlock provides an example of logging a block of data.
// Init the log system using a buffer for testing. buf := new(bytes.Buffer) InitTest("EXAMPLE", buf) { Start("1234", "Data_Block") data := `<?xml version="1.0" encoding="utf-8"?> <TeardownSession xmlns="urn:com:comcast:ngsrm:s1:2010:12:03" onDemandSessionId="7591a2ebfa574133bce831163356ccb2" reasonCode="200" clientReasonCode="0x1" > </TeardownSession>` DataBlock("1234", "Data_Block", "XML", data) Complete("1234", "Data_Block") } // Flush the output for testing. fmt.Println(buf.String())
Output: EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_Block: Started: EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_Block: DATA: <?xml version="1.0" encoding="utf-8"?> EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_Block: DATA: <TeardownSession EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_Block: DATA: xmlns="urn:com:comcast:ngsrm:s1:2010:12:03" EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_Block: DATA: onDemandSessionId="7591a2ebfa574133bce831163356ccb2" EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_Block: DATA: reasonCode="200" EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_Block: DATA: clientReasonCode="0x1" EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_Block: DATA: > EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_Block: DATA: </TeardownSession> EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_Block: Completed:
func DataKV ¶
func DataKV(context interface{}, key string, value interface{})
DataKV is used to write a key/value pair into the trace.
Example ¶
ExampleDataKV provides an example of logging K/V pair data.
// Init the log system using a buffer for testing. buf := new(bytes.Buffer) InitTest("EXAMPLE", buf) { Start("1234", "Data_KV") DataKV("1234", "Data_KV", "Protocol Discriminator", 17) DataKV("1234", "Data_KV", "Transaction ID", 0x00000003) Complete("1234", "Data_KV") } // Flush the output for testing. fmt.Println(buf.String())
Output: EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_KV: Started: EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_KV: DATA: Protocol Discriminator: 17 EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_KV: DATA: Transaction ID: 3 EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_KV: Completed:
func DataString ¶
func DataString(context interface{}, message string)
DataString is used to write a string with CRLF each on their own line.
func DataTrace ¶
func DataTrace(context interface{}, formatters ...Formatter)
DataTrace is used to write a block of data from an io.Stringer respecting each line.
Example ¶
ExampleDataTrace provides an example of logging from a fmt.Stringer.
/* // Message is a named type (type Message []byte) and implements the Stringer interface. type Message []byte // The Formatter interface is implemented for the named type. func (m Message) Format() string { var buf bytes.Buffer // Message Bytes: (0x0000) EE 6E 11 00 00 00 3E EA DE 18 00 00 2D 00 00 00 // (0x0010) 00 00 00 00 00 0A 16 C3 9B 00 00 00 00 00 00 00 fmt.Fprintf(&buf, "Message Bytes:\t") rows := (len(m) / 16) + 1 l := len(m) for row := 0; row < rows; row++ { var r []byte st := row * 16 if row < (rows - 1) { r = m[st : st+16] } else { r = m[st : st+(l-st)] } if row > 0 { fmt.Fprintf(&buf, "\t\t\t") } fmt.Fprintf(&buf, "(0x%.4X)", st) for i := 0; i < len(r); i++ { fmt.Fprintf(&buf, " %.2X", r[i]) } fmt.Fprintf(&buf, "\n") } return buf.String() } */ // Init the log system using a buffer for testing. buf := new(bytes.Buffer) InitTest("EXAMPLE", buf) { Start("1234", "Data_String") b1 := []byte{0xEE, 0x6E, 0x11, 0x00, 0x00, 0x00, 0x3E, 0xEA, 0xDE, 0x18, 0x00, 0x00, 0x2D, 0x00, 0x00, 0x00, 0x3E, 0xEA, 0xDE} b2 := []byte{0xEE, 0x6E, 0x11, 0x00, 0x00, 0x00, 0x3E, 0xEA, 0xDE, 0x18, 0x00, 0x00, 0x2D, 0x00, 0x00, 0x00, 0x3E, 0xEA, 0xDE} DataTrace("1234", "Data_String", Message(b1), Message(b2)) Complete("1234", "Data_String") } // Flush the output for testing. fmt.Println(buf.String())
Output: EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_String: Started: EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_String: DATA: Message Bytes: (0x0000) EE 6E 11 00 00 00 3E EA DE 18 00 00 2D 00 00 00 EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_String: DATA: (0x0010) 3E EA DE EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_String: DATA: Message Bytes: (0x0000) EE 6E 11 00 00 00 3E EA DE 18 00 00 2D 00 00 00 EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_String: DATA: (0x0010) 3E EA DE EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Data_String: Completed:
func Err ¶
func Err(err error, context interface{})
Err is used to write an error into the trace.
Example ¶
ExampleErr provides an example of logging an error.
// Init the log system using a buffer for testing. buf := new(bytes.Buffer) InitTest("EXAMPLE", buf) { Start("1234", "Error") v, err := strconv.ParseInt("1080980980980980980898908", 10, 64) if err != nil { CompleteErr(err, "1234", "Error") // Flush the output for testing. fmt.Println(buf.String()) return } Completef("1234", "Error", "Conv[%d]", v) }
Output: EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Error: Started: EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Error: Completed ERROR: strconv.ParseInt: parsing "1080980980980980980898908": value out of range
func ErrFatal ¶
func ErrFatal(err error, context interface{})
ErrFatal is used to write an error into the trace then terminate the program.
func ErrFatalf ¶
ErrFatalf is used to write an error into the trace with a formatted message then terminate the program.
func Infof ¶
func Infof(context interface{}, format string, a ...interface{})
Infof is used to write information into the trace with a formatted message.
func Queryf ¶
func Queryf(context interface{}, format string, a ...interface{})
Queryf is used to write a query into the trace with a formatted message.
func Start ¶
func Start(context interface{})
Start is used for the entry into a function.
Example ¶
ExampleStart provides a basic example for using the log package.
// Init the log system using a buffer for testing. buf := new(bytes.Buffer) InitTest("EXAMPLE", buf) { Start("1234", "Basic") v, err := strconv.ParseInt("10", 10, 64) if err != nil { CompleteErr(err, "1234", "Basic") return } Completef("1234", "Basic", "Conv[%d]", v) } // Flush the output for testing. fmt.Println(buf.String())
Output: EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Basic: Started: EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Basic: Completed: Conv[10]
Types ¶
type Formatter ¶
type Formatter interface {
Format() string
}
Formatter provide support for special formatting.
type Uplevel ¶
type Uplevel int
Uplevel controls the stack frame level for file name, line number and function name. It can be used to embed logging calls in helper functions that report the file name, line number and function name of the routine that calls the helper.
var Up1 Uplevel = 1
Up1 is short for Uplevel(1).
func (Uplevel) CompleteErr ¶
CompleteErr is used to write an error with complete into the trace.
func (Uplevel) CompleteErrf ¶
func (lvl Uplevel) CompleteErrf(err error, context interface{}, function string, format string, a ...interface{})
CompleteErrf is used to write an error with complete into the trace with a formatted message.
func (Uplevel) DataString ¶
DataString is used to write a string with CRLF each on their own line.
func (Uplevel) DataTrace ¶
DataTrace is used to write a block of data from an io.Stringer respecting each line.
func (Uplevel) ErrFatal ¶
ErrFatal is used to write an error into the trace then terminate the program.
func (Uplevel) ErrFatalf ¶
func (lvl Uplevel) ErrFatalf(err error, context interface{}, function string, format string, a ...interface{})
ErrFatalf is used to write an error into the trace with a formatted message then terminate the program.
func (Uplevel) Errf ¶
func (lvl Uplevel) Errf(err error, context interface{}, function string, format string, a ...interface{})
Errf is used to write an error into the trace with a formatted message.
func (Uplevel) Start ¶
Start is used for the entry into a function.
Example ¶
ExampleUplevel_Start provides an example of using the level up functionality. For example, the following code would generate a log message with line number 13 (the line number where handleErr is called) and function name "example.someFunc".
1: package example 2: 3: func handleErr(err error, context interface{}, function string) { 4: ... 5: // log with caller's file, line, and function name. 6: log.Up1.Err(err, context, function) 7: ... 8: } 9: 10: func someFunc() { 11: ... 12: if err := doSomething(); err != nil { 13: handleErr(err, context, "") 14: } 15: ... 16: }
// Init the log system using a buffer for testing. buf := new(bytes.Buffer) InitTest("EXAMPLE", buf) { levelUp := func(context interface{}, function string) { Up1.Tracef(context, function, "Test") } Start("1234", "Basic") levelUp("1234", "Basic") Complete("1234", "Basic") } // Flush the output for testing. fmt.Println(buf.String())
Output: EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Basic: Started: EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Basic: Info: Test EXAMPLE[69910]: 2009/11/10 15:00:00.000: file.go:512: 1234: Basic: Completed: