[metu71]

I have been trying Kodi for few days, previously I used old Gotham with cmyth add-on, but now I decided to give newer versions a try. Since I'm having this issue, I though I should ask if it is already a known one.

I have just updated to Openelec 6.0 on Raspberry Pi B+. It includes Kodi 15.2 (?) and enabled Mythtv PVR add-on 2.8.4. The problem I have been seeing was there also with add-on version 2.4.3, but I thought maybe updating add-on could help...

So I have Mythbackend 0.27 running and I have both server and RasPi B+ connected to gigabit ethernet via a router. I have been seeing problems with playback. It usually plays fine for a minute or two and then playback stops without a warning. I have tried 10+ times in a row and same behaviour. If I stop for 10min or for an hour, I might not face it when I watch the same program again. But it is as likely to see than not to see it. There has been no reboots or anything like that in between.

I have checked the log and it says connection error:

8:18:44 64163.035156 T:1773139008 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)__connectAddr: failed to connect (110)
18:18:44 64163.035156 T:1773139008 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)GetPreviewImage1_32: invalid response
18:18:44 64163.035156 T:1704981568 DEBUG: AddOnLog: MythTV PVR Client: (CPPMyth)RcvMessageLength: 111
18:18:44 64163.039062 T:1704981568 DEBUG: AddOnLog: MythTV PVR Client: (CPPMyth)RcvBackendMessage: SYSTEM_EVENT CLIENT_DISCONNECTED HOSTNAME OlkkariRPiOpenElec SENDER tvserveri-ssd (6)
18:18:44 64163.039062 T:1773139008 ERROR: AddOnLog: MythTV PVR Client: Process: Failed to read file: type: 1, local: /storage/.kodi/userdata/addon_data/pvr.mythtv/cache/thumbnail/2043_1409
984100_000
18:18:44 64163.039062 T:1773139008 DEBUG: AddOnLog: MythTV PVR Client: Process: Delayed recache file: type: 1, local: /storage/.kodi/userdata/addon_data/pvr.mythtv/cache/thumbnail/2043_140
9984100_000

I recorded a log from server side using tcpdump. Inside that log I see sequences of data block which are then acknowledged with single ack-message. All of those data messages are of size 1448 (probably bytes), but just before the playback stops there is same package sent twice and size of that package is less than 1448. Response to that from client is not looking the same as successful ones and then playback stops. Here is example of successful sequence:

21:42:05.736018 IP 192.168.1.3.6543 > 192.168.1.100.57169: Flags [.], seq 281796863:281798311, ack 131, win 227, options [nop,nop,TS val 27249789 ecr 22819434], length 1448
21:42:05.736027 IP 192.168.1.3.6543 > 192.168.1.100.57169: Flags [.], seq 281798311:281799759, ack 131, win 227, options [nop,nop,TS val 27249789 ecr 22819434], length 1448
21:42:05.736032 IP 192.168.1.3.6543 > 192.168.1.100.57169: Flags [.], seq 281799759:281801207, ack 131, win 227, options [nop,nop,TS val 27249789 ecr 22819434], length 1448
21:42:05.736037 IP 192.168.1.3.6543 > 192.168.1.100.57169: Flags [.], seq 281801207:281802655, ack 131, win 227, options [nop,nop,TS val 27249789 ecr 22819434], length 1448
21:42:05.736043 IP 192.168.1.3.6543 > 192.168.1.100.57169: Flags [P.], seq 281802655:281804103, ack 131, win 227, options [nop,nop,TS val 27249789 ecr 22819434], length 1448
21:42:05.736048 IP 192.168.1.3.6543 > 192.168.1.100.57169: Flags [.], seq 281804103:281805551, ack 131, win 227, options [nop,nop,TS val 27249789 ecr 22819434], length 1448
21:42:05.736052 IP 192.168.1.3.6543 > 192.168.1.100.57169: Flags [.], seq 281805551:281806999, ack 131, win 227, options [nop,nop,TS val 27249789 ecr 22819434], length 1448
21:42:05.736058 IP 192.168.1.3.6543 > 192.168.1.100.57169: Flags [.], seq 281806999:281808447, ack 131, win 227, options [nop,nop,TS val 27249789 ecr 22819434], length 1448
21:42:05.756514 IP 192.168.1.3.6543 > 192.168.1.100.57169: Flags [.], seq 281808447:281809895, ack 131, win 227, options [nop,nop,TS val 27249795 ecr 22819434], length 1448
21:42:05.776135 IP 192.168.1.100.57169 > 192.168.1.3.6543: Flags [.], ack 281809895, win 43440, options [nop,nop,TS val 22819446 ecr 27249789], length 0


