search

jellyfin-archive / jellyfin-android-original

Android Client for Jellyfin
https://jellyfin.org
GNU General Public License v2.0
271 stars 65 forks source link

Music Fails to Transcode #254

Closed Artiume closed 4 years ago

Artiume commented 4 years ago

I suspect this is the cause of https://github.com/jellyfin/jellyfin-android/issues/206 and a duplicate of https://github.com/jellyfin/jellyfin-android/issues/135

Currently music cannot transcode. The Remote Music default to Auto, thus if the app detects any sort of latency or bandwidth issues, it will fail and halt the music. I changed it to the max of 2mbps. Even with spotty internet and the music will skip due to the spotty internet, the music is still playing without halting.

If we can't get transcoding fixed, I recommend we shift the default to the max setting and not recommand using Auto until the root cause is fixed.

dkanada commented 4 years ago

This would explain a lot of intermittent problems I've had over the years.

Artiume commented 4 years ago

Yeah. As soon as I suspected the Transcoder, it all made sense

JustAMan commented 4 years ago

Does music transcode work when you use a mobile browser? Got any server logs?

Artiume commented 4 years ago

Yeah, chrome mobile works fine. I tried getting logs but the few times I did it to verify the failure, it didn't produce ffmpeg logs so it feels like it's before the ffmpeg is called for.

I don't have a nightly Android build so I haven't tested nightly yet

JustAMan commented 4 years ago

Server logs include JF logs themselves, not only ffmpeg ones :)

Artiume commented 4 years ago

Let me get a clean environment going so I can proper scrape those logs :p. If we had better tags in the logs, I could get them more easily ;)

Artiume commented 4 years ago

Nothing showing up except for it crying about Cinema Mode missing (we should go ahead and rip that out). I made it fail, changed the bitrate to a non-transcoding value, verified it played, dropped the bitrate back down and it failed again. Those are the last two lines in the logs. Let me enable debug logs.

[2020-02-12 08:45:59.938 -05:00] [INF] [19] SessionManager: Playback stopped reported by app "Jellyfin Android" "907" playing "Back To The Old House". Stopped at "0" ms
[2020-02-12 08:46:57.709 -05:00] [ERR] [33] Emby.Server.Implementations.HttpServer.HttpListenerHost: Error processing request
MediaBrowser.Common.Extensions.ResourceNotFoundException: Configuration with key cinemamode not found.
   at Emby.Server.Implementations.AppBase.BaseConfigurationManager.<>c__DisplayClass42_0.<GetConfiguration>b__0(String k)
   at System.Collections.Concurrent.ConcurrentDictionary`2.GetOrAdd(TKey key, Func`2 valueFactory)
   at MediaBrowser.Api.ConfigurationService.Get(GetNamedConfiguration request)
   at Emby.Server.Implementations.Services.ServiceExecGeneral.Execute(Type serviceType, IRequest request, Object instance, Object requestDto, String requestName)
   at Emby.Server.Implementations.Services.ServiceController.Execute(HttpListenerHost httpHost, Object requestDto, IRequest req)
   at Emby.Server.Implementations.Services.ServiceHandler.ProcessRequestAsync(HttpListenerHost httpHost, IRequest httpReq, HttpResponse httpRes, ILogger logger, CancellationToken cancellationToken)
   at Emby.Server.Implementations.HttpServer.HttpListenerHost.RequestHandler(IHttpRequest httpReq, String urlString, String host, String localPath, CancellationToken cancellationToken)
