// Package api exposes the gateway's HTTP surface. // // The API is shaped for one TV screen at a time rather than mirroring Emby: /v1/home // returns everything the launcher renders in a single round trip, which is the whole // point of putting a gateway in front of Emby. package api import ( "context" "crypto/rand" "crypto/sha256" "crypto/subtle" "encoding/base64" "encoding/hex" "encoding/json" "errors" "log/slog" "net/http" "slices" "strconv" "strings" "sync" "time" "github.com/ponzischeme89/memby/server/internal/adminevents" "github.com/ponzischeme89/memby/server/internal/appupdate" "github.com/ponzischeme89/memby/server/internal/bazarr" "github.com/ponzischeme89/memby/server/internal/cache" "github.com/ponzischeme89/memby/server/internal/config" "github.com/ponzischeme89/memby/server/internal/credits" "github.com/ponzischeme89/memby/server/internal/emby" "github.com/ponzischeme89/memby/server/internal/foryou" "github.com/ponzischeme89/memby/server/internal/integrations" serverlogging "github.com/ponzischeme89/memby/server/internal/logging" "github.com/ponzischeme89/memby/server/internal/mdblist" "github.com/ponzischeme89/memby/server/internal/notify" "github.com/ponzischeme89/memby/server/internal/opensubtitles" "github.com/ponzischeme89/memby/server/internal/radarr" "github.com/ponzischeme89/memby/server/internal/recommend" "github.com/ponzischeme89/memby/server/internal/scheduler" "github.com/ponzischeme89/memby/server/internal/sonarr" "github.com/ponzischeme89/memby/server/internal/store" "github.com/ponzischeme89/memby/server/internal/timing" ) type Server struct { cfg config.Config emby *emby.Client store *store.Store cache *cache.Cache recommender *recommend.Engine forYou *foryou.Service sonarr *sonarr.Client radarr *radarr.Client bazarr *bazarr.Client mdblist *mdblist.Client // credits discovers where an episode's closing credits begin, for the small number of // episodes the household is about to watch. Nil when the subsystem is switched off, and // every call site tolerates that — a missing marker simply means no Skip Credits button, // which is the same state a library with no chapter markers is already in. credits *credits.Service creditsLoad *credits.PlaybackLoad syncer syncerHandle // ingester records what Sonarr and Radarr say changed. Nil where no webhook token is // configured, which is also what makes both hooks 404. ingester ingesterHandle log *slog.Logger events *serverlogging.Buffer // adminEvents is the administrative feed: the console's notification bell and every // outgoing integration read from it. Distinct from `events` above, which is the // structured log ring — a log line is what the gateway did, an admin event is // something an operator would want to be told. adminEvents *adminevents.Bus scheduler *scheduler.Scheduler integrations *integrations.Dispatcher // notify is the one door every outbound notification leaves through, and the only // thing that writes the notification log. Producers never call a delivery provider // directly any more — see internal/api/notifications.go. notify *notify.Service sonarrMu sync.Mutex // sonarrSeriesMu guards the catalogue cache separately from the calendar's, so an add // to My Shows never waits behind a launcher rebuilding the schedule row. sonarrSeriesMu sync.Mutex radarrMu sync.Mutex bazarrMu sync.Mutex // openSubtitles is built from the operator's saved credentials rather than from // configuration, so it is cached against a fingerprint of them and rebuilt when they // change. It is cached at all because the client holds a login token, and logging in // per download would spend a different allowance than the one being conserved. openSubtitlesMu sync.Mutex openSubtitles *opensubtitles.Client openSubtitlesKey string mdblistMu sync.Mutex // viewerLists spares every authenticated request a read of the account's people. viewerLists viewerListCache // mdblistSettingsCache spares every row and keystroke a settings read. mdblistSettingsCache mdblistSettingsCache // ratingsWarm fills and renews the durable rating cache behind the viewer, so a row // never waits on MDBList and the operator's daily allowance is spent once per title. ratingsWarm ratingsWarmer // integrationHealth is what the last reachability probe found for each external // service. Cached rather than probed on request because the console polls: every open // tab would otherwise be its own request against somebody's Sonarr. integrationHealth integrationHealthCache // alertMu serialises the read-modify-write of the shared alert list. Its producers // are events — a webhook, a finished sync, a health probe — none of them paced by // this server, so two can land at once. alertMu sync.Mutex // playbackTitles lets a progress or stop report, which carries only an item id, be // logged by name. playbackTitles playbackTitles // featurePolicy keeps the operator's feature switches out of the request path. See // features_cache.go. featurePolicy featurePolicyCache // heroPolicy keeps the operator's hero choices out of the request path, which now // includes the status poll every open television makes. See hero_revision.go. heroPolicy heroPolicyCache // upstream deduplicates concurrent cache misses for the same key, so two televisions // asking for the same expensive answer at the same moment cost one upstream call // rather than two. See coalesce.go. upstream upstreamGroup // household caches the completion scores every viewer's ranking reads and none of // them can get a different answer to. See ranking.go. household householdScores // followChecks stops the automatic My Shows check repeating for the length of an // episode. See playback_follow.go. followChecks followChecks // ingestRuns collapses a season pack's worth of finished scans into one banner. ingestRuns ingestRuns recommendationBuilds recommendationBuilds maintenance maintenanceState quietTime quietTimeState // metadataHeroSettings is the shared launcher composition sent to every television. metadataHeroSettings metadataHeroSettingsState // gatewaySettings is the operator's runtime amendment to what the container was // started with. deployedLogLevel is remembered beside the live level variable // because clearing an override has to restore something, and the level variable // itself has by then been moved. gatewaySettings gatewaySettingsState logLevel *slog.LevelVar deployedLogLevel slog.Level updatePolicy updatePolicyCache // embyHealth is the reachability probe's live finding, which /v1/status publishes so // a TV can show why playback stopped even if it missed the announcement. embyHealth embyHealth // The console is a separate container the gateway proxies; see admin_spa.go. adminUIHandle } // Deps are the collaborators the API needs. A struct rather than positional arguments: // this list has grown three times already. type Deps struct { Emby *emby.Client Store *store.Store Cache *cache.Cache Recommender *recommend.Engine ForYou *foryou.Service Sonarr *sonarr.Client Radarr *radarr.Client Bazarr *bazarr.Client MDBList *mdblist.Client Credits *credits.Service CreditsLoad *credits.PlaybackLoad Syncer syncerHandle Ingester ingesterHandle Log *slog.Logger Events *serverlogging.Buffer AdminEvents *adminevents.Bus Scheduler *scheduler.Scheduler Integrations *integrations.Dispatcher // Notify is optional. A server built without one still delivers every notification — // Send falls through to the providers regardless — it simply records nothing, which is // what every unit test in this package wants. Notify *notify.Service // LogLevel is the live level of the process's own logger, so the console can turn // debug on and watch the thing it turned it on for. Nil is allowed and means the // level is fixed at whatever the container was started with. LogLevel *slog.LevelVar } func New(cfg config.Config, deps Deps) *Server { server := &Server{ cfg: cfg, emby: deps.Emby, store: deps.Store, cache: deps.Cache, recommender: deps.Recommender, forYou: deps.ForYou, sonarr: deps.Sonarr, radarr: deps.Radarr, bazarr: deps.Bazarr, mdblist: deps.MDBList, credits: deps.Credits, creditsLoad: deps.CreditsLoad, syncer: deps.Syncer, ingester: deps.Ingester, log: deps.Log, events: deps.Events, adminEvents: deps.AdminEvents, scheduler: deps.Scheduler, integrations: deps.Integrations, notify: deps.Notify, logLevel: deps.LogLevel, deployedLogLevel: deployedLevel(deps.LogLevel), } // The providers are installed here rather than by the caller so a producer can assume // the channels it uses exist: a channel with no provider is a configuration fault the // audit trail would faithfully record on every single notification. server.registerNotifiers() return server } func deployedLevel(level *slog.LevelVar) slog.Level { if level == nil { return slog.LevelInfo } return level.Level() } // publishAdmin reports something an operator would want to know about. // // Every caller treats it as fire-and-forget, which is why it returns nothing: the feed is // a convenience over things that are already logged, and a bell that could fail a sign-in // would be worse than no bell. A server built without a bus — every unit test in this // package — publishes into a nil receiver, which is a no-op. func (s *Server) publishAdmin(ctx context.Context, event adminevents.Event) { s.adminEvents.Publish(ctx, event) } func (s *Server) sonarrEnabled(ctx context.Context) bool { if s.sonarr == nil || s.store == nil { return false } policy, err := s.store.ArrIntegrationPolicy(ctx) if err != nil { s.loggerFor(ctx).Warn("arr integration policy read failed", "error", err) return false } return policy.SonarrEnabled } func (s *Server) radarrEnabled(ctx context.Context) bool { if s.radarr == nil || s.store == nil { return false } policy, err := s.store.ArrIntegrationPolicy(ctx) if err != nil { s.loggerFor(ctx).Warn("arr integration policy read failed", "error", err) return false } return policy.RadarrEnabled } func (s *Server) Routes() http.Handler { // The client API lives on its own mux so maintenance mode can gate all of it at // once, without the gate ever touching health checks or the admin page. v1 := http.NewServeMux() v1.HandleFunc("POST /v1/auth/login", s.requireSupportedClient(s.handleLogin)) v1.HandleFunc("GET /v1/auth/recovery", s.handleRecoveryProfiles) v1.HandleFunc("POST /v1/auth/recovery", s.requireSupportedClient(s.handleRecovery)) v1.Handle("POST /v1/auth/logout", s.authed(s.handleLogout)) v1.Handle("GET /v1/auth/session", s.authed(s.handleSession)) v1.Handle("GET /v1/auth/devices", s.authed(s.handleDevices)) v1.Handle("PUT /v1/auth/devices/{deviceID}", s.authed(s.handleRenameDevice)) v1.Handle("DELETE /v1/auth/devices/{deviceID}", s.authed(s.handleDeleteDevice)) // Viewers: the people under one account. The list is what the picker draws; every // other route learns who is watching from the X-Memby-Viewer header instead. v1.Handle("GET /v1/viewers", s.authed(s.handleViewers)) v1.Handle("POST /v1/viewers", s.authed(s.handleViewers)) v1.Handle("PUT /v1/viewers/{viewerID}", s.authed(s.handleViewer)) v1.Handle("PUT /v1/viewers/{viewerID}/pin", s.authed(s.handleViewerPIN)) v1.Handle("DELETE /v1/viewers/{viewerID}", s.authed(s.handleViewer)) v1.Handle("GET /v1/home", s.authed(s.handleHome)) v1.Handle("GET /v1/heroes/active", s.authed(s.handleActiveHero)) v1.Handle("GET /v1/screensaver", s.authed(s.handleScreensaver)) v1.Handle("GET /v1/search", s.authed(s.handleSearch)) // A genre is browsed, not searched: the chip is a filter and this is the route that // treats it as one. Paged, because a household's Drama shelf is not a screenful. v1.Handle("GET /v1/genres/{genre}/items", s.authed(s.handleGenreItems)) v1.Handle("GET /v1/library/items", s.authed(s.handleLibraryItems)) v1.Handle("GET /v1/genres/affinity", s.authed(s.handleGenreAffinity)) v1.Handle("POST /v1/search/history", s.authed(s.handleSearchHistory)) v1.Handle("GET /v1/requests/lookup", s.authed(s.handleRequestLookup)) v1.Handle("GET /v1/requests", s.authed(s.handleMyRequests)) v1.Handle("POST /v1/requests", s.authed(s.handleRequest)) v1.Handle("DELETE /v1/requests/{mediaType}/{foreignId}", s.authed(s.handleDeleteRequest)) v1.Handle("GET /v1/recommendations", s.authed(s.handleRecommendations)) v1.Handle("PUT /v1/recommendations/{id}/action", s.authed(s.handleRecommendationAction)) v1.Handle("DELETE /v1/recommendations/{id}/action", s.authed(s.handleRecommendationAction)) v1.Handle("PUT /v1/recommendations/preferences", s.authed(s.handleRecommendationPreferences)) v1.Handle("GET /v1/recommendations/preferences", s.authed(s.handleRecommendationPreferences)) v1.Handle("GET /v1/for-you", s.authed(s.handleForYou)) v1.Handle("GET /v1/preroll", s.authed(s.handlePreroll)) v1.Handle("GET /v1/calendar", s.authed(s.handleCalendar)) v1.Handle("GET /v1/my-shows", s.authed(s.handleMyShows)) v1.Handle("POST /v1/my-shows", s.authed(s.handleMyShows)) v1.Handle("DELETE /v1/my-shows/{id}", s.authed(s.handleMyShow)) v1.Handle("GET /v1/notifications", s.authed(s.handleNotifications)) v1.Handle("PUT /v1/notifications", s.authed(s.handleNotifications)) // Ahead of the per-alert route: three path segments rather than four, so the two never // compete, and a shortcut that clears the lot needs one request and one log line. v1.Handle("POST /v1/notifications/clear", s.authed(s.handleClearNotifications)) v1.Handle("POST /v1/notifications/{id}/{action}", s.authed(s.handleNotificationAction)) v1.Handle("GET /v1/features", s.authed(s.handleFeatures)) // A viewer's settings follow the person, not the television. Both verbs land on one // handler because a write answers with the stored document, not the submitted one. // The palette, fetched only when the revision on the status poll moves. A GET with no // write beside it: what a viewer may change is themeId, and that is an ordinary // setting on the route above — this route only answers with what came of it. v1.Handle("GET /v1/theme", s.authed(s.handleTheme)) v1.Handle("GET /v1/preferences", s.authed(s.handlePreferences)) v1.Handle("PUT /v1/preferences", s.authed(s.handlePreferences)) v1.Handle("GET /v1/items/{id}", s.authed(s.handleItem)) v1.Handle("GET /v1/people/{id}", s.authed(s.handlePerson)) v1.Handle("GET /v1/people/{id}/filmography", s.authed(s.handlePersonFilmography)) v1.Handle("GET /v1/items/{id}/ratings", s.authed(s.handleMovieRatings)) v1.Handle("GET /v1/items/{id}/season-finale", s.authed(s.handleSeasonFinale)) v1.Handle("GET /v1/items/{id}/episodes", s.authed(s.handleSeriesEpisodes)) v1.Handle("GET /v1/items/{id}/related", s.authed(s.handleRelated)) v1.Handle("POST /v1/magic", s.authed(s.handleMagic)) v1.Handle("GET /v1/items/{id}/extras", s.authed(s.handleExtras)) v1.Handle("POST /v1/items/{id}/favorite", s.authed(s.handleFavorite)) v1.Handle("POST /v1/items/{id}/played", s.authed(s.handlePlayed)) v1.Handle("POST /v1/items/{id}/hide-from-resume", s.authed(s.handleHideFromResume)) v1.Handle("GET /v1/items/{id}/playback", s.authed(s.handlePlayback)) v1.Handle("GET /v1/items/{id}/next", s.authed(s.handleNextEpisode)) v1.Handle("GET /v1/items/{id}/subtitles/search", s.authed(s.handleSubtitleSearch)) v1.Handle("POST /v1/items/{id}/subtitles/download", s.authed(s.handleSubtitleDownload)) // Repairing the timing of a subtitle the title already has, which is a different // question from fetching another copy of it — see subtitle_fix.go. v1.Handle("POST /v1/items/{id}/subtitles/fix", s.authed(s.handleSubtitleFix)) // The one route that serves a subtitle rather than pointing at Emby's. It exists for // the provider that hands back bytes instead of writing beside the media file; the // token arrives in the query string, the way artwork's does, because a media player // fetching a sidecar sends none of Memby's headers. v1.Handle("GET /v1/subtitles/{file}", s.authed(s.handleStoredSubtitle)) v1.Handle("GET /v1/radarr/movies/{id}", s.authed(s.handleRadarrMovie)) v1.Handle("GET /v1/items/{id}/trailer", s.authed(s.handleTrailer)) v1.Handle("GET /v1/items/{id}/trailers", s.authed(s.handleTrailers)) v1.Handle("POST /v1/items/{id}/trailers/resolve", s.authed(s.handleResolveTrailer)) v1.Handle("POST /v1/items/{id}/trailers/report", s.authed(s.handleTrailerReport)) v1.Handle("POST /v1/items/{id}/report", s.authed(s.handleMediaReport)) v1.Handle("GET /v1/items/{id}/intro", s.authed(s.handleIntro)) v1.Handle("GET /v1/items/{id}/trickplay", s.authed(s.handleTrickplay)) v1.Handle("GET /v1/items/{id}/trickplay/{frame}", s.authed(s.handleTrickplayFrame)) v1.Handle("POST /v1/playback/{phase}", s.authed(s.handlePlaybackReport)) v1.Handle("POST /v1/analytics/rows", s.authed(s.handleRowAnalytics)) v1.Handle("POST /v1/analytics/events", s.authed(s.handleJourneyAnalytics)) v1.Handle("GET /v1/images/{itemId}/{imageType}", s.authed(s.handleImage)) mux := http.NewServeMux() mux.HandleFunc("GET /healthz", s.handleHealth) mux.HandleFunc("GET /readyz", s.handleReady) // Remote Config is app-scoped, contains presentation data only, and warms the next // process. Keep it outside authentication and maintenance so offline/start-up fallback // never depends on a session being available. mux.HandleFunc("GET /v1/config", s.handleRemoteConfig) // Update compatibility is app-scoped; a signed-in viewer may only mute the optional // prompt. Keep this outside authentication and maintenance so a fresh install, a // signed-out TV, and especially a retired build can still learn what it must do. mux.Handle("GET /v1/update", s.identifyOptionalSession(http.HandlerFunc(s.handleUpdate))) // Exact route outside the maintenance gate: signed-in clients poll this lightweight // status even while every normal /v1 operation is deliberately unavailable. mux.Handle("GET /v1/status", s.authed(s.handleServiceStatus)) mux.Handle("/v1/", s.maintenanceGate(v1)) // Sonarr and Radarr push here when something lands, is upgraded, is renamed or is // deleted. Outside the maintenance gate on purpose: an event arriving during // maintenance would otherwise be lost rather than delayed. // // Outside the *quiet-time* gate too, which the Radarr hook was previously inside. That // gate answers 503, and neither *arr re-delivers — so a quiet hour used to silently // discard every import that happened during it. The durable queue is what makes the // distinction possible: the hook records the news whatever the hour, and the worker is // where quiet time is honoured. mux.HandleFunc("POST /hooks/radarr", s.handleRadarrWebhook) mux.HandleFunc("POST /hooks/sonarr", s.handleSonarrWebhook) // State the canonical console URL explicitly. The console and its assets live below // /admin/, while a bare /admin is routinely typed and some reverse proxies do not // preserve ServeMux's implicit trailing-slash redirect for a mounted subtree. mux.HandleFunc("GET /admin", func(w http.ResponseWriter, r *http.Request) { http.Redirect(w, r, "/admin/", http.StatusFound) }) mux.Handle("/admin/", s.adminRoutes()) mux.HandleFunc("GET /{$}", s.handleInstallPage) mux.HandleFunc("GET /install", s.handleInstallPage) mux.HandleFunc("GET /install/{$}", s.handleInstallPage) mux.HandleFunc("POST /install/login", s.handleInstallLogin) mux.HandleFunc("POST /install/logout", s.handleInstallLogout) mux.HandleFunc("GET /robots.txt", handleRobots) mux.HandleFunc("GET /updates/latest.apk", s.handleLatestReleaseDownload) mux.HandleFunc("GET /updates/{filename}", s.handleReleaseDownload) return s.withLogging(mux) } // --- middleware ------------------------------------------------------------- type authedFunc func(http.ResponseWriter, *http.Request, store.Session) // identifyOptionalSession gives public routes the viewer and television attached to a // valid bearer token without turning authentication into a condition of access. The // update check must remain reachable before sign-in, but an offer made to a signed-in // client should still say whose session is affected in the logs. func (s *Server) identifyOptionalSession(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { if token := bearerToken(r); token != "" { if sess, err := s.sessionFor(r.Context(), token); err == nil { identify(r.Context(), sess) } } next.ServeHTTP(w, r) }) } // authed resolves the bearer token to a session before running h. // // Images are also accepted with a `t=` query parameter: Coil builds plain URLs from the // repository's helpers and cannot attach headers to them. func (s *Server) authed(h authedFunc) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { token := bearerToken(r) if token == "" { writeError(w, http.StatusUnauthorized, "missing token") return } sess, err := s.sessionFor(r.Context(), token) if err != nil { if errors.Is(err, store.ErrNotFound) { writeError(w, http.StatusUnauthorized, "invalid token") return } s.log.Error("session lookup failed", "error", err) writeError(w, http.StatusInternalServerError, "session lookup failed") return } sess = s.captureClientIdentity(r, sess) identify(r.Context(), sess) // Resolved once, here, and read out of the context by everything downstream. The // header short-circuits when it is absent, so a household running no viewers pays // a map lookup and nothing else. viewer := s.activeViewer(r.Context(), sess, r) identifyViewer(r.Context(), viewer) r = r.WithContext(withViewer(r.Context(), viewer)) policy := s.updatePolicy.get() decision := appupdate.Decide(effectiveUpdatePolicy(policy), clientVersion(r)) retireBelow := destructiveUpdateFloor(policy) if mustRetireForUpdate(decision, clientVersion(r), retireBelow) { // Mirror an ordinary sign-out closely enough that this token cannot be restored // from either database or Redis. The 401 is intentional: every supported client // treats it as authoritative and removes the rejected local profile. if err := s.store.DeleteSession(r.Context(), sess.TokenHash); err != nil { s.loggerFor(r.Context()).Error("required-update session delete failed", "error", err) } _ = s.cache.Delete(r.Context(), cache.SessionKey(hexHash(sess.TokenHash))) s.invalidateAccountViews(r.Context(), sess) s.loggerFor(r.Context()).Info("signed out for required update", "device_id", sess.DeviceID, "from", clientLogValue(clientVersion(r)), "minimum", retireBelow, "to", decision.Version, ) w.Header().Set("X-Memby-Update-Required", decision.Version) writeError(w, http.StatusUnauthorized, "Memby must be updated before signing in again") return } h(w, r, sess) }) } // captureClientIdentity makes the session the durable source of attribution. Normal API // calls refresh it from headers; authenticated artwork requests, which can only carry a // query token, inherit the last identity reported by that same TV. func (s *Server) captureClientIdentity(r *http.Request, sess store.Session) store.Session { previousVersion := sess.ClientVersion changed := mergeClientIdentity(r, &sess) if changed { if err := s.store.UpdateSessionClientIdentity( r.Context(), sess.TokenHash, sess.ClientVersion, sess.ClientProtocol, sess.ClientCapabilities, ); err != nil { s.log.Warn("client identity update failed", "error", err) } else { s.cacheSession(r.Context(), sess) } // A television that updates itself never signs in again, so this is the only // place the new build would otherwise be seen. Guarded on the version actually // having moved: every request reaches here, and all but the first after an // update would be a write of what is already stored. if sess.ClientVersion != previousVersion { if err := s.store.RecordDeviceVersion( r.Context(), sess.DeviceID, sess.ClientVersion, ); err != nil { s.log.Warn("device version record failed", "device_id", sess.DeviceID, "error", err) } // And it is the only place an operator would otherwise learn that an update // they offered was actually taken. s.announceDeviceUpdate(r.Context(), sess, previousVersion) } } return sess } func mergeClientIdentity(r *http.Request, sess *store.Session) bool { version := clientVersion(r) protocol := clientProtocol(r) capabilities := clientCapabilities(r) changed := false if version != "" && version != sess.ClientVersion { sess.ClientVersion = version changed = true } if protocol != "" && protocol != sess.ClientProtocol { sess.ClientProtocol = protocol changed = true } if len(capabilities) > 0 && !slices.Equal(capabilities, sess.ClientCapabilities) { sess.ClientCapabilities = capabilities changed = true } if version == "" && sess.ClientVersion != "" { r.Header.Set("X-Memby-Version", sess.ClientVersion) } if protocol == "" && sess.ClientProtocol != "" { r.Header.Set("X-Memby-Protocol", sess.ClientProtocol) } return changed } func (s *Server) withLogging(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { start := time.Now() r, identity := withRequestIdentity(r) // Every layer under this one — the Emby client, the *arr clients, Postgres, // Redis — records against this. It is installed for every request rather than // only for ones that turn out to be slow, because nothing knows a request is // slow until it has finished and the evidence has to have been collected on the // way through. What it costs when the request is fast is a map nobody reads. ctx, trace := timing.New(r.Context()) r = r.WithContext(ctx) w.Header().Set("X-Memby-Correlation", identity.correlation) s.loggerFor(r.Context()).Log(r.Context(), serverlogging.LevelTrace, "request started", "method", r.Method, "path", r.URL.Path, "query_keys", queryKeys(r)) rec := &statusRecorder{ResponseWriter: w, status: http.StatusOK} next.ServeHTTP(rec, r) // Polling the live-log endpoint must not create another live-log record and // become a self-sustaining stream. if r.URL.Path == "/admin/api/events" { return } // The request line is a transcript of one exchange, not the record of what the // viewer did — that is what the events the handlers log are for. It stays terse // and identical in shape for every route so it can be scanned in a column. // // Path only: query strings can carry image tokens. level := requestLogLevel(r.URL.Path, rec.status) fields := []any{"component", identity.component, "correlation", identity.correlation} fields = append(fields, identity.viewerAttrs()...) // The app build keeps its placeholder where the viewer does not, because "which // build made this call" always has an answer worth seeing, including "it did // not say". fields = append(fields, "client", clientLogValue(identity.client), "protocol", clientLogValue(identity.protocol), "method", r.Method, "path", r.URL.Path, "status", rec.status, "duration", time.Since(start).Round(time.Millisecond), ) // Whether an answer came from cache is the first thing anyone asks of a slow // screen, and only the handler knows. if cached := rec.Header().Get("X-Memby-Cache"); cached != "" { fields = append(fields, "cache", cached) } // A duration on its own says something is slow and nothing about why, which is // the state every latency investigation here started from. The breakdown is // attached only past the threshold: on a fast request it would be a second // column of noise on every line, and on a slow one it is the answer. if elapsed := time.Since(start); elapsed >= s.slowRequestThreshold() && !trace.Empty() { fields = append(fields, "breakdown", trace.Breakdown()) if rest := trace.Unattributed(elapsed); rest > 0 { fields = append(fields, "elsewhere", rest.Round(time.Millisecond)) } } s.log.Log(r.Context(), level, "request", fields...) }) } // queryKeys is diagnostic context without values: query values can contain title searches, // tokens or other private values, while their keys are enough to explain the route shape. func queryKeys(r *http.Request) string { keys := make([]string, 0, len(r.URL.Query())) for key := range r.URL.Query() { keys = append(keys, key) } slices.Sort(keys) return strings.Join(keys, ",") } func clientLogValue(value string) string { if value == "" { return "unknown" } return value } // Successful high-frequency probes and artwork fetches stay available at DEBUG without // overwhelming the normal Docker log. Failures are always promoted so they remain // visible regardless of path. func requestLogLevel(path string, status int) slog.Level { switch { // A request nobody is waiting for any more is not a failure of anything. It is only // ever answered this way deliberately, so it never hides a fault. case status == statusClientClosedRequest: return slog.LevelDebug case status >= http.StatusInternalServerError: return slog.LevelError case status >= http.StatusBadRequest: return slog.LevelWarn case path == "/healthz", path == "/readyz", path == "/v1/status", path == "/admin/api/status", strings.HasPrefix(path, "/v1/images/"): return slog.LevelDebug default: return slog.LevelInfo } } type statusRecorder struct { http.ResponseWriter status int } func (r *statusRecorder) WriteHeader(code int) { r.status = code r.ResponseWriter.WriteHeader(code) } // Flush preserves streaming support through the request logger. In particular, the admin // notification feed is Server-Sent Events and correctly refuses to start unless its writer // implements http.Flusher. Embedding ResponseWriter alone does not promote optional // interfaces, so the old recorder turned every stream request into a 500. func (r *statusRecorder) Flush() { if flusher, ok := r.ResponseWriter.(http.Flusher); ok { flusher.Flush() } } // --- sessions --------------------------------------------------------------- func bearerToken(r *http.Request) string { if h := r.Header.Get("Authorization"); strings.HasPrefix(h, "Bearer ") { return strings.TrimSpace(strings.TrimPrefix(h, "Bearer ")) } if h := r.Header.Get("X-Memby-Token"); h != "" { return strings.TrimSpace(h) } return strings.TrimSpace(r.URL.Query().Get("t")) } func hashToken(token string) []byte { sum := sha256.Sum256([]byte(token)) return sum[:] } func newToken() (string, error) { buf := make([]byte, 32) if _, err := rand.Read(buf); err != nil { return "", err } return base64.RawURLEncoding.EncodeToString(buf), nil } type cachedSession struct { EmbyUserID string `json:"u"` EmbyToken string `json:"t"` Username string `json:"n"` ServerID string `json:"s"` DeviceID string `json:"d"` DeviceName string `json:"dn,omitempty"` ClientVersion string `json:"v,omitempty"` ClientProtocol string `json:"p,omitempty"` } // sessionFor resolves a token, using Redis to keep the hot path off Postgres. func (s *Server) sessionFor(ctx context.Context, token string) (store.Session, error) { hash := hashToken(token) key := cache.SessionKey(hex.EncodeToString(hash)) if raw, err := s.cache.Get(ctx, key); err == nil { var cs cachedSession if json.Unmarshal(raw, &cs) == nil { if enabled, err := s.store.UserEnabled(ctx, cs.EmbyUserID); err != nil || !enabled { return store.Session{}, store.ErrNotFound } return store.Session{ TokenHash: hash, EmbyUserID: cs.EmbyUserID, EmbyToken: cs.EmbyToken, Username: cs.Username, ServerID: cs.ServerID, DeviceID: cs.DeviceID, DeviceName: cs.DeviceName, ClientVersion: cs.ClientVersion, ClientProtocol: cs.ClientProtocol, }, nil } } sess, err := s.store.SessionByTokenHash(ctx, hash) if err != nil { return store.Session{}, err } // Constant-time confirmation that the stored hash matches the presented token. if subtle.ConstantTimeCompare(sess.TokenHash, hash) != 1 { return store.Session{}, store.ErrNotFound } s.cacheSession(ctx, sess) // Best-effort activity stamp; a failure here must not fail the request. if err := s.store.Touch(ctx, hash); err != nil { s.log.Warn("touch session failed", "error", err) } return sess, nil } func (s *Server) cacheSession(ctx context.Context, sess store.Session) { if raw, err := json.Marshal(cachedSession{ EmbyUserID: sess.EmbyUserID, EmbyToken: sess.EmbyToken, Username: sess.Username, ServerID: sess.ServerID, DeviceID: sess.DeviceID, DeviceName: sess.DeviceName, ClientVersion: sess.ClientVersion, ClientProtocol: sess.ClientProtocol, }); err == nil { _ = s.cache.Set( ctx, cache.SessionKey(hex.EncodeToString(sess.TokenHash)), raw, s.cfg.SessionTTL, ) } } func credentials(sess store.Session) emby.Credentials { return emby.Credentials{ UserID: sess.EmbyUserID, Token: sess.EmbyToken, DeviceID: sess.DeviceID, DeviceName: sess.DeviceName, ClientVersion: sess.ClientVersion, } } // --- responses -------------------------------------------------------------- func writeJSON(w http.ResponseWriter, status int, body any) { w.Header().Set("Content-Type", "application/json; charset=utf-8") w.WriteHeader(status) if err := json.NewEncoder(w).Encode(body); err != nil { // Headers are already out; nothing useful left to do but stop. return } } func writeRaw(w http.ResponseWriter, status int, body []byte) { w.Header().Set("Content-Type", "application/json; charset=utf-8") w.WriteHeader(status) _, _ = w.Write(body) } // statusClientClosedRequest is nginx's 499. Go has no constant for it because it is not // in the RFC — it exists to say "this was not answered, and that is nobody's fault", // which is a distinction a log is read for and a 5xx destroys. const statusClientClosedRequest = 499 func writeError(w http.ResponseWriter, status int, message string) { writeJSON(w, status, map[string]string{"error": message}) } // writeUpstreamError mirrors Emby's status so the TV can tell "signed out" (401) from // "server is unwell" (5xx) without parsing strings. func (s *Server) writeUpstreamError( ctx context.Context, w http.ResponseWriter, err error, message string, ) { // The television having navigated on is not a fault, and it is the ordinary case here: // artwork loaders abandon requests as cards leave the screen, and a detail page warmed // on focus is cancelled the moment the D-pad moves. Reported as 502 it filled the // operator's log with errors describing a launcher working exactly as designed, and // buried the ones that meant something. Nobody is left to read the answer, so it goes // out as 499 — nginx's "client closed request" — and is recorded at DEBUG. if clientGaveUp(ctx, err) { s.loggerFor(ctx).Debug("abandoned before the answer", "detail", message, "error", err) writeError(w, statusClientClosedRequest, "the request was abandoned") return } var apiErr *emby.APIError if errors.As(err, &apiErr) { switch { case apiErr.StatusCode == http.StatusUnauthorized, apiErr.StatusCode == http.StatusForbidden: writeError(w, http.StatusUnauthorized, "emby rejected the session") return case apiErr.StatusCode == http.StatusNotFound: writeError(w, http.StatusNotFound, "not found on the emby server") return case apiErr.StatusCode == http.StatusTooManyRequests: retryAfter := strings.TrimSpace(apiErr.RetryAfter) if retryAfter == "" { retryAfter = "60" } w.Header().Set("Retry-After", retryAfter) writeError(w, http.StatusTooManyRequests, "the emby server is receiving too many requests") return } } s.loggerFor(ctx).Error(message, "error", err) writeError(w, http.StatusBadGateway, message) } func queryInt(r *http.Request, key string, fallback, max int) int { raw := r.URL.Query().Get(key) if raw == "" { return fallback } v, err := strconv.Atoi(raw) if err != nil || v <= 0 { return fallback } if v > max { return max } return v }