Have you experts seen anything like this? If there is any info I could provide which helps to solve this?

I also wondered how is video transfer implemented. Is there just block of data which is chopped into pieces for transfer inside MythTV or is there some library called from MythTV which is doing that?

Help much appreciated...

-Pasi-

[janbar]

Seems there is a network shutdown. The client (addon) is disconnected and all connections are broken including the playback transfer.

The addon use the MythTV protocol to transfer the video: Needs 2 connections: One to control the transfer, and an other to received block of data. You could see at https://www.mythtv.org/wiki/Category:Myth_Protocol (section Backend commands).

[janbar]

Also i explained the issue here: http://janbar.github.io/pvr.mythtv/manua...leshooting .

[metu71]

Thanks for the replies.

I agree about the network issue, but any ideas what could cause it? I never saw anything like this with cmyth. I haven't changed anything (and I mean anything, same HW and even the IP address is the same) in my network after I switched to Myth PVR add-on.

I did some more testing. I have a TV show recorded both HD and SD resolutions. I saw this issue with both of them and issue happends approximately 2min after starting playback. Then I disabled TV from System -> Settings -> TV and noticed that SW hang for a minute or so immediately after disabling. I have no idea why. After it came responsive again I enabled TV again and started to play SD version of the TV show. I was able to watch it without any problems for 6min before I stopped the playback. Immediately I started to watch the HD version and saw the issue after ~2min of playback. Then I tried to watch the SD version again and the issue was there also and it happened after 2min of playback (@8min, since I continued from 6min spot). Based on this it seemed that after disabling it works with 1st playback, but not with 2nd or 3rd etc.

I did same sequence with TV disable/enable and started to watch HD version first, no issue seen, then SD version and issue was seen as before. Next watching again HD version and issue was there also.

I tried this sequence 4 times and always the same result. It really seems that something changes between 1st and 2nd playback. I'm not sure if MythTV backend knows about TV disable/enable sequence, but there must be some sort of registration when TV is enabled. I would also expect that resources used by TV/MythTV PVR add-on are released when TV is disabled, but is there some sort of timer based housekeeping if TV is not used for a while?

I have understood that this add-on uses MythTV Services API, right? Or is add-on using the same MythTV protocol that MythTV frontend uses? Or is it using both?

I appreciate what you guys have created. This is the first client SW which my family has accepted without a fight

[janbar]

Network connexion failure could be caused by multiple factors:

- To many file descriptors opened: check os config for max open file.
- a other host use same ip : drop the malicious host
- intr signal was received: upgrade to addon verson 2.8.4. I had this issue using a virtual host as guest. But not the case for you.

[janbar]

On raspberry pi , try first using wired network. Sometimes driver for wifi dongle crash.

[metu71]

I have 2.8.4 in use and using wired network.

[metu71]

I found the root cause of the issue. Started taking logs with Myth PVR image built by myself. Added log messages to mythprotobase.cpp and mythprotoplayback.cpp. Those showed that the problem happened with preview image fetch. For some reason server responded 'Unknown' (code 301) with some recordings. Because of that add-on tried to do redirection, which I think is implemented to support multiple backend servers (not sure about that). To do the redirection, add-on gets hostname for the recording from server and requests IP address of that server. I did server HW upgrade some time earlier this year and changed servers hostname. This old hostname was still in that recordings SQL data. I also changed my ADSM modem/router earlier this year, which also meant change in my local networks address space. When add-on asked for IP address of the hostname of the recording, it got servers old IP, whic of course did not connect.