[2020-02-12 08:47:11.275 -05:00] [WRN] [118] Emby.Server.Implementations.HttpServer.HttpListenerHost: HTTP Response 206 to "199.229.249.174". Time (slow): 0:00:01.6614838. "http://jellyfin3.domain.tld/Audio/df893e7c5e10cc2699eb226e092cbfda/universal?UserId=bfd6bed33b7048fa9d558df8e79142f5&DeviceId=1054e4fb08cc9a4a&MaxStreamingBitrate=320000&Container=opus,mp3%7Cmp3,aac,m4a%7Caac,flac,webma,webm,wav&TranscodingContainer=ts&TranscodingProtocol=hls&AudioCodec=aac&PlaySessionId=1581508124557&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false"
[2020-02-12 08:47:13.494 -05:00] [ERR] [43] Emby.Server.Implementations.HttpServer.HttpListenerHost: Error processing request
MediaBrowser.Common.Extensions.ResourceNotFoundException: Configuration with key cinemamode not found.
   at Emby.Server.Implementations.AppBase.BaseConfigurationManager.<>c__DisplayClass42_0.<GetConfiguration>b__0(String k)
   at System.Collections.Concurrent.ConcurrentDictionary`2.GetOrAdd(TKey key, Func`2 valueFactory)
   at MediaBrowser.Api.ConfigurationService.Get(GetNamedConfiguration request)
   at Emby.Server.Implementations.Services.ServiceExecGeneral.Execute(Type serviceType, IRequest request, Object instance, Object requestDto, String requestName)
   at Emby.Server.Implementations.Services.ServiceController.Execute(HttpListenerHost httpHost, Object requestDto, IRequest req)
   at Emby.Server.Implementations.Services.ServiceHandler.ProcessRequestAsync(HttpListenerHost httpHost, IRequest httpReq, HttpResponse httpRes, ILogger logger, CancellationToken cancellationToken)
   at Emby.Server.Implementations.HttpServer.HttpListenerHost.RequestHandler(IHttpRequest httpReq, String urlString, String host, String localPath, CancellationToken cancellationToken)
[2020-02-12 08:47:20.904 -05:00] [INF] [37] SessionManager: Playback stopped reported by app "Jellyfin Android" "907" playing "Back To The Old House". Stopped at "897" ms
[2020-02-12 08:47:21.334 -05:00] [INF] [92] SessionManager: Playback stopped reported by app "Jellyfin Android" "907" playing "Back To The Old House". Stopped at "0" ms
Artiume commented 4 years ago

Debug logs 

[2020-02-12 08:51:20.265 -05:00] [ERR] [4] Emby.Server.Implementations.HttpServer.HttpListenerHost: Error processing request
MediaBrowser.Common.Extensions.ResourceNotFoundException: Configuration with key cinemamode not found.
   at Emby.Server.Implementations.AppBase.BaseConfigurationManager.<>c__DisplayClass42_0.<GetConfiguration>b__0(String k)
   at System.Collections.Concurrent.ConcurrentDictionary`2.GetOrAdd(TKey key, Func`2 valueFactory)
   at MediaBrowser.Api.ConfigurationService.Get(GetNamedConfiguration request)
   at Emby.Server.Implementations.Services.ServiceExecGeneral.Execute(Type serviceType, IRequest request, Object instance, Object requestDto, String requestName)
   at Emby.Server.Implementations.Services.ServiceController.Execute(HttpListenerHost httpHost, Object requestDto, IRequest req)
   at Emby.Server.Implementations.Services.ServiceHandler.ProcessRequestAsync(HttpListenerHost httpHost, IRequest httpReq, HttpResponse httpRes, ILogger logger, CancellationToken cancellationToken)
   at Emby.Server.Implementations.HttpServer.HttpListenerHost.RequestHandler(IHttpRequest httpReq, String urlString, String host, String localPath, CancellationToken cancellationToken)
