Merge pull request #8 from getwtxt/multiple-logfiles

Using separate log files for requests and other messages

7 files changed, 46 insertions, 58 deletions

diff --git a/.gitignore b/.gitignore
index 4c5d984..90b4945 100644
--- a/.gitignore
+++ b/.gitignore
@@ -1,5 +1,6 @@
 getwtxt
 *.log
+logs/
 local/
 *.db/
 *.db
diff --git a/getwtxt.yml b/getwtxt.yml
index d9f5c90..0e0969f 100644
--- a/getwtxt.yml
+++ b/getwtxt.yml
@@ -64,9 +64,11 @@ AssetsDirectory: "assets"
 # logs.
 StdoutLogging: false
 
-# The file getwtxt will append log messages to. Can be a
-# relative or absolute path.
-LogFile: "getwtxt.log"
+# Log files getwtxt will use. Requests will be logged
+# to RequestLog, while everything else will go into
+# MessageLog. These can be relative or absolute paths.
+MessageLog: "logs/message.log"
+RequestLog: "logs/request.log"
 
 # This is the interval between data pushes from the 
 # in-memory cache to the on-disk database. 
diff --git a/svc/cache.go b/svc/cache.go
index d3ac872..7bad078 100644
--- a/svc/cache.go
+++ b/svc/cache.go
@@ -41,10 +41,8 @@ type staticAssets struct {
 // file's "Instance" section.
 func initTemplates() *template.Template {
 	confObj.Mu.RLock()
-	assetsDir := confObj.AssetsDir
-	confObj.Mu.RUnlock()
-
-	return template.Must(template.ParseFiles(assetsDir + "/tmpl/index.html"))
+	defer confObj.Mu.RUnlock()
+	return template.Must(template.ParseFiles(confObj.AssetsDir + "/tmpl/index.html"))
 }
 
 func cacheUpdate() {
@@ -73,44 +71,31 @@ func cacheUpdate() {
 // pulled back into memory from disk.
 func pingAssets() {
 	confObj.Mu.RLock()
-	assetsDir := confObj.AssetsDir
-	confObj.Mu.RUnlock()
+	defer confObj.Mu.RUnlock()
+	staticCache.mu.Lock()
+	defer staticCache.mu.Unlock()
 
-	cssStat, err := os.Stat(assetsDir + "/style.css")
+	cssStat, err := os.Stat(confObj.AssetsDir + "/style.css")
 	errLog("", err)
-
-	indexStat, err := os.Stat(assetsDir + "/tmpl/index.html")
+	indexStat, err := os.Stat(confObj.AssetsDir + "/tmpl/index.html")
 	errLog("", err)
 
-	staticCache.mu.RLock()
-	indexMod := staticCache.indexMod
-	cssMod := staticCache.cssMod
-	staticCache.mu.RUnlock()
-
-	if !indexMod.Equal(indexStat.ModTime()) {
+	if !staticCache.indexMod.Equal(indexStat.ModTime()) {
 		tmpls = initTemplates()
 
 		var b []byte
 		buf := bytes.NewBuffer(b)
-
-		confObj.Mu.RLock()
 		errLog("", tmpls.ExecuteTemplate(buf, "index.html", confObj.Instance))
-		confObj.Mu.RUnlock()
 
-		staticCache.mu.Lock()
 		staticCache.index = buf.Bytes()
 		staticCache.indexMod = indexStat.ModTime()
-		staticCache.mu.Unlock()
 	}
 
-	if !cssMod.Equal(cssStat.ModTime()) {
-
-		css, err := ioutil.ReadFile(assetsDir + "/style.css")
+	if !staticCache.cssMod.Equal(cssStat.ModTime()) {
+		css, err := ioutil.ReadFile(confObj.AssetsDir + "/style.css")
 		errLog("", err)
 
-		staticCache.mu.Lock()
 		staticCache.css = css
 		staticCache.cssMod = cssStat.ModTime()
-		staticCache.mu.Unlock()
 	}
 }
diff --git a/svc/conf.go b/svc/conf.go
index 538b701..c1b9abb 100644
--- a/svc/conf.go
+++ b/svc/conf.go
@@ -11,13 +11,16 @@ import (
 	"github.com/spf13/viper"
 )
 
+var reqLog *log.Logger
+
 // Configuration values are held in an instance of
 // this struct.
 type Configuration struct {
 	Mu            sync.RWMutex
 	IsProxied     bool          `yaml:"BehindProxy"`
 	Port          int           `yaml:"ListenPort"`
-	LogFile       string        `yaml:"LogFile"`
+	MsgLog        string        `yaml:"MessageLog"`
+	ReqLog        string        `yaml:"RequestLog"`
 	DBType        string        `yaml:"DatabaseType"`
 	DBPath        string        `yaml:"DatabasePath"`
 	AssetsDir     string        `yaml:"-"`
@@ -68,28 +71,34 @@ func initConfig() {
 }
 
 // Registers either stdout or a specified file
-// to the default logger.
+// to the default logger, and the same for the
+// request logger.
 func initLogging() {
 
 	confObj.Mu.RLock()
 	if confObj.StdoutLogging {
 		log.SetOutput(os.Stdout)
+		reqLog = log.New(os.Stdout, "", log.LstdFlags)
 
 	} else {
-		logfile, err := os.OpenFile(confObj.LogFile, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0600)
+		msgLog, err := os.OpenFile(confObj.MsgLog, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0600)
+		errLog("Could not open log file: ", err)
+		reqLogFile, err := os.OpenFile(confObj.ReqLog, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0600)
 		errLog("Could not open log file: ", err)
 
 		// Listen for the signal to close the log file
 		// in a separate thread. Passing it as an argument
 		// to prevent race conditions when the config is
 		// reloaded.
-		go func(logfile *os.File) {
+		go func(msg *os.File, req *os.File) {
 			<-closeLog
-			log.Printf("Closing log file ...\n\n")
-			errLog("Could not close log file: ", logfile.Close())
-		}(logfile)
+			log.Printf("Closing log files ...\n\n")
+			errLog("Could not close log file: ", msg.Close())
+			errLog("Could not close log file: ", req.Close())
+		}(msgLog, reqLogFile)
 
-		log.SetOutput(logfile)
+		log.SetOutput(msgLog)
+		reqLog = log.New(reqLogFile, "", log.LstdFlags)
 	}
 	confObj.Mu.RUnlock()
 }
@@ -102,7 +111,8 @@ func setConfigDefaults() {
 	viper.SetDefault("TLSCert", "cert.pem")
 	viper.SetDefault("TLSKey", "key.pem")
 	viper.SetDefault("ListenPort", 9001)
-	viper.SetDefault("LogFile", "getwtxt.log")
+	viper.SetDefault("MessageLog", "logs/message.log")
+	viper.SetDefault("RequestLog", "logs/request.log")
 	viper.SetDefault("DatabasePath", "getwtxt.db")
 	viper.SetDefault("AssetsDirectory", "assets")
 	viper.SetDefault("DatabaseType", "leveldb")
@@ -148,7 +158,8 @@ func bindConfig() {
 
 	confObj.IsProxied = viper.GetBool("BehindProxy")
 	confObj.Port = viper.GetInt("ListenPort")
-	confObj.LogFile = viper.GetString("LogFile")
+	confObj.MsgLog = viper.GetString("MessageLog")
+	confObj.ReqLog = viper.GetString("RequestLog")
 	confObj.DBType = strings.ToLower(viper.GetString("DatabaseType"))
 	confObj.DBPath = viper.GetString("DatabasePath")
 	confObj.AssetsDir = viper.GetString("AssetsDirectory")
@@ -199,7 +210,8 @@ func announceConfig() {
 	if confObj.StdoutLogging {
 		log.Printf("Logging to: stdout\n")
 	} else {
-		log.Printf("Logging to: %v\n", confObj.LogFile)
+		log.Printf("Logging messages to: %v\n", confObj.MsgLog)
+		log.Printf("Logging requests to: %v\n", confObj.ReqLog)
 	}
 	log.Printf("Using %v database: %v\n", confObj.DBType, confObj.DBPath)
 	log.Printf("Database push interval: %v\n", confObj.DBInterval)
diff --git a/svc/handlers.go b/svc/handlers.go
index def01ad..924b487 100644
--- a/svc/handlers.go
+++ b/svc/handlers.go
@@ -42,12 +42,10 @@ func servStatic(w http.ResponseWriter, isCSS bool) error {
 // handles "/" and "/css"
 func staticHandler(w http.ResponseWriter, r *http.Request) {
 	isCSS := strings.Contains(r.URL.Path, "css")
-
 	if err := servStatic(w, isCSS); err != nil {
 		errHTTP(w, r, err, http.StatusInternalServerError)
 		return
 	}
-
 	log200(r)
 }
 
@@ -69,17 +67,15 @@ func apiAllTweetsHandler(w http.ResponseWriter, r *http.Request) {
 	}
 
 	data := parseQueryOut(out)
-
 	etag := fmt.Sprintf("%x", sha256.Sum256(data))
+
 	w.Header().Set("ETag", etag)
 	w.Header().Set("Content-Type", txtutf8)
-
 	_, err = w.Write(data)
 	if err != nil {
 		errHTTP(w, r, err, http.StatusInternalServerError)
 		return
 	}
-
 	log200(r)
 }
 
@@ -134,8 +130,8 @@ func apiEndpointHandler(w http.ResponseWriter, r *http.Request) {
 	errLog("", err)
 
 	data := parseQueryOut(out)
-
 	etag := fmt.Sprintf("%x", sha256.Sum256(data))
+
 	w.Header().Set("ETag", etag)
 	w.Header().Set("Content-Type", txtutf8)
 
@@ -162,8 +158,8 @@ func apiTagsBaseHandler(w http.ResponseWriter, r *http.Request) {
 
 	out = registry.ReduceToPage(1, out)
 	data := parseQueryOut(out)
-
 	etag := fmt.Sprintf("%x", sha256.Sum256(data))
+
 	w.Header().Set("ETag", etag)
 	w.Header().Set("Content-Type", txtutf8)
 
@@ -172,7 +168,6 @@ func apiTagsBaseHandler(w http.ResponseWriter, r *http.Request) {
 		errHTTP(w, r, err, http.StatusInternalServerError)
 		return
 	}
-
 	log200(r)
 }
 
@@ -184,8 +179,8 @@ func apiTagsHandler(w http.ResponseWriter, r *http.Request) {
 	out := compositeStatusQuery("#"+tags, r)
 	out = registry.ReduceToPage(1, out)
 	data := parseQueryOut(out)
-
 	etag := fmt.Sprintf("%x", sha256.Sum256(data))
+
 	w.Header().Set("ETag", etag)
 	w.Header().Set("Content-Type", txtutf8)
 
@@ -194,6 +189,5 @@ func apiTagsHandler(w http.ResponseWriter, r *http.Request) {
 		errHTTP(w, r, err, http.StatusInternalServerError)
 		return
 	}
-
 	log200(r)
 }
diff --git a/svc/http.go b/svc/http.go
index d39ab4e..95cb613 100644
--- a/svc/http.go
+++ b/svc/http.go
@@ -62,12 +62,12 @@ func ipMiddleware(hop http.Handler) http.Handler {
 func log200(r *http.Request) {
 	useragent := r.Header["User-Agent"]
 	uip := getIPFromCtx(r.Context())
-	log.Printf("*** %v :: 200 :: %v %v :: %v\n", uip, r.Method, r.URL, useragent)
+	reqLog.Printf("*** %v :: 200 :: %v %v :: %v\n", uip, r.Method, r.URL, useragent)
 }
 
 func errHTTP(w http.ResponseWriter, r *http.Request, err error, code int) {
 	useragent := r.Header["User-Agent"]
 	uip := getIPFromCtx(r.Context())
-	log.Printf("*** %v :: %v :: %v %v :: %v :: %v\n", uip, code, r.Method, r.URL, useragent, err.Error())
+	reqLog.Printf("*** %v :: %v :: %v %v :: %v :: %v\n", uip, code, r.Method, r.URL, useragent, err.Error())
 	http.Error(w, fmt.Sprintf("Error %v: %v", code, err.Error()), code)
 }
diff --git a/svc/init_test.go b/svc/init_test.go
index 0c417b4..314d5f4 100644
--- a/svc/init_test.go
+++ b/svc/init_test.go
@@ -18,7 +18,6 @@ var (
 	testport     string
 	initTestOnce sync.Once
 	initDBOnce   sync.Once
-	initPersOnce sync.Once
 )
 
 func initTestConf() {
@@ -41,18 +40,13 @@ func initTestDB() {
 	})
 }
 
-func initTestPers() {
-	initPersOnce.Do(func() {
-		initPersistence()
-	})
-}
-
 func logToNull() {
 	hush, err := os.Open("/dev/null")
 	if err != nil {
 		log.Printf("%v\n", err)
 	}
 	log.SetOutput(hush)
+	reqLog = log.New(hush, "", log.LstdFlags)
 }
 
 func testConfig() {