To fix this I edited 'recorded' table in mythconverg SQL database. All lines in 'recorded' table was modified to have current servers hostname. After this change issue was not seen anymore.

This issue cannot be directly linked to wrong hostname. What I saw in add-on log was that during playback add-on was using a socket to transfer data from master backend (the only backend). During playback some other process wants to read preview images from the backend. As it fails add-on wants to read it from another backend as indicated by the response. When this another backend is not responding also those sockets to active backend are shutdown. This is what I saw in log. First there was this error (110), then right after that 'select' system call exits with an error 9. For some reason, fail on socket to non-existing server causes closing of active socket to existing server and I think this should not happen.

@janbar, as I think you know the code best, do you have time to check this out or at least correct me if I have understood something wrong?

Here is pieces of trace log to show what happens. I have modified existing log messages and added some new, but I think you get the point.

...
02:03:46 226.648911 T:1556943936 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)GetPreviewImage1_32: chanID 1003
02:03:46 226.649353 T:1556943936 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)WSResponse: P1 serv: 192.168.1.3 port: 6544
....
02:03:46 226.653107 T:1556943936 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)GetResponse: HTTP/1.1 301 Unknown
02:03:46 226.653244 T:1556943936 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)GetResponse: Date: 10 joulukuuta 2015 20:10:53
02:03:46 226.653381 T:1556943936 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)GetResponse: Server: Linux 3.16.0-30-generic, UPnP/1.0, MythTV 0.27.20140323-1
02:03:46 226.653473 T:1556943936 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)GetResponse: Accept-Ranges: bytes
02:03:46 226.653580 T:1556943936 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)GetResponse: Location: http://tvserveri:6544/Content/GetPreview...A%30%30%5A
02:03:46 226.653656 T:1556943936 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)GetResponse: Connection: Close
02:03:46 226.653778 T:1556943936 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)GetResponse: Content-Type:
02:03:46 226.653854 T:1556943936 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)GetResponse: Content-Length: 0
02:03:46 226.653931 T:1556943936 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)GetResponse:
02:03:46 226.654419 T:1556943936 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)WSResponse: P1 serv: 192.168.0.3 port: 6544
....
02:05:53 353.971252 T:1556943936 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)__connectAddr: failed to connect (110)
02:05:53 353.971771 T:1556943936 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)GetPreviewImage1_32: REDIR /Content/GetPreviewImage?ChanId=%31%30%30%33&StartTime=%32%30%31%35%2D%30%31%2D%32%34%54%32%32%3A%35%33%3A%30%30%5A
02:05:53 353.971893 T:1556943936 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)GetPreviewImage1_32: invalid response
02:05:53 353.972076 T:1556943936 ERROR: AddOnLog: MythTV PVR Client: Process: Failed to read file: type: 1, local: /storage/.kodi/userdata/addon_data/pvr.mythtv/cache/thumbnail/1003_1422139980_000
02:05:53 353.972565 T:1481446464 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)TransferRequestBlock: select error (-1)
02:05:53 353.972870 T:1481446464 ERROR: AddOnLog: MythTV PVR Client: (CPPMyth)HangException: protocol connection hang with error 9
....

[janbar]

Yes you have anderstand how cppmyth work. The master backend redirect client depending of the server owner of the recordings (slave). As you change the hostname of your server you have to migrate some data in mythconverg because recordings are linked with their backend.

[janbar]

Disconnection of other socket should not happen. During normal operation every socket opened to webservice call is closed after received a response or a timeout: the close procedure starts with a shutdown to the socket to close and finish by a close. Now i haven't explaination about this behavior on your rpi.

[janbar]

Also in the code never wsapi relates proto and sockets are never shared. Really weird ...

[metu71]

Ok, thanks. I will try to debug further if I can find how those sockets are depending on each other...

[janbar]

One way to explore could be addon received signal SIGPIPE during select(), caused by shutdown invalid socket (error 9 = EBADF) ...