search

jellyfin / jellyfin-kodi

Jellyfin Plugin for Kodi
https://jellyfin.org
GNU General Public License v3.0
860 stars 113 forks source link

DirectStream self stop minutes after begining #288

Open Marc-Vieg opened 4 years ago

Marc-Vieg commented 4 years ago

Describe the bug Every time I start a via directStream, it start and play fine, but stop and return to previous screen without a word after some minutes (~2-6) like if I pressed the stop button But when i select transcode, it runs fine and finish the video normaly

To Reproduce

  1. goto movie
  2. click on play
  3. enjoy your quick cinema experience

Expected behavior play the media to the end

Logs server log snippet : https://pastebin.com/Tt9MQkEM kodi log (DEBUG) : https://pastebin.com/4Y3dex1S

System (please complete the following information):

Additional context

the server and the client are on the same lan subnet, everything hooked by gigabit ethernet. there is no reverse proxy, nor https. comming just recently from emby, i noticed the same issue but never took the time to investigate. here i find that kodi seem to react like i have pressed the stop button (which i didn't)

CLIENT : 2020-04-22 16:22:54.613 T:2602561744 NOTICE: JELLYFIN.jellyfin.http -> DEBUG::jellyfin_kodi/jellyfin/http.py:84 --->[ http ] { "url": "http://**ServerIp**:8096/Sessions/Playing/Stopped", "verify": true, "headers": { "Accept-Charset": "UTF-8,*", "Accept-encoding": "gzip", "X-MediaBrowser-Token": "{jellyfin-token}", "Content-type": "application/json", "x-emby-authorization": "MediaBrowser Client=Kodi, Device=tv, DeviceId=bdccf51e-c77e-448b-ba94-d0b2a77c67bc, Version=0.5.5, UserId=**UserId**", "User-Agent": "Jellyfin-Kodi/0.5.5" }, "json": { "ItemId": "2f343f84856c5fb8c1e03eaa733fa9d0", "MediaSourceId": "2f343f84856c5fb8c1e03eaa733fa9d0", "PositionTicks": 2310000000, "PlaySessionId": "7772e3fee71340df8f9d5626b1c0b781" }, "params": null, "timeout": 30, "type": "POST" }

SERVER : [2020-04-22 16:22:54.623 +02:00] [INF] Playback stopped reported by app "Kodi" "0.5.5" playing "Color Out of Space". Stopped at "231000" ms [2020-04-22 16:22:54.662 +02:00] [INF] Playback Stopped

I'll be glad to help you investigate this issue, thank for your time

oddstr13 commented 4 years ago

Please provide full client logs

oddstr13 commented 4 years ago

On mobile, so missed the pastebin link initially. Only error I could spot right now is ERROR::jellyfin_kodi/library.py:435 time data '22 Apr 2020 14:18:21 GMT' does not match format '%d %b %Y %H:%M:%S GMT' Likely caused by system locale having a different abbrevation for month than english.

I don't know if this is the reason for the stopping.

Marc-Vieg commented 4 years ago

just verified, the local both on client and server are fr_FR.UTF-8 UTF-8 from python there is a 1 hour delta between client and server : client : 

import datetime
datetime.datetime.now()
datetime.datetime(2020, 4, 23, 6, 10, 21, 318250)

server : 

import datetime
datetime.datetime.now()
datetime.datetime(2020, 4, 23, 7, 10, 21, 318250)

so digging a bit more, timedatectl returns a different location, server is in Europe/Paris Timezone, client in Europe/London I use timedatectl set-timezone "Europe/Paris" on client they are now both at the same time zone, however the direct play crash even earlier (about 5-10 seconds)

But this error is again present : 

2020-04-23 07:27:13.291 T:2277503184  NOTICE: JELLYFIN.library -> ERROR::jellyfin_kodi/library.py:435 time data '23 Apr 2020 05:27:09 GMT' does not match format '%d %b %Y %H:%M:%S GMT'
                                            Traceback (most recent call last):
                                              File "jellyfin_kodi/library.py", line 432, in save_last_sync
                                                time_now = datetime.strptime(self.server.config.data['server-time'].split(', ', 1)[1], '%d %b %Y %H:%M:%S GMT') - timedelta(minutes=2)
                                              File "/usr/lib/python2.7/_strptime.py", line 332, in _strptime
                                                (data_string, format))
                                            ValueError: time data '23 Apr 2020 05:27:09 GMT' does not match format '%d %b %Y %H:%M:%S GMT'
oddstr13 commented 4 years ago

What strftime/strptime outputs/expects for %b depends on the language of the locale set in LC_TIME.

The RFC 5322 date format is not suitable for software communication, only human display. ISO 8601 should be used instead.

