# Writing to rotating log file via channels

I'm an experienced programmer (mostly C#, JavaScript, PHP). Go is quite a paradigm shift and I want to make sure I'm starting on the right foot.

This is my first Golang package. It's purpose is to be initiated and sent log lines (in the form of map[string]string to AddEntry. It's using channels since the lines could be added VERY frequently and I don't want to consume I/O time on the receiving function (outside of this package).

Any ways this could better follow Go's practices I am definitely interested to hear.

Usage Example:

testLog := chatlog.NewChatLog("/opt/test/logs/", "IRC", "SomeServerName", 1000)
testEntry := make(map[string]string)
testEntry["Type"] = "PRIVMSG"
testEntry["Entity"] = "SomeUser"
testEntry["Content"] = "This is the message!"


The Package:

// Package chatlog provides a structure way of storing chatlogs for consumption by CelestialStats.
package chatlog

import (
"encoding/json"
"fmt"
"log"
"os"
"path"
"strconv"
"time"
)

type ChatLog struct {
Protocol   string
Server     string
logDir     string
logFile    *os.File
logChannel chan map[string]string
}

// NewChatLog returns a new ChatLog ready to recieve log entries and write them to disk.
func NewChatLog(LogDir, Protocol, Server string, MaxQueue int) *ChatLog {
cl := new(ChatLog)
cl.logDir = LogDir
cl.Protocol = Protocol
cl.Server = Server
cl.logChannel = make(chan map[string]string, MaxQueue)
go cl.Write()
return cl
}

// Open opens a specific structured file for later writing.
func (chatLog *ChatLog) Open() {
var logFilename = chatLog.GenerateFilename()
var parentDir = path.Dir(logFilename)
if _, err := os.Stat(parentDir); os.IsNotExist(err) {
os.MkdirAll(parentDir, 0755)
}
f, err := os.OpenFile(logFilename, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0644)
if err != nil {
log.Println("Error opening file:", logFilename)
}
chatLog.logFile = f
}

// AddEntry adds a map representing the chat message to the log channel. It
// also appends the current Unix Timestamp in milliseconds to the map.
func (chatLog *ChatLog) AddEntry(newEntry map[string]string) {
newEntry["Timestamp"] = strconv.FormatInt(time.Now().UTC().UnixNano()/int64(time.Millisecond), 36)
chatLog.logChannel <- newEntry
}

// Write outputs any additions to the log channel to the current log file.
// If the log does not exist or is old this triggers the log to be opened
// or rotated. All entries are converted to JSON and stored on object per.
// line.
func (chatLog *ChatLog) Write() {
for i := range chatLog.logChannel {
chatLog.RotateIfNeeded()
jsonVal, _ := json.Marshal(i)
_, err := chatLog.logFile.WriteString(string(jsonVal) + "\n")
if err != nil {
log.Println("Error writing to file:", err)
}
chatLog.logFile.Sync()
}
}

// RotateIfNeeded checks if the current ChatLog struct is referencing the
// proper log file. If the reference is incorrect or doesn't exist then this
// function opens the proper log, and if necessary closes the old one.
func (chatLog *ChatLog) RotateIfNeeded() {
if chatLog.logFile == nil {
// Open file if not opened
chatLog.Open()
} else if chatLog.logFile.Name() != chatLog.GenerateFilename() {
// If the filename doesn't match where we should be writing
// close the old file and reopen with a new name.
chatLog.logFile.Close()
chatLog.Open()
}
}

// GenerateFilename returns a filename in the following format
// using the current timestamp:
// $LOGDIR/$PROTOCOL/\$SERVER/YYYY/MM/DD/HH.csl
func (chatLog *ChatLog) GenerateFilename() string {
return path.Join(
chatLog.logDir,
chatLog.Protocol,
chatLog.Server,
time.Now().UTC().Format("2006/01/02/15.csl"))
}


First up, as I understand it, you want to write to log files, but avoid constant IO operations. That's understandable. What I struggle to understand, however, is why you wouldn't use the standard golang packages to do buffered writes? the bufio package has a buffered writer that does just that.

Seeing as this is a code review site, allow me to first address some aspects of your code that could do with some more work. A quick overview of these things:

