0.3.33

server/internal/api/auth.go

@@ -87,6 +87,13 @@ func (s *Server) handleLogin(w http.ResponseWriter, r *http.Request) {
 		writeError(w, http.StatusBadRequest, "device name is too long")
 		return
 	}
+	log := s.loggerFor(r.Context()).With(
+		"emby_client", s.cfg.ClientName,
+		"device", req.DeviceName,
+		"device_id", req.DeviceID,
+		"client_version", clientVersion(r),
+	)
+	log.Info("Emby client registration starting")
 
 	auth, err := s.emby.Authenticate(
 		r.Context(), req.Username, req.Password,
@@ -98,7 +105,7 @@ func (s *Server) handleLogin(w http.ResponseWriter, r *http.Request) {
 	if err != nil {
 		// Never echo Emby's body here: a failed sign-in is the one place a wrong
 		// password could be reflected back.
-		s.loggerFor(r.Context()).Warn("sign-in rejected",
+		log.Warn("sign-in rejected",
 			"username", req.Username, "device", req.DeviceName, "device_id", req.DeviceID,
 			"reason", "emby refused the credentials",
 		)
@@ -179,6 +186,11 @@ func (s *Server) handleLogin(w http.ResponseWriter, r *http.Request) {
 	if len(created.ReplacedHash) > 0 {
 		_ = s.cache.Delete(r.Context(), cache.SessionKey(hexHash(created.ReplacedHash)))
 	}
+	log.Info("Emby client registration succeeded",
+		"user", sess.Username,
+		"user_id", sess.EmbyUserID,
+		"replaced", len(created.ReplacedHash) > 0,
+	)
 	s.retireSupersededDevices(r.Context(), created.Superseded)
 	// Recorded after the session exists, so a build history can only describe a
 	// television that got as far as signing in.

server/internal/api/installer_auth.go

@@ -284,6 +284,12 @@ func (s *Server) handleInstallLogin(w http.ResponseWriter, r *http.Request) {
 
 	// Gateway, not a television: this sign-in is the admin console or the web installer
 	// checking a password, so Emby records it under the gateway's own client name.
+	log := s.loggerFor(r.Context()).With(
+		"emby_client", s.cfg.GatewayClientName,
+		"device", s.installerDeviceName(),
+		"device_id", installerDeviceID,
+	)
+	log.Info("Emby installer authentication starting")
 	auth, err := s.emby.Authenticate(
 		r.Context(), username, password,
 		emby.Credentials{
@@ -291,10 +297,11 @@ func (s *Server) handleInstallLogin(w http.ResponseWriter, r *http.Request) {
 		},
 	)
 	if err != nil {
-		s.loggerFor(r.Context()).Warn("installer Emby authentication failed", "username", username)
+		log.Warn("installer Emby authentication failed", "username", username)
 		s.renderAccessLogin(w, r, "Sign-in failed.", http.StatusUnauthorized, next)
 		return
 	}
+	log.Info("Emby installer authentication succeeded", "username", username, "user_id", auth.User.ID)
 	// Ask before the token is retired below: the fallback lookup needs it. Whether the
 	// answer is wanted depends on where the sign-in was headed, but it is asked either way
 	// so that the cleanup underneath runs on one path rather than two.

server/internal/api/playback.go

@@ -559,7 +559,9 @@ func (s *Server) playbackSubtitles(
 ) ([]playableSubtitle, string, string, string, string) {
 	started := time.Now()
 	log := s.loggerFor(ctx).With("item", itemID, "force_transcode", forceTranscode,
-		"subtitle_index", subtitleIndex != nil, "resume", millisecondDuration(startTicks/ticksPerMillisecond))
+		"subtitle_index", subtitleIndex != nil, "resume", millisecondDuration(startTicks/ticksPerMillisecond),
+		"emby_client", s.cfg.ClientName, "device", cred.DeviceName, "device_id", cred.DeviceID,
+		"client_version", cred.ClientVersion)
 	log.Log(ctx, serverlogging.LevelTrace, "Emby playback negotiation started")
 	info, err := s.emby.PlaybackInfo(
 		ctx, cred, itemID, startTicks, subtitleIndex, currentPlaySessionID, forceTranscode,