>>> import time
>>> 
>>> date = '22 Apr 2020 14:18:21 GMT'
>>> format = '%d %b %Y %H:%M:%S GMT'
>>> 
>>> time.strptime(date, format)
time.struct_time(tm_year=2020, tm_mon=4, tm_mday=22, tm_hour=14, tm_min=18, tm_sec=21, tm_wday=2, tm_yday=113, tm_isdst=-1)
>>> 
>>> 
>>> import locale
>>> 
>>> locale.setlocale(locale.LC_TIME, locale=('nb_NO', 'UTF-8'))
'nb_NO.UTF-8'
>>> 
>>> time.strptime(date, format)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/lib/python2.7/_strptime.py", line 478, in _strptime_time
    return _strptime(data_string, format)[0]
  File "/usr/lib/python2.7/_strptime.py", line 332, in _strptime
    (data_string, format))
ValueError: time data '22 Apr 2020 14:18:21 GMT' does not match format '%d %b %Y %H:%M:%S GMT'
>>> 
>>> time.strftime(format)
'23 april 2020 09:42:47 GMT'
>>>
Marc-Vieg commented 4 years ago

you are right, i changed my locale on the client to en_US UTF-8 with dpkg-reconfigure locales it seems to play normaly. but now the stream stops within 10-20 minutes now.. client : kodi_crash_en_US.log

server : server_en_US.log

Marc-Vieg commented 4 years ago

when reproducing for X time, i notice that the buffer on the seekbar stops moving forward after a bit, and when the play gets to the buffer end, the stream ends and return to the last screen.

Maybe it comes from this error message ? 

2020-04-24 09:17:51.385 T:2203042000   ERROR: CCurlFile::FillBuffer - Failed: Transferred a partial file(18)

so i enable specific Curl debugging in kodi and i notice that