[2020-02-12 08:51:29.394 -05:00] [DBG] [13] App: PingTranscodingJob PlaySessionId="1581508124559" isUsedPaused: False
[2020-02-12 08:51:30.060 -05:00] [DBG] [46] App: PingTranscodingJob PlaySessionId="1581508124559" isUsedPaused: True
[2020-02-12 08:51:32.035 -05:00] [WRN] [47] Emby.Server.Implementations.HttpServer.HttpListenerHost: HTTP Response 206 to "199.229.249.174". Time (slow): 0:00:03.2912769. "http://jellyfin3.domain.tld/Audio/df893e7c5e10cc2699eb226e092cbfda/universal?UserId=bfd6bed33b7048fa9d558df8e79142f5&DeviceId=1054e4fb08cc9a4a&MaxStreamingBitrate=320000&Container=opus,mp3%7Cmp3,aac,m4a%7Caac,flac,webma,webm,wav&TranscodingContainer=ts&TranscodingProtocol=hls&AudioCodec=aac&PlaySessionId=1581508124559&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false"
[2020-02-12 08:51:33.250 -05:00] [ERR] [45] Emby.Server.Implementations.HttpServer.HttpListenerHost: Error processing request
MediaBrowser.Common.Extensions.ResourceNotFoundException: Configuration with key cinemamode not found.
   at Emby.Server.Implementations.AppBase.BaseConfigurationManager.<>c__DisplayClass42_0.<GetConfiguration>b__0(String k)
   at System.Collections.Concurrent.ConcurrentDictionary`2.GetOrAdd(TKey key, Func`2 valueFactory)
   at MediaBrowser.Api.ConfigurationService.Get(GetNamedConfiguration request)
   at Emby.Server.Implementations.Services.ServiceExecGeneral.Execute(Type serviceType, IRequest request, Object instance, Object requestDto, String requestName)
   at Emby.Server.Implementations.Services.ServiceController.Execute(HttpListenerHost httpHost, Object requestDto, IRequest req)
   at Emby.Server.Implementations.Services.ServiceHandler.ProcessRequestAsync(HttpListenerHost httpHost, IRequest httpReq, HttpResponse httpRes, ILogger logger, CancellationToken cancellationToken)
   at Emby.Server.Implementations.HttpServer.HttpListenerHost.RequestHandler(IHttpRequest httpReq, String urlString, String host, String localPath, CancellationToken cancellationToken)
[2020-02-12 08:51:38.754 -05:00] [INF] [45] SessionManager: Playback stopped reported by app "Jellyfin Android" "907" playing "Back To The Old House". Stopped at "777" ms
[2020-02-12 08:51:38.785 -05:00] [DBG] [51] Emby.Server.Implementations.Data.SqliteItemRepository: "GetItemList" query time (slow): 30.9003ms. Query: "select type,data,StartDate,EndDate,ChannelId,IsMovie,IsSeries,EpisodeTitle,IsRepeat,CommunityRating,CustomRating,IndexNumber,IsLocked,PreferredMetadataLanguage,PreferredMetadataCountryCode,Width,Height,DateLastRefreshed,Name,Path,PremiereDate,Overview,ParentIndexNumber,ProductionYear,OfficialRating,ForcedSortName,RunTimeTicks,Size,DateCreated,DateModified,guid,Genres,ParentId,Audio,ExternalServiceId,IsInMixedFolder,DateLastSaved,LockedFields,Studios,Tags,TrailerTypes,OriginalTitle,PrimaryVersionId,DateLastMediaAdded,Album,CriticRating,IsVirtualItem,SeriesName,SeasonName,SeasonId,SeriesId,PresentationUniqueKey,InheritedParentalRatingValue,ExternalSeriesId,Tagline,ProviderIds,Images,ProductionLocations,ExtraIds,TotalBitrate,ExtraType,Artists,AlbumArtists,ExternalId,SeriesPresentationUniqueKey,ShowId,OwnerId from TypedBaseItems A where ParentId=@ParentId"
[2020-02-12 08:51:38.809 -05:00] [DBG] [109] App: PingTranscodingJob PlaySessionId="1581508124559" isUsedPaused: True
[2020-02-12 08:51:39.184 -05:00] [INF] [13] SessionManager: Playback stopped reported by app "Jellyfin Android" "907" playing "Back To The Old House". Stopped at "0" ms
[2020-02-12 08:51:39.206 -05:00] [DBG] [46] Emby.Server.Implementations.Data.SqliteItemRepository: "GetItemList" query time (slow): 11.3066ms. Query: "select type,data,StartDate,EndDate,ChannelId,IsMovie,IsSeries,EpisodeTitle,IsRepeat,CommunityRating,CustomRating,IndexNumber,IsLocked,PreferredMetadataLanguage,PreferredMetadataCountryCode,Width,Height,DateLastRefreshed,Name,Path,PremiereDate,Overview,ParentIndexNumber,ProductionYear,OfficialRating,ForcedSortName,RunTimeTicks,Size,DateCreated,DateModified,guid,Genres,ParentId,Audio,ExternalServiceId,IsInMixedFolder,DateLastSaved,LockedFields,Studios,Tags,TrailerTypes,OriginalTitle,PrimaryVersionId,DateLastMediaAdded,Album,CriticRating,IsVirtualItem,SeriesName,SeasonName,SeasonId,SeriesId,PresentationUniqueKey,InheritedParentalRatingValue,ExternalSeriesId,Tagline,ProviderIds,Images,ProductionLocations,ExtraIds,TotalBitrate,ExtraType,Artists,AlbumArtists,ExternalId,SeriesPresentationUniqueKey,ShowId,OwnerId from TypedBaseItems A where ParentId=@ParentId"
Artiume commented 4 years ago

