Add auth & gin logging, fixed dummy logger

auth.go

@@ -21,6 +21,7 @@ func (ctx *appContext) authenticate(gc *gin.Context) {
 	}
 	header := strings.SplitN(gc.Request.Header.Get("Authorization"), " ", 2)
 	if header[0] != "Basic" {
+		ctx.debug.Println("Invalid authentication header")
 		respond(401, "Unauthorized", gc)
 		return
 	}
@@ -28,11 +29,13 @@ func (ctx *appContext) authenticate(gc *gin.Context) {
 	creds := strings.SplitN(string(auth), ":", 2)
 	token, err := jwt.Parse(creds[0], func(token *jwt.Token) (interface{}, error) {
 		if _, ok := token.Method.(*jwt.SigningMethodHMAC); !ok {
+			ctx.debug.Printf("Invalid JWT signing method %s", token.Header["alg"])
 			return nil, fmt.Errorf("Unexpected signing method %v", token.Header["alg"])
 		}
 		return []byte(os.Getenv("JFA_SECRET")), nil
 	})
 	if err != nil {
+		ctx.debug.Printf("Auth denied: %s", err)
 		respond(401, "Unauthorized", gc)
 		return
 	}
@@ -43,29 +46,32 @@ func (ctx *appContext) authenticate(gc *gin.Context) {
 		userId = claims["id"].(string)
 		jfId = claims["jfid"].(string)
 	} else {
+		ctx.debug.Printf("Invalid token")
 		respond(401, "Unauthorized", gc)
 		return
 	}
 	match := false
 	for _, user := range ctx.users {
-		fmt.Println("checking:", user.UserID, userId)
 		if user.UserID == userId {
 			match = true
 		}
 	}
 	if !match {
-		fmt.Println("error no match")
+		ctx.debug.Printf("Couldn't find user ID %s", userId)
 		respond(401, "Unauthorized", gc)
 		return
 	}
 	gc.Set("jfId", jfId)
 	gc.Set("userId", userId)
+	ctx.debug.Println("Authentication successful")
 	gc.Next()
 }
 
 func (ctx *appContext) GetToken(gc *gin.Context) {
+	ctx.info.Println("Token requested (login attempt)")
 	header := strings.SplitN(gc.Request.Header.Get("Authorization"), " ", 2)
 	if header[0] != "Basic" {
+		ctx.debug.Println("Invalid authentication header")
 		respond(401, "Unauthorized", gc)
 		return
 	}
@@ -82,21 +88,28 @@ func (ctx *appContext) GetToken(gc *gin.Context) {
 	jfId := ""
 	if !match {
 		if !ctx.jellyfinLogin {
+			ctx.info.Println("Auth failed: Invalid username and/or password")
 			respond(401, "Unauthorized", gc)
 			return
 		}
-		// eventually, make authenticate return a user to avoid two calls.
 		var status int
 		var err error
 		var user map[string]interface{}
 		user, status, err = ctx.authJf.authenticate(creds[0], creds[1])
 		jfId = user["Id"].(string)
 		if status != 200 || err != nil {
+			if status == 401 {
+				ctx.info.Println("Auth failed: Invalid username and/or password")
 				respond(401, "Unauthorized", gc)
 				return
+			}
+			ctx.err.Printf("Auth failed: Couldn't authenticate with Jellyfin: Code %d", status)
+			respond(500, "Jellyfin error", gc)
+			return
 		} else {
 			if ctx.config.Section("ui").Key("admin_only").MustBool(true) {
 				if !user["Policy"].(map[string]interface{})["IsAdministrator"].(bool) {
+					ctx.debug.Printf("Auth failed: User \"%s\" isn't admin", creds[0])
 					respond(401, "Unauthorized", gc)
 				}
 			}
@@ -104,6 +117,7 @@ func (ctx *appContext) GetToken(gc *gin.Context) {
 			newuser.UserID = shortuuid.New()
 			userId = newuser.UserID
 			// uuid, nothing else identifiable!
+			ctx.debug.Printf("Token generated for user \"%s\"", creds[0])
 			ctx.users = append(ctx.users, newuser)
 		}
 	}

main.go

@@ -70,6 +70,31 @@ func GenerateSecret(length int) (string, error) {
 // 	// bg.Ctx.WriteString(out)
 // }
 
+func setGinLogger(router *gin.Engine, debugMode bool) {
+	if debugMode {
+		router.Use(gin.LoggerWithFormatter(func(param gin.LogFormatterParams) string {
+			return fmt.Sprintf("[GIN/DEBUG] %s: %s(%s) => %d in %s; Errors: %s\n",
+				param.TimeStamp.Format("15:04:05"),
+				param.Method,
+				param.Path,
+				param.StatusCode,
+				param.Latency,
+				param.ErrorMessage,
+			)
+		}))
+		gin.SetMode(gin.DebugMode)
+	} else {
+		router.Use(gin.LoggerWithFormatter(func(param gin.LogFormatterParams) string {
+			return fmt.Sprintf("[GIN] %s(%s) => %d\n",
+				param.Method,
+				param.Path,
+				param.StatusCode,
+			)
+		}))
+		gin.SetMode(gin.ReleaseMode)
+	}
+}
+
 func main() {
 	ctx := new(appContext)
 	ctx.config_path = "/home/hrfee/.jf-accounts/config.ini"
@@ -79,12 +104,13 @@ func main() {
 		ctx.err.Fatalf("Failed to load config file \"%s\"", ctx.config_path)
 	}
 
-	ctx.info = log.New(os.Stdout, "INFO: ", log.Ltime)
+	ctx.info = log.New(os.Stdout, "[INFO] ", log.Ltime)
-	ctx.err = log.New(os.Stdout, "INFO: ", log.Ltime|log.Lshortfile)
+	ctx.err = log.New(os.Stdout, "[ERROR] ", log.Ltime|log.Lshortfile)
-	if ctx.config.Section("ui").Key("debug").MustBool(true) {
+	debugMode := ctx.config.Section("ui").Key("debug").MustBool(true)
-		ctx.debug = log.New(os.Stdout, "DEBUG: ", log.Ltime|log.Lshortfile)
+	if debugMode {
+		ctx.debug = log.New(os.Stdout, "[DEBUG] ", log.Ltime|log.Lshortfile)
 	} else {
-		ctx.debug = log.New(nil, "", 0)
+		ctx.debug = log.New(ioutil.Discard, "", 0)
 	}
 
 	ctx.debug.Printf("Loaded config file \"%s\"", ctx.config_path)
@@ -167,8 +193,12 @@ func main() {
 
 	ctx.email.init(ctx)
 
-	ctx.debug.Println("Loading routes")
+	ctx.info.Println("Loading routes")
-	router := gin.Default()
+	router := gin.New()
+
+	setGinLogger(router, debugMode)
+
+	router.Use(gin.Recovery())
 	router.Use(static.Serve("/", static.LocalFile("data/static", false)))
 	router.Use(static.Serve("/invite/", static.LocalFile("data/static", false)))
 	router.LoadHTMLGlob("data/templates/*")
@@ -188,5 +218,6 @@ func main() {
 	api.GET("/getConfig", ctx.GetConfig)
 	api.POST("/modifyConfig", ctx.ModifyConfig)
 	addr := fmt.Sprintf("%s:%d", ctx.config.Section("ui").Key("host").String(), ctx.config.Section("ui").Key("port").MustInt(8056))
+	ctx.info.Printf("Starting router @ %s", addr)
 	router.Run(addr)
 }