From f649e20d24c7681a7f4f9c04fb72ae6942ec4056 Mon Sep 17 00:00:00 2001 From: Vishwas Mittal Date: Thu, 16 May 2019 02:25:17 +0530 Subject: [PATCH 1/9] [WIP]replaced usage of inbuilt logger with logrus --- src/fs/auth.go | 12 ++- src/fs/fs.go | 84 ++++++++++++----- src/fs/hda_apps.go | 9 +- src/fs/hda_shares.go | 26 ++++-- src/fs/hda_users.go | 28 ++++-- src/fs/local_server.go | 35 +++++-- src/fs/logging.go | 100 ++++++++++++++++---- src/fs/service.go | 201 +++++++++++++++++++++++++++-------------- 8 files changed, 358 insertions(+), 137 deletions(-) diff --git a/src/fs/auth.go b/src/fs/auth.go index dc4b85e..8785abe 100644 --- a/src/fs/auth.go +++ b/src/fs/auth.go @@ -1,10 +1,10 @@ package main import ( - "net/http" - "encoding/json" "database/sql" + "encoding/json" "fmt" + "net/http" "strconv" ) @@ -49,12 +49,16 @@ func (service *MercuryFsService) authenticate(writer http.ResponseWriter, reques 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) + //log("No user with pin: %s", pin) + //log2.Info(fmt.Sprintf("No user with pin: %s", pin)) + log_info("No user with pin: %s", pin) http.Error(writer, "Authentication Failed", http.StatusUnauthorized) break case err != nil: // if some other error, send 500 Internal Server Error http.Error(writer, "Internal Server Error", http.StatusInternalServerError) - log(err.Error()) + //log(err.Error()) + //log2.Info(err.Error()) + log_info(err.Error()) break default: // if no error, send proper auth token for that user respJson := fmt.Sprintf("{\"auth_token\": \"%s\"}", *authToken) diff --git a/src/fs/fs.go b/src/fs/fs.go index c85b4fd..08e39cb 100644 --- a/src/fs/fs.go +++ b/src/fs/fs.go @@ -17,7 +17,9 @@ import ( "errors" "flag" "fmt" + log2 "github.com/Sirupsen/logrus" "github.com/amahi/go-metadata" + "golang.org/x/net/http2" "hda_api_key" "io/ioutil" "math/rand" @@ -30,7 +32,6 @@ import ( "strconv" "strings" "time" - "golang.org/x/net/http2" ) // DANGER DANGER DANGER @@ -95,7 +96,10 @@ func main() { flag.PrintDefaults() return } - debugLevel(dbg) + + //debugLevel(dbg) + //log2.SetLevel(log2.Level(dbg)) + setLogLevel(log2.Level(dbg)) if noDelete { fmt.Printf("NOTICE: running without deleting content!\n") @@ -124,9 +128,13 @@ func main() { go service.Shares.startMetadataPrefill(metadata) - log("Amahi Anywhere service v%s", VERSION) + //log("Amahi Anywhere service v%s", VERSION) + //log2.Info(fmt.Sprintf("Amahi Anywhere Service v%s", VERSION)) + log_info("Amahi Anywhere service v%s", VERSION) - debug(4, "using api-key %s", apiKey) + //debug(4, "using api-key %s", apiKey) + //log2.Info(fmt.Sprintf("Using API-KEY %s", apiKey)) + log_info("using api-key %s", apiKey) if http2Debug { http2.VerboseLogs = true @@ -140,17 +148,22 @@ 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) + //debug(2, "Error contacting the proxy: %s", err) + //log2.Error(fmt.Sprintf("Error contacting the proxy: %s", err)) + log_error("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) + //log("Error serving requests") + //log2.Warn("Error serving requests") + log_warn("Error serving requests") + //debug(2, "Error in StartServing: %s", err) + //log2.Error(fmt.Sprintf("Error in StartServing: %s", err)) + log_error("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) @@ -160,16 +173,22 @@ func main() { func contactPfe(relayHost, relayPort, apiKey string, service *MercuryFsService) (net.Conn, error) { relayLocation := relayHost + ":" + relayPort - log("Contacting Relay at: " + relayLocation) + //log("Contacting Relay at: " + relayLocation) + //log2.Info("Contacting Relay at: " + relayLocation) + log_info("Contacting Relay at: " + relayLocation) addr, err := net.ResolveTCPAddr("tcp", relayLocation) if err != nil { - debug(2, "Error with ResolveTCPAddr: %s", err) + //debug(2, "Error with ResolveTCPAddr: %s", err) + //log2.Error(fmt.Sprintf("Error with ResolveTCPAddr: %s", err)) + log_error("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) + //debug(2, "Error with initial DialTCP: %s", err) + //log2.Error(fmt.Sprintf("Error with initial DialTCP: %s", err)) + log_error("Error with initial DialTCP: %s", err) return nil, err } @@ -181,12 +200,19 @@ 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) + //log(warning) + //log(warning) + //log(warning) + //log2.Warn(warning) + //log2.Warn(warning) + //log2.Warn(warning) + log_warn(warning) + log_warn(warning) + log_warn(warning) fmt.Println(warning) fmt.Println(warning) fmt.Println(warning) + service.TLSConfig = &tls.Config{InsecureSkipVerify: true} } @@ -194,20 +220,26 @@ func contactPfe(relayHost, relayPort, apiKey string, service *MercuryFsService) buf := strings.NewReader(service.info.to_json()) request, err := http.NewRequest("PUT", "https://"+relayLocation+"/fs", buf) if err != nil { - debug(2, "Error creating NewRequest:", err) + //debug(2, "Error creating NewRequest:", err) + //log2.Error(fmt.Sprintf("Error creating NewRequest:", err)) + log_error("Error creating NewRequest:", err) return nil, err } 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, "%s", rawRequest) + //log2.Debug(fmt.Sprintf("&s", rawRequest)) + log_debug("%s", rawRequest) var client *httputil.ClientConn if DisableHttps { warning := "WARNING WARNING: running without TLS!!" - log(warning) + //log(warning) + //log2.Warn(warning) + log_warn(warning) fmt.Println(warning) conn := tcpConn client = httputil.NewClientConn(conn, nil) @@ -218,17 +250,23 @@ func contactPfe(relayHost, relayPort, apiKey string, service *MercuryFsService) response, err := client.Do(request) if err != nil { - debug(2, "Error writing to connection with Do: %s", err) + //debug(2, "Error writing to connection with Do: %s", err) + //log2.Error(fmt.Sprintf("Error writing to connection with Do: %s", err)) + log_error("Error writing to connection with Do: %s", err) return nil, err } if response.StatusCode != 200 { msg := fmt.Sprintf("Got an error response: %s", response.Status) - log(msg) + //log(msg) + //log2.Info(msg) + log_info(msg) return nil, errors.New(msg) } - log("Connected to the proxy") + //log("Connected to the proxy") + //log2.Info("Connected to the proxy") + log_info("Connected to the proxy") netCon, _ := client.Hijack() @@ -256,7 +294,9 @@ func setup() error { signal.Notify(c, os.Interrupt) go func() { for sig := range c { - log("Exiting with %v", sig) + //log("Exiting with %v", sig) + //log2.Info(fmt.Sprintf("Exiting with %v", sig)) + log_info("Exiting with %v", sig) os.Remove(PID_FILE) os.Exit(1) } diff --git a/src/fs/hda_apps.go b/src/fs/hda_apps.go index 3d7cc1e..159b051 100644 --- a/src/fs/hda_apps.go +++ b/src/fs/hda_apps.go @@ -37,14 +37,19 @@ func newHdaApps() (*HdaApps, error) { func (apps *HdaApps) list() error { dbconn, err := sql.Open("mysql", MYSQL_CREDENTIALS) if err != nil { - log(err.Error()) + //log(err.Error()) + //TODO: to check with mentors about the debug level of these type of errors. Currently assigning INFO + //log2.Info(err.Error()) + log_info(err.Error()) return err } defer dbconn.Close() q := SQL_SELECT_APPS rows, err := dbconn.Query(q) if err != nil { - log(err.Error()) + //log(err.Error()) + //log2.Info(err.Error()) + log_info(err.Error()) return err } newApps := make([]*HdaApp, 0) diff --git a/src/fs/hda_shares.go b/src/fs/hda_shares.go index f7d1115..a6fb156 100644 --- a/src/fs/hda_shares.go +++ b/src/fs/hda_shares.go @@ -35,7 +35,7 @@ type HdaShares struct { Shares []*HdaShare LastChecked time.Time sync.RWMutex - rootDir string + rootDir string } func NewHdaShares(rootDir string) (*HdaShares, error) { @@ -57,22 +57,30 @@ func (shares *HdaShares) updateShares() error { func (shares *HdaShares) updateSqlShares() error { dbconn, err := sql.Open("mysql", MYSQL_CREDENTIALS) if err != nil { - log(err.Error()) + //log(err.Error()) + //log2.Info(err.Error()) + log_info(err.Error()) return err } defer dbconn.Close() q := SQL_SELECT_SHARES - debug(5, "share query: %s\n", q) + //debug(5, "share query: %s\n", q) + //log2.Debug(fmt.Sprintf("share query: %s\n", q)) + log_debug("share query: %s\n", q) rows, err := dbconn.Query(q) if err != nil { - log(err.Error()) + //log(err.Error()) + //log2.Info(err.Error()) + log_info(err.Error()) return err } newShares := make([]*HdaShare, 0) for rows.Next() { share := new(HdaShare) rows.Scan(&share.name, &share.updatedAt, &share.path, &share.tags) - debug(5, "share found: %s\n", share.name) + //debug(5, "share found: %s\n", share.name) + //log2.Debug(fmt.Sprintf("share found: %s\n", share.name)) + log_debug("share found: %s\n", share.name) newShares = append(newShares, share) } @@ -88,7 +96,9 @@ func (shares *HdaShares) updateDirShares() (nil error) { dir, err := os.Open(shares.rootDir) if err != nil { - log(err.Error()) + //log(err.Error()) + //log2.Info(err.Error()) + log_info(err.Error()) return err } defer dir.Close() @@ -183,7 +193,9 @@ func (shares *HdaShares) startMetadataPrefill(library *metadata.Library) { for i := range shares.Shares { path := shares.Shares[i].path tags := strings.ToLower(shares.Shares[i].tags) - debug(5, `checking share "%s" (%s) with tags: %s\n`, shares.Shares[i].name, path, tags) + //debug(5, `checking share "%s" (%s) with tags: %s\n`, shares.Shares[i].name, path, tags) + //log2.Debug(fmt.Sprintf(`checking share "%s" (%s) with tags: %s\n`, shares.Shares[i].name, path, tags)) + log_debug(`checking share "%s" (%s) with tags: %s\n`, shares.Shares[i].name, path, tags) if path == "" || tags == "" { continue } diff --git a/src/fs/hda_users.go b/src/fs/hda_users.go index f242e5f..78f33ea 100644 --- a/src/fs/hda_users.go +++ b/src/fs/hda_users.go @@ -1,11 +1,11 @@ package main import ( - "sync" + "crypto/rand" "database/sql" "fmt" + "sync" "time" - "crypto/rand" ) type HdaUser struct { @@ -44,7 +44,9 @@ func (users *HdaUsers) queryUser(pin string) (*string, error) { } else { dbconn, err := sql.Open("mysql", MYSQL_CREDENTIALS) if err != nil { - log(err.Error()) + //log(err.Error()) + //log2.Info(err.Error()) + log_info(err.Error()) return nil, err } defer dbconn.Close() @@ -109,7 +111,9 @@ func (users *HdaUsers) remove(authToken string) { func (users *HdaUsers) revalidateSession(authToken string, user *HdaUser) (isValid bool, err error) { dbconn, err := sql.Open("mysql", MYSQL_CREDENTIALS) if err != nil { - log(err.Error()) + //log(err.Error()) + //log2.Info(err.Error()) + log_info(err.Error()) return } defer dbconn.Close() @@ -130,7 +134,9 @@ func (users *HdaUsers) revalidateSession(authToken string, user *HdaUser) (isVal func (user *HdaUser) AvailableShares() ([]*HdaShare, error) { dbconn, err := sql.Open("mysql", MYSQL_CREDENTIALS) if err != nil { - log(err.Error()) + //log(err.Error()) + //log2.Info(err.Error()) + log_info(err.Error()) return nil, err } defer dbconn.Close() @@ -143,7 +149,9 @@ func (user *HdaUser) AvailableShares() ([]*HdaShare, error) { "WHERE u.id = ? AND s.visible = 1 ORDER BY s.name ASC;" rows, err := dbconn.Query(q, user.id) if err != nil { - log(err.Error()) + //log(err.Error()) + //log2.Info(err.Error()) + log_info(err.Error()) return nil, err } newShares := make([]*HdaShare, 0) @@ -161,7 +169,9 @@ func (user *HdaUser) HasReadAccess(shareName string) (access bool, err error) { } dbconn, err := sql.Open("mysql", MYSQL_CREDENTIALS) if err != nil { - log(err.Error()) + //log(err.Error()) + //log2.Info(err.Error()) + log_info(err.Error()) return } defer dbconn.Close() @@ -179,7 +189,9 @@ func (user *HdaUser) HasWriteAccess(shareName string) (access bool, err error) { } dbconn, err := sql.Open("mysql", MYSQL_CREDENTIALS) if err != nil { - log(err.Error()) + //log(err.Error()) + //log2.Info(err.Error()) + log_info(err.Error()) return } defer dbconn.Close() diff --git a/src/fs/local_server.go b/src/fs/local_server.go index 49dec6e..9e36f7b 100644 --- a/src/fs/local_server.go +++ b/src/fs/local_server.go @@ -19,26 +19,45 @@ func (service *MercuryFsService) startLocalServer() { addr, err := net.ResolveTCPAddr("tcp", ":"+LocalServerPort) if err != nil { - log("Could not resolve local address") - debug(2, "Error resolving local address: %s", err.Error()) + //log("Could not resolve local address") + //log2.Fatal("Could not resolve local address") + log_fatal("Could not resolve local address") + + //debug(2, "Error resolving local address: %s", err.Error()) + //log2.Error(fmt.Sprintf("Error resolving local address: %s", err.Error())) + log_debug("Error resolving local address: %s", err.Error()) return } listener, err := net.ListenTCP("tcp", addr) if err != nil { - log("Local server could not be started") - debug(2, "Error on ListenTCP: %s", err.Error()) + //log("Local server could not be started") + //log2.Fatal("Local server could not be started") + log_fatal("Local server could not be started") + + //debug(2, "Error on ListenTCP: %s", err.Error()) + //log2.Debug(fmt.Sprintf("Error on ListenTCP: %s", err.Error())) + log_debug("Error on ListenTCP: %s", err.Error()) return } defer listener.Close() for { - log("Starting local file server") - debug(2, "Starting local file server at: %s", LocalServerPort) + //log("Starting local file server") + //log2.Info("Starting local file server") + log_info("Starting local file server") + + //debug(2, "Starting local file server at: %s", LocalServerPort) + //log2.Debug(fmt.Sprintf("Starting local file server at: %s", LocalServerPort)) + log_info("Starting local file server at: %s", LocalServerPort) err = service.server.Serve(listener) if err != nil { - log("An error occurred in the local file server") - debug(2, "local file server: %s", err.Error()) + //log("An error occurred in the local file server") + //log2.Error("An error occurred in the local file server") + log_error("An error occurred in the local file server") + //debug(2, "local file server: %s", err.Error()) + //log2.Debug(fmt.Sprintf(2, "local file server: %s", err.Error())) + log_debug("local file server: %s", err.Error()) } } } diff --git a/src/fs/logging.go b/src/fs/logging.go index 0af7004..0ebee95 100644 --- a/src/fs/logging.go +++ b/src/fs/logging.go @@ -11,39 +11,103 @@ package main import ( "fmt" - logging "log" + log2 "github.com/Sirupsen/logrus" "os" ) const LOGFILE = "/var/log/amahi-anywhere.log" -var currentDebugLevel = 3 - -var logger *logging.Logger - func initializeLogging() { - logFile, err := os.OpenFile(LOGFILE, os.O_APPEND|os.O_CREATE|os.O_RDWR, 0644) + logFile, err := os.OpenFile(LOGFILE, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644) if err != nil { fmt.Println("WARNING: failed to open ", LOGFILE, " defaulting to standard output") logFile = os.Stdout } - logger = logging.New(logFile, "", logging.LstdFlags) + Formatter := new(log2.TextFormatter) + Formatter.TimestampFormat = "02-01-2006 15:04:05" + Formatter.FullTimestamp = true + //Formatter.DisableColors = true + log2.SetFormatter(Formatter) + log2.SetOutput(logFile) } -func log(f string, args ...interface{}) { - logger.Printf(f, args...) +func setLogLevel(level log2.Level) { + log2.SetLevel(level) } -func debugLevel(level int) { - currentDebugLevel = level +func getLogLevel() log2.Level { + return log2.GetLevel() } -func debug(level int, f string, args ...interface{}) { - if PRODUCTION { - return - } - if level <= currentDebugLevel { - log(f, args...) - } +func log_trace(f string, args ...interface{}) { + msg := fmt.Sprintf(f, args) + log2.Trace(msg) } + +func log_debug(f string, args ...interface{}) { + msg := fmt.Sprintf(f, args) + log2.Debug(msg) +} + +func log_info(f string, args ...interface{}) { + msg := fmt.Sprintf(f, args) + log2.Info(msg) +} + +func log_warn(f string, args ...interface{}) { + msg := fmt.Sprintf(f, args) + log2.Warn(msg) +} + +func log_error(f string, args ...interface{}) { + msg := fmt.Sprintf(f, args) + log2.Error(msg) +} + +func log_fatal(f string, args ...interface{}) { + msg := fmt.Sprintf(f, args) + log2.Fatal(msg) +} + +func log_panic(f string, args ...interface{}) { + msg := fmt.Sprintf(f, args) + log2.Panic(msg) +} + +// +//var logger *logging.Logger +// +//func initializeLogging() { +// logFile, err := os.OpenFile(LOGFILE, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644) +// if err != nil { +// fmt.Println("WARNING: failed to open ", LOGFILE, " defaulting to standard output") +// logFile = os.Stdout +// } +// +// Formatter := new(log2.TextFormatter) +// Formatter.TimestampFormat = "02-01-2006 15:04:05" +// Formatter.FullTimestamp = true +// //Formatter.DisableColors = true +// log2.SetFormatter(Formatter) +// log2.SetOutput(logFile) +// +// logger = logging.New(logFile, "", logging.LstdFlags) +//} +// +//func log(f string, args ...interface{}) { +// logger.Printf(f, args...) +//} +// +//func debugLevel(level int) { +// currentDebugLevel = level +//} +// +//func debug(level int, f string, args ...interface{}) { +// if PRODUCTION { +// return +// } +// if level <= currentDebugLevel { +// log(f, args...) +// } +//} diff --git a/src/fs/service.go b/src/fs/service.go index fffecb3..bd66e42 100644 --- a/src/fs/service.go +++ b/src/fs/service.go @@ -62,7 +62,8 @@ func NewMercuryFSService(rootDir, localAddr string, isDemo bool) (service *Mercu service.Users = NewHdaUsers(isDemo) service.Shares, err = NewHdaShares(rootDir) if err != nil { - debug(3, "Error making HdaShares: %s", err.Error()) + //debug(3, "Error making HdaShares: %s", err.Error()) + log_warn("Error making HdaShares: %s", err.Error()) return nil, err } service.debugInfo = new(debugInfo) @@ -94,7 +95,8 @@ func NewMercuryFSService(rootDir, localAddr string, isDemo bool) (service *Mercu actualAddr, err := GetLocalAddr(rootDir) if err != nil { - debug(2, "Error getting local address: %s", err.Error()) + //debug(2, "Error getting local address: %s", err.Error()) + log_error("Error getting local address: %s", err.Error()) return nil, err } service.info.local_addr = actualAddr + ":" + LocalServerPort @@ -102,8 +104,10 @@ func NewMercuryFSService(rootDir, localAddr string, isDemo bool) (service *Mercu // This will be set when the HDA connects to the proxy service.info.relay_addr = "" - debug(3, "Amahi FS Service started %s", SharesJson(service.Shares.Shares)) - debug(4, "HDA Info: %s", service.info.to_json()) + //debug(3, "Amahi FS Service started %s", SharesJson(service.Shares.Shares)) + log_warn("Amahi FS Service started %s", SharesJson(service.Shares.Shares)) + //debug(4, "HDA Info: %s", service.info.to_json()) + log_info("HDA Info: %s", service.info.to_json()) return service, err } @@ -152,11 +156,13 @@ func directory(fi os.FileInfo, js string, w http.ResponseWriter, request *http.R inm := request.Header.Get("If-None-Match") if inm == etag { size = 0 - debug(4, "If-None-Match match found for %s", etag) + //debug(4, "If-None-Match match found for %s", etag) + log_info("If-None-Match match found for %s", etag) w.WriteHeader(http.StatusNotModified) status = 304 } else { - debug(4, "If-None-Match (%s) match NOT found for Etag %s", inm, etag) + //debug(4, "If-None-Match (%s) match NOT found for Etag %s", inm, etag) + log_info("If-None-Match (%s) match NOT found for Etag %s", inm, etag) size = int64(len(json)) w.Header().Set("Content-Length", strconv.FormatInt(size, 10)) w.Header().Set("Last-Modified", fi.ModTime().UTC().Format(http.TimeFormat)) @@ -181,13 +187,13 @@ func (service *MercuryFsService) fullPathToFile(shareName, relativePath string) } path := share.GetPath() + relativePath - debug(3, "Full path: %s", path) return path, nil } // serve requests with the ServeConn function over HTTP/2, in goroutines, until we get some error func (service *MercuryFsService) StartServing(conn net.Conn) error { - log("Connection to the proxy established.") + //log("Connection to the proxy established.") + log_info("Connection to the proxy established.") service.info.relay_addr = conn.RemoteAddr().String() @@ -197,7 +203,8 @@ func (service *MercuryFsService) StartServing(conn net.Conn) error { // start serving over http2 on provided conn and block until connection is lost server2.ServeConn(conn, serveConnOpts) - log("Lost connection to the proxy.") + //log("Lost connection to the proxy.") + log_warn("Lost connection to the proxy.") service.info.relay_addr = "" return errors.New("connection is no longer readable") @@ -210,24 +217,30 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * ua := request.Header.Get("User-Agent") query := pathForLog(request.URL) - debug(2, "serve_file GET request") + //debug(2, "serveFile GET request") + log_trace("deleteFile DELETE request") + service.printRequest(request) fullPath, err := service.fullPathToFile(share, path) if err != nil { - debug(2, "File not found: %s", err) + //debug(2, "File not found: %s", err) + log_error("File not found: %s", err) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - log("\"GET %s\" 404 0 \"%s\"", query, ua) + //log("\"GET %s\" 404 0 \"%s\"", query, ua) + log_info("\"GET %s\" 404 0 \"%s\"", query, ua) return } osFile, err := os.Open(fullPath) if err != nil { - debug(2, "Error opening file: %s", err.Error()) + //debug(2, "Error opening file: %s", err.Error()) + log_error("Error opening file: %s", err.Error()) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - log("\"GET %s\" 404 0 \"%s\"", query, ua) + //log("\"GET %s\" 404 0 \"%s\"", query, ua) + log_info("\"GET %s\" 404 0 \"%s\"", query, ua) return } defer osFile.Close() @@ -239,16 +252,18 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * if fi.IsDir() || isSymlinkDir(fi, fullPath) { jsonDir, err := dirToJSON(osFile, fullPath) if err != nil { - debug(2, "Error converting dir to JSON: %s", err.Error()) - log("\"GET %s\" 404 0 \"%s\"", query, ua) + //debug(2, "Error converting dir to JSON: %s", err.Error()) + log_error("Error converting dir to JSON: %s", err.Error()) + //log("\"GET %s\" 404 0 \"%s\"", query, ua) + log_info("\"GET %s\" 404 0 \"%s\"", query, ua) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) return } - debug(5, "%s", jsonDir) status, size := directory(fi, jsonDir, writer, request) service.debugInfo.requestServed(size) - log("\"GET %s\" %d %d \"%s\"", query, status, size, ua) + //log("\"GET %s\" %d %d \"%s\"", query, status, size, ua) + log_info("\"GET %s\" %d %d \"%s\"", query, status, size, ua) return } @@ -257,16 +272,20 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * etag := `"` + sha1string(path+mtime) + `"` inm := request.Header.Get("If-None-Match") if inm == etag { - debug(4, "If-None-Match match found for %s", etag) + //debug(4, "If-None-Match match found for %s", etag) + log_info("If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) - log("\"GET %s\" %d \"%s\"", query, 304, ua) + //log("\"GET %s\" %d \"%s\"", query, 304, ua) + log_info("\"GET %s\" %d \"%s\"", query, 304, ua) } else { writer.Header().Set("Last-Modified", mtime) writer.Header().Set("ETag", etag) writer.Header().Set("Cache-Control", "max-age=0, private, must-revalidate") - debug(4, "Etag sent: %s", etag) + //debug(4, "Etag sent: %s", etag) + log_info("Etag sent: %s", etag) http.ServeContent(writer, request, fullPath, fi.ModTime(), osFile) - log("\"GET %s\" %d %d \"%s\"", query, 200, fi.Size(), ua) + //log("\"GET %s\" %d %d \"%s\"", query, 200, fi.Size(), ua) + log_info("\"GET %s\" %d %d \"%s\"", query, 200, fi.Size(), ua) service.debugInfo.requestServed(fi.Size()) } @@ -292,17 +311,21 @@ func (service *MercuryFsService) serveShares(writer http.ResponseWriter, request service.Shares.updateShares() shares = service.Shares.Shares } - debug(5, "========= DEBUG Share request: %d", len(shares)) + //debug(5, "========= DEBUG Share request: %d", len(shares)) + log_debug("========= DEBUG Share request: %d", len(shares)) json := SharesJson(shares) - debug(5, "Share JSON: %s", json) + //debug(5, "Share JSON: %s", json) + log_debug("Share JSON: %s", json) etag := `"` + sha1bytes([]byte(json)) + `"` inm := request.Header.Get("If-None-Match") if inm == etag { - debug(4, "If-None-Match match found for %s", etag) + //debug(4, "If-None-Match match found for %s", etag) + log_info("If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) service.debugInfo.requestServed(int64(0)) } else { - debug(4, "If-None-Match (%s) match NOT found for Etag %s", inm, etag) + //debug(4, "If-None-Match (%s) match NOT found for Etag %s", inm, etag) + log_info("If-None-Match (%s) match NOT found for Etag %s", inm, etag) size := int64(len(json)) writer.Header().Set("Content-Length", strconv.FormatInt(size, 10)) writer.Header().Set("Last-Modified", time.Now().Format(http.TimeFormat)) @@ -323,7 +346,8 @@ func GetLocalAddr(rootDir string) (string, error) { dbconn, err := sql.Open("mysql", MYSQL_CREDENTIALS) if err != nil { - log(err.Error()) + //log(err.Error()) + log_info(err.Error()) return "", err } defer dbconn.Close() @@ -333,17 +357,21 @@ func GetLocalAddr(rootDir string) (string, error) { row := dbconn.QueryRow(q, "net") err = row.Scan(&prefix) if err != nil { - log(err.Error()) + //log(err.Error()) + log_info(err.Error()) return "", err } row = dbconn.QueryRow(q, "self-address") err = row.Scan(&addr) if err != nil { - log("Error scanning self-address: %s\n", err.Error()) + //log("Error scanning self-address: %s\n", err.Error()) + log_error("Error scanning self-address: %s\n", err.Error()) return "", err } - debug(4, "prefix: %s\taddr: %s", prefix, addr) + //debug(4, "prefix: %s\taddr: %s", prefix, addr) + log_info("prefix: %s\taddr: %s", prefix, addr) + return prefix + "." + addr, nil } @@ -406,17 +434,21 @@ func (service *MercuryFsService) appsList(writer http.ResponseWriter, request *h } service.Apps = apps service.Apps.list() - debug(5, "========= DEBUG apps_list request: %d", len(service.Shares.Shares)) + //debug(5, "========= DEBUG apps_list request: %d", len(service.Shares.Shares)) + log_debug("========= DEBUG apps_list request: %d", len(service.Shares.Shares)) json := service.Apps.toJson() - debug(5, "App JSON: %s", json) + //debug(5, "App JSON: %s", json) + log_debug("App JSON: %s", json) etag := `"` + sha1bytes([]byte(json)) + `"` inm := request.Header.Get("If-None-Match") if inm == etag { - debug(4, "If-None-Match match found for %s", etag) + //debug(4, "If-None-Match match found for %s", etag) + log_info("If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) service.debugInfo.requestServed(int64(0)) } else { - debug(4, "If-None-Match (%s) match NOT found for Etag %s", inm, etag) + //debug(4, "If-None-Match (%s) match NOT found for Etag %s", inm, etag) + log_info("If-None-Match (%s) match NOT found for Etag %s", inm, etag) size := int64(len(json)) writer.Header().Set("Content-Length", strconv.FormatInt(size, 10)) writer.Header().Set("ETag", etag) @@ -433,35 +465,44 @@ func (service *MercuryFsService) getMetadata(writer http.ResponseWriter, request q := request.URL filename, err := url.QueryUnescape(q.Query().Get("f")) if err != nil { - debug(3, "get_metadata error parsing file: %s", err) + //debug(3, "get_metadata error parsing file: %s", err) + log_warn("get_metadata error parsing file: %s", err) http.NotFound(writer, request) return } hint, err := url.QueryUnescape(q.Query().Get("h")) if err != nil { - debug(3, "get_metadata error parsing hint: %s", err) + //debug(3, "get_metadata error parsing hint: %s", err) + log_warn("get_metadata error parsing hint: %s", err) http.NotFound(writer, request) return } - debug(5, "metadata filename: %s", filename) - debug(5, "metadata hint: %s", hint) + //debug(5, "metadata filename: %s", filename) + log_debug("metadata filename: %s", filename) + //debug(5, "metadata hint: %s", hint) + log_debug("metadata hint: %s", hint) // FIXME json, err := service.metadata.GetMetadata(filename, hint) if err != nil { - debug(3, "metadata error: %s", err) + //debug(3, "metadata error: %s", err) + log_warn("metadata error: %s", err) http.NotFound(writer, request) return } - debug(5, "========= DEBUG get_metadata request: %d", len(service.Shares.Shares)) - debug(5, "metadata JSON: %s", json) + //debug(5, "========= DEBUG get_metadata request: %d", len(service.Shares.Shares)) + log_debug("========= DEBUG get_metadata request: %d", len(service.Shares.Shares)) + //debug(5, "metadata JSON: %s", json) + log_debug("metadata JSON: %s", json) etag := `"` + sha1bytes([]byte(json)) + `"` inm := request.Header.Get("If-None-Match") if inm == etag { - debug(4, "If-None-Match match found for %s", etag) + //debug(4, "If-None-Match match found for %s", etag) + log_info("If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) service.debugInfo.requestServed(int64(0)) } else { - debug(4, "If-None-Match (%s) match NOT found for Etag %s", inm, etag) + //debug(4, "If-None-Match (%s) match NOT found for Etag %s", inm, etag) + log_info("If-None-Match (%s) match NOT found for Etag %s", inm, etag) size := int64(len(json)) writer.Header().Set("Content-Length", strconv.FormatInt(size, 10)) writer.Header().Set("ETag", etag) @@ -474,14 +515,18 @@ func (service *MercuryFsService) getMetadata(writer http.ResponseWriter, request } func (service *MercuryFsService) printRequest(request *http.Request) { - debug(5, "REQUEST [from %s] BEGIN =========================", request.RemoteAddr) + //debug(5, "REQUEST [from %s] BEGIN =========================", request.RemoteAddr) + log_debug("REQUEST [from %s] BEGIN =========================", request.RemoteAddr) if request.Method != "POST" { rawRequest, _ := httputil.DumpRequest(request, true) - debug(5, "%s", rawRequest) + //debug(5, "%s", rawRequest) + log_debug("%s", rawRequest) } else { - debug(5, "POST Request to %s (details removed)", request.URL) + //debug(5, "POST Request to %s (details removed)", request.URL) + log_debug("POST Request to %s (details removed)", request.URL) } - debug(5, "REQUEST END =========================") + //debug(5, "REQUEST END =========================") + log_debug("REQUEST END =========================") } func (service *MercuryFsService) topVhostFilter(writer http.ResponseWriter, request *http.Request) { @@ -501,7 +546,8 @@ func (service *MercuryFsService) topVhostFilter(writer http.ResponseWriter, requ // search for vhost re := regexp.MustCompile(`Vhost/([^\s]*)`) matches := re.FindStringSubmatch(ua) - debug(5, "VHOST matches %q *************************", matches) + //debug(5, "VHOST matches %q *************************", matches) + log_debug("VHOST matches %q *************************", matches) if len(matches) != 2 { service.printRequest(request) // if no vhost, default to API? @@ -514,12 +560,14 @@ func (service *MercuryFsService) topVhostFilter(writer http.ResponseWriter, requ vhost := matches[1] app := service.Apps.get(vhost) if app == nil { - debug(5, "No matching app found for VHOST %s", vhost) + //debug(5, "No matching app found for VHOST %s", vhost) + log_debug("No matching app found for VHOST %s", vhost) http.Error(writer, "Unknown App", http.StatusNotFound) return } - debug(5, "VHOST REQUEST FOR %s *************************", vhost) + //debug(5, "VHOST REQUEST FOR %s *************************", vhost) + log_debug("VHOST REQUEST FOR %s *************************", vhost) request.URL.Host = "hda" request.Host = vhost @@ -527,7 +575,8 @@ func (service *MercuryFsService) topVhostFilter(writer http.ResponseWriter, requ // FIXME - support https and other ports later remote, err := url.Parse("http://" + vhost) if err != nil { - debug(5, "REQUEST ERROR: %s", err) + //debug(5, "REQUEST ERROR: %s", err) + log_debug("REQUEST ERROR: %s", err) http.NotFound(writer, request) return } @@ -547,7 +596,7 @@ func (service *MercuryFsService) deleteFile(writer http.ResponseWriter, request ua := request.Header.Get("User-Agent") query := pathForLog(request.URL) - debug(2, "deleteFile DELETE request") + //debug(2, "deleteFile DELETE request") service.printRequest(request) @@ -556,22 +605,27 @@ func (service *MercuryFsService) deleteFile(writer http.ResponseWriter, request // if using the welcome server, just return OK without deleting anything if !noDelete { if err != nil { - debug(2, "File not found: %s", err) + //debug(2, "File not found: %s", err) + log_error("File not found: %s", err) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - log("\"DELETE %s\" 404 0 \"%s\"", query, ua) + //log("\"DELETE %s\" 404 0 \"%s\"", query, ua) + log_info("\"DELETE %s\" 404 0 \"%s\"", query, ua) return } err = os.Remove(fullPath) if err != nil { - debug(2, "Error removing file: %s", err.Error()) + //debug(2, "Error removing file: %s", err.Error()) + log_error("Error removing file: %s", err.Error()) writer.WriteHeader(http.StatusExpectationFailed) service.debugInfo.requestServed(int64(0)) - log("\"DELETE %s\" 417 0 \"%s\"", query, ua) + //log("\"DELETE %s\" 417 0 \"%s\"", query, ua) + log_info("\"DELETE %s\" 417 0 \"%s\"", query, ua) return } } else { - debug(2, "NOTICE: Running in no-delete mode. Would have deleted: %s", fullPath) + //debug(2, "NOTICE: Running in no-delete mode. Would have deleted: %s", fullPath) + log_error("NOTICE: Running in no-delete mode. Would have deleted: %s", fullPath) } writer.WriteHeader(http.StatusOK) @@ -587,7 +641,8 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request ua := request.Header.Get("User-Agent") query := pathForLog(request.URL) - debug(2, "upload_file POST request") + //debug(2, "upload_file POST request") + log_trace("upload_file POST request") // do NOT print the whole request, as an image may be way way too big service.printRequest(request) @@ -609,20 +664,24 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request err := request.ParseMultipartForm(32 << 20) if err != nil { - debug(2, "Error parsing image: %s", err.Error()) + //debug(2, "Error parsing image: %s", err.Error()) + log_error("Error parsing image: %s", err.Error()) writer.WriteHeader(http.StatusPreconditionFailed) service.debugInfo.requestServed(int64(0)) - log("\"POST %s\" 412 0 \"%s\"", query, ua) + //log("\"POST %s\" 412 0 \"%s\"", query, ua) + log_info("\"POST %s\" 412 0 \"%s\"", query, ua) return } // debug(2, "Form data: %s", values) file, handler, err := request.FormFile("file") if err != nil { - debug(2, "Error finding uploaded file: %s", err.Error()) + //debug(2, "Error finding uploaded file: %s", err.Error()) + log_error("Error finding uploaded file: %s", err.Error()) writer.WriteHeader(http.StatusExpectationFailed) service.debugInfo.requestServed(int64(0)) - log("\"POST %s\" 417 0 \"%s\"", query, ua) + //log("\"POST %s\" 417 0 \"%s\"", query, ua) + log_info("\"POST %s\" 417 0 \"%s\"", query, ua) return } defer file.Close() @@ -630,10 +689,12 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request fullPath, _ := service.fullPathToFile(share, path+"/"+handler.Filename) //check if the file name is valid if !validFilename(fullPath) { - debug(2, "invalid filename") + //debug(2, "invalid filename") + log_error("invalid filename") writer.WriteHeader(http.StatusUnsupportedMediaType) service.debugInfo.requestServed(int64(0)) - log("\"POST %s\" 415 0 \"%s\"", query, ua) + //log("\"POST %s\" 415 0 \"%s\"", query, ua) + log_info("\"POST %s\" 415 0 \"%s\"", query, ua) return } @@ -652,20 +713,24 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request f, err = os.OpenFile(fullPath, os.O_WRONLY|os.O_CREATE, 0644) } if err != nil { - debug(2, "Error creating uploaded file: %s", err.Error()) + //debug(2, "Error creating uploaded file: %s", err.Error()) + log_error("Error creating uploaded file: %s", err.Error()) writer.WriteHeader(http.StatusServiceUnavailable) service.debugInfo.requestServed(int64(0)) - log("\"POST %s\" 503 0 \"%s\"", query, ua) + //log("\"POST %s\" 503 0 \"%s\"", query, ua) + log_info("\"POST %s\" 503 0 \"%s\"", query, ua) return } // status == FILE_SAME_MD5, ignore it defer f.Close() io.Copy(f, file) - debug(2, "POST of a file upload parsed successfully") + //debug(2, "POST of a file upload parsed successfully") + log_trace("POST of a file upload parsed successfully") } else { - debug(2, "NOTICE: Running in no-upload mode.") + //debug(2, "NOTICE: Running in no-upload mode.") + log_trace("NOTICE: Running in no-upload mode.") } writer.WriteHeader(http.StatusOK) From 293d90e919fd7bdd564a257622e8fcc548a16355 Mon Sep 17 00:00:00 2001 From: Vishwas Mittal Date: Sat, 25 May 2019 01:37:41 +0530 Subject: [PATCH 2/9] added api for serving logs --- src/fs/service.go | 40 +++++++++++++++++++++++++++++++++++++++- 1 file changed, 39 insertions(+), 1 deletion(-) diff --git a/src/fs/service.go b/src/fs/service.go index bd66e42..3bd1df5 100644 --- a/src/fs/service.go +++ b/src/fs/service.go @@ -79,6 +79,7 @@ func NewMercuryFSService(rootDir, localAddr string, isDemo bool) (service *Mercu apiRouter.HandleFunc("/apps", service.appsList).Methods("GET") apiRouter.HandleFunc("/md", service.getMetadata).Methods("GET") apiRouter.HandleFunc("/hda_debug", service.hdaDebug).Methods("GET") + apiRouter.HandleFunc("/logs", service.serveLogs).Methods("GET") service.apiRouter = apiRouter @@ -220,7 +221,6 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * //debug(2, "serveFile GET request") log_trace("deleteFile DELETE request") - service.printRequest(request) fullPath, err := service.fullPathToFile(share, path) @@ -737,3 +737,41 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request return } + +func (service *MercuryFsService) serveLogs(writer http.ResponseWriter, request *http.Request) { + q := request.URL + amt := q.Query().Get("mode") + ua := request.Header.Get("User-Agent") + query := pathForLog(request.URL) + + mode := 100 // determines the numbers of lines to serve (from last). -1 will cause serving complete log file + + if n, err := strconv.Atoi(amt); err == nil { + mode = n + } else { + if strings.ToLower(amt) == "all" { + mode = -1 + } + } + + osFile, err := os.Open(LOGFILE) + if err != nil { + log_error("Error opening log file: %s", err.Error()) + http.NotFound(writer, request) + service.debugInfo.requestServed(int64(0)) + log_info("\"GET %s\" 404 0 \"%s\"", query, ua) + return + } + defer osFile.Close() + + fi, _ := osFile.Stat() + if mode == -1 { + http.ServeContent(writer, request, osFile.Name(), fi.ModTime(), osFile) + log_info("\"GET %s\" %d %d \"%s\"", query, 200, fi.Size(), ua) + } else { + // TODO: add log number to the log file. Make use of bufio.Scanner to readlines. Make use of binary search + // to find the appropriate line number. + http.ServeContent(writer, request, osFile.Name(), fi.ModTime(), osFile) + log_info("\"GET %s\" %d %d \"%s\"", query, 200, fi.Size(), ua) + } +} From 613cf7d5213944cd2784c15b0270925edb631275 Mon Sep 17 00:00:00 2001 From: Vishwas Mittal Date: Fri, 14 Jun 2019 21:31:56 +0530 Subject: [PATCH 3/9] updated log statements --- src/fs/auth.go | 2 +- src/fs/fs.go | 81 +++++++++++++--------------------------- src/fs/hda_apps.go | 4 +- src/fs/hda_shares.go | 6 +-- src/fs/hda_users.go | 12 +++--- src/fs/local_server.go | 8 ++-- src/fs/logging.go | 56 +++++----------------------- src/fs/service.go | 84 ++++++++++++++---------------------------- 8 files changed, 79 insertions(+), 174 deletions(-) diff --git a/src/fs/auth.go b/src/fs/auth.go index 8785abe..7c7b856 100644 --- a/src/fs/auth.go +++ b/src/fs/auth.go @@ -58,7 +58,7 @@ func (service *MercuryFsService) authenticate(writer http.ResponseWriter, reques http.Error(writer, "Internal Server Error", http.StatusInternalServerError) //log(err.Error()) //log2.Info(err.Error()) - log_info(err.Error()) + log_error(err.Error()) break default: // if no error, send proper auth token for that user respJson := fmt.Sprintf("{\"auth_token\": \"%s\"}", *authToken) diff --git a/src/fs/fs.go b/src/fs/fs.go index 08e39cb..04a5c09 100644 --- a/src/fs/fs.go +++ b/src/fs/fs.go @@ -97,43 +97,36 @@ func main() { return } - //debugLevel(dbg) - //log2.SetLevel(log2.Level(dbg)) setLogLevel(log2.Level(dbg)) if noDelete { - fmt.Printf("NOTICE: running without deleting content!\n") + log_warn("Running without deleting content!") } if noUpload { - fmt.Printf("NOTICE: running without uploading content!\n") + log_warn("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") + log_fatal("Error initializing metadata library") os.Remove(PID_FILE) os.Exit(1) } service, err := NewMercuryFSService(rootDir, localAddr, isDemo) if err != nil { - fmt.Printf("Error making service (%s, %s): %s\n", rootDir, localAddr, err.Error()) + log_fatal("Error making service (%s, %s): %s\n", rootDir, localAddr, err.Error()) os.Remove(PID_FILE) 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) - //log("Amahi Anywhere service v%s", VERSION) - //log2.Info(fmt.Sprintf("Amahi Anywhere Service v%s", VERSION)) log_info("Amahi Anywhere service v%s", VERSION) - - //debug(4, "using api-key %s", apiKey) - //log2.Info(fmt.Sprintf("Using API-KEY %s", apiKey)) log_info("using api-key %s", apiKey) if http2Debug { @@ -148,17 +141,10 @@ func main() { for { conn, err := contactPfe(relayHost, relayPort, apiKey, service) if err != nil { - //debug(2, "Error contacting the proxy: %s", err) - //log2.Error(fmt.Sprintf("Error contacting the proxy: %s", err)) log_error("Error contacting the proxy: %s", err) } else { err = service.StartServing(conn) if err != nil { - //log("Error serving requests") - //log2.Warn("Error serving requests") - log_warn("Error serving requests") - //debug(2, "Error in StartServing: %s", err) - //log2.Error(fmt.Sprintf("Error in StartServing: %s", err)) log_error("Error in StartServing: %s", err) } } @@ -171,23 +157,16 @@ func main() { // 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) - //log2.Info("Contacting Relay at: " + relayLocation) log_info("Contacting Relay at: " + relayLocation) addr, err := net.ResolveTCPAddr("tcp", relayLocation) if err != nil { - //debug(2, "Error with ResolveTCPAddr: %s", err) - //log2.Error(fmt.Sprintf("Error with ResolveTCPAddr: %s", err)) log_error("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) - //log2.Error(fmt.Sprintf("Error with initial DialTCP: %s", err)) log_error("Error with initial DialTCP: %s", err) return nil, err } @@ -200,12 +179,6 @@ 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) - //log2.Warn(warning) - //log2.Warn(warning) - //log2.Warn(warning) log_warn(warning) log_warn(warning) log_warn(warning) @@ -220,8 +193,6 @@ func contactPfe(relayHost, relayPort, apiKey string, service *MercuryFsService) buf := strings.NewReader(service.info.to_json()) request, err := http.NewRequest("PUT", "https://"+relayLocation+"/fs", buf) if err != nil { - //debug(2, "Error creating NewRequest:", err) - //log2.Error(fmt.Sprintf("Error creating NewRequest:", err)) log_error("Error creating NewRequest:", err) return nil, err } @@ -229,16 +200,12 @@ 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) - //log2.Debug(fmt.Sprintf("&s", rawRequest)) - log_debug("%s", rawRequest) + log_debug("Raw API-key request: %s", rawRequest) var client *httputil.ClientConn if DisableHttps { warning := "WARNING WARNING: running without TLS!!" - //log(warning) - //log2.Warn(warning) log_warn(warning) fmt.Println(warning) conn := tcpConn @@ -250,22 +217,16 @@ func contactPfe(relayHost, relayPort, apiKey string, service *MercuryFsService) response, err := client.Do(request) if err != nil { - //debug(2, "Error writing to connection with Do: %s", err) - //log2.Error(fmt.Sprintf("Error writing to connection with Do: %s", err)) log_error("Error writing to connection with Do: %s", err) return nil, err } if response.StatusCode != 200 { msg := fmt.Sprintf("Got an error response: %s", response.Status) - //log(msg) - //log2.Info(msg) log_info(msg) return nil, errors.New(msg) } - //log("Connected to the proxy") - //log2.Info("Connected to the proxy") log_info("Connected to the proxy") netCon, _ := client.Hijack() @@ -275,13 +236,23 @@ func contactPfe(relayHost, relayPort, apiKey string, service *MercuryFsService) // Clean up and quit func cleanQuit(exitCode int, message string) { - fmt.Println("FATAL:", message) + //fmt.Println("FATAL:", message) + log_fatal(message) os.Exit(exitCode) } func panicHandler() { - if v := recover(); v != nil { - fmt.Println("PANIC:", v) + if r := recover(); r != nil { + var errStr string + switch t := r.(type) { + case error: + errStr = t.Error() + default: + errStr = "Error in mapping. Can't process the error" + } + log_panic(errStr) + os.Remove(PID_FILE) + os.Exit(1) } os.Remove(PID_FILE) } @@ -294,9 +265,7 @@ func setup() error { signal.Notify(c, os.Interrupt) go func() { for sig := range c { - //log("Exiting with %v", sig) - //log2.Info(fmt.Sprintf("Exiting with %v", sig)) - log_info("Exiting with %v", sig) + log_fatal("Exiting with %v", sig) os.Remove(PID_FILE) os.Exit(1) } @@ -318,7 +287,7 @@ func checkPidFile() { c, err := f.Read(pid) if err == nil { v, _ := strconv.Atoi(string(pid[:c])) - fmt.Printf("PID: %#v\n", v) + log_info("PID: %#v\n", v) if !exists(fmt.Sprintf("/proc/%s/stat", string(pid[:c]))) { // the process does not exist. pid file is stale // note: this works on systems with /proc/ @@ -328,9 +297,9 @@ func checkPidFile() { } } if stale { - fmt.Printf("PID file exists, but it's stale. Continuing.\n") + log_info("PID file exists, but it's stale. Continuing.") } else { - fmt.Printf("PID file exists and process is running. Exiting.\n") + log_fatal("PID file exists and process is running. Exiting.") os.Exit(1) } } diff --git a/src/fs/hda_apps.go b/src/fs/hda_apps.go index 159b051..9407586 100644 --- a/src/fs/hda_apps.go +++ b/src/fs/hda_apps.go @@ -40,7 +40,7 @@ func (apps *HdaApps) list() error { //log(err.Error()) //TODO: to check with mentors about the debug level of these type of errors. Currently assigning INFO //log2.Info(err.Error()) - log_info(err.Error()) + log_error(err.Error()) return err } defer dbconn.Close() @@ -49,7 +49,7 @@ func (apps *HdaApps) list() error { if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_info(err.Error()) + log_error(err.Error()) return err } newApps := make([]*HdaApp, 0) diff --git a/src/fs/hda_shares.go b/src/fs/hda_shares.go index a6fb156..ca24f48 100644 --- a/src/fs/hda_shares.go +++ b/src/fs/hda_shares.go @@ -59,7 +59,7 @@ func (shares *HdaShares) updateSqlShares() error { if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_info(err.Error()) + log_error(err.Error()) return err } defer dbconn.Close() @@ -71,7 +71,7 @@ func (shares *HdaShares) updateSqlShares() error { if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_info(err.Error()) + log_error(err.Error()) return err } newShares := make([]*HdaShare, 0) @@ -98,7 +98,7 @@ func (shares *HdaShares) updateDirShares() (nil error) { if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_info(err.Error()) + log_error(err.Error()) return err } defer dir.Close() diff --git a/src/fs/hda_users.go b/src/fs/hda_users.go index 78f33ea..d56671d 100644 --- a/src/fs/hda_users.go +++ b/src/fs/hda_users.go @@ -46,7 +46,7 @@ func (users *HdaUsers) queryUser(pin string) (*string, error) { if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_info(err.Error()) + log_error(err.Error()) return nil, err } defer dbconn.Close() @@ -113,7 +113,7 @@ func (users *HdaUsers) revalidateSession(authToken string, user *HdaUser) (isVal if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_info(err.Error()) + log_error(err.Error()) return } defer dbconn.Close() @@ -136,7 +136,7 @@ func (user *HdaUser) AvailableShares() ([]*HdaShare, error) { if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_info(err.Error()) + log_error(err.Error()) return nil, err } defer dbconn.Close() @@ -151,7 +151,7 @@ func (user *HdaUser) AvailableShares() ([]*HdaShare, error) { if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_info(err.Error()) + log_error(err.Error()) return nil, err } newShares := make([]*HdaShare, 0) @@ -171,7 +171,7 @@ func (user *HdaUser) HasReadAccess(shareName string) (access bool, err error) { if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_info(err.Error()) + log_error(err.Error()) return } defer dbconn.Close() @@ -191,7 +191,7 @@ func (user *HdaUser) HasWriteAccess(shareName string) (access bool, err error) { if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_info(err.Error()) + log_error(err.Error()) return } defer dbconn.Close() diff --git a/src/fs/local_server.go b/src/fs/local_server.go index 9e36f7b..cdc768d 100644 --- a/src/fs/local_server.go +++ b/src/fs/local_server.go @@ -25,7 +25,7 @@ func (service *MercuryFsService) startLocalServer() { //debug(2, "Error resolving local address: %s", err.Error()) //log2.Error(fmt.Sprintf("Error resolving local address: %s", err.Error())) - log_debug("Error resolving local address: %s", err.Error()) + log_error("Error resolving local address: %s", err.Error()) return } @@ -37,7 +37,7 @@ func (service *MercuryFsService) startLocalServer() { //debug(2, "Error on ListenTCP: %s", err.Error()) //log2.Debug(fmt.Sprintf("Error on ListenTCP: %s", err.Error())) - log_debug("Error on ListenTCP: %s", err.Error()) + log_error("Error on ListenTCP: %s", err.Error()) return } defer listener.Close() @@ -54,10 +54,10 @@ func (service *MercuryFsService) startLocalServer() { if err != nil { //log("An error occurred in the local file server") //log2.Error("An error occurred in the local file server") - log_error("An error occurred in the local file server") + log_warn("An error occurred in the local file server") //debug(2, "local file server: %s", err.Error()) //log2.Debug(fmt.Sprintf(2, "local file server: %s", err.Error())) - log_debug("local file server: %s", err.Error()) + log_error("local file server: %s", err.Error()) } } } diff --git a/src/fs/logging.go b/src/fs/logging.go index 0ebee95..e9e9d5f 100644 --- a/src/fs/logging.go +++ b/src/fs/logging.go @@ -15,7 +15,8 @@ import ( "os" ) -const LOGFILE = "/var/log/amahi-anywhere.log" +//const LOGFILE = "/var/log/amahi-anywhere.log" +const LOGFILE = "temp_log.log" func initializeLogging() { logFile, err := os.OpenFile(LOGFILE, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644) @@ -27,7 +28,7 @@ func initializeLogging() { Formatter := new(log2.TextFormatter) Formatter.TimestampFormat = "02-01-2006 15:04:05" Formatter.FullTimestamp = true - //Formatter.DisableColors = true + Formatter.DisableColors = true log2.SetFormatter(Formatter) log2.SetOutput(logFile) } @@ -41,73 +42,36 @@ func getLogLevel() log2.Level { } func log_trace(f string, args ...interface{}) { - msg := fmt.Sprintf(f, args) + msg := fmt.Sprintf(f, args...) log2.Trace(msg) } func log_debug(f string, args ...interface{}) { - msg := fmt.Sprintf(f, args) + msg := fmt.Sprintf(f, args...) log2.Debug(msg) } func log_info(f string, args ...interface{}) { - msg := fmt.Sprintf(f, args) + msg := fmt.Sprintf(f, args...) log2.Info(msg) } func log_warn(f string, args ...interface{}) { - msg := fmt.Sprintf(f, args) + msg := fmt.Sprintf(f, args...) log2.Warn(msg) } func log_error(f string, args ...interface{}) { - msg := fmt.Sprintf(f, args) + msg := fmt.Sprintf(f, args...) log2.Error(msg) } func log_fatal(f string, args ...interface{}) { - msg := fmt.Sprintf(f, args) + msg := fmt.Sprintf(f, args...) log2.Fatal(msg) } func log_panic(f string, args ...interface{}) { - msg := fmt.Sprintf(f, args) + msg := fmt.Sprintf(f, args...) log2.Panic(msg) } - -// -//var logger *logging.Logger -// -//func initializeLogging() { -// logFile, err := os.OpenFile(LOGFILE, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644) -// if err != nil { -// fmt.Println("WARNING: failed to open ", LOGFILE, " defaulting to standard output") -// logFile = os.Stdout -// } -// -// Formatter := new(log2.TextFormatter) -// Formatter.TimestampFormat = "02-01-2006 15:04:05" -// Formatter.FullTimestamp = true -// //Formatter.DisableColors = true -// log2.SetFormatter(Formatter) -// log2.SetOutput(logFile) -// -// logger = logging.New(logFile, "", logging.LstdFlags) -//} -// -//func log(f string, args ...interface{}) { -// logger.Printf(f, args...) -//} -// -//func debugLevel(level int) { -// currentDebugLevel = level -//} -// -//func debug(level int, f string, args ...interface{}) { -// if PRODUCTION { -// return -// } -// if level <= currentDebugLevel { -// log(f, args...) -// } -//} diff --git a/src/fs/service.go b/src/fs/service.go index 3bd1df5..8601ba8 100644 --- a/src/fs/service.go +++ b/src/fs/service.go @@ -62,8 +62,7 @@ func NewMercuryFSService(rootDir, localAddr string, isDemo bool) (service *Mercu service.Users = NewHdaUsers(isDemo) service.Shares, err = NewHdaShares(rootDir) if err != nil { - //debug(3, "Error making HdaShares: %s", err.Error()) - log_warn("Error making HdaShares: %s", err.Error()) + log_error("Error making HdaShares: %s", err.Error()) return nil, err } service.debugInfo = new(debugInfo) @@ -93,10 +92,8 @@ func NewMercuryFSService(rootDir, localAddr string, isDemo bool) (service *Mercu if localAddr != "" { service.info.local_addr = localAddr } else { - actualAddr, err := GetLocalAddr(rootDir) if err != nil { - //debug(2, "Error getting local address: %s", err.Error()) log_error("Error getting local address: %s", err.Error()) return nil, err } @@ -105,10 +102,8 @@ func NewMercuryFSService(rootDir, localAddr string, isDemo bool) (service *Mercu // This will be set when the HDA connects to the proxy service.info.relay_addr = "" - //debug(3, "Amahi FS Service started %s", SharesJson(service.Shares.Shares)) - log_warn("Amahi FS Service started %s", SharesJson(service.Shares.Shares)) - //debug(4, "HDA Info: %s", service.info.to_json()) - log_info("HDA Info: %s", service.info.to_json()) + log_debug("Amahi FS Service started") + log_debug("HDA Info: %s", service.info.to_json()) return service, err } @@ -157,13 +152,11 @@ func directory(fi os.FileInfo, js string, w http.ResponseWriter, request *http.R inm := request.Header.Get("If-None-Match") if inm == etag { size = 0 - //debug(4, "If-None-Match match found for %s", etag) - log_info("If-None-Match match found for %s", etag) + log_debug("If-None-Match match found for %s", etag) w.WriteHeader(http.StatusNotModified) status = 304 } else { - //debug(4, "If-None-Match (%s) match NOT found for Etag %s", inm, etag) - log_info("If-None-Match (%s) match NOT found for Etag %s", inm, etag) + log_debug("If-None-Match (%s) match NOT found for Etag %s", inm, etag) size = int64(len(json)) w.Header().Set("Content-Length", strconv.FormatInt(size, 10)) w.Header().Set("Last-Modified", fi.ModTime().UTC().Format(http.TimeFormat)) @@ -180,7 +173,6 @@ func directory(fi os.FileInfo, js string, w http.ResponseWriter, request *http.R // there aren't any '..' to prevent unauthorized access func (service *MercuryFsService) fullPathToFile(shareName, relativePath string) (string, error) { share := service.Shares.Get(shareName) - if share == nil { return "", errors.New(fmt.Sprintf("Share %s not found", shareName)) } else if strings.Contains(relativePath, "../") { @@ -193,21 +185,17 @@ func (service *MercuryFsService) fullPathToFile(shareName, relativePath string) // serve requests with the ServeConn function over HTTP/2, in goroutines, until we get some error func (service *MercuryFsService) StartServing(conn net.Conn) error { - //log("Connection to the proxy established.") log_info("Connection to the proxy established.") service.info.relay_addr = conn.RemoteAddr().String() - serveConnOpts := &http2.ServeConnOpts{BaseConfig: service.server} server2 := new(http2.Server) // start serving over http2 on provided conn and block until connection is lost server2.ServeConn(conn, serveConnOpts) - //log("Lost connection to the proxy.") log_warn("Lost connection to the proxy.") service.info.relay_addr = "" - return errors.New("connection is no longer readable") } @@ -218,28 +206,23 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * ua := request.Header.Get("User-Agent") query := pathForLog(request.URL) - //debug(2, "serveFile GET request") - log_trace("deleteFile DELETE request") + log_debug(2, "serveFile GET request") service.printRequest(request) fullPath, err := service.fullPathToFile(share, path) if err != nil { - //debug(2, "File not found: %s", err) - log_error("File not found: %s", err) + log_debug("File not found: %s", err) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - //log("\"GET %s\" 404 0 \"%s\"", query, ua) log_info("\"GET %s\" 404 0 \"%s\"", query, ua) return } osFile, err := os.Open(fullPath) if err != nil { - //debug(2, "Error opening file: %s", err.Error()) - log_error("Error opening file: %s", err.Error()) + log_debug("Error opening file: %s", err.Error()) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - //log("\"GET %s\" 404 0 \"%s\"", query, ua) log_info("\"GET %s\" 404 0 \"%s\"", query, ua) return } @@ -253,7 +236,7 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * jsonDir, err := dirToJSON(osFile, fullPath) if err != nil { //debug(2, "Error converting dir to JSON: %s", err.Error()) - log_error("Error converting dir to JSON: %s", err.Error()) + log_debug("Error converting dir to JSON: %s", err.Error()) //log("\"GET %s\" 404 0 \"%s\"", query, ua) log_info("\"GET %s\" 404 0 \"%s\"", query, ua) http.NotFound(writer, request) @@ -262,7 +245,6 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * } status, size := directory(fi, jsonDir, writer, request) service.debugInfo.requestServed(size) - //log("\"GET %s\" %d %d \"%s\"", query, status, size, ua) log_info("\"GET %s\" %d %d \"%s\"", query, status, size, ua) return } @@ -272,23 +254,18 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * etag := `"` + sha1string(path+mtime) + `"` inm := request.Header.Get("If-None-Match") if inm == etag { - //debug(4, "If-None-Match match found for %s", etag) log_info("If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) - //log("\"GET %s\" %d \"%s\"", query, 304, ua) log_info("\"GET %s\" %d \"%s\"", query, 304, ua) } else { writer.Header().Set("Last-Modified", mtime) writer.Header().Set("ETag", etag) writer.Header().Set("Cache-Control", "max-age=0, private, must-revalidate") - //debug(4, "Etag sent: %s", etag) log_info("Etag sent: %s", etag) http.ServeContent(writer, request, fullPath, fi.ModTime(), osFile) - //log("\"GET %s\" %d %d \"%s\"", query, 200, fi.Size(), ua) log_info("\"GET %s\" %d %d \"%s\"", query, 200, fi.Size(), ua) service.debugInfo.requestServed(fi.Size()) } - return } @@ -311,20 +288,16 @@ func (service *MercuryFsService) serveShares(writer http.ResponseWriter, request service.Shares.updateShares() shares = service.Shares.Shares } - //debug(5, "========= DEBUG Share request: %d", len(shares)) log_debug("========= DEBUG Share request: %d", len(shares)) json := SharesJson(shares) - //debug(5, "Share JSON: %s", json) log_debug("Share JSON: %s", json) etag := `"` + sha1bytes([]byte(json)) + `"` inm := request.Header.Get("If-None-Match") if inm == etag { - //debug(4, "If-None-Match match found for %s", etag) log_info("If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) service.debugInfo.requestServed(int64(0)) } else { - //debug(4, "If-None-Match (%s) match NOT found for Etag %s", inm, etag) log_info("If-None-Match (%s) match NOT found for Etag %s", inm, etag) size := int64(len(json)) writer.Header().Set("Content-Length", strconv.FormatInt(size, 10)) @@ -347,7 +320,7 @@ func GetLocalAddr(rootDir string) (string, error) { dbconn, err := sql.Open("mysql", MYSQL_CREDENTIALS) if err != nil { //log(err.Error()) - log_info(err.Error()) + log_error(err.Error()) return "", err } defer dbconn.Close() @@ -364,12 +337,10 @@ func GetLocalAddr(rootDir string) (string, error) { row = dbconn.QueryRow(q, "self-address") err = row.Scan(&addr) if err != nil { - //log("Error scanning self-address: %s\n", err.Error()) log_error("Error scanning self-address: %s\n", err.Error()) return "", err } - //debug(4, "prefix: %s\taddr: %s", prefix, addr) log_info("prefix: %s\taddr: %s", prefix, addr) return prefix + "." + addr, nil @@ -434,20 +405,16 @@ func (service *MercuryFsService) appsList(writer http.ResponseWriter, request *h } service.Apps = apps service.Apps.list() - //debug(5, "========= DEBUG apps_list request: %d", len(service.Shares.Shares)) log_debug("========= DEBUG apps_list request: %d", len(service.Shares.Shares)) json := service.Apps.toJson() - //debug(5, "App JSON: %s", json) log_debug("App JSON: %s", json) etag := `"` + sha1bytes([]byte(json)) + `"` inm := request.Header.Get("If-None-Match") if inm == etag { - //debug(4, "If-None-Match match found for %s", etag) log_info("If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) service.debugInfo.requestServed(int64(0)) } else { - //debug(4, "If-None-Match (%s) match NOT found for Etag %s", inm, etag) log_info("If-None-Match (%s) match NOT found for Etag %s", inm, etag) size := int64(len(json)) writer.Header().Set("Content-Length", strconv.FormatInt(size, 10)) @@ -466,14 +433,18 @@ func (service *MercuryFsService) getMetadata(writer http.ResponseWriter, request filename, err := url.QueryUnescape(q.Query().Get("f")) if err != nil { //debug(3, "get_metadata error parsing file: %s", err) - log_warn("get_metadata error parsing file: %s", err) + log_debug("get_metadata error parsing file: %s", err) + // FIXME: write proper log statement + log_info("404") http.NotFound(writer, request) return } hint, err := url.QueryUnescape(q.Query().Get("h")) if err != nil { //debug(3, "get_metadata error parsing hint: %s", err) - log_warn("get_metadata error parsing hint: %s", err) + log_debug("get_metadata error parsing hint: %s", err) + // FIXME: write proper log statement + log_info("404") http.NotFound(writer, request) return } @@ -485,7 +456,9 @@ func (service *MercuryFsService) getMetadata(writer http.ResponseWriter, request json, err := service.metadata.GetMetadata(filename, hint) if err != nil { //debug(3, "metadata error: %s", err) - log_warn("metadata error: %s", err) + log_debug("metadata error: %s", err) + // FIXME: write proper log statement + log_info("404") http.NotFound(writer, request) return } @@ -530,9 +503,7 @@ func (service *MercuryFsService) printRequest(request *http.Request) { } func (service *MercuryFsService) topVhostFilter(writer http.ResponseWriter, request *http.Request) { - header := writer.Header() - ua := request.Header.Get("User-Agent") // since data will change with the session, we should indicate that to keep caching! header.Add("Vary", "Session") @@ -597,6 +568,7 @@ func (service *MercuryFsService) deleteFile(writer http.ResponseWriter, request query := pathForLog(request.URL) //debug(2, "deleteFile DELETE request") + log_debug("deleteFile DELETE request") service.printRequest(request) @@ -606,7 +578,7 @@ func (service *MercuryFsService) deleteFile(writer http.ResponseWriter, request if !noDelete { if err != nil { //debug(2, "File not found: %s", err) - log_error("File not found: %s", err) + log_debug("File not found: %s", err) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) //log("\"DELETE %s\" 404 0 \"%s\"", query, ua) @@ -616,7 +588,7 @@ func (service *MercuryFsService) deleteFile(writer http.ResponseWriter, request err = os.Remove(fullPath) if err != nil { //debug(2, "Error removing file: %s", err.Error()) - log_error("Error removing file: %s", err.Error()) + log_debug("Error removing file: %s", err.Error()) writer.WriteHeader(http.StatusExpectationFailed) service.debugInfo.requestServed(int64(0)) //log("\"DELETE %s\" 417 0 \"%s\"", query, ua) @@ -625,7 +597,7 @@ func (service *MercuryFsService) deleteFile(writer http.ResponseWriter, request } } else { //debug(2, "NOTICE: Running in no-delete mode. Would have deleted: %s", fullPath) - log_error("NOTICE: Running in no-delete mode. Would have deleted: %s", fullPath) + log_warn("NOTICE: Running in no-delete mode. Would have deleted: %s", fullPath) } writer.WriteHeader(http.StatusOK) @@ -642,7 +614,7 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request query := pathForLog(request.URL) //debug(2, "upload_file POST request") - log_trace("upload_file POST request") + log_debug("upload_file POST request") // do NOT print the whole request, as an image may be way way too big service.printRequest(request) @@ -665,7 +637,7 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request if err != nil { //debug(2, "Error parsing image: %s", err.Error()) - log_error("Error parsing image: %s", err.Error()) + log_debug("Error parsing image: %s", err.Error()) writer.WriteHeader(http.StatusPreconditionFailed) service.debugInfo.requestServed(int64(0)) //log("\"POST %s\" 412 0 \"%s\"", query, ua) @@ -677,7 +649,7 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request file, handler, err := request.FormFile("file") if err != nil { //debug(2, "Error finding uploaded file: %s", err.Error()) - log_error("Error finding uploaded file: %s", err.Error()) + log_debug("Error finding uploaded file: %s", err.Error()) writer.WriteHeader(http.StatusExpectationFailed) service.debugInfo.requestServed(int64(0)) //log("\"POST %s\" 417 0 \"%s\"", query, ua) @@ -690,7 +662,7 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request //check if the file name is valid if !validFilename(fullPath) { //debug(2, "invalid filename") - log_error("invalid filename") + log_debug("invalid filename") writer.WriteHeader(http.StatusUnsupportedMediaType) service.debugInfo.requestServed(int64(0)) //log("\"POST %s\" 415 0 \"%s\"", query, ua) @@ -756,7 +728,7 @@ func (service *MercuryFsService) serveLogs(writer http.ResponseWriter, request * osFile, err := os.Open(LOGFILE) if err != nil { - log_error("Error opening log file: %s", err.Error()) + log_debug("Error opening log file: %s", err.Error()) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) log_info("\"GET %s\" 404 0 \"%s\"", query, ua) From 7fe834fd806b133cbe2a620e85333e71ee9b69c4 Mon Sep 17 00:00:00 2001 From: Vishwas Mittal Date: Sat, 15 Jun 2019 12:22:52 +0530 Subject: [PATCH 4/9] updated log statements --- src/fs/auth.go | 4 +- src/fs/fs.go | 52 ++++++------- src/fs/hda_apps.go | 4 +- src/fs/hda_shares.go | 12 +-- src/fs/hda_users.go | 12 +-- src/fs/local_server.go | 16 ++-- src/fs/logging.go | 19 +++-- src/fs/service.go | 167 ++++++++++++++++++++++------------------- 8 files changed, 153 insertions(+), 133 deletions(-) diff --git a/src/fs/auth.go b/src/fs/auth.go index 7c7b856..78df24c 100644 --- a/src/fs/auth.go +++ b/src/fs/auth.go @@ -51,14 +51,14 @@ func (service *MercuryFsService) authenticate(writer http.ResponseWriter, reques case err == sql.ErrNoRows: // if no such user exits, send 401 Unauthorized //log("No user with pin: %s", pin) //log2.Info(fmt.Sprintf("No user with pin: %s", pin)) - log_info("No user with pin: %s", pin) + logInfo("No user with pin: %s", pin) http.Error(writer, "Authentication Failed", http.StatusUnauthorized) break case err != nil: // if some other error, send 500 Internal Server Error http.Error(writer, "Internal Server Error", http.StatusInternalServerError) //log(err.Error()) //log2.Info(err.Error()) - log_error(err.Error()) + logError(err.Error()) break default: // if no error, send proper auth token for that user respJson := fmt.Sprintf("{\"auth_token\": \"%s\"}", *authToken) diff --git a/src/fs/fs.go b/src/fs/fs.go index 04a5c09..6712c15 100644 --- a/src/fs/fs.go +++ b/src/fs/fs.go @@ -100,24 +100,24 @@ func main() { setLogLevel(log2.Level(dbg)) if noDelete { - log_warn("Running without deleting content!") + logWarn("Running without deleting content!") } if noUpload { - log_warn("Running without uploading content!") + logWarn("Running without uploading content!") } initializeLogging() meta, err := metadata.Init(100000, METADATA_FILE, TMDB_API_KEY, TVRAGE_API_KEY, TVDB_API_KEY) if err != nil { - log_fatal("Error initializing metadata library") + logFatal("Error initializing metadata library") os.Remove(PID_FILE) os.Exit(1) } service, err := NewMercuryFSService(rootDir, localAddr, isDemo) if err != nil { - log_fatal("Error making service (%s, %s): %s\n", rootDir, localAddr, err.Error()) + logFatal("Error making service (%s, %s): %s\n", rootDir, localAddr, err.Error()) os.Remove(PID_FILE) os.Exit(1) } @@ -126,8 +126,8 @@ func main() { go service.Shares.startMetadataPrefill(meta) - log_info("Amahi Anywhere service v%s", VERSION) - log_info("using api-key %s", apiKey) + logInfo("Amahi Anywhere service v%s", VERSION) + logInfo("using api-key %s", apiKey) if http2Debug { http2.VerboseLogs = true @@ -141,11 +141,11 @@ func main() { for { conn, err := contactPfe(relayHost, relayPort, apiKey, service) if err != nil { - log_error("Error contacting the proxy: %s", err) + logError("Error contacting the proxy: %s", err) } else { err = service.StartServing(conn) if err != nil { - log_error("Error in StartServing: %s", err) + logError("Error in StartServing: %s", err) } } // reconnect fairly quickly, with some randomness @@ -158,16 +158,16 @@ func main() { // 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_info("Contacting Relay at: " + relayLocation) + logInfo("Contacting Relay at: " + relayLocation) addr, err := net.ResolveTCPAddr("tcp", relayLocation) if err != nil { - log_error("Error with ResolveTCPAddr: %s", err) + logError("Error with ResolveTCPAddr: %s", err) return nil, err } tcpConn, err := net.DialTCP("tcp", nil, addr) if err != nil { - log_error("Error with initial DialTCP: %s", err) + logError("Error with initial DialTCP: %s", err) return nil, err } @@ -179,9 +179,9 @@ func contactPfe(relayHost, relayPort, apiKey string, service *MercuryFsService) if DisableCertChecking { warning := "WARNING WARNING WARNING: running without checking TLS certs!!" - log_warn(warning) - log_warn(warning) - log_warn(warning) + logWarn(warning) + logWarn(warning) + logWarn(warning) fmt.Println(warning) fmt.Println(warning) fmt.Println(warning) @@ -193,20 +193,20 @@ func contactPfe(relayHost, relayPort, apiKey string, service *MercuryFsService) buf := strings.NewReader(service.info.to_json()) request, err := http.NewRequest("PUT", "https://"+relayLocation+"/fs", buf) if err != nil { - log_error("Error creating NewRequest:", err) + logError("Error creating NewRequest:", err) return nil, err } request.Header.Add("Api-Key", apiKey) request.Header.Add("Authorization", fmt.Sprintf("Token %s", SECRET_TOKEN)) rawRequest, _ := httputil.DumpRequest(request, true) - log_debug("Raw API-key request: %s", rawRequest) + logDebug("Raw API-key request: %s", rawRequest) var client *httputil.ClientConn if DisableHttps { warning := "WARNING WARNING: running without TLS!!" - log_warn(warning) + logWarn(warning) fmt.Println(warning) conn := tcpConn client = httputil.NewClientConn(conn, nil) @@ -217,17 +217,17 @@ func contactPfe(relayHost, relayPort, apiKey string, service *MercuryFsService) response, err := client.Do(request) if err != nil { - log_error("Error writing to connection with Do: %s", err) + logError("Error writing to connection with Do: %s", err) return nil, err } if response.StatusCode != 200 { msg := fmt.Sprintf("Got an error response: %s", response.Status) - log_info(msg) + logInfo(msg) return nil, errors.New(msg) } - log_info("Connected to the proxy") + logInfo("Connected to the proxy") netCon, _ := client.Hijack() @@ -237,7 +237,7 @@ func contactPfe(relayHost, relayPort, apiKey string, service *MercuryFsService) // Clean up and quit func cleanQuit(exitCode int, message string) { //fmt.Println("FATAL:", message) - log_fatal(message) + logFatal(message) os.Exit(exitCode) } @@ -250,7 +250,7 @@ func panicHandler() { default: errStr = "Error in mapping. Can't process the error" } - log_panic(errStr) + logPanic(errStr) os.Remove(PID_FILE) os.Exit(1) } @@ -265,7 +265,7 @@ func setup() error { signal.Notify(c, os.Interrupt) go func() { for sig := range c { - log_fatal("Exiting with %v", sig) + logFatal("Exiting with %v", sig) os.Remove(PID_FILE) os.Exit(1) } @@ -287,7 +287,7 @@ func checkPidFile() { c, err := f.Read(pid) if err == nil { v, _ := strconv.Atoi(string(pid[:c])) - log_info("PID: %#v\n", v) + logInfo("PID: %#v\n", v) if !exists(fmt.Sprintf("/proc/%s/stat", string(pid[:c]))) { // the process does not exist. pid file is stale // note: this works on systems with /proc/ @@ -297,9 +297,9 @@ func checkPidFile() { } } if stale { - log_info("PID file exists, but it's stale. Continuing.") + logInfo("PID file exists, but it's stale. Continuing.") } else { - log_fatal("PID file exists and process is running. Exiting.") + logFatal("PID file exists and process is running. Exiting.") os.Exit(1) } } diff --git a/src/fs/hda_apps.go b/src/fs/hda_apps.go index 9407586..2ba549a 100644 --- a/src/fs/hda_apps.go +++ b/src/fs/hda_apps.go @@ -40,7 +40,7 @@ func (apps *HdaApps) list() error { //log(err.Error()) //TODO: to check with mentors about the debug level of these type of errors. Currently assigning INFO //log2.Info(err.Error()) - log_error(err.Error()) + logError(err.Error()) return err } defer dbconn.Close() @@ -49,7 +49,7 @@ func (apps *HdaApps) list() error { if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_error(err.Error()) + logError(err.Error()) return err } newApps := make([]*HdaApp, 0) diff --git a/src/fs/hda_shares.go b/src/fs/hda_shares.go index ca24f48..2896858 100644 --- a/src/fs/hda_shares.go +++ b/src/fs/hda_shares.go @@ -59,19 +59,19 @@ func (shares *HdaShares) updateSqlShares() error { if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_error(err.Error()) + logError(err.Error()) return err } defer dbconn.Close() q := SQL_SELECT_SHARES //debug(5, "share query: %s\n", q) //log2.Debug(fmt.Sprintf("share query: %s\n", q)) - log_debug("share query: %s\n", q) + logDebug("share query: %s\n", q) rows, err := dbconn.Query(q) if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_error(err.Error()) + logError(err.Error()) return err } newShares := make([]*HdaShare, 0) @@ -80,7 +80,7 @@ func (shares *HdaShares) updateSqlShares() error { rows.Scan(&share.name, &share.updatedAt, &share.path, &share.tags) //debug(5, "share found: %s\n", share.name) //log2.Debug(fmt.Sprintf("share found: %s\n", share.name)) - log_debug("share found: %s\n", share.name) + logDebug("share found: %s\n", share.name) newShares = append(newShares, share) } @@ -98,7 +98,7 @@ func (shares *HdaShares) updateDirShares() (nil error) { if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_error(err.Error()) + logError(err.Error()) return err } defer dir.Close() @@ -195,7 +195,7 @@ func (shares *HdaShares) startMetadataPrefill(library *metadata.Library) { tags := strings.ToLower(shares.Shares[i].tags) //debug(5, `checking share "%s" (%s) with tags: %s\n`, shares.Shares[i].name, path, tags) //log2.Debug(fmt.Sprintf(`checking share "%s" (%s) with tags: %s\n`, shares.Shares[i].name, path, tags)) - log_debug(`checking share "%s" (%s) with tags: %s\n`, shares.Shares[i].name, path, tags) + logDebug(`checking share "%s" (%s) with tags: %s\n`, shares.Shares[i].name, path, tags) if path == "" || tags == "" { continue } diff --git a/src/fs/hda_users.go b/src/fs/hda_users.go index d56671d..f905ab9 100644 --- a/src/fs/hda_users.go +++ b/src/fs/hda_users.go @@ -46,7 +46,7 @@ func (users *HdaUsers) queryUser(pin string) (*string, error) { if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_error(err.Error()) + logError(err.Error()) return nil, err } defer dbconn.Close() @@ -113,7 +113,7 @@ func (users *HdaUsers) revalidateSession(authToken string, user *HdaUser) (isVal if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_error(err.Error()) + logError(err.Error()) return } defer dbconn.Close() @@ -136,7 +136,7 @@ func (user *HdaUser) AvailableShares() ([]*HdaShare, error) { if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_error(err.Error()) + logError(err.Error()) return nil, err } defer dbconn.Close() @@ -151,7 +151,7 @@ func (user *HdaUser) AvailableShares() ([]*HdaShare, error) { if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_error(err.Error()) + logError(err.Error()) return nil, err } newShares := make([]*HdaShare, 0) @@ -171,7 +171,7 @@ func (user *HdaUser) HasReadAccess(shareName string) (access bool, err error) { if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_error(err.Error()) + logError(err.Error()) return } defer dbconn.Close() @@ -191,7 +191,7 @@ func (user *HdaUser) HasWriteAccess(shareName string) (access bool, err error) { if err != nil { //log(err.Error()) //log2.Info(err.Error()) - log_error(err.Error()) + logError(err.Error()) return } defer dbconn.Close() diff --git a/src/fs/local_server.go b/src/fs/local_server.go index cdc768d..41b3b23 100644 --- a/src/fs/local_server.go +++ b/src/fs/local_server.go @@ -21,11 +21,11 @@ func (service *MercuryFsService) startLocalServer() { if err != nil { //log("Could not resolve local address") //log2.Fatal("Could not resolve local address") - log_fatal("Could not resolve local address") + logFatal("Could not resolve local address") //debug(2, "Error resolving local address: %s", err.Error()) //log2.Error(fmt.Sprintf("Error resolving local address: %s", err.Error())) - log_error("Error resolving local address: %s", err.Error()) + logError("Error resolving local address: %s", err.Error()) return } @@ -33,11 +33,11 @@ func (service *MercuryFsService) startLocalServer() { if err != nil { //log("Local server could not be started") //log2.Fatal("Local server could not be started") - log_fatal("Local server could not be started") + logFatal("Local server could not be started") //debug(2, "Error on ListenTCP: %s", err.Error()) //log2.Debug(fmt.Sprintf("Error on ListenTCP: %s", err.Error())) - log_error("Error on ListenTCP: %s", err.Error()) + logError("Error on ListenTCP: %s", err.Error()) return } defer listener.Close() @@ -45,19 +45,19 @@ func (service *MercuryFsService) startLocalServer() { for { //log("Starting local file server") //log2.Info("Starting local file server") - log_info("Starting local file server") + logInfo("Starting local file server") //debug(2, "Starting local file server at: %s", LocalServerPort) //log2.Debug(fmt.Sprintf("Starting local file server at: %s", LocalServerPort)) - log_info("Starting local file server at: %s", LocalServerPort) + logInfo("Starting local file server at: %s", LocalServerPort) err = service.server.Serve(listener) if err != nil { //log("An error occurred in the local file server") //log2.Error("An error occurred in the local file server") - log_warn("An error occurred in the local file server") + logWarn("An error occurred in the local file server") //debug(2, "local file server: %s", err.Error()) //log2.Debug(fmt.Sprintf(2, "local file server: %s", err.Error())) - log_error("local file server: %s", err.Error()) + logError("local file server: %s", err.Error()) } } } diff --git a/src/fs/logging.go b/src/fs/logging.go index e9e9d5f..4ffda98 100644 --- a/src/fs/logging.go +++ b/src/fs/logging.go @@ -41,37 +41,42 @@ func getLogLevel() log2.Level { return log2.GetLevel() } -func log_trace(f string, args ...interface{}) { +func logTrace(f string, args ...interface{}) { msg := fmt.Sprintf(f, args...) log2.Trace(msg) } -func log_debug(f string, args ...interface{}) { +func logDebug(f string, args ...interface{}) { msg := fmt.Sprintf(f, args...) log2.Debug(msg) } -func log_info(f string, args ...interface{}) { +func logInfo(f string, args ...interface{}) { msg := fmt.Sprintf(f, args...) log2.Info(msg) } -func log_warn(f string, args ...interface{}) { +func logWarn(f string, args ...interface{}) { msg := fmt.Sprintf(f, args...) log2.Warn(msg) } -func log_error(f string, args ...interface{}) { +func logError(f string, args ...interface{}) { msg := fmt.Sprintf(f, args...) log2.Error(msg) } -func log_fatal(f string, args ...interface{}) { +func logFatal(f string, args ...interface{}) { msg := fmt.Sprintf(f, args...) log2.Fatal(msg) } -func log_panic(f string, args ...interface{}) { +func logPanic(f string, args ...interface{}) { msg := fmt.Sprintf(f, args...) log2.Panic(msg) } + +func logHttp(method, endpoint string, responseCode, responseSize int, ua string) { + //having a separate method for logging will help easily modify the log statements if required + logInfo("\"%s %s\" %d %d \"%s\"", method, endpoint, responseCode, responseSize, ua) +} diff --git a/src/fs/service.go b/src/fs/service.go index 8601ba8..f0d84da 100644 --- a/src/fs/service.go +++ b/src/fs/service.go @@ -62,7 +62,7 @@ func NewMercuryFSService(rootDir, localAddr string, isDemo bool) (service *Mercu service.Users = NewHdaUsers(isDemo) service.Shares, err = NewHdaShares(rootDir) if err != nil { - log_error("Error making HdaShares: %s", err.Error()) + logError("Error making HdaShares: %s", err.Error()) return nil, err } service.debugInfo = new(debugInfo) @@ -94,7 +94,7 @@ func NewMercuryFSService(rootDir, localAddr string, isDemo bool) (service *Mercu } else { actualAddr, err := GetLocalAddr(rootDir) if err != nil { - log_error("Error getting local address: %s", err.Error()) + logError("Error getting local address: %s", err.Error()) return nil, err } service.info.local_addr = actualAddr + ":" + LocalServerPort @@ -102,8 +102,8 @@ func NewMercuryFSService(rootDir, localAddr string, isDemo bool) (service *Mercu // This will be set when the HDA connects to the proxy service.info.relay_addr = "" - log_debug("Amahi FS Service started") - log_debug("HDA Info: %s", service.info.to_json()) + logDebug("Amahi FS Service started") + logDebug("HDA Info: %s", service.info.to_json()) return service, err } @@ -152,11 +152,11 @@ func directory(fi os.FileInfo, js string, w http.ResponseWriter, request *http.R inm := request.Header.Get("If-None-Match") if inm == etag { size = 0 - log_debug("If-None-Match match found for %s", etag) + logDebug("If-None-Match match found for %s", etag) w.WriteHeader(http.StatusNotModified) status = 304 } else { - log_debug("If-None-Match (%s) match NOT found for Etag %s", inm, etag) + logDebug("If-None-Match (%s) match NOT found for Etag %s", inm, etag) size = int64(len(json)) w.Header().Set("Content-Length", strconv.FormatInt(size, 10)) w.Header().Set("Last-Modified", fi.ModTime().UTC().Format(http.TimeFormat)) @@ -185,7 +185,7 @@ func (service *MercuryFsService) fullPathToFile(shareName, relativePath string) // serve requests with the ServeConn function over HTTP/2, in goroutines, until we get some error func (service *MercuryFsService) StartServing(conn net.Conn) error { - log_info("Connection to the proxy established.") + logInfo("Connection to the proxy established.") service.info.relay_addr = conn.RemoteAddr().String() serveConnOpts := &http2.ServeConnOpts{BaseConfig: service.server} @@ -194,7 +194,7 @@ func (service *MercuryFsService) StartServing(conn net.Conn) error { // start serving over http2 on provided conn and block until connection is lost server2.ServeConn(conn, serveConnOpts) - log_warn("Lost connection to the proxy.") + logWarn("Lost connection to the proxy.") service.info.relay_addr = "" return errors.New("connection is no longer readable") } @@ -206,24 +206,26 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * ua := request.Header.Get("User-Agent") query := pathForLog(request.URL) - log_debug(2, "serveFile GET request") + logDebug("serveFile GET request") service.printRequest(request) fullPath, err := service.fullPathToFile(share, path) if err != nil { - log_debug("File not found: %s", err) + logDebug("File not found: %s", err) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - log_info("\"GET %s\" 404 0 \"%s\"", query, ua) + //logInfo("\"GET %s\" 404 0 \"%s\"", query, ua) + logHttp("GET", query, 404, 0, ua) return } osFile, err := os.Open(fullPath) if err != nil { - log_debug("Error opening file: %s", err.Error()) + logDebug("Error opening file: %s", err.Error()) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - log_info("\"GET %s\" 404 0 \"%s\"", query, ua) + //logInfo("\"GET %s\" 404 0 \"%s\"", query, ua) + logHttp("GET", query, 404, 0, ua) return } defer osFile.Close() @@ -236,16 +238,18 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * jsonDir, err := dirToJSON(osFile, fullPath) if err != nil { //debug(2, "Error converting dir to JSON: %s", err.Error()) - log_debug("Error converting dir to JSON: %s", err.Error()) + logDebug("Error converting dir to JSON: %s", err.Error()) //log("\"GET %s\" 404 0 \"%s\"", query, ua) - log_info("\"GET %s\" 404 0 \"%s\"", query, ua) + //logInfo("\"GET %s\" 404 0 \"%s\"", query, ua) + logHttp("GET", query, 404, 0, ua) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) return } status, size := directory(fi, jsonDir, writer, request) service.debugInfo.requestServed(size) - log_info("\"GET %s\" %d %d \"%s\"", query, status, size, ua) + //logInfo("\"GET %s\" %d %d \"%s\"", query, status, size, ua) + logHttp("GET", query, int(status), int(size), ua) return } @@ -254,16 +258,18 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * etag := `"` + sha1string(path+mtime) + `"` inm := request.Header.Get("If-None-Match") if inm == etag { - log_info("If-None-Match match found for %s", etag) + logInfo("If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) - log_info("\"GET %s\" %d \"%s\"", query, 304, ua) + //logInfo("\"GET %s\" %d \"%s\"", query, 304, ua) + logHttp("GET", query, 304, 0, ua) } else { writer.Header().Set("Last-Modified", mtime) writer.Header().Set("ETag", etag) writer.Header().Set("Cache-Control", "max-age=0, private, must-revalidate") - log_info("Etag sent: %s", etag) + logInfo("Etag sent: %s", etag) http.ServeContent(writer, request, fullPath, fi.ModTime(), osFile) - log_info("\"GET %s\" %d %d \"%s\"", query, 200, fi.Size(), ua) + //logInfo("\"GET %s\" %d %d \"%s\"", query, 200, fi.Size(), ua) + logHttp("GET", query, 200, int(fi.Size()), ua) service.debugInfo.requestServed(fi.Size()) } return @@ -288,17 +294,17 @@ func (service *MercuryFsService) serveShares(writer http.ResponseWriter, request service.Shares.updateShares() shares = service.Shares.Shares } - log_debug("========= DEBUG Share request: %d", len(shares)) + logDebug("========= DEBUG Share request: %d", len(shares)) json := SharesJson(shares) - log_debug("Share JSON: %s", json) + logDebug("Share JSON: %s", json) etag := `"` + sha1bytes([]byte(json)) + `"` inm := request.Header.Get("If-None-Match") if inm == etag { - log_info("If-None-Match match found for %s", etag) + logInfo("If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) service.debugInfo.requestServed(int64(0)) } else { - log_info("If-None-Match (%s) match NOT found for Etag %s", inm, etag) + logInfo("If-None-Match (%s) match NOT found for Etag %s", inm, etag) size := int64(len(json)) writer.Header().Set("Content-Length", strconv.FormatInt(size, 10)) writer.Header().Set("Last-Modified", time.Now().Format(http.TimeFormat)) @@ -320,7 +326,7 @@ func GetLocalAddr(rootDir string) (string, error) { dbconn, err := sql.Open("mysql", MYSQL_CREDENTIALS) if err != nil { //log(err.Error()) - log_error(err.Error()) + logError(err.Error()) return "", err } defer dbconn.Close() @@ -331,17 +337,17 @@ func GetLocalAddr(rootDir string) (string, error) { err = row.Scan(&prefix) if err != nil { //log(err.Error()) - log_info(err.Error()) + logInfo(err.Error()) return "", err } row = dbconn.QueryRow(q, "self-address") err = row.Scan(&addr) if err != nil { - log_error("Error scanning self-address: %s\n", err.Error()) + logError("Error scanning self-address: %s\n", err.Error()) return "", err } - log_info("prefix: %s\taddr: %s", prefix, addr) + logInfo("prefix: %s\taddr: %s", prefix, addr) return prefix + "." + addr, nil } @@ -405,17 +411,17 @@ func (service *MercuryFsService) appsList(writer http.ResponseWriter, request *h } service.Apps = apps service.Apps.list() - log_debug("========= DEBUG apps_list request: %d", len(service.Shares.Shares)) + logDebug("========= DEBUG apps_list request: %d", len(service.Shares.Shares)) json := service.Apps.toJson() - log_debug("App JSON: %s", json) + logDebug("App JSON: %s", json) etag := `"` + sha1bytes([]byte(json)) + `"` inm := request.Header.Get("If-None-Match") if inm == etag { - log_info("If-None-Match match found for %s", etag) + logInfo("If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) service.debugInfo.requestServed(int64(0)) } else { - log_info("If-None-Match (%s) match NOT found for Etag %s", inm, etag) + logInfo("If-None-Match (%s) match NOT found for Etag %s", inm, etag) size := int64(len(json)) writer.Header().Set("Content-Length", strconv.FormatInt(size, 10)) writer.Header().Set("ETag", etag) @@ -430,52 +436,52 @@ func (service *MercuryFsService) appsList(writer http.ResponseWriter, request *h func (service *MercuryFsService) getMetadata(writer http.ResponseWriter, request *http.Request) { // get the filename and the hint q := request.URL + ua := request.Header.Get("User-Agent") + query := pathForLog(request.URL) + filename, err := url.QueryUnescape(q.Query().Get("f")) if err != nil { //debug(3, "get_metadata error parsing file: %s", err) - log_debug("get_metadata error parsing file: %s", err) - // FIXME: write proper log statement - log_info("404") + logDebug("get_metadata error parsing file: %s", err) + logHttp("GET", query, 404, 0, ua) http.NotFound(writer, request) return } hint, err := url.QueryUnescape(q.Query().Get("h")) if err != nil { //debug(3, "get_metadata error parsing hint: %s", err) - log_debug("get_metadata error parsing hint: %s", err) - // FIXME: write proper log statement - log_info("404") + logDebug("get_metadata error parsing hint: %s", err) + logHttp("GET", query, 404, 0, ua) http.NotFound(writer, request) return } //debug(5, "metadata filename: %s", filename) - log_debug("metadata filename: %s", filename) + logDebug("metadata filename: %s", filename) //debug(5, "metadata hint: %s", hint) - log_debug("metadata hint: %s", hint) + logDebug("metadata hint: %s", hint) // FIXME json, err := service.metadata.GetMetadata(filename, hint) if err != nil { //debug(3, "metadata error: %s", err) - log_debug("metadata error: %s", err) - // FIXME: write proper log statement - log_info("404") + logDebug("metadata error: %s", err) + logHttp("GET", query, 404, 0, ua) http.NotFound(writer, request) return } //debug(5, "========= DEBUG get_metadata request: %d", len(service.Shares.Shares)) - log_debug("========= DEBUG get_metadata request: %d", len(service.Shares.Shares)) + logDebug("========= DEBUG get_metadata request: %d", len(service.Shares.Shares)) //debug(5, "metadata JSON: %s", json) - log_debug("metadata JSON: %s", json) + logDebug("metadata JSON: %s", json) etag := `"` + sha1bytes([]byte(json)) + `"` inm := request.Header.Get("If-None-Match") if inm == etag { //debug(4, "If-None-Match match found for %s", etag) - log_info("If-None-Match match found for %s", etag) + logInfo("If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) service.debugInfo.requestServed(int64(0)) } else { //debug(4, "If-None-Match (%s) match NOT found for Etag %s", inm, etag) - log_info("If-None-Match (%s) match NOT found for Etag %s", inm, etag) + logInfo("If-None-Match (%s) match NOT found for Etag %s", inm, etag) size := int64(len(json)) writer.Header().Set("Content-Length", strconv.FormatInt(size, 10)) writer.Header().Set("ETag", etag) @@ -489,17 +495,17 @@ func (service *MercuryFsService) getMetadata(writer http.ResponseWriter, request func (service *MercuryFsService) printRequest(request *http.Request) { //debug(5, "REQUEST [from %s] BEGIN =========================", request.RemoteAddr) - log_debug("REQUEST [from %s] BEGIN =========================", request.RemoteAddr) + logDebug("REQUEST [from %s] BEGIN =========================", request.RemoteAddr) if request.Method != "POST" { rawRequest, _ := httputil.DumpRequest(request, true) //debug(5, "%s", rawRequest) - log_debug("%s", rawRequest) + logDebug("%s", rawRequest) } else { //debug(5, "POST Request to %s (details removed)", request.URL) - log_debug("POST Request to %s (details removed)", request.URL) + logDebug("POST Request to %s (details removed)", request.URL) } //debug(5, "REQUEST END =========================") - log_debug("REQUEST END =========================") + logDebug("REQUEST END =========================") } func (service *MercuryFsService) topVhostFilter(writer http.ResponseWriter, request *http.Request) { @@ -518,7 +524,7 @@ func (service *MercuryFsService) topVhostFilter(writer http.ResponseWriter, requ re := regexp.MustCompile(`Vhost/([^\s]*)`) matches := re.FindStringSubmatch(ua) //debug(5, "VHOST matches %q *************************", matches) - log_debug("VHOST matches %q *************************", matches) + logDebug("VHOST matches %q *************************", matches) if len(matches) != 2 { service.printRequest(request) // if no vhost, default to API? @@ -532,13 +538,13 @@ func (service *MercuryFsService) topVhostFilter(writer http.ResponseWriter, requ app := service.Apps.get(vhost) if app == nil { //debug(5, "No matching app found for VHOST %s", vhost) - log_debug("No matching app found for VHOST %s", vhost) + logDebug("No matching app found for VHOST %s", vhost) http.Error(writer, "Unknown App", http.StatusNotFound) return } //debug(5, "VHOST REQUEST FOR %s *************************", vhost) - log_debug("VHOST REQUEST FOR %s *************************", vhost) + logDebug("VHOST REQUEST FOR %s *************************", vhost) request.URL.Host = "hda" request.Host = vhost @@ -547,7 +553,7 @@ func (service *MercuryFsService) topVhostFilter(writer http.ResponseWriter, requ remote, err := url.Parse("http://" + vhost) if err != nil { //debug(5, "REQUEST ERROR: %s", err) - log_debug("REQUEST ERROR: %s", err) + logDebug("REQUEST ERROR: %s", err) http.NotFound(writer, request) return } @@ -568,7 +574,7 @@ func (service *MercuryFsService) deleteFile(writer http.ResponseWriter, request query := pathForLog(request.URL) //debug(2, "deleteFile DELETE request") - log_debug("deleteFile DELETE request") + logDebug("deleteFile DELETE request") service.printRequest(request) @@ -578,26 +584,28 @@ func (service *MercuryFsService) deleteFile(writer http.ResponseWriter, request if !noDelete { if err != nil { //debug(2, "File not found: %s", err) - log_debug("File not found: %s", err) + logDebug("File not found: %s", err) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) //log("\"DELETE %s\" 404 0 \"%s\"", query, ua) - log_info("\"DELETE %s\" 404 0 \"%s\"", query, ua) + //logInfo("\"DELETE %s\" 404 0 \"%s\"", query, ua) + logHttp("GET", query, 404, 0, ua) return } err = os.Remove(fullPath) if err != nil { //debug(2, "Error removing file: %s", err.Error()) - log_debug("Error removing file: %s", err.Error()) + logDebug("Error removing file: %s", err.Error()) writer.WriteHeader(http.StatusExpectationFailed) service.debugInfo.requestServed(int64(0)) //log("\"DELETE %s\" 417 0 \"%s\"", query, ua) - log_info("\"DELETE %s\" 417 0 \"%s\"", query, ua) + //logInfo("\"DELETE %s\" 417 0 \"%s\"", query, ua) + logHttp("GET", query, 417, 0, ua) return } } else { //debug(2, "NOTICE: Running in no-delete mode. Would have deleted: %s", fullPath) - log_warn("NOTICE: Running in no-delete mode. Would have deleted: %s", fullPath) + logWarn("NOTICE: Running in no-delete mode. Would have deleted: %s", fullPath) } writer.WriteHeader(http.StatusOK) @@ -614,7 +622,7 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request query := pathForLog(request.URL) //debug(2, "upload_file POST request") - log_debug("upload_file POST request") + logDebug("upload_file POST request") // do NOT print the whole request, as an image may be way way too big service.printRequest(request) @@ -637,11 +645,12 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request if err != nil { //debug(2, "Error parsing image: %s", err.Error()) - log_debug("Error parsing image: %s", err.Error()) + logDebug("Error parsing image: %s", err.Error()) writer.WriteHeader(http.StatusPreconditionFailed) service.debugInfo.requestServed(int64(0)) //log("\"POST %s\" 412 0 \"%s\"", query, ua) - log_info("\"POST %s\" 412 0 \"%s\"", query, ua) + //logInfo("\"POST %s\" 412 0 \"%s\"", query, ua) + logHttp("GET", query, 412, 0, ua) return } @@ -649,11 +658,12 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request file, handler, err := request.FormFile("file") if err != nil { //debug(2, "Error finding uploaded file: %s", err.Error()) - log_debug("Error finding uploaded file: %s", err.Error()) + logDebug("Error finding uploaded file: %s", err.Error()) writer.WriteHeader(http.StatusExpectationFailed) service.debugInfo.requestServed(int64(0)) //log("\"POST %s\" 417 0 \"%s\"", query, ua) - log_info("\"POST %s\" 417 0 \"%s\"", query, ua) + //logInfo("\"POST %s\" 417 0 \"%s\"", query, ua) + logHttp("GET", query, 417, 0, ua) return } defer file.Close() @@ -662,11 +672,12 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request //check if the file name is valid if !validFilename(fullPath) { //debug(2, "invalid filename") - log_debug("invalid filename") + logDebug("invalid filename") writer.WriteHeader(http.StatusUnsupportedMediaType) service.debugInfo.requestServed(int64(0)) //log("\"POST %s\" 415 0 \"%s\"", query, ua) - log_info("\"POST %s\" 415 0 \"%s\"", query, ua) + //logInfo("\"POST %s\" 415 0 \"%s\"", query, ua) + logHttp("GET", query, 415, 0, ua) return } @@ -686,11 +697,12 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request } if err != nil { //debug(2, "Error creating uploaded file: %s", err.Error()) - log_error("Error creating uploaded file: %s", err.Error()) + logError("Error creating uploaded file: %s", err.Error()) writer.WriteHeader(http.StatusServiceUnavailable) service.debugInfo.requestServed(int64(0)) //log("\"POST %s\" 503 0 \"%s\"", query, ua) - log_info("\"POST %s\" 503 0 \"%s\"", query, ua) + logInfo("\"POST %s\" 503 0 \"%s\"", query, ua) + logHttp("GET", query, 503, 0, ua) return } // status == FILE_SAME_MD5, ignore it @@ -698,11 +710,11 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request io.Copy(f, file) //debug(2, "POST of a file upload parsed successfully") - log_trace("POST of a file upload parsed successfully") + logTrace("POST of a file upload parsed successfully") } else { //debug(2, "NOTICE: Running in no-upload mode.") - log_trace("NOTICE: Running in no-upload mode.") + logTrace("NOTICE: Running in no-upload mode.") } writer.WriteHeader(http.StatusOK) @@ -728,10 +740,11 @@ func (service *MercuryFsService) serveLogs(writer http.ResponseWriter, request * osFile, err := os.Open(LOGFILE) if err != nil { - log_debug("Error opening log file: %s", err.Error()) + logDebug("Error opening log file: %s", err.Error()) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - log_info("\"GET %s\" 404 0 \"%s\"", query, ua) + //logInfo("\"GET %s\" 404 0 \"%s\"", query, ua) + logHttp("GET", query, 404, 0, ua) return } defer osFile.Close() @@ -739,11 +752,13 @@ func (service *MercuryFsService) serveLogs(writer http.ResponseWriter, request * fi, _ := osFile.Stat() if mode == -1 { http.ServeContent(writer, request, osFile.Name(), fi.ModTime(), osFile) - log_info("\"GET %s\" %d %d \"%s\"", query, 200, fi.Size(), ua) + //logInfo("\"GET %s\" %d %d \"%s\"", query, 200, fi.Size(), ua) + logHttp("GET", query, 200, int(fi.Size()), ua) } else { // TODO: add log number to the log file. Make use of bufio.Scanner to readlines. Make use of binary search // to find the appropriate line number. http.ServeContent(writer, request, osFile.Name(), fi.ModTime(), osFile) - log_info("\"GET %s\" %d %d \"%s\"", query, 200, fi.Size(), ua) + //logInfo("\"GET %s\" %d %d \"%s\"", query, 200, fi.Size(), ua) + logHttp("GET", query, 200, int(fi.Size()), ua) } } From ae78fc91455cfa3d42101b826f317db0ee389937 Mon Sep 17 00:00:00 2001 From: Vishwas Mittal Date: Thu, 22 Aug 2019 16:39:22 +0530 Subject: [PATCH 5/9] refactoring and fixing log API --- src/fs/auth.go | 44 ++++++++++++++++++++++++++++++++------------ src/fs/file_utils.go | 25 +++++++++++++++++++++++++ src/fs/logging.go | 5 ++--- src/fs/service.go | 29 +++++++++++++++++++++++++---- 4 files changed, 84 insertions(+), 19 deletions(-) create mode 100644 src/fs/file_utils.go diff --git a/src/fs/auth.go b/src/fs/auth.go index 81012c2..6b5c0be 100644 --- a/src/fs/auth.go +++ b/src/fs/auth.go @@ -37,6 +37,7 @@ func (service *MercuryFsService) authenticate(writer http.ResponseWriter, reques err := decoder.Decode(&data) if err != nil { writer.WriteHeader(http.StatusBadRequest) + logHttp(request.Method, pathForLog(request.URL), http.StatusBadRequest, 0, request.Header.Get("User-Agent")) return } // read pin from the json body @@ -44,6 +45,7 @@ func (service *MercuryFsService) authenticate(writer http.ResponseWriter, reques if !ok { // pin is not a string, send 400 Bad Request writer.WriteHeader(http.StatusBadRequest) + logHttp(request.Method, pathForLog(request.URL), http.StatusBadRequest, 0, request.Header.Get("User-Agent")) return } // query user for the given pin from the list of all users @@ -51,11 +53,15 @@ func (service *MercuryFsService) authenticate(writer http.ResponseWriter, reques switch { case err == sql.ErrNoRows: // if no such user exits, send 401 Unauthorized logInfo("No user with pin: %s", pin) - http.Error(writer, "Authentication Failed", http.StatusUnauthorized) + errMsg := "Authentication Failed" + http.Error(writer, errMsg, http.StatusUnauthorized) + logHttp(request.Method, pathForLog(request.URL), http.StatusUnauthorized, len(errMsg), request.Header.Get("User-Agent")) break case err != nil: // if some other error, send 500 Internal Server Error - http.Error(writer, "Internal Server Error", http.StatusInternalServerError) logError(err.Error()) + errMsg := "Internal Server Error" + http.Error(writer, errMsg, http.StatusInternalServerError) + logHttp(request.Method, pathForLog(request.URL), http.StatusInternalServerError, len(errMsg), request.Header.Get("User-Agent")) break default: // if no error, send proper auth token for that user respJson := fmt.Sprintf("{\"auth_token\": \"%s\"}", *authToken) @@ -64,13 +70,15 @@ 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(request.Method, pathForLog(request.URL), http.StatusOK, int(size), request.Header.Get("User-Agent")) } } -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(request.Method, pathForLog(request.URL), http.StatusOK, 0, request.Header.Get("User-Agent")) } func (service *MercuryFsService) checkAuthHeader(w http.ResponseWriter, r *http.Request) (user *HdaUser) { @@ -78,9 +86,11 @@ func (service *MercuryFsService) checkAuthHeader(w http.ResponseWriter, r *http. 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(r.Method, pathForLog(r.URL), http.StatusUnauthorized, len(errMsg), r.Header.Get("User-Agent")) } - 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(r.Method, pathForLog(r.URL), http.StatusForbidden, len(errMsg), r.Header.Get("User-Agent")) } else { - http.Error(w, "Internal Server Error", http.StatusInternalServerError) + errMsg := "Internal Server Error" + http.Error(w, errMsg, http.StatusInternalServerError) + logHttp(r.Method, pathForLog(r.URL), http.StatusInternalServerError, len(errMsg), r.Header.Get("User-Agent")) } 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(r.Method, pathForLog(r.URL), http.StatusForbidden, len(errMsg), r.Header.Get("User-Agent")) 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(r.Method, pathForLog(r.URL), http.StatusForbidden, len(errMsg), r.Header.Get("User-Agent")) } else { - http.Error(w, "Internal Server Error", http.StatusInternalServerError) + errMsg := "Internal Server Error" + http.Error(w, errMsg, http.StatusInternalServerError) + logHttp(r.Method, pathForLog(r.URL), http.StatusForbidden, len(errMsg), r.Header.Get("User-Agent")) } return } diff --git a/src/fs/file_utils.go b/src/fs/file_utils.go new file mode 100644 index 0000000..224ce61 --- /dev/null +++ b/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 +} diff --git a/src/fs/logging.go b/src/fs/logging.go index 26016aa..c84e984 100644 --- a/src/fs/logging.go +++ b/src/fs/logging.go @@ -15,8 +15,7 @@ import ( "os" ) -//const LOGFILE = "/var/log/amahi-anywhere.log" -const LOGFILE = "temp_log.log" +const LOGFILE = "/var/log/amahi-anywhere.log" func initializeLogging() { logFile, err := os.OpenFile(LOGFILE, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644) @@ -26,7 +25,7 @@ func initializeLogging() { } Formatter := new(log.TextFormatter) - Formatter.TimestampFormat = "02-01-2006 15:04:05" + Formatter.TimestampFormat = "02-01-2006 15:04:05.000" Formatter.FullTimestamp = true Formatter.DisableColors = true log.SetFormatter(Formatter) diff --git a/src/fs/service.go b/src/fs/service.go index ada3333..bfbd16d 100644 --- a/src/fs/service.go +++ b/src/fs/service.go @@ -81,6 +81,9 @@ func NewMercuryFSService(rootDir, localAddr string, isDemo bool) (service *Mercu apiRouter.HandleFunc("/hda_debug", service.hdaDebug).Methods("GET") apiRouter.HandleFunc("/logs", service.serveLogs).Methods("GET") + apiRouter.MethodNotAllowedHandler = http.HandlerFunc(service.methodNotAllowedHandler) + apiRouter.NotFoundHandler = http.HandlerFunc(service.notFoundHandler) + service.apiRouter = apiRouter serveMux := http.NewServeMux() @@ -115,6 +118,22 @@ func (service *MercuryFsService) String() string { return SharesJson(service.Shares.Shares) } +//type notFoundHandler struct {} +func (servier *MercuryFsService) notFoundHandler(writer http.ResponseWriter, request *http.Request) { + errMsg := "404 page not found" + writer.WriteHeader(http.StatusNotFound) + writer.Write([]byte(errMsg)) + logHttp(request.Method, pathForLog(request.URL), http.StatusNotFound, len(errMsg), request.Header.Get("User-Agent")) +} + +//type methodNotAllowedHandler struct{} +func (service *MercuryFsService) methodNotAllowedHandler(writer http.ResponseWriter, request *http.Request) { + errMsg := "405 method not allowed" + writer.WriteHeader(http.StatusMethodNotAllowed) + writer.Write([]byte(errMsg)) + logHttp(request.Method, pathForLog(request.URL), http.StatusMethodNotAllowed, len(errMsg), request.Header.Get("User-Agent")) +} + func (service *MercuryFsService) hdaDebug(writer http.ResponseWriter, request *http.Request) { // I am purposely not calling any of the update methods of debugInfo to actually provide valuable info result := "{\n" @@ -775,9 +794,11 @@ func (service *MercuryFsService) serveLogs(writer http.ResponseWriter, request * http.ServeContent(writer, request, osFile.Name(), fi.ModTime(), osFile) logHttp("GET", query, 200, int(fi.Size()), ua) } else { - // TODO: add log number to the log file. Make use of bufio.Scanner to readlines. Make use of binary search - // to find the appropriate line number. - http.ServeContent(writer, request, osFile.Name(), fi.ModTime(), osFile) - logHttp("GET", query, 200, int(fi.Size()), ua) + data, err := Tail(mode) + if err != nil { + writer.WriteHeader(http.StatusNotFound) + } + size, _ := writer.Write(data) + logHttp("GET", query, 200, size, ua) } } From 5cc3ad024b692f92ca6a01c0efd4690e4999b4c5 Mon Sep 17 00:00:00 2001 From: Vishwas Mittal Date: Thu, 22 Aug 2019 17:12:27 +0530 Subject: [PATCH 6/9] updated HTTP logging function --- src/fs/auth.go | 24 ++++++++-------- src/fs/fs.go | 4 +-- src/fs/logging.go | 10 +++++-- src/fs/service.go | 71 ++++++++++++++++++++++------------------------- 4 files changed, 55 insertions(+), 54 deletions(-) diff --git a/src/fs/auth.go b/src/fs/auth.go index 6b5c0be..de3a1fb 100644 --- a/src/fs/auth.go +++ b/src/fs/auth.go @@ -37,7 +37,7 @@ func (service *MercuryFsService) authenticate(writer http.ResponseWriter, reques err := decoder.Decode(&data) if err != nil { writer.WriteHeader(http.StatusBadRequest) - logHttp(request.Method, pathForLog(request.URL), http.StatusBadRequest, 0, request.Header.Get("User-Agent")) + logHttp(request, http.StatusBadRequest, 0) return } // read pin from the json body @@ -45,7 +45,7 @@ func (service *MercuryFsService) authenticate(writer http.ResponseWriter, reques if !ok { // pin is not a string, send 400 Bad Request writer.WriteHeader(http.StatusBadRequest) - logHttp(request.Method, pathForLog(request.URL), http.StatusBadRequest, 0, request.Header.Get("User-Agent")) + logHttp(request, http.StatusBadRequest, 0) return } // query user for the given pin from the list of all users @@ -55,13 +55,13 @@ func (service *MercuryFsService) authenticate(writer http.ResponseWriter, reques logInfo("No user with pin: %s", pin) errMsg := "Authentication Failed" http.Error(writer, errMsg, http.StatusUnauthorized) - logHttp(request.Method, pathForLog(request.URL), http.StatusUnauthorized, len(errMsg), request.Header.Get("User-Agent")) + logHttp(request, http.StatusUnauthorized, len(errMsg)) break case err != nil: // if some other error, send 500 Internal Server Error logError(err.Error()) errMsg := "Internal Server Error" http.Error(writer, errMsg, http.StatusInternalServerError) - logHttp(request.Method, pathForLog(request.URL), http.StatusInternalServerError, len(errMsg), request.Header.Get("User-Agent")) + logHttp(request, http.StatusInternalServerError, len(errMsg)) break default: // if no error, send proper auth token for that user respJson := fmt.Sprintf("{\"auth_token\": \"%s\"}", *authToken) @@ -70,7 +70,7 @@ 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(request.Method, pathForLog(request.URL), http.StatusOK, int(size), request.Header.Get("User-Agent")) + logHttp(request, http.StatusOK, int(size)) } } @@ -78,7 +78,7 @@ func (service *MercuryFsService) logout(writer http.ResponseWriter, request *htt authToken := parseAuthToken(request) service.Users.remove(authToken) writer.WriteHeader(http.StatusOK) - logHttp(request.Method, pathForLog(request.URL), http.StatusOK, 0, request.Header.Get("User-Agent")) + logHttp(request, http.StatusOK, 0) } func (service *MercuryFsService) checkAuthHeader(w http.ResponseWriter, r *http.Request) (user *HdaUser) { @@ -88,7 +88,7 @@ func (service *MercuryFsService) checkAuthHeader(w http.ResponseWriter, r *http. if user == nil { errMsg := "Authentication Failed" http.Error(w, errMsg, http.StatusUnauthorized) - logHttp(r.Method, pathForLog(r.URL), http.StatusUnauthorized, len(errMsg), r.Header.Get("User-Agent")) + logHttp(r, http.StatusUnauthorized, len(errMsg)) } return user } @@ -127,11 +127,11 @@ func (service *MercuryFsService) shareReadAccess(pass http.HandlerFunc) http.Han if err == nil { errMsg := "Access Forbidden" http.Error(w, errMsg, http.StatusForbidden) - logHttp(r.Method, pathForLog(r.URL), http.StatusForbidden, len(errMsg), r.Header.Get("User-Agent")) + logHttp(r, http.StatusForbidden, len(errMsg)) } else { errMsg := "Internal Server Error" http.Error(w, errMsg, http.StatusInternalServerError) - logHttp(r.Method, pathForLog(r.URL), http.StatusInternalServerError, len(errMsg), r.Header.Get("User-Agent")) + logHttp(r, http.StatusInternalServerError, len(errMsg)) } return } @@ -149,7 +149,7 @@ func (service *MercuryFsService) restrictCache(pass http.HandlerFunc) http.Handl if strings.Contains(fullPath, ".fscache") { errMsg := "Cannot access cache via /files" http.Error(w, errMsg, http.StatusForbidden) - logHttp(r.Method, pathForLog(r.URL), http.StatusForbidden, len(errMsg), r.Header.Get("User-Agent")) + logHttp(r, http.StatusForbidden, len(errMsg)) return } @@ -176,11 +176,11 @@ func (service *MercuryFsService) shareWriteAccess(pass http.HandlerFunc) http.Ha if err == nil { errMsg := "Access Forbidden" http.Error(w, errMsg, http.StatusForbidden) - logHttp(r.Method, pathForLog(r.URL), http.StatusForbidden, len(errMsg), r.Header.Get("User-Agent")) + logHttp(r, http.StatusForbidden, len(errMsg)) } else { errMsg := "Internal Server Error" http.Error(w, errMsg, http.StatusInternalServerError) - logHttp(r.Method, pathForLog(r.URL), http.StatusForbidden, len(errMsg), r.Header.Get("User-Agent")) + logHttp(r, http.StatusForbidden, len(errMsg)) } return } diff --git a/src/fs/fs.go b/src/fs/fs.go index 52b5e7d..a54bbfc 100644 --- a/src/fs/fs.go +++ b/src/fs/fs.go @@ -38,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" diff --git a/src/fs/logging.go b/src/fs/logging.go index c84e984..8a86341 100644 --- a/src/fs/logging.go +++ b/src/fs/logging.go @@ -12,6 +12,7 @@ package main import ( "fmt" log "github.com/Sirupsen/logrus" + "net/http" "os" ) @@ -75,9 +76,14 @@ func logPanic(f string, args ...interface{}) { log.Panic(msg) } -func logHttp(method, endpoint string, responseCode, responseSize int, ua string) { +//func logHttp(method, endpoint string, responseCode, responseSize int, ua string) { +// //having a separate method for logging will help easily modify the log statements if required +// logInfo("\"%s %s\" %d %d \"%s\"", method, endpoint, responseCode, responseSize, ua) +//} + +func logHttp(r *http.Request, responseCode,responseSize int) { //having a separate method for logging will help easily modify the log statements if required - logInfo("\"%s %s\" %d %d \"%s\"", method, endpoint, responseCode, responseSize, ua) + logInfo("\"%s %s\" %d %d \"%s\"", r.Method, pathForLog(r.URL), responseCode, responseSize, r.Header.Get("User-Agent")) } func debug(level int, f string, args ...interface{}) { diff --git a/src/fs/service.go b/src/fs/service.go index bfbd16d..396716d 100644 --- a/src/fs/service.go +++ b/src/fs/service.go @@ -123,7 +123,7 @@ func (servier *MercuryFsService) notFoundHandler(writer http.ResponseWriter, req errMsg := "404 page not found" writer.WriteHeader(http.StatusNotFound) writer.Write([]byte(errMsg)) - logHttp(request.Method, pathForLog(request.URL), http.StatusNotFound, len(errMsg), request.Header.Get("User-Agent")) + logHttp(request, http.StatusNotFound, len(errMsg)) } //type methodNotAllowedHandler struct{} @@ -131,7 +131,7 @@ func (service *MercuryFsService) methodNotAllowedHandler(writer http.ResponseWri errMsg := "405 method not allowed" writer.WriteHeader(http.StatusMethodNotAllowed) writer.Write([]byte(errMsg)) - logHttp(request.Method, pathForLog(request.URL), http.StatusMethodNotAllowed, len(errMsg), request.Header.Get("User-Agent")) + logHttp(request, http.StatusMethodNotAllowed, len(errMsg)) } func (service *MercuryFsService) hdaDebug(writer http.ResponseWriter, request *http.Request) { @@ -162,7 +162,8 @@ func (service *MercuryFsService) hdaDebug(writer http.ResponseWriter, request *h result += "}" writer.WriteHeader(200) - writer.Write([]byte(result)) + size, _ := writer.Write([]byte(result)) + logHttp(request, 200, size) } func directory(fi os.FileInfo, js string, w http.ResponseWriter, request *http.Request) (status, size int64) { @@ -223,8 +224,6 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * q := request.URL path := q.Query().Get("p") share := q.Query().Get("s") - ua := request.Header.Get("User-Agent") - query := pathForLog(request.URL) debug(2, "serve_file GET request") @@ -235,7 +234,7 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * debug(2, "File not found: %s", err) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - logHttp("GET", query, 404, 0, ua) + logHttp(request, 404, 0) return } osFile, err := os.Open(fullPath) @@ -243,7 +242,7 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * debug(2, "Error opening file: %s", err.Error()) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - logHttp("GET", query, 404, 0, ua) + logHttp(request, 404, 0) return } defer osFile.Close() @@ -256,15 +255,15 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * jsonDir, err := dirToJSON(osFile, fullPath, share, path) if err != nil { debug(2, "Error converting dir to JSON: %s", err.Error()) - logHttp("GET", query, 404, 0, ua) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) + logHttp(request, 404, 0) return } debug(5, "%s", jsonDir) status, size := directory(fi, jsonDir, writer, request) service.debugInfo.requestServed(size) - logHttp("GET", query, int(status), int(size), ua) + logHttp(request, int(status), int(size)) return } @@ -275,15 +274,15 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * if inm == etag { debug(4, "If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) - logHttp("GET", query, 304, 0, ua) + logHttp(request, 304, 0) } else { writer.Header().Set("Last-Modified", mtime) writer.Header().Set("ETag", etag) writer.Header().Set("Cache-Control", "max-age=0, private, must-revalidate") debug(4, "Etag sent: %s", etag) http.ServeContent(writer, request, fullPath, fi.ModTime(), osFile) - logHttp("GET", query, 200, int(fi.Size()), ua) service.debugInfo.requestServed(fi.Size()) + logHttp(request, 200, int(fi.Size())) } return } @@ -292,8 +291,6 @@ func (service *MercuryFsService) serveCache(writer http.ResponseWriter, request q := request.URL path := q.Query().Get("p") share := q.Query().Get("s") - ua := request.Header.Get("User-Agent") - query := pathForLog(request.URL) debug(2, "serve_file GET request") @@ -310,7 +307,7 @@ func (service *MercuryFsService) serveCache(writer http.ResponseWriter, request debug(2, "File not found: %s", err) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - logHttp("GET", query, 404, 0, ua) + logHttp(request, 404, 0) return } osFile, err := os.Open(thumbnailPath) @@ -318,7 +315,7 @@ func (service *MercuryFsService) serveCache(writer http.ResponseWriter, request debug(2, "Error opening cache file: %s", err.Error()) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - logHttp("GET", query, 404, 0, ua) + logHttp(request, 404, 0) return } defer osFile.Close() @@ -331,7 +328,7 @@ func (service *MercuryFsService) serveCache(writer http.ResponseWriter, request debug(2, "Cache for directory not available") http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - logHttp("GET", query, 404, 0, ua) + logHttp(request, 404, 0) return } @@ -342,7 +339,7 @@ func (service *MercuryFsService) serveCache(writer http.ResponseWriter, request if inm == etag { debug(4, "If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) - logHttp("GET", query, 304, 0, ua) + logHttp(request, 304, 0) } else { writer.Header().Set("Last-Modified", mtime) writer.Header().Set("ETag", etag) @@ -350,8 +347,8 @@ func (service *MercuryFsService) serveCache(writer http.ResponseWriter, request debug(4, "Etag sent: %s", etag) http.ServeContent(writer, request, thumbnailPath, fi.ModTime(), osFile) - logHttp("GET", query, 200, int(fi.Size()), ua) service.debugInfo.requestServed(fi.Size()) + logHttp(request, 200, int(fi.Size())) } return @@ -386,6 +383,7 @@ func (service *MercuryFsService) serveShares(writer http.ResponseWriter, request debug(4, "If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) service.debugInfo.requestServed(int64(0)) + logHttp(request, http.StatusNotModified, 0) } else { debug(4, "If-None-Match (%s) match NOT found for Etag %s", inm, etag) size := int64(len(json)) @@ -397,6 +395,7 @@ func (service *MercuryFsService) serveShares(writer http.ResponseWriter, request writer.WriteHeader(http.StatusOK) writer.Write([]byte(json)) service.debugInfo.requestServed(size) + logHttp(request, http.StatusOK, int(size)) } } @@ -516,21 +515,19 @@ func (service *MercuryFsService) appsList(writer http.ResponseWriter, request *h func (service *MercuryFsService) getMetadata(writer http.ResponseWriter, request *http.Request) { // get the filename and the hint q := request.URL - ua := request.Header.Get("User-Agent") - query := pathForLog(request.URL) filename, err := url.QueryUnescape(q.Query().Get("f")) if err != nil { debug(3, "get_metadata error parsing file: %s", err) http.NotFound(writer, request) - logHttp("GET", query, 404, 0, ua) + logHttp(request, 404, 0) return } hint, err := url.QueryUnescape(q.Query().Get("h")) if err != nil { debug(3, "get_metadata error parsing hint: %s", err) http.NotFound(writer, request) - logHttp("GET", query, 404, 0, ua) + logHttp(request, 404, 0) return } debug(5, "metadata filename: %s", filename) @@ -540,7 +537,7 @@ func (service *MercuryFsService) getMetadata(writer http.ResponseWriter, request if err != nil { debug(3, "metadata error: %s", err) http.NotFound(writer, request) - logHttp("GET", query, 404, 0, ua) + logHttp(request, 404, 0) return } debug(5, "========= DEBUG get_metadata request: %d", len(service.Shares.Shares)) @@ -551,6 +548,7 @@ func (service *MercuryFsService) getMetadata(writer http.ResponseWriter, request debug(4, "If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) service.debugInfo.requestServed(int64(0)) + logHttp(request, http.StatusUnauthorized, 0) } else { debug(4, "If-None-Match (%s) match NOT found for Etag %s", inm, etag) size := int64(len(json)) @@ -561,6 +559,7 @@ func (service *MercuryFsService) getMetadata(writer http.ResponseWriter, request writer.WriteHeader(http.StatusOK) writer.Write([]byte(json)) service.debugInfo.requestServed(size) + logHttp(request, http.StatusOK, int(size)) } } @@ -633,8 +632,6 @@ func (service *MercuryFsService) deleteFile(writer http.ResponseWriter, request q := request.URL path := q.Query().Get("p") share := q.Query().Get("s") - ua := request.Header.Get("User-Agent") - query := pathForLog(request.URL) debug(2, "deleteFile DELETE request") @@ -648,7 +645,7 @@ func (service *MercuryFsService) deleteFile(writer http.ResponseWriter, request debug(2, "File not found: %s", err) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - logHttp("GET", query, 404, 0, ua) + logHttp(request, 404, 0) return } err = os.Remove(fullPath) @@ -656,7 +653,7 @@ func (service *MercuryFsService) deleteFile(writer http.ResponseWriter, request debug(2, "Error removing file: %s", err.Error()) writer.WriteHeader(http.StatusExpectationFailed) service.debugInfo.requestServed(int64(0)) - logHttp("GET", query, 417, 0, ua) + logHttp(request, 417, 0) return } } else { @@ -664,6 +661,7 @@ func (service *MercuryFsService) deleteFile(writer http.ResponseWriter, request } writer.WriteHeader(http.StatusOK) + logHttp(request, http.StatusOK, 0) return } @@ -673,8 +671,6 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request q := request.URL path := q.Query().Get("p") share := q.Query().Get("s") - ua := request.Header.Get("User-Agent") - query := pathForLog(request.URL) debug(2, "upload_file POST request") @@ -701,7 +697,7 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request debug(2, "Error parsing image: %s", err.Error()) writer.WriteHeader(http.StatusPreconditionFailed) service.debugInfo.requestServed(int64(0)) - logHttp("GET", query, 412, 0, ua) + logHttp(request, 412, 0) return } @@ -711,7 +707,7 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request debug(2, "Error finding uploaded file: %s", err.Error()) writer.WriteHeader(http.StatusExpectationFailed) service.debugInfo.requestServed(int64(0)) - logHttp("GET", query, 417, 0, ua) + logHttp(request, 417, 0) return } defer file.Close() @@ -722,7 +718,7 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request debug(2, "invalid filename") writer.WriteHeader(http.StatusUnsupportedMediaType) service.debugInfo.requestServed(int64(0)) - logHttp("GET", query, 415, 0, ua) + logHttp(request, 415, 0) return } @@ -744,7 +740,7 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request debug(2, "Error creating uploaded file: %s", err.Error()) writer.WriteHeader(http.StatusServiceUnavailable) service.debugInfo.requestServed(int64(0)) - logHttp("POST", query, 503, 0, ua) + logHttp(request, 503, 0) return } // status == FILE_SAME_MD5, ignore it @@ -758,6 +754,7 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request } writer.WriteHeader(http.StatusOK) + logHttp(request, 200, 0) return } @@ -766,8 +763,6 @@ func (service *MercuryFsService) serveLogs(writer http.ResponseWriter, request * // TODO: add log serving API similar to PFE q := request.URL amt := q.Query().Get("mode") - ua := request.Header.Get("User-Agent") - query := pathForLog(request.URL) mode := 100 // determines the numbers of lines to serve (from last). -1 will cause serving complete log file @@ -784,7 +779,7 @@ func (service *MercuryFsService) serveLogs(writer http.ResponseWriter, request * debug(2, "Error opening log file: %s", err.Error()) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - logHttp("GET", query, 404, 0, ua) + logHttp(request, 404, 0) return } defer osFile.Close() @@ -792,13 +787,13 @@ func (service *MercuryFsService) serveLogs(writer http.ResponseWriter, request * fi, _ := osFile.Stat() if mode == -1 { http.ServeContent(writer, request, osFile.Name(), fi.ModTime(), osFile) - logHttp("GET", query, 200, int(fi.Size()), ua) + logHttp(request, 200, int(fi.Size())) } else { data, err := Tail(mode) if err != nil { writer.WriteHeader(http.StatusNotFound) } size, _ := writer.Write(data) - logHttp("GET", query, 200, size, ua) + logHttp(request, 200, size) } } From 5da28d88f1d6d26cfbf4c6fa0ad0714e8c68f82b Mon Sep 17 00:00:00 2001 From: Vishwas Mittal Date: Thu, 22 Aug 2019 17:56:54 +0530 Subject: [PATCH 7/9] added origin location (local/remote) to https log statements --- src/fs/auth.go | 24 ++++++++--------- src/fs/logging.go | 20 +++++++++----- src/fs/service.go | 68 ++++++++++++++++++++++++----------------------- 3 files changed, 60 insertions(+), 52 deletions(-) diff --git a/src/fs/auth.go b/src/fs/auth.go index de3a1fb..b89e822 100644 --- a/src/fs/auth.go +++ b/src/fs/auth.go @@ -37,7 +37,7 @@ func (service *MercuryFsService) authenticate(writer http.ResponseWriter, reques err := decoder.Decode(&data) if err != nil { writer.WriteHeader(http.StatusBadRequest) - logHttp(request, http.StatusBadRequest, 0) + logHttp(service, request, http.StatusBadRequest, 0) return } // read pin from the json body @@ -45,7 +45,7 @@ func (service *MercuryFsService) authenticate(writer http.ResponseWriter, reques if !ok { // pin is not a string, send 400 Bad Request writer.WriteHeader(http.StatusBadRequest) - logHttp(request, http.StatusBadRequest, 0) + logHttp(service, request, http.StatusBadRequest, 0) return } // query user for the given pin from the list of all users @@ -55,13 +55,13 @@ func (service *MercuryFsService) authenticate(writer http.ResponseWriter, reques logInfo("No user with pin: %s", pin) errMsg := "Authentication Failed" http.Error(writer, errMsg, http.StatusUnauthorized) - logHttp(request, http.StatusUnauthorized, len(errMsg)) + logHttp(service, request, http.StatusUnauthorized, len(errMsg)) break case err != nil: // if some other error, send 500 Internal Server Error logError(err.Error()) errMsg := "Internal Server Error" http.Error(writer, errMsg, http.StatusInternalServerError) - logHttp(request, http.StatusInternalServerError, len(errMsg)) + 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) @@ -70,7 +70,7 @@ 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(request, http.StatusOK, int(size)) + logHttp(service, request, http.StatusOK, int(size)) } } @@ -78,7 +78,7 @@ func (service *MercuryFsService) logout(writer http.ResponseWriter, request *htt authToken := parseAuthToken(request) service.Users.remove(authToken) writer.WriteHeader(http.StatusOK) - logHttp(request, http.StatusOK, 0) + logHttp(service, request, http.StatusOK, 0) } func (service *MercuryFsService) checkAuthHeader(w http.ResponseWriter, r *http.Request) (user *HdaUser) { @@ -88,7 +88,7 @@ func (service *MercuryFsService) checkAuthHeader(w http.ResponseWriter, r *http. if user == nil { errMsg := "Authentication Failed" http.Error(w, errMsg, http.StatusUnauthorized) - logHttp(r, http.StatusUnauthorized, len(errMsg)) + logHttp(service, r, http.StatusUnauthorized, len(errMsg)) } return user } @@ -127,11 +127,11 @@ func (service *MercuryFsService) shareReadAccess(pass http.HandlerFunc) http.Han if err == nil { errMsg := "Access Forbidden" http.Error(w, errMsg, http.StatusForbidden) - logHttp(r, http.StatusForbidden, len(errMsg)) + logHttp(service, r, http.StatusForbidden, len(errMsg)) } else { errMsg := "Internal Server Error" http.Error(w, errMsg, http.StatusInternalServerError) - logHttp(r, http.StatusInternalServerError, len(errMsg)) + logHttp(service, r, http.StatusInternalServerError, len(errMsg)) } return } @@ -149,7 +149,7 @@ func (service *MercuryFsService) restrictCache(pass http.HandlerFunc) http.Handl if strings.Contains(fullPath, ".fscache") { errMsg := "Cannot access cache via /files" http.Error(w, errMsg, http.StatusForbidden) - logHttp(r, http.StatusForbidden, len(errMsg)) + logHttp(service, r, http.StatusForbidden, len(errMsg)) return } @@ -176,11 +176,11 @@ func (service *MercuryFsService) shareWriteAccess(pass http.HandlerFunc) http.Ha if err == nil { errMsg := "Access Forbidden" http.Error(w, errMsg, http.StatusForbidden) - logHttp(r, http.StatusForbidden, len(errMsg)) + logHttp(service, r, http.StatusForbidden, len(errMsg)) } else { errMsg := "Internal Server Error" http.Error(w, errMsg, http.StatusInternalServerError) - logHttp(r, http.StatusForbidden, len(errMsg)) + logHttp(service, r, http.StatusForbidden, len(errMsg)) } return } diff --git a/src/fs/logging.go b/src/fs/logging.go index 8a86341..ad48814 100644 --- a/src/fs/logging.go +++ b/src/fs/logging.go @@ -76,14 +76,20 @@ func logPanic(f string, args ...interface{}) { log.Panic(msg) } -//func logHttp(method, endpoint string, responseCode, responseSize int, ua string) { -// //having a separate method for logging will help easily modify the log statements if required -// logInfo("\"%s %s\" %d %d \"%s\"", method, endpoint, responseCode, responseSize, ua) -//} - -func logHttp(r *http.Request, responseCode,responseSize int) { +func logHttp(service *MercuryFsService, r *http.Request, responseCode,responseSize int) { //having a separate method for logging will help easily modify the log statements if required - logInfo("\"%s %s\" %d %d \"%s\"", r.Method, pathForLog(r.URL), responseCode, responseSize, r.Header.Get("User-Agent")) + + var origin string + switch r.Host { + case service.info.local_addr: + origin = "local" + case service.info.relay_addr: + origin = "remote" + default: + origin = "unknown" + } + + logInfo("\"%s %s\" %d %d \"%s\" origin:%s", r.Method, pathForLog(r.URL), responseCode, responseSize, r.Header.Get("User-Agent"), origin) } func debug(level int, f string, args ...interface{}) { diff --git a/src/fs/service.go b/src/fs/service.go index 396716d..79e9a10 100644 --- a/src/fs/service.go +++ b/src/fs/service.go @@ -119,11 +119,11 @@ func (service *MercuryFsService) String() string { } //type notFoundHandler struct {} -func (servier *MercuryFsService) notFoundHandler(writer http.ResponseWriter, request *http.Request) { +func (service *MercuryFsService) notFoundHandler(writer http.ResponseWriter, request *http.Request) { errMsg := "404 page not found" writer.WriteHeader(http.StatusNotFound) writer.Write([]byte(errMsg)) - logHttp(request, http.StatusNotFound, len(errMsg)) + logHttp(service, request, http.StatusNotFound, len(errMsg)) } //type methodNotAllowedHandler struct{} @@ -131,7 +131,7 @@ func (service *MercuryFsService) methodNotAllowedHandler(writer http.ResponseWri errMsg := "405 method not allowed" writer.WriteHeader(http.StatusMethodNotAllowed) writer.Write([]byte(errMsg)) - logHttp(request, http.StatusMethodNotAllowed, len(errMsg)) + logHttp(service, request, http.StatusMethodNotAllowed, len(errMsg)) } func (service *MercuryFsService) hdaDebug(writer http.ResponseWriter, request *http.Request) { @@ -163,7 +163,7 @@ func (service *MercuryFsService) hdaDebug(writer http.ResponseWriter, request *h result += "}" writer.WriteHeader(200) size, _ := writer.Write([]byte(result)) - logHttp(request, 200, size) + logHttp(service, request, 200, size) } func directory(fi os.FileInfo, js string, w http.ResponseWriter, request *http.Request) (status, size int64) { @@ -234,7 +234,7 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * debug(2, "File not found: %s", err) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - logHttp(request, 404, 0) + logHttp(service, request, 404, 0) return } osFile, err := os.Open(fullPath) @@ -242,7 +242,7 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * debug(2, "Error opening file: %s", err.Error()) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - logHttp(request, 404, 0) + logHttp(service, request, 404, 0) return } defer osFile.Close() @@ -257,13 +257,13 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * debug(2, "Error converting dir to JSON: %s", err.Error()) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - logHttp(request, 404, 0) + logHttp(service, request, 404, 0) return } debug(5, "%s", jsonDir) status, size := directory(fi, jsonDir, writer, request) service.debugInfo.requestServed(size) - logHttp(request, int(status), int(size)) + logHttp(service, request, int(status), int(size)) return } @@ -274,7 +274,7 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * if inm == etag { debug(4, "If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) - logHttp(request, 304, 0) + logHttp(service, request, 304, 0) } else { writer.Header().Set("Last-Modified", mtime) writer.Header().Set("ETag", etag) @@ -282,7 +282,7 @@ func (service *MercuryFsService) serveFile(writer http.ResponseWriter, request * debug(4, "Etag sent: %s", etag) http.ServeContent(writer, request, fullPath, fi.ModTime(), osFile) service.debugInfo.requestServed(fi.Size()) - logHttp(request, 200, int(fi.Size())) + logHttp(service, request, 200, int(fi.Size())) } return } @@ -307,7 +307,7 @@ func (service *MercuryFsService) serveCache(writer http.ResponseWriter, request debug(2, "File not found: %s", err) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - logHttp(request, 404, 0) + logHttp(service, request, 404, 0) return } osFile, err := os.Open(thumbnailPath) @@ -315,7 +315,7 @@ func (service *MercuryFsService) serveCache(writer http.ResponseWriter, request debug(2, "Error opening cache file: %s", err.Error()) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - logHttp(request, 404, 0) + logHttp(service, request, 404, 0) return } defer osFile.Close() @@ -328,7 +328,7 @@ func (service *MercuryFsService) serveCache(writer http.ResponseWriter, request debug(2, "Cache for directory not available") http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - logHttp(request, 404, 0) + logHttp(service, request, 404, 0) return } @@ -339,7 +339,7 @@ func (service *MercuryFsService) serveCache(writer http.ResponseWriter, request if inm == etag { debug(4, "If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) - logHttp(request, 304, 0) + logHttp(service, request, 304, 0) } else { writer.Header().Set("Last-Modified", mtime) writer.Header().Set("ETag", etag) @@ -348,7 +348,7 @@ func (service *MercuryFsService) serveCache(writer http.ResponseWriter, request http.ServeContent(writer, request, thumbnailPath, fi.ModTime(), osFile) service.debugInfo.requestServed(fi.Size()) - logHttp(request, 200, int(fi.Size())) + logHttp(service, request, 200, int(fi.Size())) } return @@ -383,7 +383,7 @@ func (service *MercuryFsService) serveShares(writer http.ResponseWriter, request debug(4, "If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) service.debugInfo.requestServed(int64(0)) - logHttp(request, http.StatusNotModified, 0) + logHttp(service, request, http.StatusNotModified, 0) } else { debug(4, "If-None-Match (%s) match NOT found for Etag %s", inm, etag) size := int64(len(json)) @@ -395,7 +395,7 @@ func (service *MercuryFsService) serveShares(writer http.ResponseWriter, request writer.WriteHeader(http.StatusOK) writer.Write([]byte(json)) service.debugInfo.requestServed(size) - logHttp(request, http.StatusOK, int(size)) + logHttp(service, request, http.StatusOK, int(size)) } } @@ -499,6 +499,7 @@ func (service *MercuryFsService) appsList(writer http.ResponseWriter, request *h debug(4, "If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) service.debugInfo.requestServed(int64(0)) + logHttp(service, request, http.StatusNotModified, 0) } else { debug(4, "If-None-Match (%s) match NOT found for Etag %s", inm, etag) size := int64(len(json)) @@ -509,6 +510,7 @@ func (service *MercuryFsService) appsList(writer http.ResponseWriter, request *h writer.WriteHeader(http.StatusOK) writer.Write([]byte(json)) service.debugInfo.requestServed(size) + logHttp(service, request, http.StatusOK, int(size)) } } @@ -520,14 +522,14 @@ func (service *MercuryFsService) getMetadata(writer http.ResponseWriter, request if err != nil { debug(3, "get_metadata error parsing file: %s", err) http.NotFound(writer, request) - logHttp(request, 404, 0) + logHttp(service, request, 404, 0) return } hint, err := url.QueryUnescape(q.Query().Get("h")) if err != nil { debug(3, "get_metadata error parsing hint: %s", err) http.NotFound(writer, request) - logHttp(request, 404, 0) + logHttp(service, request, 404, 0) return } debug(5, "metadata filename: %s", filename) @@ -537,7 +539,7 @@ func (service *MercuryFsService) getMetadata(writer http.ResponseWriter, request if err != nil { debug(3, "metadata error: %s", err) http.NotFound(writer, request) - logHttp(request, 404, 0) + logHttp(service, request, 404, 0) return } debug(5, "========= DEBUG get_metadata request: %d", len(service.Shares.Shares)) @@ -548,7 +550,7 @@ func (service *MercuryFsService) getMetadata(writer http.ResponseWriter, request debug(4, "If-None-Match match found for %s", etag) writer.WriteHeader(http.StatusNotModified) service.debugInfo.requestServed(int64(0)) - logHttp(request, http.StatusUnauthorized, 0) + logHttp(service, request, http.StatusUnauthorized, 0) } else { debug(4, "If-None-Match (%s) match NOT found for Etag %s", inm, etag) size := int64(len(json)) @@ -559,7 +561,7 @@ func (service *MercuryFsService) getMetadata(writer http.ResponseWriter, request writer.WriteHeader(http.StatusOK) writer.Write([]byte(json)) service.debugInfo.requestServed(size) - logHttp(request, http.StatusOK, int(size)) + logHttp(service, request, http.StatusOK, int(size)) } } @@ -645,7 +647,7 @@ func (service *MercuryFsService) deleteFile(writer http.ResponseWriter, request debug(2, "File not found: %s", err) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - logHttp(request, 404, 0) + logHttp(service, request, 404, 0) return } err = os.Remove(fullPath) @@ -653,7 +655,7 @@ func (service *MercuryFsService) deleteFile(writer http.ResponseWriter, request debug(2, "Error removing file: %s", err.Error()) writer.WriteHeader(http.StatusExpectationFailed) service.debugInfo.requestServed(int64(0)) - logHttp(request, 417, 0) + logHttp(service, request, 417, 0) return } } else { @@ -661,7 +663,7 @@ func (service *MercuryFsService) deleteFile(writer http.ResponseWriter, request } writer.WriteHeader(http.StatusOK) - logHttp(request, http.StatusOK, 0) + logHttp(service, request, http.StatusOK, 0) return } @@ -697,7 +699,7 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request debug(2, "Error parsing image: %s", err.Error()) writer.WriteHeader(http.StatusPreconditionFailed) service.debugInfo.requestServed(int64(0)) - logHttp(request, 412, 0) + logHttp(service, request, 412, 0) return } @@ -707,7 +709,7 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request debug(2, "Error finding uploaded file: %s", err.Error()) writer.WriteHeader(http.StatusExpectationFailed) service.debugInfo.requestServed(int64(0)) - logHttp(request, 417, 0) + logHttp(service, request, 417, 0) return } defer file.Close() @@ -718,7 +720,7 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request debug(2, "invalid filename") writer.WriteHeader(http.StatusUnsupportedMediaType) service.debugInfo.requestServed(int64(0)) - logHttp(request, 415, 0) + logHttp(service, request, 415, 0) return } @@ -740,7 +742,7 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request debug(2, "Error creating uploaded file: %s", err.Error()) writer.WriteHeader(http.StatusServiceUnavailable) service.debugInfo.requestServed(int64(0)) - logHttp(request, 503, 0) + logHttp(service, request, 503, 0) return } // status == FILE_SAME_MD5, ignore it @@ -754,7 +756,7 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request } writer.WriteHeader(http.StatusOK) - logHttp(request, 200, 0) + logHttp(service, request, 200, 0) return } @@ -779,7 +781,7 @@ func (service *MercuryFsService) serveLogs(writer http.ResponseWriter, request * debug(2, "Error opening log file: %s", err.Error()) http.NotFound(writer, request) service.debugInfo.requestServed(int64(0)) - logHttp(request, 404, 0) + logHttp(service, request, 404, 0) return } defer osFile.Close() @@ -787,13 +789,13 @@ func (service *MercuryFsService) serveLogs(writer http.ResponseWriter, request * fi, _ := osFile.Stat() if mode == -1 { http.ServeContent(writer, request, osFile.Name(), fi.ModTime(), osFile) - logHttp(request, 200, int(fi.Size())) + logHttp(service, request, 200, int(fi.Size())) } else { data, err := Tail(mode) if err != nil { writer.WriteHeader(http.StatusNotFound) } size, _ := writer.Write(data) - logHttp(request, 200, size) + logHttp(service, request, 200, size) } } From cb67969a6ad0bc156660ec89d7913947813b3e2a Mon Sep 17 00:00:00 2001 From: Vishwas Mittal Date: Thu, 22 Aug 2019 18:03:07 +0530 Subject: [PATCH 8/9] refactoring --- src/fs/fs.go | 25 +++++-------------------- src/fs/local_server.go | 8 ++------ src/fs/service.go | 1 - 3 files changed, 7 insertions(+), 27 deletions(-) diff --git a/src/fs/fs.go b/src/fs/fs.go index a54bbfc..c16e62f 100644 --- a/src/fs/fs.go +++ b/src/fs/fs.go @@ -117,16 +117,14 @@ func main() { meta, err := metadata.Init(100000, METADATA_FILE, TMDB_API_KEY, TVRAGE_API_KEY, TVDB_API_KEY) if err != nil { - // TODO: remove logFatal or register exitHandler - logFatal("Error initializing metadata library") + fmt.Println("Error initializing metadata library") os.Remove(PID_FILE) os.Exit(1) } service, err := NewMercuryFSService(rootDir, localAddr, isDemo) if err != nil { - // TODO: remove logFatal or register exitHandler - logFatal("Error making service (%s, %s): %s\n", rootDir, localAddr, err.Error()) + fmt.Printf("Error making service (%s, %s): %s\n", rootDir, localAddr, err.Error()) os.Remove(PID_FILE) os.Exit(1) } @@ -251,26 +249,14 @@ func contactPfe(relayHost, relayPort, apiKey string, service *MercuryFsService) // Clean up and quit func cleanQuit(exitCode int, message string) { fmt.Println("FATAL:", message) - // TODO: add fatal log statement with proper exit code handling etc. - //logFatal(message) + log.Println("FATAL:", message) os.Exit(exitCode) } func panicHandler() { if v := recover(); v != nil { fmt.Println("PANIC:", v) - // TODO: uncomment below and add proper handling of logPanic - //if r := recover(); r != nil { - // var errStr string - // switch t := r.(type) { - // case error: - // errStr = t.Error() - // default: - // errStr = "Error in mapping. Can't process the error" - // } - // logPanic(errStr) - // os.Remove(PID_FILE) - // os.Exit(1) + log.Println("PANIC:", v) } os.Remove(PID_FILE) } @@ -283,9 +269,8 @@ func setup() error { signal.Notify(c, os.Interrupt) go func() { for sig := range c { + fmt.Printf("Exiting with %v", sig) log.Printf("Exiting with %v", sig) - // TODO: handle logFatal - //logFatal("Exiting with %v", sig) os.Remove(PID_FILE) os.Exit(1) } diff --git a/src/fs/local_server.go b/src/fs/local_server.go index 799807c..209ceb0 100644 --- a/src/fs/local_server.go +++ b/src/fs/local_server.go @@ -19,18 +19,14 @@ func (service *MercuryFsService) startLocalServer() { addr, err := net.ResolveTCPAddr("tcp", ":"+LocalServerPort) if err != nil { - logInfo("Could not resolve local address") - // TODO: handle logFatal - //logFatal("Could not resolve local address") + logError("Could not resolve local address") debug(2, "Error resolving local address: %s", err.Error()) return } listener, err := net.ListenTCP("tcp", addr) if err != nil { - logInfo("Local server could not be started") - // TODO: handle logFatal - logFatal("Local server could not be started") + logError("Local server could not be started") debug(2, "Error on ListenTCP: %s", err.Error()) return } diff --git a/src/fs/service.go b/src/fs/service.go index 79e9a10..d235cd5 100644 --- a/src/fs/service.go +++ b/src/fs/service.go @@ -762,7 +762,6 @@ func (service *MercuryFsService) uploadFile(writer http.ResponseWriter, request } func (service *MercuryFsService) serveLogs(writer http.ResponseWriter, request *http.Request) { - // TODO: add log serving API similar to PFE q := request.URL amt := q.Query().Get("mode") From d92e6215b6de5f1532f17a03f6b1a18c161d7415 Mon Sep 17 00:00:00 2001 From: Vishwas Mittal Date: Sun, 25 Aug 2019 17:23:59 +0530 Subject: [PATCH 9/9] enabled https and certChecking --- src/fs/fs.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/fs/fs.go b/src/fs/fs.go index c16e62f..3568a66 100644 --- a/src/fs/fs.go +++ b/src/fs/fs.go @@ -38,8 +38,8 @@ import ( // DANGER DANGER DANGER // compile-time only options in case we need to disable checking the certs or https -const DisableCertChecking = true -const DisableHttps = true +const DisableCertChecking = false +const DisableHttps = false const VERSION = "2.2" @@ -269,8 +269,8 @@ func setup() error { signal.Notify(c, os.Interrupt) go func() { for sig := range c { - fmt.Printf("Exiting with %v", sig) - log.Printf("Exiting with %v", sig) + fmt.Printf("Exiting with %v\n", sig) + log.Printf("Exiting with %v\n", sig) os.Remove(PID_FILE) os.Exit(1) }