• Avoid using new(). It's more idiomatic, and flexible, to actually create a literal: new(ChatLog) => &ChatLog{}. This has the advantage of offering the visual reminder that it's a pointer (&), and allows you to initialze any exported fields.

This allows you to write the following:

cl := new(ChatLog)
cl.logDir = LogDir
cl.Protocol = Protocol
cl.Server = Server
cl.logChannel = make(chan map[string]string, MaxQueue)


As a oneliner:

cl := &ChatLog{
logDir: logDir,
Protocol: Protocol,
Server: Server,
logChannel: make(chan map[string]string, MaxQueue),
}


That, to my eye looks a lot cleaner.
A similar thing can be said about your example usage snippet. make is a construct you use to create buffered channels, slices with a pre-set length and/or capacity. If you don't need to do that, you might just as well use a literal:

testEntry := make(map[string]string)
testEntry["Type"] = "PRIVMSG"
testEntry["Entity"] = "SomeUser"
testEntry["Content"] = "This is the message!"


Can be written as:

testLog.AddEntry(
map[string]string{
"Type": "PRIVMSG",
"Entity": "SomeUser",
"Content": "This is the message!",
},
)


A lot cleaner, I'd say.

• "Errors are values, just like any other" is an adage you might have heard. This is true, but when you're doing something quite fundamental like logging, it's a really, really bad idea to ignore errors. If your logging component fails, I'd argue the best thing to do at that point is simply to call it a day, and exit. It's a fatal error IMO.

This means, for example that in your Open function:

if err != nil {
log.Println("Error opening file:", logFilename)
}
chatLog.logFile = f


You're using the standard log package to simply print out a line saying you couldn't open the log file, and then you happily go and assign what can only be a nil pointer to chatLog.logFile. The first time you try and log something, you'll get a runtime panic because you'll attempt to dereference a nil-pointer. What I'd do at that point is log the actual error value I received and call os.Exit(1) or something:

f, err := os.OpenFile(logFilename, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0644)
if err != nil {
log.Println("Failed to open logfile %v - %v", logFilename, err)
os.Exit(1)
}
chatLog.logFile = f


Some other things to consider (quite urgently)

• Your code is not thread-safe. You're exporting both RotateIfNeeded and Write. Neither of these functions actually lock. I can see why, but what could happen if, when someone calls the RotateIfNeeded function, which then decides to open a new log, and in that time your Write function reaches the chatLog.logFile.Sync call? You close the logFile before you open a new one. These operations aren't atomic, not by a long shot, and you've got no means of locking. This is a very risky thing to do.
• For every message you read from the channel, you're currently comparing the file name to a on-the-spot generated name. Wouldn't it be so much easier to move the occasional checking of the file to a routine instead? Just have it generate a new name every Nms, compare and if needed, acquire a lock on the os.File pointer, rotate the log file, and release? Whilst doing that, you'd only need to lock and release the a mutex every time you actually write a message to the log, instead of comparing file names. This has the added benefit that, owing to using a mutex, resolves to a large extent the concurrency problems mentioned earlier.
• The risk of using channels for logging: You're using channels to write to a log, instead of writing to a log directly. This clearly suggests the use of routines. Given this, you have to understand that you stand to loose a great deal of logs should your main func return before you've worked through the entire set of messages on the channel. What would happen in that case? You're losing information you were trying to log. Plain and simple. This is unacceptable.
• Reinventing the wheel: Logging is something that can be implemented cheaply, and without requiring the use of a mutex, or essentially re-implementing a mature tool like logrotate. Why not write your logs to stdout or stderr, and pipe those streams to a log, that is managed by logrotate for you? KISS
• Elias, thank you for your well thought out and exhaustive analysis. I've taken your suggestions to heart and made the appropriate adjustments. Without boring you with the details I'm not trying to reinvent the wheel with application logging. The use case isn't directly apparent from the example, but structure and later processing of the logs to me doesn't seem like a good candidate to just dump to stdout. In the event of an application crash losing logs in memory is acceptable. As far as main(), that will be blocked awaiting user interaction that will confirm before exit. Thanks again! – Caesar Kabalan Apr 13 '17 at 4:19