Improved logging

src/fs/auth.go

@@ -37,25 +37,31 @@ func (service *MercuryFsService) authenticate(writer http.ResponseWriter, reques
 	err := decoder.Decode(&data)
 	if err != nil {
 		writer.WriteHeader(http.StatusBadRequest)
+		logHttp(service, request, http.StatusBadRequest, 0)
 		return
 	}
 	// read pin from the json body
 	pin, ok := data["pin"].(string)
 	if !ok {
 		// pin is not a string, send 400 Bad Request
 		writer.WriteHeader(http.StatusBadRequest)
+		logHttp(service, request, http.StatusBadRequest, 0)
 		return
 	}
 	// query user for the given pin from the list of all users
 	authToken, err := service.Users.queryUser(pin)
 	switch {
 	case err == sql.ErrNoRows: // if no such user exits, send 401 Unauthorized
-		log("No user with pin: %s", pin)
-		http.Error(writer, "Authentication Failed", http.StatusUnauthorized)
+		logInfo("No user with pin: %s", pin)
+		errMsg := "Authentication Failed"
+		http.Error(writer, errMsg, http.StatusUnauthorized)
+		logHttp(service, request, http.StatusUnauthorized, len(errMsg))
 		break
 	case err != nil: // if some other error, send 500 Internal Server Error
-		http.Error(writer, "Internal Server Error", http.StatusInternalServerError)
-		log(err.Error())
+		logError(err.Error())
+		errMsg := "Internal Server Error"
+		http.Error(writer, errMsg, http.StatusInternalServerError)
+		logHttp(service, request, http.StatusInternalServerError, len(errMsg))
 		break
 	default: // if no error, send proper auth token for that user
 		respJson := fmt.Sprintf("{\"auth_token\": \"%s\"}", *authToken)
@@ -64,23 +70,27 @@ func (service *MercuryFsService) authenticate(writer http.ResponseWriter, reques
 		writer.Header().Set("Content-Length", strconv.FormatInt(size, 10))
 		writer.Header().Set("Content-Type", "application/json")
 		writer.Write([]byte(respJson))
+		logHttp(service, request, http.StatusOK, int(size))
 	}
 }
 
-func (service *MercuryFsService) logout(w http.ResponseWriter, r *http.Request) {
-	authToken := parseAuthToken(r)
+func (service *MercuryFsService) logout(writer http.ResponseWriter, request *http.Request) {
+	authToken := parseAuthToken(request)
 	service.Users.remove(authToken)
-	w.WriteHeader(http.StatusOK)
+	writer.WriteHeader(http.StatusOK)
+	logHttp(service, request, http.StatusOK, 0)
 }
 
 func (service *MercuryFsService) checkAuthHeader(w http.ResponseWriter, r *http.Request) (user *HdaUser) {
 	authToken := parseAuthToken(r)
 	user = service.Users.find(authToken)
 	// if user is nil, respond with 401 Unauthorized
 	if user == nil {
-		http.Error(w, "Authentication Failed", http.StatusUnauthorized)
+		errMsg := "Authentication Failed"
+		http.Error(w, errMsg, http.StatusUnauthorized)
+		logHttp(service, r, http.StatusUnauthorized, len(errMsg))
 	}
-	return
+	return user
 }
 
 func (service *MercuryFsService) authMiddleware(pass http.HandlerFunc) http.HandlerFunc {
@@ -115,9 +125,13 @@ func (service *MercuryFsService) shareReadAccess(pass http.HandlerFunc) http.Han
 			shareName := r.URL.Query().Get("s")
 			if access, err := user.HasReadAccess(shareName); !access {
 				if err == nil {
-					http.Error(w, "Access Forbidden", http.StatusForbidden)
+					errMsg := "Access Forbidden"
+					http.Error(w, errMsg, http.StatusForbidden)
+					logHttp(service, r, http.StatusForbidden, len(errMsg))
 				} else {
-					http.Error(w, "Internal Server Error", http.StatusInternalServerError)
+					errMsg := "Internal Server Error"
+					http.Error(w, errMsg, http.StatusInternalServerError)
+					logHttp(service, r, http.StatusInternalServerError, len(errMsg))
 				}
 				return
 			}
@@ -133,7 +147,9 @@ func (service *MercuryFsService) restrictCache(pass http.HandlerFunc) http.Handl
 		fullPath, _ := service.fullPathToFile(share, path)
 
 		if strings.Contains(fullPath, ".fscache") {
-			http.Error(w, "Cannot access cache via /files", http.StatusForbidden)
+			errMsg := "Cannot access cache via /files"
+			http.Error(w, errMsg, http.StatusForbidden)
+			logHttp(service, r, http.StatusForbidden, len(errMsg))
 			return
 		}
 
@@ -158,9 +174,13 @@ func (service *MercuryFsService) shareWriteAccess(pass http.HandlerFunc) http.Ha
 			shareName := r.URL.Query().Get("s")
 			if access, err := user.HasWriteAccess(shareName); !access {
 				if err == nil {
-					http.Error(w, "Access Forbidden", http.StatusForbidden)
+					errMsg := "Access Forbidden"
+					http.Error(w, errMsg, http.StatusForbidden)
+					logHttp(service, r, http.StatusForbidden, len(errMsg))
 				} else {
-					http.Error(w, "Internal Server Error", http.StatusInternalServerError)
+					errMsg := "Internal Server Error"
+					http.Error(w, errMsg, http.StatusInternalServerError)
+					logHttp(service, r, http.StatusForbidden, len(errMsg))
 				}
 				return
 			}

src/fs/cache.go

@@ -1,7 +1,6 @@
 package main
 
 import (
-	"fmt"
 	"github.com/disintegration/imaging"
 	"os"
 	"path/filepath"
@@ -11,7 +10,7 @@ import (
 func thumbnailer(imagePath string, savePath string) error {
 	img, err := imaging.Open(imagePath)
 	if err != nil {
-		log(`Error opening file at location: "%s" as image. Error is: "%s"`, imagePath, err.Error())
+		logError(`Error opening file at location: "%s" as image. Error is: "%s"`, imagePath, err.Error())
 		return err
 	}
 	imgX := img.Bounds().Max.X
@@ -25,7 +24,7 @@ func thumbnailer(imagePath string, savePath string) error {
 	os.MkdirAll(filepath.Dir(savePath), os.ModePerm)
 	err = imaging.Save(thumb, savePath)
 	if err != nil {
-		log(`Error saving image thumbnail for file at location: "%s". Error is: "%s"`, imagePath, err.Error())
+		logError(`Error saving image thumbnail for file at location: "%s". Error is: "%s"`, imagePath, err.Error())
 		return err
 	}
 
@@ -40,7 +39,7 @@ func fillCache(root string) error {
 func fillCacheWalkFunc(path string, info os.FileInfo, err error) error {
 	defer func() {
 		if v := recover(); v != nil {
-			log(fmt.Sprintf("Panic while creating thumbnail: %s", v))
+			logError("Panic while creating thumbnail: %s", v)
 		}
 	}()
 
@@ -84,12 +83,12 @@ func removeCacheWalkFunc(path string, info os.FileInfo, err error) error {
 	if ! os.IsNotExist(err) {
 		err := os.Remove(thumbnailPath)
 		if err != nil {
-			log(`Error while deleting cache file. Error: "%s"`, err.Error())
+			logError(`Error while deleting cache file. Error: "%s"`, err.Error())
 		}
 	}
 	err = watcher.Remove(path)
 	if err != nil {
-		log(fmt.Sprintf("Error while removing file from watcher: %s", err))
+		logError("Error while removing file from watcher: %s", err)
 	}
 	return nil
 }

src/fs/file_utils.go

@@ -0,0 +1,25 @@
+package main
+
+import (
+	"errors"
+	"fmt"
+	"os/exec"
+)
+
+func Sed(offset, lines int) ([]byte, error) {
+	out, err := exec.Command("sed", "-n", fmt.Sprintf("%d,%dp", offset, offset+lines), LOGFILE).Output()
+	if err != nil {
+		logError(err.Error())
+		return nil, errors.New("cannot read from logs")
+	}
+	return out, nil
+}
+
+func Tail(lines int) ([]byte, error) {
+	out, err := exec.Command("tail", "-n", fmt.Sprintf("%d", lines), LOGFILE).Output()
+	if err != nil {
+		logError(err.Error())
+		return nil, errors.New("cannot read from logs")
+	}
+	return out, nil
+}

src/fs/fs.go

@@ -19,6 +19,7 @@ import (
 	"errors"
 	"flag"
 	"fmt"
+	log "github.com/Sirupsen/logrus"
 	"github.com/amahi/go-metadata"
 	"golang.org/x/net/http2"
 	"hda_api_key"
@@ -37,8 +38,8 @@ import (
 
 // DANGER DANGER DANGER
 // compile-time only options in case we need to disable checking the certs or https
-const DisableCertChecking = false
-const DisableHttps = false
+const DisableCertChecking = true
+const DisableHttps = true
 
 const VERSION = "2.2"
 
@@ -100,20 +101,23 @@ func main() {
 		flag.PrintDefaults()
 		return
 	}
-	debugLevel(dbg)
+
+	setLogLevel(log.Level(dbg))
 
 	if noDelete {
-		fmt.Printf("NOTICE: running without deleting content!\n")
+		fmt.Println("Running without deleting content!")
+		logWarn("Running without deleting content!")
 	}
 	if noUpload {
-		fmt.Printf("NOTICE: running without uploading content!\n")
+		fmt.Println("Running without uploading content!")
+		logWarn("Running without uploading content!")
 	}
 
 	initializeLogging()
 
-	metadata, err := metadata.Init(100000, METADATA_FILE, TMDB_API_KEY, TVRAGE_API_KEY, TVDB_API_KEY)
+	meta, err := metadata.Init(100000, METADATA_FILE, TMDB_API_KEY, TVRAGE_API_KEY, TVDB_API_KEY)
 	if err != nil {
-		fmt.Printf("Error initializing metadata library\n")
+		fmt.Println("Error initializing metadata library")
 		os.Remove(PID_FILE)
 		os.Exit(1)
 	}
@@ -125,17 +129,16 @@ func main() {
 		os.Exit(1)
 	}
 	// start ONE delayed, background metadata prefill of the cache
-	service.metadata = metadata
+	service.metadata = meta
 
-	go service.Shares.startMetadataPrefill(metadata)
+	go service.Shares.startMetadataPrefill(meta)
 
 	watcher, _ = fsnotify.NewWatcher()
 	defer watcher.Close()
 
 	go service.Shares.createThumbnailCache()
 
-	log("Amahi Anywhere service v%s", VERSION)
-
+	logInfo("Amahi Anywhere service v%s", VERSION)
 	debug(4, "using api-key %s", apiKey)
 
 	if http2Debug {
@@ -150,36 +153,33 @@ func main() {
 	for {
 		conn, err := contactPfe(relayHost, relayPort, apiKey, service)
 		if err != nil {
-			log("Error contacting the proxy.")
-			debug(2, "Error contacting the proxy: %s", err)
+			logError("Error contacting the proxy: %s", err)
 		} else {
 			err = service.StartServing(conn)
 			if err != nil {
-				log("Error serving requests")
-				debug(2, "Error in StartServing: %s", err)
+				logError("Error in StartServing: %s", err)
 			}
 		}
 		// reconnect fairly quickly, with some randomness
-		sleepTime := time.Duration(2000 + rand.Intn(2000))
+		sleepTime := time.Duration(20000 + rand.Intn(2000))
 		time.Sleep(sleepTime * time.Millisecond)
 	}
 	os.Remove(PID_FILE)
 }
 
 // connect to the proxy and send a POST request with the api-key
 func contactPfe(relayHost, relayPort, apiKey string, service *MercuryFsService) (net.Conn, error) {
-
 	relayLocation := relayHost + ":" + relayPort
-	log("Contacting Relay at: " + relayLocation)
+	logInfo("Contacting Relay at: " + relayLocation)
 	addr, err := net.ResolveTCPAddr("tcp", relayLocation)
 	if err != nil {
-		debug(2, "Error with ResolveTCPAddr: %s", err)
+		logError("Error with ResolveTCPAddr: %s", err)
 		return nil, err
 	}
 
 	tcpConn, err := net.DialTCP("tcp", nil, addr)
 	if err != nil {
-		debug(2, "Error with initial DialTCP: %s", err)
+		logError("Error with initial DialTCP: %s", err)
 		return nil, err
 	}
 
@@ -191,12 +191,13 @@ func contactPfe(relayHost, relayPort, apiKey string, service *MercuryFsService)
 
 	if DisableCertChecking {
 		warning := "WARNING WARNING WARNING: running without checking TLS certs!!"
-		log(warning)
-		log(warning)
-		log(warning)
+		logWarn(warning)
+		logWarn(warning)
+		logWarn(warning)
 		fmt.Println(warning)
 		fmt.Println(warning)
 		fmt.Println(warning)
+
 		service.TLSConfig = &tls.Config{InsecureSkipVerify: true}
 	}
 
@@ -211,13 +212,13 @@ func contactPfe(relayHost, relayPort, apiKey string, service *MercuryFsService)
 	request.Header.Add("Api-Key", apiKey)
 	request.Header.Add("Authorization", fmt.Sprintf("Token %s", SECRET_TOKEN))
 	rawRequest, _ := httputil.DumpRequest(request, true)
-	debug(5, "%s", rawRequest)
+	debug(5, "Raw API-key request: %s", rawRequest)
 
 	var client *httputil.ClientConn
 
 	if DisableHttps {
 		warning := "WARNING WARNING: running without TLS!!"
-		log(warning)
+		logWarn(warning)
 		fmt.Println(warning)
 		conn := tcpConn
 		client = httputil.NewClientConn(conn, nil)
@@ -234,11 +235,11 @@ func contactPfe(relayHost, relayPort, apiKey string, service *MercuryFsService)
 
 	if response.StatusCode != 200 {
 		msg := fmt.Sprintf("Got an error response: %s", response.Status)
-		log(msg)
+		logInfo(msg)
 		return nil, errors.New(msg)
 	}
 
-	log("Connected to the proxy")
+	logInfo("Connected to the proxy")
 
 	netCon, _ := client.Hijack()
 
@@ -248,12 +249,14 @@ func contactPfe(relayHost, relayPort, apiKey string, service *MercuryFsService)
 // Clean up and quit
 func cleanQuit(exitCode int, message string) {
 	fmt.Println("FATAL:", message)
+	log.Println("FATAL:", message)
 	os.Exit(exitCode)
 }
 
 func panicHandler() {
 	if v := recover(); v != nil {
 		fmt.Println("PANIC:", v)
+		log.Println("PANIC:", v)
 	}
 	os.Remove(PID_FILE)
 }
@@ -266,7 +269,8 @@ func setup() error {
 	signal.Notify(c, os.Interrupt)
 	go func() {
 		for sig := range c {
-			log("Exiting with %v", sig)
+			fmt.Printf("Exiting with %v", sig)
+			log.Printf("Exiting with %v", sig)
 			os.Remove(PID_FILE)
 			os.Exit(1)
 		}
@@ -298,9 +302,9 @@ func checkPidFile() {
 		}
 	}
 	if stale {
-		fmt.Printf("PID file exists, but it's stale. Continuing.\n")
+		fmt.Println("PID file exists, but it's stale. Continuing.")
 	} else {
-		fmt.Printf("PID file exists and process is running. Exiting.\n")
+		fmt.Println("PID file exists and process is running. Exiting.")
 		os.Exit(1)
 	}
 }