Bug #4802

Experiencing regular crashes

Added by Peter Brockamp about 1 month ago. Updated 4 days ago.

Status:NewStart date:2017-12-17
Priority:NormalDue date:
Assignee:-% Done:

0%

Category:Crashes
Target version:-
Found in version:4.2.4-42~g1c9944bb2 Affected Versions:

Description

Hello!

I'm experiencing regular crashes. Dunno if this is a problem of tvh itself or the Linux kernel, but somewhere I need to start.

I'm using tvheadend on a headless Debian stretch system, running on a hexacore amd phenom with 4GB RAM:
Linux version 4.9.0-4-amd64 () (gcc version 6.3.0 20170516 (Debian 6.3.0-18) ) #1 SMP Debian 4.9.65-3 (2017-12-03)
Current tvh version: 4.2.4-42~g1c9944bb2
I'm using a SAT-IP server (Megasat SAT>IP Server 3) connected to my LAN for recording and live TV. Tvh has exclusive access to the server.
Up to now I could not recognize any systematics on when the crashes occur (like e. g. start of a recording).

However I already had problems with earlier tvh version and jessie as follows:
  • At first (Jessie) I experienced regular complete freezing(!) of the machine with no output in the syslog. "Regular" means it could be that the machine lived only for an hour, but maybe also for several days.
  • I started wondering if I'm having a hardware problem on my machine, Linux should at least Kernel panic and I was expecting something in the logs, but nothing like that. I didn't find the time to do some in depth checking, plus I'm using a board, CPU and RAM that had been running without problems under Win 10 for many months.
  • I decided to migrate from jessie to stretch (to see if this changes something) but this did not solve the freezing problem.
  • I did some of the usual apt-get updates and suddenly with one update behavior changed so that my machine no longer froze but tvh started crashing instead (I had no debug version installed at that time, so no useful stack dump available):

? tvheadend.service - (null)
Loaded: loaded (/etc/init.d/tvheadend)
Active: active (exited) since So 2017-09-24 13:27:06 CEST; 10h ago
Process: 601 ExecStart=/etc/init.d/tvheadend start (code=exited, status=0/SUCCESS)

Sep 24 19:30:57 TVHeadend tvheadend989: CRASH: ??:0 0x563308e2fe2a 0x563308c30000
Sep 24 19:30:57 TVHeadend tvheadend989: CRASH: ??:0 0x7ff76e50d890 0x7ff76e4fe000
Sep 24 19:30:57 TVHeadend tvheadend989: CRASH: gsignal+0x37 (/lib/x86_64-linux-gnu/libc.so.6)
Sep 24 19:30:57 TVHeadend tvheadend989: CRASH: abort+0x148 (/lib/x86_64-linux-gnu/libc.so.6)
Sep 24 19:30:57 TVHeadend tvheadend989: CRASH: ??:0 0x563308dbb423 0x563308c30000
Sep 24 19:30:57 TVHeadend tvheadend989: CRASH: ??:0 0x563308e18980 0x563308c30000
Sep 24 19:30:57 TVHeadend tvheadend989: CRASH: ??:0 0x563308e1e7c9 0x563308c30000
Sep 24 19:30:57 TVHeadend tvheadend989: CRASH: ??:0 0x563308e224e5 0x563308c30000
Sep 24 19:30:57 TVHeadend tvheadend989: CRASH: ??:0 0x563308dfc670 0x563308c30000
Sep 24 19:30:57 TVHeadend tvheadend989: CRASH: ??:0 0x563308df81f4 0x563308c30000

  • After some more updates suddenly all problems seem to have been gone, the machine was running without problems and no crashes for a whole bunch of weeks and for several updates.
  • Unfortunately with the latest apt-get update the problems came back, I could even experience crashes after only 10 min uptime! The difference: Now is there is a kernel Oops:

Dec 17 21:00:39 TVHeadend kernel: [ 662.841326] BUG: unable to handle kernel paging request at fffff30207b85ee0
Dec 17 21:00:39 TVHeadend kernel: [ 662.844241] IP: [<ffffffffb8b47970>] __list_del_entry+0x0/0xb0
Dec 17 21:00:39 TVHeadend kernel: [ 662.847220] PGD 11f7f6067
Dec 17 21:00:39 TVHeadend kernel: [ 662.847275] PUD 0
Dec 17 21:00:39 TVHeadend kernel: [ 662.850253]
Dec 17 21:00:39 TVHeadend kernel: [ 662.853271] Oops: 0000 [#1] SMP

I attached the complete Oops plus the log with hardware information for my machine in case this is useful.
Apparently something's going badly awry here. I have no idea what's happening and why. Could anyone please support how to find out the reason for these crashes, be it tvh or the kernel, and how to proceed? A machine intended for doing unattended video recordings that crashes regularly has a very limited value and is of course rather frustrating... :-/

THX

Don

Kernel crash.txt Magnifier - Kernel Oops (31.7 KB) Peter Brockamp, 2017-12-17 22:50

Boot.txt Magnifier - Boot sequence (66 KB) Peter Brockamp, 2017-12-17 22:50

History

#1 Updated by saen acro about 1 month ago

Do you use transcoding?

#2 Updated by Mark Clarkstone about 1 month ago

If you can install the debug packages (tvheadend-dbg) and get a full crash log that may show where the problem is (see Debugging & Traces).

#3 Updated by Mark Clarkstone about 1 month ago

  • Subject changed from Expieriencing regular crashes to Experiencing regular crashes

#4 Updated by Peter Brockamp about 1 month ago

saen acro wrote:

Do you use transcoding?

You mean the output format for storing records? I tried both, pass thru and MKV, both behave identical, it crashes.

Some additional remarks:
  • The Kernel Oops I posted happened only once. In all other cases so far the machine completely froze.
  • Could it be that what I receive as "freezing" is in fact a kernel panic? As said I'm running the machine headless. For testing purposes I attached an LCD but got not picture after the crash. But maybe this is due to the screen being blanked due to powersafe timeout before the crash (if the kernel does not reenable the screen in case of a panic)? I added "consoleblank=0" to my grub configuration, let's see if this changes something.
  • After the latest updates freezing became even more nagging than previously, the machine hangs several times per day now, I could not experience a situation where it ran for a couple of days! So the problem is very present.
  • Crashing could happen during silent phases (AKA machine is currently idling, nobody's watching something, and only some recording timer is set), during an active recording and also while somebody's watching a recording. So this is quite weird and unspecific.

THX

Don

#5 Updated by Peter Brockamp about 1 month ago

Mark Clarkstone wrote:

If you can install the debug packages (tvheadend-dbg) and get a full crash log that may show where the problem is (see Debugging & Traces).

Will try that and report. Please hold on.

THX

Don

#6 Updated by Peter Brockamp about 1 month ago

Peter Brockamp wrote:

Some additional remarks:
  • Could it be that what I receive as "freezing" is in fact a kernel panic? As said I'm running the machine headless. For testing purposes I attached an LCD but got not picture after the crash. But maybe this is due to the screen being blanked due to powersafe timeout before the crash (if the kernel does not reenable the screen in case of a panic)? I added "consoleblank=0" to my grub configuration, let's see if this changes something.
Now here's the result:
  • "consoleblank=0" inhibits the blanking of the console and after a crash now there is a picture.
  • However there is no Kernel Panic shown, I simply see the login prompt of the first tty.
  • There is an underscore of the cursor, but it stopped blinking. So this in fact is a complete machine freeze, WTF! :(

So this again looks more like a hardware problem?? Can hardly imagine Linux crashes that lousy...

THX

Don

#7 Updated by Peter Brockamp 12 days ago

Mark Clarkstone wrote:

If you can install the debug packages (tvheadend-dbg) and get a full crash log that may show where the problem is (see Debugging & Traces).

Is there anything additional I have to do to enable logging? It seems to me as if I don't get any additional log entries. Things all look pretty normal, except that the machine suddenly freezes without any prior log entry hinting at some problem. It simply dies :(

Once during my tests I had a strange behavior, the machine went into full RAM load, started swapping like hell and didn't stop until I manually restarted tvh. In the log I saw this:


Dec 21 22:11:35 TVHeadend tvheadend[1041]: TS: Astra 19.2e/11493.75H/arte HD: H264
#5111 Continuity counter error (total 1)
Dec 21 22:11:35 TVHeadend tvheadend1041: TS: Astra 19.2e/11493.75H/Das Erste HD: H264 #5101 Continuity counter error (total 1)
Dec 21 22:11:35 TVHeadend tvheadend[1041]: TS: Astra 19.2e/11493.75H/Das Erste HD: MPEG2AUDIO
#5102 Continuity counter error (total 1)
Dec 21 22:11:35 TVHeadend tvheadend1041: TS: Astra 19.2e/11493.75H/Das Erste HD: MPEG2AUDIO #5103 Continuity counter error (total 1)
Dec 21 22:11:35 TVHeadend tvheadend[1041]: TS: Astra 19.2e/11493.75H/arte HD: MPEG2AUDIO
#5112 Continuity counter error (total 1)
Dec 21 22:11:35 TVHeadend tvheadend1041: TS: Astra 19.2e/11493.75H/arte HD: MPEG2AUDIO #5113 Continuity counter error (total 1)
Dec 21 22:11:35 TVHeadend tvheadend[1041]: TS: Astra 19.2e/11493.75H/arte HD: TELETEXT
#5114 Continuity counter error (total 1)
Dec 21 22:11:35 TVHeadend tvheadend1041: TS: Astra 19.2e/11493.75H/arte HD: MPEG2AUDIO #5117 Continuity counter error (total 1)
Dec 21 22:11:35 TVHeadend tvheadend[1041]: TS: Astra 19.2e/11493.75H/Das Erste HD: TELETEXT
#5104 Continuity counter error (total 1)
Dec 21 22:11:35 TVHeadend tvheadend1041: TS: Astra 19.2e/11493.75H/Das Erste HD: DVBSUB #5105 Continuity counter error (total 1)
Dec 21 22:11:35 TVHeadend tvheadend[1041]: TS: Astra 19.2e/11493.75H/arte HD: DVBSUB
#5118 Continuity counter error (total 1)
Dec 21 22:11:35 TVHeadend tvheadend1041: tsfix: transport stream AC3, DTS discontinuity. DTS = 108380160, last = 108285120
Dec 21 22:11:35 TVHeadend tvheadend1041: tsfix: transport stream AC3, DTS discontinuity. DTS = 462211, last = 367171
Dec 21 22:11:41 TVHeadend tvheadend1041: tsfix: transport stream AC3, DTS discontinuity. DTS = 1015171, last = 920131
Dec 21 22:11:41 TVHeadend tvheadend1041: tsfix: transport stream AC3, DTS discontinuity. DTS = 108944640, last = 108849600
Dec 21 22:11:46 TVHeadend tvheadend1041: TS: Astra 19.2e/11493.75H/arte HD: H264 #5111 Continuity counter error (total 3)
Dec 21 22:11:46 TVHeadend tvheadend[1041]: TS: Astra 19.2e/11493.75H/Das Erste HD: H264
#5101 Continuity counter error (total 3)
Dec 21 22:11:46 TVHeadend tvheadend1041: TS: Astra 19.2e/11493.75H/arte HD: MPEG2AUDIO #5112 Continuity counter error (total 3)
Dec 21 22:11:46 TVHeadend tvheadend[1041]: TS: Astra 19.2e/11493.75H/arte HD: MPEG2AUDIO
#5113 Continuity counter error (total 3)
Dec 21 22:11:46 TVHeadend tvheadend1041: TS: Astra 19.2e/11493.75H/arte HD: AC3 #5116 Continuity counter error (total 1)
Dec 21 22:11:46 TVHeadend tvheadend[1041]: TS: Astra 19.2e/11493.75H/Das Erste HD: AC3
#5106 Continuity counter error (total 1)
Dec 21 22:11:46 TVHeadend tvheadend1041: TS: Astra 19.2e/11493.75H/Das Erste HD: TELETEXT #5104 Continuity counter error (total 3)
Dec 21 22:11:46 TVHeadend tvheadend[1041]: TS: Astra 19.2e/11493.75H/arte HD: MPEG2AUDIO
#5117 Continuity counter error (total 3)
Dec 21 22:11:46 TVHeadend tvheadend1041: TS: Astra 19.2e/11493.75H/Das Erste HD: MPEG2AUDIO #5102 Continuity counter error (total 2)
Dec 21 22:11:46 TVHeadend tvheadend[1041]: TS: Astra 19.2e/11493.75H/arte HD: TELETEXT
#5114 Continuity counter error (total 3)
Dec 21 22:11:46 TVHeadend tvheadend1041: TS: Astra 19.2e/11493.75H/Das Erste HD: MPEG2AUDIO #5103 Continuity counter error (total 2)
Dec 21 22:11:47 TVHeadend tvheadend[1041]: tsfix: transport stream AC3, DTS discontinuity. DTS = 1510531, last = 1415491
Dec 21 22:11:47 TVHeadend tvheadend[1041]: tsfix: transport stream AC3, DTS discontinuity. DTS = 109440000, last = 109344960
Dec 21 22:11:47 TVHeadend tvheadend[1041]: TS: Astra 19.2e/11493.75H/arte HD: DVBSUB
#5118 Continuity counter error (total 3)
Dec 21 22:11:51 TVHeadend tvheadend1041: tsfix: transport stream AC3, DTS discontinuity. DTS = 109866240, last = 109771200
Dec 21 22:11:52 TVHeadend tvheadend1041: tsfix: transport stream AC3, DTS discontinuity. DTS = 1994371, last = 1841731
Dec 21 22:11:55 TVHeadend tvheadend1041: TS: Astra 19.2e/11493.75H/Das Erste HD: DVBSUB #5105 Continuity counter error (total 2)
Dec 21 22:11:56 TVHeadend tvheadend[1041]: tsfix: transport stream AC3, DTS discontinuity. DTS = 2339971, last = 2244931
Dec 21 22:11:56 TVHeadend tvheadend[1041]: tsfix: transport stream AC3, DTS discontinuity. DTS = 110269440, last = 110174400
Dec 21 22:12:00 TVHeadend tvheadend[1041]: dvr: /media/tvheadend/video/Liebe ist das perfekte Verbrechen/Liebe ist das perfekte Verbrechen.mkv from adapter: "SAT>IP DVB-S Tuner #3 (192.168.178.45)", network: "Astra 19.2e", mux: "11493.75H", provider: "ARD", service: "arte HD"
Dec 21 22:12:00 TVHeadend tvheadend[1041]: dvr: # type lang resolution aspect ratio sample rate channels
Dec 21 22:12:00 TVHeadend tvheadend[1041]: dvr: 1 H264 1280x720 16:9
Dec 21 22:12:00 TVHeadend tvheadend[1041]: dvr: 2 MPEG2AUDIO ger 48000 2
Dec 21 22:12:00 TVHeadend tvheadend[1041]: dvr: 3 MPEG2AUDIO fre 48000 2
Dec 21 22:12:00 TVHeadend tvheadend[1041]: dvr: 5 DVBSUB ger
Dec 21 22:12:00 TVHeadend tvheadend[1041]: dvr: 6 AC3 mul 48000 5.1
Dec 21 22:12:00 TVHeadend tvheadend[1041]: dvr: 7 MPEG2AUDIO mis 48000 2
Dec 21 22:12:00 TVHeadend tvheadend[1041]: dvr: 8 DVBSUB fre
Dec 21 22:12:00 TVHeadend tvheadend[1041]: dvr: 9 DVBSUB ger
Dec 21 22:12:00 TVHeadend tvheadend[1041]: TS: Astra 19.2e/11493.75H/Das Erste HD: H264
#5101 Continuity counter error (total 6)
Dec 21 22:12:00 TVHeadend tvheadend1041: TS: Astra 19.2e/11493.75H/arte HD: H264 #5111 Continuity counter error (total 6)
Dec 21 22:12:00 TVHeadend tvheadend[1041]: TS: Astra 19.2e/11493.75H/Das Erste HD: MPEG2AUDIO
#5102 Continuity counter error (total 5)
Dec 21 22:12:00 TVHeadend tvheadend1041: TS: Astra 19.2e/11493.75H/Das Erste HD: MPEG2AUDIO #5103 Continuity counter error (total 5)
Dec 21 22:12:00 TVHeadend tvheadend[1041]: TS: Astra 19.2e/11493.75H/arte HD: MPEG2AUDIO
#5117 Continuity counter error (total 6)
Dec 21 22:12:00 TVHeadend tvheadend1041: TS: Astra 19.2e/11493.75H/arte HD: TELETEXT #5114 Continuity counter error (total 6)

This went on for a while, then switching to lots of entries like this:


Dec 21 22:49:18 TVHeadend tvheadend[1041]: subscription: 000D: service instance is bad, reason: Tuning failed
Dec 21 22:49:18 TVHeadend tvheadend[1041]: subscription: 000D: "DVR: Liebe ist das perfekte Verbrechen" subscribing on channel "arte HD", weight: 300, adapter: "SAT>IP DVB-S Tuner #3 (192.168.178.45)", network: "Astra 19.2e", mux: "11493.75H", provider: "ARD", service: "arte HD", profile="matroska"
Dec 21 22:49:18 TVHeadend tvheadend[1041]: subscription: 000C: service instance is bad, reason: Tuning failed
Dec 21 22:49:18 TVHeadend tvheadend[1041]: mpegts: 12460.5H in Astra 19.2e - tuning on SAT>IP DVB-S Tuner #4 (192.168.178.45)
Dec 21 22:49:18 TVHeadend tvheadend[1041]: subscription: 000C: "DVR: The 100" subscribing on channel "SIXX", weight: 300, adapter: "SAT>IP DVB-S Tuner #4 (192.168.178.45)", network: "Astra 19.2e", mux: "12460.5H", provider: "ProSiebenSat.1", service: "SIXX", profile="matroska"
Dec 21 22:49:18 TVHeadend tvheadend[1041]: subscription: 000B: service instance is bad, reason: Tuning failed
Dec 21 22:49:18 TVHeadend tvheadend[1041]: subscription: 000B: "DVR: Nuhr 2017 - Der Jahresrückblick" subscribing on channel "Das Erste HD", weight: 300, adapter: "SAT>IP DVB-S Tuner #3 (192.168.178.45)", network: "Astra 19.2e", mux: "11493.75H", provider: "ARD", service: "Das Erste HD", profile="matroska"
Dec 21 22:49:18 TVHeadend tvheadend[1041]: subscription: 0008: service instance is bad, reason: Tuning failed
Dec 21 22:49:18 TVHeadend tvheadend[1041]: mpegts: 12187.5H in Astra 19.2e - tuning on SAT>IP DVB-S Tuner #2 (192.168.178.45)
Dec 21 22:49:18 TVHeadend tvheadend[1041]: subscription: 0008: "192.168.178.43 [ glotzer | Kodi Media Center ]" subscribing on channel "VOX", weight: 150, adapter: "SAT>IP DVB-S Tuner #2 (192.168.178.45)", network: "Astra 19.2e", mux: "12187.5H", provider: "CBC", service: "VOX", profile="htsp", hostname="192.168.178.43", username="glotzer", client="Kodi Media Center"
Dec 21 22:49:18 TVHeadend tvheadend[1041]: satip: SAT>IP DVB-S Tuner #2 (192.168.178.45) - RTSP error -111 (Verbindungsaufbau abgelehnt) [6-0]
Dec 21 22:49:18 TVHeadend tvheadend[1041]: satip: SAT>IP DVB-S Tuner #4 (192.168.178.45) - RTSP error -111 (Verbindungsaufbau abgelehnt) [6-0]
Dec 21 22:49:20 TVHeadend tvheadend[1041]: subscription: 000C: service instance is bad, reason: Tuning failed
Dec 21 22:49:20 TVHeadend tvheadend[1041]: mpegts: 12460.5H in Astra 19.2e - tuning on SAT>IP DVB-S Tuner #5 (192.168.178.45)
Dec 21 22:49:20 TVHeadend tvheadend[1041]: subscription: 000C: "DVR: The 100" subscribing on channel "SIXX", weight: 300, adapter: "SAT>IP DVB-S Tuner #5 (192.168.178.45)", network: "Astra 19.2e", mux: "12460.5H", provider: "ProSiebenSat.1", service: "SIXX", profile="matroska"
Dec 21 22:49:20 TVHeadend tvheadend[1041]: subscription: 0008: service instance is bad, reason: Tuning failed
Dec 21 22:49:20 TVHeadend tvheadend[1041]: mpegts: 12187.5H in Astra 19.2e - tuning on SAT>IP DVB-S Tuner #6 (192.168.178.45)
Dec 21 22:49:20 TVHeadend tvheadend[1041]: subscription: 0008: "192.168.178.43 [ glotzer | Kodi Media Center ]" subscribing on channel "VOX", weight: 150, adapter: "SAT>IP DVB-S Tuner #6 (192.168.178.45)", network: "Astra 19.2e", mux: "12187.5H", provider: "CBC", service: "VOX", profile="htsp", hostname="192.168.178.43", username="glotzer", client="Kodi Media Center"
Dec 21 22:49:28 TVHeadend tvheadend[1041]: subscription: 000D: service instance is bad, reason: No input detected
Dec 21 22:49:28 TVHeadend tvheadend[1041]: subscription: 000D: "DVR: Liebe ist das perfekte Verbrechen" subscribing on channel "arte HD", weight: 300, adapter: "SAT>IP DVB-S Tuner #3 (192.168.178.45)", network: "Astra 19.2e", mux: "11493.75H", provider: "ARD", service: "arte HD", profile="matroska"
Dec 21 22:49:28 TVHeadend tvheadend[1041]: subscription: 000B: service instance is bad, reason: No input detected
Dec 21 22:49:28 TVHeadend tvheadend[1041]: subscription: 000B: "DVR: Nuhr 2017 - Der Jahresrückblick" subscribing on channel "Das Erste HD", weight: 300, adapter: "SAT>IP DVB-S Tuner #3 (192.168.178.45)", network: "Astra 19.2e", mux: "11493.75H", provider: "ARD", service: "Das Erste HD", profile="matroska"
Dec 21 22:49:38 TVHeadend tvheadend[1041]: subscription: 000D: service instance is bad, reason: No input detected

And finally filling the log with


Dec 21 22:50:22 TVHeadend tvheadend[1041]: subscription: 000D: No input source available for subscription "DVR: Liebe ist das perfekte Verbrechen" to channel "arte HD"
Dec 21 22:50:24 TVHeadend tvheadend[1041]: subscription: 000D: No input source available for subscription "DVR: Liebe ist das perfekte Verbrechen" to channel "arte HD"
Dec 21 22:50:26 TVHeadend tvheadend[1041]: subscription: 000D: No input source available for subscription "DVR: Liebe ist das perfekte Verbrechen" to channel "arte HD"

and


Dec 22 07:23:25 TVHeadend tvheadend[901]: mpegts: too much queued table input data (over 2MB), discarding new
Dec 22 07:23:35 TVHeadend tvheadend[901]: mpegts: too much queued table input data (over 2MB), discarding new
Dec 22 07:23:45 TVHeadend tvheadend[901]: mpegts: too much queued table input data (over 2MB), discarding new
Dec 22 07:23:55 TVHeadend tvheadend[901]: mpegts: too much queued table input data (over 2MB), discarding new
Dec 22 07:24:06 TVHeadend tvheadend[901]: mpegts: too much queued table input data (over 2MB), discarding new
Dec 22 07:24:16 TVHeadend tvheadend[901]: mpegts: too much queued table input data (over 2MB), discarding new

This effect I only had once, seems like tvh was going berserk then.

What is relly annoying is that kern.log is spammed every ten seconds with


Jan 1 06:25:39 TVHeadend kernel: [60253.009168] i2c i2c-0: sendbytes: NAK bailout.
Jan 1 06:25:39 TVHeadend kernel: [60253.013559] i2c i2c-0: sendbytes: NAK bailout.
Jan 1 06:25:39 TVHeadend kernel: [60253.017926] i2c i2c-0: sendbytes: NAK bailout.
Jan 1 06:25:39 TVHeadend kernel: [60253.022374] i2c i2c-0: sendbytes: NAK bailout.
Jan 1 06:25:39 TVHeadend kernel: [60253.026616] i2c i2c-0: sendbytes: NAK bailout.
Jan 1 06:25:39 TVHeadend kernel: [60253.030364] [drm:radeon_vga_detect [radeon]] *ERROR* VGA-1: probed a monitor but no|invalid EDID

But no debug related log entries at all. Of course I enabled debug in Configuration\Debugging\}Configuration (and I'm aware this only lasts until the restarting tvh). May I have to uninstall the non-debug version of tvh in order to see debug output?

Again I bacame more suspicious that the machine dies due to a hardware issue. I will start a long run memtest run tomorrow in the hope to locate some problem. We'll see...

THX

Don

#8 Updated by Mark Clarkstone 12 days ago

Peter Brockamp wrote:

..snip..
Again I bacame more suspicious that the machine dies due to a hardware issue. I will start a long run memtest run tomorrow in the hope to locate some problem. We'll see...

The i2c errors are very suspect! If tvh is crashing and dropping a core (crash lines) you can install corekeeper to grab it & analyse it later.

#9 Updated by Peter Brockamp 12 days ago

Mark Clarkstone wrote:

The i2c errors are very suspect! If tvh is crashing and dropping a core (crash lines) you can install corekeeper to grab it & analyse it later.

I doubt this is really critical. If you google for "i2c i2c-0: sendbytes: NAK bailout" you'll find a couple of hits referring to e.g. noveau or other graphics driver stuff. Seems to occur under different conditions but obviously not critial or fatal ones. Unfortunately I could not yet find out definitely what the device 0 (i2c-0) in my case is, so this kernel message is not very enligthening.

However I'm doing an educated guess:
Reading the capabilities of a display (EDID) is also being done via an i2c bus. This works already for legacy VGA connectors (the first EDID specification is from 1994!), see here:
[[http://www.chrisbot.com/i2c-and-monitor-ddc.html]]
So I'm assuming the i2c message simply tell's me that the kernel attempts to get the monitor capabilities but as no monitor is connected of course it get's no reply. Thus it runs into a couple of timeouts and finally gives up with "probed a monitor but no|invalid EDID". This would be no problem if not the kernel repeated this attempts (and logs it) every 10 seconds. Retrying would be OK in order to detect an monitor as soons as it's being connected, but continuously spamming the log is a real nag.

The only strange point about it is that according to the specification reading EDID parameters should be possible also with a monitor connected but switched off (the device willing to send a video signal supplies 5V for reading EDID). I asume it should also be able to distinguish "switched off" from "not connected" and deal with that appropriately. Due to the crashes I currently don't run completely headless but I have a monitor attached which is most of the times either switched off or set to another input. Nevertheless the reading of the DDC fails which should not happen as I understand it. Could be that my monitor is not completely standard conformant and this is causing this strange behavior. Whatever is the case, I don't think this messages are connected to the crashes. It would be good to have at least a kernel parameter to shut down the spaming as those log messages have no value and I cannot fix the triggering problem.

Cheerz

#10 Updated by Peter Brockamp 12 days ago

Just started a long run memtest on the machine now with all CPU cores active for maximum stress and load on RAM. The first run passed succesfully without errors. CPU temperature partially rises above 70°C, fan regulation audibly kicks in, increases cooling efforts and brings the temparature rise to a halt. So this is all to be expected and seem to work OK and as designed. Will see how the long term progress is, I plan to have memtest running for at least two days or even more.

If this does not uncover any problems I will try to disable those hardware drivers that do not hamper current operation. E. g. the machine has an onboard firewire controller which is not used in the tvh scenario. I could disable it to check if this has an impact on crashes. Same the video driver, here I could fallback to the standard FB driver. And so on. However I even have no PCI cards plugged in, just the naked mainboard running, the onboard components are by far sufficient here and it's not a noname board, so things should be pretty stable.

I will also try to strip down BIOS settings to the most conservative ones. Annoyingly since a couple of years board vendors started to press users into overclocking components, even major brands. This really pisses me off, there's no obvious setting "F... off, I want no bloody OC, just give me stable, power saving options", you have to figure out for yourself and set it manually :(

#11 Updated by Peter Brockamp 6 days ago

Well, finished the Memtest run but it did not reveal any problems. No RAM errors detected and the machine did not crash or freeze...

#12 Updated by Mark Clarkstone 6 days ago

Peter Brockamp wrote:

Well, finished the Memtest run but it did not reveal any problems. No RAM errors detected and the machine did not crash or freeze...

This is a very strange one. If you can, install corekeeper & the tvheadend-dbg package. Paste the full trace lines here from the crash. Take a look at Debugging.

#13 Updated by Peter Brockamp 5 days ago

Mark Clarkstone wrote:

This is a very strange one. If you can, install corekeeper & the tvheadend-dbg package. Paste the full trace lines here from the crash. Take a look at Debugging.

OK, thanks for instructing:
  • I installed corekeeper - is there anything else I have to configure? man corekeeper seems not to exist...
  • I installed tvheadend-dbg - is it correct to keep tvheadend installed or must I uninstall it?
    apt list --installed
    tvheadend/stretch,now 4.2.5-14~g1665c355c~stretch amd64 [installiert]
    tvheadend-dbg/stretch,now 4.2.5-14~g1665c355c~stretch amd64 [installiert]
  • I globally switched on debugging for tvheadend in etc/default/tvheadend:
    TVH_DEBUG=1
    TVH_ARGS="-D -l /var/log/tvheadend"

    Any further command line arguments required?
  • /etc/security/limits.d/corekeeper.conf has both, hard and soft limit set to unlimited and I gave the daemon the "-D" parameter - is that sufficient to permanently enable debugging mode and core dumps?

Will try "-A" and see what is being dumped on my HDD...

Cheerz

#14 Updated by Peter Brockamp 4 days ago

Successfully configured the system to write coredumps:

ulimit -a
core file size (blocks, -c) unlimited
data seg size (kbytes, -d) unlimited
scheduling priority (-e) 0
file size (blocks, -f) unlimited
pending signals (-i) 14460
max locked memory (kbytes, -l) 64
max memory size (kbytes, -m) unlimited
open files (-n) 1024
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
real-time priority (-r) 0
stack size (kbytes, -s) 8192
cpu time (seconds, -t) unlimited
max user processes (-u) 14460
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited

Testing with -A what happens in case of a crash I get:

@service tvheadend status
● tvheadend.service
Loaded: loaded (/etc/init.d/tvheadend; generated; vendor preset: enabled)
Active: active (exited) since Sun 2018-01-14 20:56:28 CET; 43s ago
Docs: man:systemd-sysv-generator(8)
Process: 8409 ExecStop=/etc/init.d/tvheadend stop (code=exited, status=0/SUCCESS)
Process: 8416 ExecStart=/etc/init.d/tvheadend start (code=exited, status=0/SUCCESS)

Jan 14 20:56:30 TVHeadend tvheadend8423: scanfile: DVB-C - loaded 18 regions with 58 networks
Jan 14 20:56:30 TVHeadend tvheadend8423: scanfile: ATSC-T - loaded 2 regions with 11 networks
Jan 14 20:56:30 TVHeadend tvheadend8423: scanfile: ATSC-C - loaded 1 regions with 5 networks
Jan 14 20:56:30 TVHeadend tvheadend8423: scanfile: ISDB-T - loaded 2 regions with 1297 networks
Jan 14 20:56:30 TVHeadend tvheadend8423: CRASH: /project/repo/checkout/src/trap.c:148 0x55e7698096da 0x55e769608000
Jan 14 20:56:30 TVHeadend tvheadend8423: CRASH: ??:0 0x7fadd8c8d0c0 0x7fadd8c7c000
Jan 14 20:56:30 TVHeadend tvheadend8423: CRASH: gsignal+0xcf (/lib/x86_64-linux-gnu/libc.so.6)
Jan 14 20:56:30 TVHeadend tvheadend8423: CRASH: abort+0x16a (/lib/x86_64-linux-gnu/libc.so.6)
Jan 14 20:56:31 TVHeadend tvheadend8423: CRASH: /project/repo/checkout/src/main.c:1267 0x55e7697c5ed6 0x55e769608000
Jan 14 20:56:31 TVHeadend tvheadend8423: CRASH: __libc_start_main+0xf1 (/lib/x86_64-linux-gnu/libc.so.6)@

So this should be OK and I also do get coredumps in /tmp including debug informations:

2018-01-14 20:56:30.336 [ DEBUG]:epg: arm channel timer 2018-01-14;21:45:00(+0100) for ONE HD
2018-01-14 20:56:30.336 [ DEBUG]:epg: now/next 3149681/3149683 set on ONE HD
2018-01-14 20:56:30.336 [ DEBUG]:epg: inform HTSP of now event change on ONE HD
2018-01-14 20:56:30.336 [ DEBUG]:epg: arm channel timer 2018-01-14;21:45:00(+0100) for ONE HD
2018-01-14 20:56:30.339 [ INFO]:epgdb: loaded v2
2018-01-14 20:56:30.339 [ INFO]:epgdb: config 1
2018-01-14 20:56:30.339 [ INFO]:epgdb: brands 0
2018-01-14 20:56:30.339 [ INFO]:epgdb: seasons 0
2018-01-14 20:56:30.339 [ INFO]:epgdb: episodes 42893
2018-01-14 20:56:30.339 [ INFO]:epgdb: broadcasts 39850
2018-01-14 20:56:30.674 [ NOTICE]:START: HTS Tvheadend version 4.2.5-14~g1665c355c started, running as PID:8423 UID:110 GID:44, C$
2018-01-14 20:56:30.674 [ ALERT]:CRASH: Signal: 6 in PRG: /usr/bin/tvheadend (4.2.5-14~g1665c355c) [c95a251627e0455abd7ae5b43747$
2018-01-14 20:56:30.674 [ ALERT]:CRASH: Fault address 0x6e000020e7 (N/A)
2018-01-14 20:56:30.674 [ ALERT]:CRASH: Loaded libraries: linux-vdso.so.1 /usr/lib/libdvben50221.so /usr/lib/libdvbapi.so /usr/l$
2018-01-14 20:56:30.677 [ INFO]:htsp: Got connection from 192.168.178.43
2018-01-14 20:56:30.677 [ ALERT]:CRASH: Register dump [23]: 000000000000000000007ffe4aba7460000000000000000800000000000002460000$
2018-01-14 20:56:30.677 [ ALERT]:CRASH: STACKTRACE
2018-01-14 20:56:30.677 [ INFO]:htsp: 192.168.178.43: Welcomed client software: Kodi Media Center (HTSPv25)
2018-01-14 20:56:30.682 [ INFO]:htsp: 192.168.178.43 [ Kodi Media Center ]: Identified as user 'glotzer'
2018-01-14 20:56:30.682 [ INFO]:htsp: 192.168.178.43 [ glotzer | Kodi Media Center ]: Privileges updated
2018-01-14 20:56:30.795 [ INFO]:scanfile: DVB-S - loaded 1 regions with 113 networks
2018-01-14 20:56:30.795 [ INFO]:scanfile: DVB-T - loaded 44 regions with 1113 networks
2018-01-14 20:56:30.795 [ INFO]:scanfile: DVB-C - loaded 18 regions with 58 networks
2018-01-14 20:56:30.795 [ INFO]:scanfile: ATSC-T - loaded 2 regions with 11 networks
2018-01-14 20:56:30.795 [ INFO]:scanfile: ATSC-C - loaded 1 regions with 5 networks
2018-01-14 20:56:30.795 [ INFO]:scanfile: ISDB-T - loaded 2 regions with 1297 networks
2018-01-14 20:56:30.826 [ ALERT]:CRASH: /project/repo/checkout/src/trap.c:148 0x55e7698096da 0x55e769608000
2018-01-14 20:56:30.979 [ ALERT]:CRASH: ??:0 0x7fadd8c8d0c0 0x7fadd8c7c000
2018-01-14 20:56:30.979 [ ALERT]:CRASH: gsignal+0xcf (/lib/x86_64-linux-gnu/libc.so.6)
2018-01-14 20:56:30.980 [ ALERT]:CRASH: abort+0x16a (/lib/x86_64-linux-gnu/libc.so.6)
2018-01-14 20:56:31.126 [ ALERT]:CRASH: /project/repo/checkout/src/main.c:1267 0x55e7697c5ed6 0x55e769608000
2018-01-14 20:56:31.126 [ ALERT]:CRASH: __libc_start_main+0xf1 (/lib/x86_64-linux-gnu/libc.so.6)

However what is being logged in /var/log/debug and daemon is really huge, it dumped 170MB each in both files just today and the day's not over.... :-O
So I'll have to switch that off quickly before it fully flooded my HDD and I also have no idea how I should supply the log in case someone's asking for it. There also seems to be a lot of stuff in there that's not relevant for my problem, summing upto around 10 screen pages being logged every second:
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6EF0 (28400) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6EF1 (28401) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6EF2 (28402) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6EF3 (28403) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6EF4 (28404) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6EF5 (28405) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6EF6 (28406) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6EF7 (28407) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6EF8 (28408) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6F03 (28419) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6F04 (28420) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6F05 (28421) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6F06 (28422) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6F07 (28423) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6F08 (28424) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6F0C (28428) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6F0D (28429) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6F0E (28430) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6F0F (28431) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6F10 (28432) running 4 free_ca 0
Jan 14 14:04:07 TVHeadend tvheadend[933]: tbl-base: sdt: sid 6F11 (28433) running 4 free_ca 0

Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: DVB-S 19.2E freq 11538000 V sym 22000000 fec 5/6 mod QPSK roff 35 is_$
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: onid 0001 (1) tsid 03FE (1022) mux 11538V in Astra 19.2e
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: DVB-S2 19.2E freq 11552750 H sym 22000000 fec 2/3 mod PSK/8 roff 35 i$
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: onid 0001 (1) tsid 03FF (1023) mux 11552.75H in Astra 19.2e
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: DVB-S2 19.2E freq 11582250 H sym 22000000 fec 2/3 mod PSK/8 roff 35 i$
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: onid 0001 (1) tsid 0401 (1025) mux 11582.25H in Astra 19.2e
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: DVB-S 19.2E freq 11597000 V sym 22000000 fec 5/6 mod QPSK roff 35 is_$
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: onid 0001 (1) tsid 0402 (1026) mux 11597V in Astra 19.2e
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: DVB-S 19.2E freq 11611750 H sym 22000000 fec 5/6 mod QPSK roff 35 is_$
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: onid 0001 (1) tsid 0403 (1027) mux 11611.75H in Astra 19.2e
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: DVB-S 19.2E freq 11626500 V sym 22000000 fec 5/6 mod QPSK roff 35 is_$
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: onid 0001 (1) tsid 0404 (1028) mux 11626.5V in Astra 19.2e
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: DVB-S2 19.2E freq 11670750 H sym 22000000 fec 2/3 mod PSK/8 roff 35 i$
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: onid 0001 (1) tsid 0407 (1031) mux 11670.75H in Astra 19.2e
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: DVB-S 19.2E freq 11685500 V sym 22000000 fec 5/6 mod QPSK roff 35 is_$
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: onid 0001 (1) tsid 0408 (1032) mux 11685.5V in Astra 19.2e
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: DVB-S2 19.2E freq 10964250 H sym 22000000 fec 2/3 mod PSK/8 roff 35 i$
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: onid 0001 (1) tsid 0409 (1033) mux 10964.25H in Astra 19.2e
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: DVB-S 19.2E freq 10979000 V sym 22000000 fec 5/6 mod QPSK roff 35 is_$
Jan 14 14:04:16 TVHeadend tvheadend[933]: tbl-base: nit: onid 0001 (1) tsid 040A (1034) mux 10979V in Astra 19.2e

I also find many entries like these that seem to point to some problem:

Jan 14 20:42:00 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:00 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:04 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:04 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:07 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:08 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:09 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:10 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:11 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:14 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:14 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:17 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:18 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:19 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:20 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:21 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:24 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:25 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 20:42:27 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new

It just started somewhen without any obvious reason:

Jan 14 14:25:26 TVHeadend kernel: [ 4909.496005] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:26 TVHeadend kernel: [ 4909.499026] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:26 TVHeadend kernel: [ 4909.502035] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:26 TVHeadend kernel: [ 4909.505105] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:26 TVHeadend kernel: [ 4909.508097] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:26 TVHeadend kernel: [ 4909.510610] [drm:radeon_vga_detect [radeon]] *ERROR* VGA-1: probed a monitor but no|invalid $
Jan 14 14:25:37 TVHeadend kernel: [ 4919.736379] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:37 TVHeadend kernel: [ 4919.739410] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:37 TVHeadend kernel: [ 4919.742429] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:37 TVHeadend kernel: [ 4919.745518] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:37 TVHeadend kernel: [ 4919.748508] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:37 TVHeadend kernel: [ 4919.751024] [drm:radeon_vga_detect [radeon]] *ERROR* VGA-1: probed a monitor but no|invalid $
Jan 14 14:25:39 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 14:25:42 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 14:25:47 TVHeadend kernel: [ 4929.976761] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:47 TVHeadend kernel: [ 4929.979786] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:47 TVHeadend kernel: [ 4929.982799] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:47 TVHeadend kernel: [ 4929.985875] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:47 TVHeadend kernel: [ 4929.988868] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:47 TVHeadend kernel: [ 4929.991391] [drm:radeon_vga_detect [radeon]] *ERROR* VGA-1: probed a monitor but no|invalid $
Jan 14 14:25:49 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 14:25:52 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 14:25:57 TVHeadend kernel: [ 4940.217171] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:57 TVHeadend kernel: [ 4940.220199] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:57 TVHeadend kernel: [ 4940.223218] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:57 TVHeadend kernel: [ 4940.226301] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:57 TVHeadend kernel: [ 4940.229295] i2c i2c-0: sendbytes: NAK bailout.
Jan 14 14:25:57 TVHeadend kernel: [ 4940.231818] [drm:radeon_vga_detect [radeon]] *ERROR* VGA-1: probed a monitor but no|invalid $
Jan 14 14:26:00 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 14:26:01 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 14:26:02 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new
Jan 14 14:26:07 TVHeadend tvheadend[933]: mpegts: too much queued table input data (over 2MB), discarding new

So let's see what it will dump when the machine freezes next time. Admittedly I'm pessimistic about seing anything useful. If the machine simply freezes it will have little opportunity to log anything...

Cheerz

#15 Updated by Peter Brockamp 4 days ago

Well, it already froze just a couple of minutes ago. Though debug is active daemon.log is no more enligthening. Crash here at around 22::10::30+, reset pressed at 22:15::30:

Jan 14 22:10:00 TVHeadend tvheadend[9442]: epg: expire event 3371651 (Dirty Dancing) from RTL Television
Jan 14 22:10:00 TVHeadend tvheadend[9442]: epg: now/next 3371913/3371915 set on RTL Television
Jan 14 22:10:00 TVHeadend tvheadend[9442]: epg: inform HTSP of now event change on RTL Television
Jan 14 22:10:00 TVHeadend tvheadend[9442]: epg: arm channel timer
2018-01-14;22:55:00(+0100) for RTL Television
Jan 14 22:10:27 TVHeadend tvheadend9442: epg: expire event 3372075 (ran Football: Jacksonville Jaguars at Pittsburgh Steelers ($
Jan 14 22:10:27 TVHeadend tvheadend9442: epg: now/next 3372141/3372143 set on Pro7 MAXX
Jan 14 22:10:27 TVHeadend tvheadend9442: epg: inform HTSP of now event change on Pro7 MAXX
Jan 14 22:10:27 TVHeadend tvheadend9442: epg: arm channel timer 2018-01-14;22:19:54(+0100) for Pro7 MAXX
Jan 14 22:10:32 TVHeadend tvheadend[9442]: epg: expire event 3370423 (Mord im Paradies) from SAT.1 Gold
Jan 14 22:10:32 TVHeadend tvheadend[9442]: epg: now/next 3370487/3370489 set on SAT.1 Gold
Jan 14 22:10:32 TVHeadend tvheadend[9442]: epg: inform HTSP of now event change on SAT.1 Gold
Jan 14 22:10:32 TVHeadend tvheadend[9442]: epg: arm channel timer
2018-01-14;23:09:51(+0100) for SAT.1 Gold
Jan 14 22:15:30 TVHeadend systemd1: Starting Flush Journal to Persistent Storage...
Jan 14 22:15:30 TVHeadend systemd1: Started Flush Journal to Persistent Storage.
Jan 14 22:15:30 TVHeadend systemd1: Started Set the console keyboard layout.
Jan 14 22:15:30 TVHeadend systemd1: Reached target Local File Systems (Pre).
Jan 14 22:15:30 TVHeadend systemd1: Found device RTL8111/8168/8411 PCI Express Gigabit Ethernet Controller (P8P67 and other mot$
Jan 14 22:15:30 TVHeadend systemd1: Reached target Sound Card.
Jan 14 22:15:30 TVHeadend systemd1: Found device SanDisk_SDSSDA120G 5.
Jan 14 22:15:30 TVHeadend systemd1: Activating swap /dev/disk/by-uuid/cfc97f77-4f0f-44d1-8bfd-1ed8d0e928a2...
Jan 14 22:15:30 TVHeadend systemd1: Activated swap /dev/disk/by-uuid/cfc97f77-4f0f-44d1-8bfd-1ed8d0e928a2.
Jan 14 22:15:30 TVHeadend systemd1: Reached target Swap.
Jan 14 22:15:30 TVHeadend systemd1: Found device ST2000DM001-1ER164 Video.
Jan 14 22:15:30 TVHeadend systemd1: Starting File System Check on /dev/disk/by-uuid/d169a2e4-9f66-4d40-8c13-dadd5ca642d7...
Jan 14 22:15:30 TVHeadend systemd1: Started File System Check Daemon to report status.
Jan 14 22:15:30 TVHeadend systemd-fsck348: Video: Journal wird wiederhergestellt
Jan 14 22:15:30 TVHeadend systemd-fsck348: Video: sauber, 6927/122101760 Dateien, 279789397/488378390 Blöcke
Jan 14 22:15:30 TVHeadend systemd1: Started File System Check on /dev/disk/by-uuid/d169a2e4-9f66-4d40-8c13-dadd5ca642d7.
Jan 14 22:15:30 TVHeadend systemd1: Mounting /media/tvheadend...
Jan 14 22:15:30 TVHeadend systemd1: Mounted /media/tvheadend.
Jan 14 22:15:30 TVHeadend systemd1: Reached target Local File Systems.
Jan 14 22:15:30 TVHeadend systemd1: Starting Create Volatile Files and Directories...
@

WTF???

In /var/crash I see coredumps, so this is operational on priciple. However these coredumps are only the ones I provocated with -A:
from /'usr/bin/tvheadend -f -u hts -g video -A -D -l /tmp/tvheadend -s'
in all files...

No cordumps for the machines freezes - Just as I already was suspecting...

#16 Updated by Mark Clarkstone 4 days ago

Peter Brockamp wrote:

... snip ...

Hmm, not sure what else to suggest here. You could try disabling all OTA EPG grabbers or perhaps give unstable a run (back up your config before upgrading).

#17 Updated by Peter Brockamp 4 days ago

Mark Clarkstone wrote:

Hmm, not sure what else to suggest here. You could try disabling all OTA EPG grabbers or perhaps give unstable a run (back up your config before upgrading).

Well, the next thing I will try to do is to attempt annalyzing the debug enriched logs for several freezes. Maybe I could espy some similarities in the prelude of the freezes. I simply inserted a mv command on the logfile in /etc/init.d/tvheadend/do_start(). E. g. if I can picture that each freeze is preluded bei some specific EPG grabber action this may be a hint in what direction to search.

Nevertheless I'm again suspicous I have a hardware problem here. I'm on SATIP, so there's no tuner plugged in my mobo and of course no hardware driver that could trigger a fatal failure. Just a TCP or UDP channel on the NIC and I expect this to be rock solid, Linux doesn't freeze out of the blue...

Also available in: Atom PDF