Working logs from Chrome Mobile while transcoding

[2020-02-12 09:05:14.339 -05:00] [DBG] [21] Emby.Server.Implementations.HttpServer.HttpListenerHost: Normalizing a URL at "/"
[2020-02-12 09:05:34.243 -05:00] [INF] [68] Emby.Server.Implementations.Library.UserManager: Authentication request for "artiume" "has succeeded".
[2020-02-12 09:05:34.244 -05:00] [INF] [68] SessionManager: Creating new access token for user bfd6bed3-3b70-48fa-9d55-8df8e79142f5
[2020-02-12 09:05:34.628 -05:00] [INF] [68] App: WS "http://jellyfin3.domain.tld/socket?api_key=a4550dc84aa6473494bc48100d471c4a&deviceId=TW96aWxsYS81LjAgKExpbnV4OyBBbmRyb2lkIDguMC4wOyBTTS1HOTMwUCkgQXBwbGVXZWJLaXQvNTM3LjM2IChLSFRNTCwgbGlrZSBHZWNrbykgQ2hyb21lLzgwLjAuMzk4Ny44NyBNb2JpbGUgU2FmYXJpLzUzNy4zNnwxNTgxNTE2MzE3NzE0". UserAgent: "Mozilla/5.0 (Linux; Android 8.0.0; SM-G930P) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/80.0.3987.87 Mobile Safari/537.36"
[2020-02-12 09:05:34.629 -05:00] [DBG] [68] SessionManager: Creating new "WebSocketController"
[2020-02-12 09:05:41.317 -05:00] [DBG] [21] App: PingTranscodingJob PlaySessionId="1581516319090" isUsedPaused: False
[2020-02-12 09:05:42.219 -05:00] [WRN] [133] Emby.Server.Implementations.HttpServer.HttpListenerHost: HTTP Response 206 to "199.229.249.174". Time (slow): 0:00:01.7609285. "http://jellyfin3./Audio/df893e7c5e10cc2699eb226e092cbfda/universal?UserId=bfd6bed33b7048fa9d558df8e79142f5&DeviceId=TW96aWxsYS81LjAgKExpbnV4OyBBbmRyb2lkIDguMC4wOyBTTS1HOTMwUCkgQXBwbGVXZWJLaXQvNTM3LjM2IChLSFRNTCwgbGlrZSBHZWNrbykgQ2hyb21lLzgwLjAuMzk4Ny44NyBNb2JpbGUgU2FmYXJpLzUzNy4zNnwxNTgxNTE2MzE3NzE0&MaxStreamingBitrate=10687023&Container=opus,mp3%7Cmp3,aac,m4a,m4b%7Caac,flac,webma,webm,wav,ogg&TranscodingContainer=ts&TranscodingProtocol=hls&AudioCodec=aac&PlaySessionId=1581516319090&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false"
[2020-02-12 09:05:42.318 -05:00] [DBG] [133] App: PingTranscodingJob PlaySessionId="1581516319090" isUsedPaused: False
[2020-02-12 09:05:43.317 -05:00] [DBG] [133] App: PingTranscodingJob PlaySessionId="1581516319090" isUsedPaused: False
[2020-02-12 09:05:44.005 -05:00] [DBG] [133] App: PingTranscodingJob PlaySessionId="1581516319090" isUsedPaused: True
Artiume commented 4 years ago

