Posts by jahutchi

I've just had another crash at 10:04.

Again, all I did was leave the machine Idle in the PVR section of the Home screen.

It recovered from the OOM condition and here is the terminal output from bcmstat: OTJb

And here is the kodi crash log: CdYB

I also managed to capture the contents of journalctl at 10:04

(there is an hour time difference because I've not set the correct timezone since resetting to a "clean" install)

Oct 04 11:04:09 LibreELEC kodi.sh[1411]: ERROR: Exception caught on main loop. Exiting
Oct 04 11:04:17 LibreELEC kernel: vchiq: 0: ignoring ERROR from callback to service a000c
Oct 04 11:04:17 LibreELEC connmand[320]: ntp: adjust (slew): +0.004130 sec
Oct 04 11:04:17 LibreELEC kodi.sh[1411]: Segmentation fault (core dumped)

I have just had another crash. Here are the steps I took:

1) Stopped kodi and removed my .kodi directory.

2) Removed the system.d files any other systemctl services I had installed (Docker, Inadyn, OpenVPN, stunnel) - these services would fail to start anyway since they were created by the addons, and I've now removed the .kodi folder.

3) Rebooted the machine.

4) Placed an advancedsettings.xml in my user data folder to enable debug logging.

5) Installed only the pvr.hts addon, and configured this to point at my tvheadend server. Note: I also enabled debug logging within the addon settings.

6) Restarted kodi for advancedsettings.xml to take effect (systemctl restart kodi)

7) Ran some SSH terminals with bcmstat, etc as suggested.

Navigated to the PVR section of the home screen and left it alone

Within 20 minutes kodi crashed and here is the terminal output for bcmstat:

FCXW

This time around it recovered from the OOM condition, and kodi has re-spawned itself - maybe something about one of the other addons was previously preventing this....

Therefore, this time around I have a complete crash log

FMPT

I was running a terminal with the repeating ps command loop; this is still running and constantly overwriting ps.log so the output there has moved on so will not be much use - SjPc

Following the crash, I have played a few PVR channels, and have now left it Idle again in the PVR section of the Home screen. I'll see whether it crashes again, and if so then I'll post up some further crash logs.

Do let me know if there are any other files required to help debug the code.

@millhouse Thanks for the tips - I shall do as you suggest, and try to reproduce with a "clean" system, and gather information on the running processes, etc.

FTR: I rebooted last night and found that once more there was an incomplete crash log left behind (.kodi_crashlog.log) - XLBA

There was also a kodi.old.log, but that only contains the same content as found in my terminal window as posted yesterday - hMAb

I shall keep you updated on the results of my testing with a "clean" system.

Quote from milhouse

Do you have any idea what process or activity is scheduled to run at 9pm? It would be interesting to know if the timing is consistent, as that might give a clue as to what process/activity is running.

As far as I'm aware I don't have anything unusual running at 9pm. This is a fairly minimal build with just a handful of add-ons. I'd be happy to wipe it clean to a vanilla install with only the pvr.hts addon installed and re-test if that would help..... since I have a backup of all my key folders (.config / .kodi etc)

FTR: The previous crash from last Thursday occurred at around 10.25 in the morning so I'm thinking the time is a red-herring.

When the system crashed I was also tailing kodi.log in a separate window - here are the final entries:

20:59:00.166 T:1592038288   DEBUG: CPVRRecordings - Update - updating recordings
20:59:00.230 T:1942807440   DEBUG: CDirectoryProvider[pvr://channels/tv/*?view=lastplayed]: refreshing..
20:59:00.231 T:1410331536   DEBUG: CPVRDirectory::GetDirectory(pvr://channels/tv/*?view=lastplayed)
20:59:00.236 T:1942807440   DEBUG: CDirectoryProvider[pvr://recordings/tv/active?view=flat]: refreshing..
20:59:00.237 T:1474294672   DEBUG: CPVRDirectory::GetDirectory(pvr://recordings/tv/active?view=flat)
20:59:00.313 T:1942807440   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - Getting play position 0 for recording Coronation Street
20:59:00.314 T:1942807440   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - Getting play position 0 for recording Emmerdale
20:59:00.315 T:1942807440   DEBUG: AddOnLog: Tvheadend HTSP Client: pvr.hts - Getting play position 0 for recording Liar
20:59:30.238 T:1439691664   DEBUG: Thread JobWorker 1439691664 terminating (autodelete)
20:59:30.244 T:1410331536   DEBUG: Thread JobWorker 1410331536 terminating (autodelete)
20:59:30.302 T:1474294672   DEBUG: Thread JobWorker 1474294672 terminating (autodelete)

I've also pasted as much content as I had from this SSH session to here:

YijkcK50

It's important to note that the problem only seems to occur when I leave it in the PVR section of the Home window.

When I reproduce the issue on LibreELEC 8.0.x / 8.1.x then kodi.bin still crashes, but respawns quite happily (by the OOM handler?) and I do get a crash log (I posted this up earlier in this thread).

I shall leave the machine in it's hung state to see if it recovers so I can run the journalctl command - though it's now been hung for 16 hours, so not holding out much hope....

Quote from milhouse

I've uploaded a new debug-enabled build #0928b: RPi2

This includes a deadlock fix for PVR database accesses, the latest version of which appears to be getting positive results so it might be worth testing with this build in case it is related.

Otherwise, I'd supsect a memory leak... you could confirm this by running "bcmstat.sh ZDAd 30" in a ssh console, then leave it running until the crash/hang occurs. If memory has been leaked then the "Memory Free" column will be close to zero, and the "Mem kB" columns (which reflect delta and accumulated ARM allocations respectively) will be consistently negative, indicating repeated memory allocations (ie. leakage - positive values are reported whenever a "free" occurs).

I installed the debug build #0928b on my RPi3.

I think you are correct about a memory leak.... The machine ran stable for several hours with fairly consistent memory usage. At 9PM last night the memory spiked and the machine is now completely locked up.

Here is the output of "bcmstat.sh ZDAd 30" from my SSH console: WS1Q9k6p

As before, the machine is now completely unresponsive. I have a black screen, and cannot SSH/Samba to the machine whatsoever to see what (if any) logs have been created. I suspect that if I reboot I will have an incomplete crash log as before.

Should I just power-off / power-on the machine, and see what logs were created? or is there anything I can do whilst the machine is in this state to get you the debug information you need?

I have plenty of space on the /storage partition:

/dev/mmcblk0p2 13.9G 3.5G 10.4G 25% /storage

I'll try again to reproduce the problem, and see whether I get a full crash log.

I wonder if it's because my machine had completely frozen, to the point that I cannot even SSH to it to grab the logfiles.

When it froze I left it several hours to see if it would recover itself, but the system remained unresponsive and I could not even SSH to it.

I therefore had to manually power cycle it by unplugging the power cable, and then plugging it back in.

The logfile I uploaded was what was left behind following this crash & hang.

Quote from jahutchi

Did you have chance to test???

I've just been trying on my RPi3 using LibreELEC-RPi2.arm-9.0-Milhouse-20170911025601-#0910b-g3e7d5d8.tar

After running for a couple of hours the machine has completely frozen, to the point that I cannot even SSH to it to grab the logfiles (not something I encountered previously with LE 8.1.1)

I am not physically in the same location as the machine so cannot power cycle it... but will reboot tonight and see if there is a kodi.log.old. If so I shall post it up...

Are there any other logs that will survive the reboot which may be of use?

Following the reboot I can see there are two logs:

kodi.old.log: eUKC

.kodi_crashlog.log: VJDj

I left the machine running overnight, but did not leave it in the pvr section of the home screen and it stayed stable.

DaVu Do you require any more logs?

Quote from DaVu

Unfortunately I'm a bit busy at the moment. So I can't test before Friday. I will, but if you are faster....just do it

Did you have chance to test???

I've just been trying on my RPi3 using LibreELEC-RPi2.arm-9.0-Milhouse-20170911025601-#0910b-g3e7d5d8.tar

After running for a couple of hours the machine has completely frozen, to the point that I cannot even SSH to it to grab the logfiles (not something I encountered previously with LE 8.1.1)

I am not physically in the same location as the machine so cannot power cycle it... but will reboot tonight and see if there is a kodi.log.old. If so I shall post it up...

Are there any other logs that will survive the reboot which may be of use?

Quote from chewitt

^ that's what git bisect does; you mark a good and bad commit and it starts halving the list of commits until you find the problem one

Understood. So it still may take ~50 builds to get close to the problem even when taking the half-way points! ...darn.

From previous posts it sounds like it will be much easier to bisect the kernel on a Generic x86 machine that hits the problem - which I do have.

I'd be happy to have a go at performing the bisects and compiling/testing some builds. Not something I've done before though so if anyone could provide assistance, or point me at some reliable links/documentation to get me started then I'll try my best to figure it out.

However, if it's simply going to be too difficult for a novice then I'll step back and hope someone else with suitable expertise is able to debug the issue.

Quote from CvH

the problem is between rev1 and rev2 are a huuuuuuuughe number of commits so its is pretty useless to to recompile if you can't do it by your self (maybe ~50 builds are needed to get close to the problem)

Ok, just thought I would make the offer. I'm happy to do the testing, even if it means testing ~50 builds so my offer still stands. Unfortunately I have absolutely no experience at compiling kernels and bisecting the commits. I am fairly technical so if someone could provide some fairly comprehensive instructions on that then I would give it a go.

Failing that, I wonder if it would cut down the number of potential builds if you were to build at "half-way" points each time. That is an approach I've used for solving similar problems before. Then we would know whether to go higher or lower than the current commit - again picking a half way point and checking the build. It's only an idea and I'm certainly no expert in this area - just thinking aloud.

Quote from CvH

which DVB HW ?

My machine (Acer Revo 3700R) has 2x DVBSky S960 USB DVB-S2 adapters and 2x MyGica T230 T2 USB adapters.

I'm currently using the builds from smp with the 4.8.13 kernel (no media build) and don't get any continuity errors, and everything is perfect. I can even record/watch upto around 6 things at once without any artefacts etc

If I upgrade to the official release or anything with a 4.9+ kernel then I get continuity errors and artefacts every few minutes.

Back on pages 3-4 of this thread you were sending me some builds to try out at various commit points, but I think this approach probably got too time-consuming...

Previously, we found the issue was introduced somewhere between the commit points of these images that you supplied LibreELEC-Generic.x86_64-8.0.0-rev1-6b5e09a.img.gz and LibreELEC-Generic.x86_64-8.0.0-rev2-2937f37.img.gz

Quote from CvH

so revert 1 is not working, revert 2 is working so the problem is somewhere between

okay going to build some images

Not sure if you want to pick this back up.

I am now using LE 8.0.1

forlotto. I had something similar to the issue you're reporting. I was unable to get automatic updates working which also come from a github url. I ran some network traces and could see that my connections were being re-routed to the wrong ip by my isp (virgin media). I did a little googling and found that there were some anti-malware/parental controls which i could set in the myvirgin web interface. I had the problem both on and off vpn because the controls seemed to cause dns requests for certain hostnames to resolve to a virgin media ip. After i turned off those limitations in the myvirgin web interface then my dns requests routed to the correct place any everything worked as it should. It would be worth checking whether your isp has any similar anti-malware/parental controls, and if so switch them off and see if the problem goes away.

Quote from popcornmix

Bisecting the kernel will be a lot easier on x86 where the upstream kernel can be used untouched.

Bisecting kernel on Pi across the 4.8/4.9 boundary would need serious git skills due to the downstream patches changing.

I am not a developer and have no idea how to bisect a kernel.

However, I am able to easily reproduce the issue on my x86_64 machine.

If a developer were able to perform the bisects & provide x86_64 test builds for me to download at various commit points, then I would be happy to work through testing each of those builds. My plan would be one per day - leaving it playing a PVR channel overnight, then check for continuity errors in the logfile the next morning and report back. Ideally the builds would be based on LE 8.0.1 (without media build) as that's what I'm running currently, so I'd be comparing like-for-like - knowing that only a different kernel has been swapped-in (without any other moving parts).

If all that would be too much messing around, and it really needs the owner of an affected x86 machine to both perform the bisecting and testing then I'm afraid I can't help.... but thought I would make the above offer to help try and resolve the issue.

Here are some examples of local streams from my machine

Live TV

14:02:43.189 T:140004189796096 NONE: VPN Mgr Debug: Changing VPN. Current playing pvr://channels/tv/All channels/pvr.hts_1304825683.pvr

Library File

14:05:53.865 T:140004189796096 NONE: VPN Mgr Debug: Changing VPN. Current playing /storage/tvshows/Bones/Bones.S12E07.720p.mkv

PVR Recording

14:09:09.342 T:140004189796096 NONE: VPN Mgr Debug: Changing VPN. Current playing pvr://recordings/tv/active/New_ Victoria/New%3a%20Victoria%20The%20Sins%20of%20the%20Father%3a%20Drama%20series.%20Despite%20giving%20birth%20to%20a%20healthy%20Prince%20of%20Wales%2c%20Victoria%20finds%20herself%20paralysed%20by%20an%20inexplicable%20sorrow.%20%5bAD%2cS%5d, TV%20(ITV%20Yorkshire%20HD), 20170917_200000, 1149230897.pvr

My use-case is probably quite unusual....

I have actually setup WindowID filtering to force it to reconnect when I use any of the PVR-related features. This is because I am using add-on filtering for certain addons e.g. BBC iPlayer, where I want the VPN to be disconnected (since they need a UK IP). When leaving the addon (e.g. BBC iPlayer), it does not automatically reconnect so I've reconfigured it so that the windows I use most commonly (e.g. TV Guide), trigger a reconnect.

We discussed this back in March via PM and you gave me a hack to the code so I could force certain WindowID's (e.g. TV Guide) to reconnect the VPN. You then added the WindowID filtering logic to the code, and then I could remove my hack and use the built-in WindowID filtering.

So I suppose I'm asking for the WindowID filtering I've setup to force it to reconnect to only take effect if there isn't video playing in the background. My hack of commenting that line out seems to kind of work though not 100% sure there won't be other side effects. It looks like the vpn_reconnect_while_playing does not take effect for the WindowID filtering.

I have a suggestion for a future release....

One thing that was annoying me was that if the VPN is dropped whilst playing LiveTV, then when you try to bring up certain windows (e.g. TVGuide) ontop of LiveTV with the current channel still playing in the background, then it reconnects the VPN, and playback stops.

I managed to get round this by commenting out the following line in service.py:

#Stop any media playing before switching VPNs around

#if player.isPlaying(): player.stop()

I had tried switching on/off the vpn_reconnect_while_playing option but that does not influence this line of code.

Just wondering if an option could be added in future to decide whether or not a (re)connect will stop playing the video. Either that, or maybe it shouldn't run this line if the vpn_reconnect_while_playing is set to false?

For the time being I have switched off automatic updates, since I'll need to repeat this hack after future updates.

Annoyingly, I've tracked back and the reason I installed that repo, and it was so I could install ITV Player. Very annoying that such a widely used addon only lives in banned repos. I looked at posts on the official kodi forums and other ITV Player users share the same frustration! I hope they manage to get it into an official repo in future. For now...lesson learnt...and I'll just have to update ITV Player manually in future (if it breaks) using links on the official Release page of the kodi forum.

Annoyingly, this all now means that the logfiles I posted here earlier will probably never be looked at now, so this bug, which affects several legitimate PVR users will go unfixed....