API: Improve logging

Signed-off-by: Michael Mayer <michael@liquidbytes.net>

frontend/package-lock.json

@@ -4136,6 +4136,21 @@
         "randomfill": "^1.0.3"
       }
     },
+    "crypto-random-string": {
+      "version": "3.0.1",
+      "resolved": "https://registry.npmjs.org/crypto-random-string/-/crypto-random-string-3.0.1.tgz",
+      "integrity": "sha512-dUL0cJ4PBLanJGJQBHQUkvZ3C4q13MXzl54oRqAIiJGiNkOZ4JDwkg/SBo7daGghzlJv16yW1p/4lIQukmbedA==",
+      "requires": {
+        "type-fest": "^0.5.2"
+      },
+      "dependencies": {
+        "type-fest": {
+          "version": "0.5.2",
+          "resolved": "https://registry.npmjs.org/type-fest/-/type-fest-0.5.2.tgz",
+          "integrity": "sha512-DWkS49EQKVX//Tbupb9TFa19c7+MK1XmzkrZUR8TAktmE/DizXoaoJV6TZ/tSIPXipqNiRI6CyAe7x69Jb6RSw=="
+        }
+      }
+    },
     "css": {
       "version": "2.2.4",
       "resolved": "https://registry.npmjs.org/css/-/css-2.2.4.tgz",

frontend/package.json

@@ -41,6 +41,7 @@
     "connect-history-api-fallback": "^1.3.0",
     "copy-webpack-plugin": "^5.0.5",
     "cross-env": "^5.2.1",
+    "crypto-random-string": "^3.0.1",
     "css-loader": "^2.1.1",
     "cssnano": "^4.1.10",
     "easygettext": "^2.7.0",

frontend/src/common/api.js

@@ -6,6 +6,8 @@ const Api = Axios.create({
     baseURL: "/api/v1",
     headers: {common: {
         "X-Session-Token": window.localStorage.getItem("session_token"),
+        "X-Client-Hash": window.clientConfig.jsHash,
+        "X-Client-Version": window.clientConfig.version,
     }},
 });
 

frontend/src/common/websocket.js

@@ -1,24 +1,31 @@
 import Sockette from "sockette";
 import Event from "pubsub-js";
+import randomString from "crypto-random-string";
 
+export const token = randomString({length: 16});
 const host = window.location.host;
 const prot = ('https:' === document.location.protocol ? 'wss://' : 'ws://');
+const url = prot + host + "/api/v1/ws";
+const clientInfo = {
+    "token": token,
+    "hash": window.clientConfig.jsHash,
+    "version": window.clientConfig.version,
+};
 
-const Socket = new Sockette(prot + host + "/api/v1/ws", {
+const Socket = new Sockette(url, {
     timeout: 5e3,
     onopen: e => {
-        // console.log('Websocket connected', e);
+        console.log('websocket: connected', e);
-        Socket.send("hello world");
+        Socket.send(JSON.stringify(clientInfo));
     },
     onmessage: e => {
         const m = JSON.parse(e.data);
-        // console.log('Websocket data received', m);
         Event.publish(m.event, m.data);
     },
-    onreconnect: e => console.log('Websocket reconnecting', e),
+    onreconnect: e => console.log('websocket: reconnecting', e),
-    onmaximum: e => console.warn('Websocket max reconnect limit', e),
+    onmaximum: e => console.warn('websocket: hit max reconnect limit', e),
-    onclose: e => console.log('Websocket closed', e),
+    onclose: e => console.log('websocket: closed', e),
-    onerror: e => console.log('Websocket error', e)
+    onerror: e => console.log('websocket: error', e)
 });
 
 export default Socket;

internal/api/websocket.go

@@ -24,7 +24,7 @@ func wsReader(ws *websocket.Conn) {
 		if err != nil {
 			break
 		}
-		log.Infof("received: %s", m)
+		log.Debugf("websocket: received %d bytes", len(m))
 	}
 }
 
@@ -64,13 +64,13 @@ func Websocket(router *gin.RouterGroup, conf *config.Config) {
 
 		ws, err := wsConnection.Upgrade(w, r, nil)
 		if err != nil {
-			log.Errorf("upgrade error: %s", err)
+			log.Error(err)
 			return
 		}
 
 		defer ws.Close()
 
-		log.Infof("websocket connected: %s", c.Request.RemoteAddr)
+		log.Debug("websocket: connected")
 
 		go wsWriter(ws, conf)
 

internal/photoprism/search.go

@@ -42,7 +42,7 @@ func (s *Search) Photos(form forms.PhotoSearchForm) (results []PhotoSearchResult
 		return results, err
 	}
 
-	defer util.ProfileTime(time.Now(), fmt.Sprintf("search for %+v", form))
+	defer util.ProfileTime(time.Now(), fmt.Sprintf("search: %+v", form))
 
 	q := s.db.NewScope(nil).DB()
 
@@ -75,7 +75,7 @@ func (s *Search) Photos(form forms.PhotoSearchForm) (results []PhotoSearchResult
 
 	if form.Label != "" {
 		if result := s.db.First(&label, "label_slug = ?", strings.ToLower(form.Label)); result.Error != nil {
-			log.Errorf("label \"%s\" not found", form.Label)
+			log.Errorf("search: label \"%s\" not found", form.Label)
 			return results, fmt.Errorf("label \"%s\" not found", form.Label)
 		} else {
 			labelIds = append(labelIds, label.ID)
@@ -103,7 +103,7 @@ func (s *Search) Photos(form forms.PhotoSearchForm) (results []PhotoSearchResult
 		likeString := "%" + lowerString + "%"
 
 		if result := s.db.First(&label, "label_slug = ?", slugString); result.Error != nil {
-			log.Infof("label \"%s\" not found", form.Query)
+			log.Infof("search: label \"%s\" not found", form.Query)
 
 			q = q.Where("labels.label_slug = ? OR LOWER(photo_title) LIKE ? OR files.file_main_color = ?", slugString, likeString, lowerString)
 		} else {
@@ -115,7 +115,7 @@ func (s *Search) Photos(form forms.PhotoSearchForm) (results []PhotoSearchResult
 				labelIds = append(labelIds, category.LabelID)
 			}
 
-			log.Infof("searching for label IDs: %#v", form.Query)
+			log.Infof("search: labels %#v", form.Query)
 
 			q = q.Where("labels.id IN (?) OR LOWER(photo_title) LIKE ? OR files.file_main_color = ?", labelIds, likeString, lowerString)
 		}
@@ -296,7 +296,7 @@ func (s *Search) Labels(form forms.LabelSearchForm) (results []LabelSearchResult
 		return results, err
 	}
 
-	defer util.ProfileTime(time.Now(), fmt.Sprintf("search for %+v", form))
+	defer util.ProfileTime(time.Now(), fmt.Sprintf("search: %+v", form))
 
 	q := s.db.NewScope(nil).DB()
 
@@ -316,7 +316,7 @@ func (s *Search) Labels(form forms.LabelSearchForm) (results []LabelSearchResult
 		likeString := "%" + strings.ToLower(form.Query) + "%"
 
 		if result := s.db.First(&label, "LOWER(label_name) LIKE LOWER(?)", form.Query); result.Error != nil {
-			log.Infof("label \"%s\" not found", form.Query)
+			log.Infof("search: label \"%s\" not found", form.Query)
 
 			q = q.Where("LOWER(labels.label_name) LIKE ?", likeString)
 		} else {
@@ -328,7 +328,7 @@ func (s *Search) Labels(form forms.LabelSearchForm) (results []LabelSearchResult
 				labelIds = append(labelIds, category.LabelID)
 			}
 
-			log.Infof("searching for label IDs: %#v", form.Query)
+			log.Infof("search: labels %#v", form.Query)
 
 			q = q.Where("labels.id IN (?) OR LOWER(labels.label_name) LIKE ?", labelIds, likeString)
 		}
@@ -395,7 +395,7 @@ func (s *Search) Albums(form forms.AlbumSearchForm) (results []AlbumSearchResult
 		return results, err
 	}
 
-	defer util.ProfileTime(time.Now(), fmt.Sprintf("search for %+v", form))
+	defer util.ProfileTime(time.Now(), fmt.Sprintf("search: %+v", form))
 
 	q := s.db.NewScope(nil).DB()
 

internal/util/time.go

@@ -6,5 +6,5 @@ import (
 
 func ProfileTime(start time.Time, name string) {
 	elapsed := time.Since(start)
-	log.Debugf("%s took %s", name, elapsed)
+	log.Debugf("%s [%s]", name, elapsed)
 }