Odd that my remoteendpoint was pointing at my wan-ip and not my FQDN.

20-03-11 13:11:56.977 +00:00] [INF] [23] PlaybackReporting - EventMonitorEntryPoint: session.RemoteEndPoint : "WAP-IP"
[2020-03-11 13:11:56.977 +00:00] [INF] [23] PlaybackReporting - EventMonitorEntryPoint: StartPlaybackTimer : event_playing_id     = "28a12ddfab3e0f8d3018ca2064f5875f"
[2020-03-11 13:11:56.978 +00:00] [INF] [23] PlaybackReporting - EventMonitorEntryPoint: StartPlaybackTimer : event_user_id        = "bd3cd6572a584e08b43f6d2652e0c2c6"
[2020-03-11 13:11:56.978 +00:00] [INF] [23] PlaybackReporting - EventMonitorEntryPoint: StartPlaybackTimer : event_user_id_int    = 1
[2020-03-11 13:11:56.978 +00:00] [INF] [23] PlaybackReporting - EventMonitorEntryPoint: StartPlaybackTimer : session_playing_id   = "28a12ddfab3e0f8d3018ca2064f5875f"
[2020-03-11 13:11:56.978 +00:00] [INF] [23] PlaybackReporting - EventMonitorEntryPoint: StartPlaybackTimer : session_user_id      = "bd3cd6572a584e08b43f6d2652e0c2c6"
[2020-03-11 13:11:56.978 +00:00] [INF] [23] PlaybackReporting - EventMonitorEntryPoint: StartPlaybackTimer : play_method          = "DirectPlay"
[2020-03-11 13:11:56.978 +00:00] [INF] [23] PlaybackReporting - EventMonitorEntryPoint: StartPlaybackTimer : e.ClientName         = "Jellyfin Android"
[2020-03-11 13:11:56.978 +00:00] [INF] [23] PlaybackReporting - EventMonitorEntryPoint: StartPlaybackTimer : e.DeviceName         = "SM-G930P"
[2020-03-11 13:11:56.978 +00:00] [INF] [23] PlaybackReporting - EventMonitorEntryPoint: StartPlaybackTimer : ItemName             = "Priscilla Ahn - I Don't Think So (A Good Day)"
[2020-03-11 13:11:56.978 +00:00] [INF] [23] PlaybackReporting - EventMonitorEntryPoint: StartPlaybackTimer : ItemId               = "28a12ddfab3e0f8d3018ca2064f5875f"
[2020-03-11 13:11:56.978 +00:00] [INF] [23] PlaybackReporting - EventMonitorEntryPoint: StartPlaybackTimer : ItemType             = "Audio"
[2020-03-11 13:11:56.978 +00:00] [INF] [23] PlaybackReporting - EventMonitorEntryPoint: StartPlaybackTimer : All matches, playback registered
[2020-03-11 13:11:56.978 +00:00] [INF] [23] PlaybackReporting - EventMonitorEntryPoint: Playback tracker found, adding playback info : "1054e4fb08cc9a4a-bd3cd6572a584e08b43f6d2652e0c2c6-28a12ddfab3e0f8d3018ca2064f5875f"
[2020-03-11 13:11:56.978 +00:00] [INF] [23] PlaybackReporting - EventMonitorEntryPoint: Saving playback tracking activity in DB
[2020-03-11 13:11:56.994 +00:00] [INF] [23] PlaybackReporting - EventMonitorEntryPoint: StartPlaybackTimer : Exited
[2020-03-11 13:11:58.097 +00:00] [INF] [28] PlaybackReporting - EventMonitorEntryPoint: Processing playback tracker : "1054e4fb08cc9a4a-bd3cd6572a584e08b43f6d2652e0c2c6-28a12ddfab3e0f8d3018ca2064f5875f"
dkanada commented 4 years ago

This is indeed a duplicate of #135 so we can track updates there.