2020-04-24 09:17:56.385 T:2203042000   DEBUG: Curl::Debug - TEXT: Expire in 0 ms for 6 (transfer 0x9df2e720)
2020-04-24 09:17:56.385 T:2203042000 WARNING: CCurlFile::FillBuffer - Reconnect, (re)try 1
2020-04-24 09:17:56.385 T:2203042000   DEBUG: Curl::Debug - TEXT: Expire in 30000 ms for 2 (transfer 0x9df2e720)
2020-04-24 09:17:56.386 T:2203042000   DEBUG: Curl::Debug - TEXT: Hostname 192.168.1.13 was found in DNS cache
2020-04-24 09:17:56.386 T:2203042000   DEBUG: Curl::Debug - TEXT:   Trying 192.168.1.13...
2020-04-24 09:17:56.386 T:2203042000   DEBUG: Curl::Debug - TEXT: TCP_NODELAY set
2020-04-24 09:17:56.386 T:2203042000   DEBUG: Curl::Debug - TEXT: Expire in 200 ms for 4 (transfer 0x9df2e720)
2020-04-24 09:17:56.386 T:2203042000   DEBUG: Curl::Debug - TEXT: Connected to 192.168.1.13 (192.168.1.13) port 8096 (#9)
2020-04-24 09:17:56.387 T:2203042000   DEBUG: Curl::Debug - HEADER_OUT: GET /Videos/5464076be83e826cd8c999e3f89484c6/stream?static=true&MediaSourceId=5464076be83e826cd8c999e3f89484c6&api_key=***ApiKey*** HTTP/1.1
2020-04-24 09:17:56.387 T:2203042000   DEBUG: Curl::Debug - HEADER_OUT: Host: 192.168.1.13:8096
2020-04-24 09:17:56.387 T:2203042000   DEBUG: Curl::Debug - HEADER_OUT: Range: bytes=35115008-
2020-04-24 09:17:56.387 T:2203042000   DEBUG: Curl::Debug - HEADER_OUT: User-Agent: Kodi/18.6 (X11; Linux armv7l) Raspbian GNU/Linux/10 App_Bitness/32 Version/18.6-Git:20200310-283bece277
2020-04-24 09:17:56.387 T:2203042000   DEBUG: Curl::Debug - HEADER_OUT: Accept: */*
2020-04-24 09:17:56.387 T:2203042000   DEBUG: Curl::Debug - HEADER_OUT: Accept-Encoding: deflate, gzip
2020-04-24 09:17:56.387 T:2203042000   DEBUG: Curl::Debug - HEADER_OUT: Connection: Upgrade, HTTP2-Settings
2020-04-24 09:17:56.387 T:2203042000   DEBUG: Curl::Debug - HEADER_OUT: Upgrade: h2c
2020-04-24 09:17:56.387 T:2203042000   DEBUG: Curl::Debug - HEADER_OUT: HTTP2-Settings: AAMAAABkAARAAAAAAAIAAAAA
2020-04-24 09:17:56.387 T:2203042000   DEBUG: Curl::Debug - HEADER_OUT: Accept-Charset: UTF-8,*;q=0.8
2020-04-24 09:17:56.387 T:2203042000   DEBUG: Curl::Debug - TEXT: Expire in 1000 ms for 7 (transfer 0x9df2e720)
2020-04-24 09:17:56.414 T:2203042000   DEBUG: Curl::Debug - TEXT: The requested URL returned error: 500 Internal Server Error
2020-04-24 09:17:56.414 T:2203042000   DEBUG: Curl::Debug - TEXT: Closing connection 9
2020-04-24 09:17:56.414 T:2203042000   ERROR: CCurlFile::FillBuffer - Failed: HTTP returned error 500
2020-04-24 09:17:56.415 T:2203042000   DEBUG: CFileCache::Process - Source read returned a fatal error! Will wait for buffer to empty.
2020-04-24 09:17:56.415 T:2203042000   DEBUG: Thread FileCache 2203042000 terminating
2020-04-24 09:17:56.418 T:1978163408   ERROR: ffmpeg[75E860D0]: [matroska,webm] Read error
2020-04-24 09:17:56.432 T:2178937040   DEBUG: CMMALPool::Configure pool:0x89c33610 720x412 (720x416) pix:-1 size:128 fmt:OPQV
2020-04-24 09:17:57.258 T:2211434704   DEBUG: Previous line repeats 21 times.

here is the full log : kodi_crash_CCURL.log

And on the server : 

[ERR] Error processing request: "Input/output error". URL: "http://192.168.1.13:8096/Videos/5464076be83e826cd8c999e3f89484c6/stream?static=true&MediaSourceId=5464076be83e826cd8c999e3f89484c6"
[2020-04-24 09:17:28.160 +02:00] [WRN] HTTP Response 206 to "192.168.1.68". Time (slow): 0:02:28.8466848. "http://192.168.1.13:8096/Videos/5464076be83e826cd8c999e3f89484c6/stream?static=true&MediaSourceId=5464076be83e826cd8c999e3f89484c6"
[2020-04-24 09:17:28.161 +02:00] [ERR] Connection id ""0HLV78OCDAKQF"", Request id ""0HLV78OCDAKQF:00000001"": An unhandled exception was thrown by the application.
System.InvalidOperationException: Response Content-Length mismatch: too few bytes written (31698267 of 41638743).
[2020-04-24 09:17:39.654 +02:00] [ERR] Error processing request: "Input/output error". URL: "http://192.168.1.13:8096/Videos/5464076be83e826cd8c999e3f89484c6/stream?static=true&MediaSourceId=5464076be83e826cd8c999e3f89484c6"
[2020-04-24 09:17:39.656 +02:00] [WRN] HTTP Response 206 to "192.168.1.68". Time (slow): 0:00:03.5835699. "http://192.168.1.13:8096/Videos/5464076be83e826cd8c999e3f89484c6/stream?static=true&MediaSourceId=5464076be83e826cd8c999e3f89484c6"
[2020-04-24 09:17:39.657 +02:00] [ERR] Connection id ""0HLV78OCDAKQH"", Request id ""0HLV78OCDAKQH:00000001"": An unhandled exception was thrown by the application.
System.InvalidOperationException: Response Content-Length mismatch: too few bytes written (3407872 of 9940476).
[2020-04-24 09:17:44.430 +02:00] [INF] Processing playback tracker : "bdccf51e-c77e-448b-ba94-d0b2a77c67bc-2880fae6f2c94fcebcd7f5169a05e6d1-5464076be83e826cd8c999e3f89484c6"
[2020-04-24 09:17:56.418 +02:00] [ERR] Error processing request: "Input/output error". URL: "http://192.168.1.13:8096/Videos/5464076be83e826cd8c999e3f89484c6/stream?static=true&MediaSourceId=5464076be83e826cd8c999e3f89484c6"
[2020-04-24 09:18:02.431 +02:00] [INF] Playback stopped reported by app "Kodi" "0.5.5" playing "Seigneur Caius". Stopped at "178000" ms
[2020-04-24 09:18:02.462 +02:00] [INF] Playback Stopped

The Server and Client seem to not understand each other during the stream ?

oddstr13 commented 4 years ago

After having had a proper look at the code regarding the date, it is a handled error which is getting printed, and is thus unrelated to the actual issue at hand here.

The error message in the server log look similar to, but not identical to jellyfin/jellyfin#2354 HTTP returned error 500 means the server is throwing an error instead of returning the expected data.

nyejon commented 4 years ago

I have the same problem on Kodi on the firestick 4k. It takes ages to start playing (if it even works), usually Kodi crashes. I notice the free RAM on the firestick keeps dropping until the point Kodi crashes.

I did manage to play a file once, but then after a few minutes the stream crashed too.