Tvheadend

Do you also have enabled Config->Channel/EPG->EPGGrabber->"save epg to disk after xmltv import"? Or do you just have the "periodically save: 2 hours"?

What happens if you set it to 3 hours instead of 2? At what time does your xmltv import finish compared to the crash?

I initially had "save epg to disk after xmltv import" activated. Not a good idea with the issue - that lead to restart loops:

- TVH starts
- EPGDB was read
- TVH runs XMLTV grab at schedule
- EPGDB save was triggered immediately and crashes
- TVH was restarted
- XMLTV grabber ran due to the restart
- EPGDB was triggered immediately and crashes
- and so on

Having it set to 2 hours periodically does the following:

- TVH is running and had read the EPGDB
- EPGDB snapshots running fine a couple of times until ...
- XMLTV grabber runs due to scheduling
- All next EPGDB snapshot runs do crash TVH. Under the bottomline I have (watchdog caused) restarts every 2 hours now
- After manually restarting TVH (via SSH) it runs fine until the XMLTV grabber runs the first time. Then proceeding with crashes every 2 hours (when epgdb snapshot is scheduled)

The time between XMLTV grabber run and epgdb snapshot does not care. It can be any time up to two hours - once the XMLTV grab ran once, any following epgdb autosave crashes.

I'll get the log with the debug version tomorrow morning after the first XMLTV run and post it here. Unfortunately epgdata.com limits the downloads with the same access PIN to 3-4 per day ... so there are not many attempts to try around per day. That's a mess ...

Thanks for the detailed info.

Couple of extra questions, what type of system do you run it on? Plenty of free memory?

That's interesting about the scrape option. It seems to suggest the xmltv has something that we're not expecting and handling incorrectly, and then passing to Kodi and causing it to fail too.

If that is the problem, are you able to run the grabber yourself outside of the Tvheadend and capture the output and verify it is valid?

tv_grab_eu_epgdata --days=14 > myfile.xml
xmllint myfile.xml

I don't know if there's documentation about the letters, but from the code they are:
"ecoOsStumdpgrviBEC"

And the letter chosen is based on this, sorry, it's a little unreadable, but the name on the left is what has changed, and the right-most number is the offset in to the string (minus one). So "DVR_UPDATE_STOP" would be offset "2", so count three characters in to the string and you get the letter "o".

DVR_UPDATED_ENABLED      (1<<0)
DVR_UPDATED_CHANNEL      (1<<1)
DVR_UPDATED_STOP         (1<<2)
DVR_UPDATED_STOP_EXTRA   (1<<3)
DVR_UPDATED_START        (1<<4)
DVR_UPDATED_START_EXTRA  (1<<5)
DVR_UPDATED_TITLE        (1<<6)
DVR_UPDATED_SUBTITLE     (1<<7)
DVR_UPDATED_SUMMARY      (1<<8)
DVR_UPDATED_DESCRIPTION  (1<<9)
DVR_UPDATED_PRIO         (1<<10)
DVR_UPDATED_GENRE        (1<<11)
DVR_UPDATED_RETENTION    (1<<12)
DVR_UPDATED_REMOVAL      (1<<13)
DVR_UPDATED_EID          (1<<14)
DVR_UPDATED_BROADCAST    (1<<15)
DVR_UPDATED_EPISODE      (1<<16)
DVR_UPDATED_CONFIG       (1<<17)
DVR_UPDATED_PLAYPOS      (1<<18)
DVR_UPDATED_PLAYCOUNT    (1<<19)

I agree, must be something odd in the file.

I can't see anything obviously wrong in the file. It validates ok, but that just means it doesn't have anything really wrong in it.

Looking through the file, categories and actors/presenters look fine.

If you get a crash log, it might show the problem. Otherwise, there were updates in mid-October to that area of code.

My build is up-to-date ... a few days old. So it should include the Mid-October-changes ;-)

I have enabled the scrape again temporarily. Let's see if it crashes tomorrow morning again after the XMLTV update. At least I'll get a crash log in that case which I can post here.

In the meantime, I'll submit a few extra "icon" mappings for the Tvheadend UI for your categories (since some of your categories are English and some in German).

We don't have great icons for everything (so some are general purpose), but hopefully the left word (from your xml file) corresponds to the right word (which will be the name of an icon we already have inside Tvheadend).

I'll submit it tomorrow unless you spot something obviously wrong with my translation:

  "boxen" : "boxing_glove",
  "erotik" : "no_one_under_eighteen_symbol",
  "familie" : "family",
  "familien-show" : "family",
  "fußball" : "soccer_ball",
  "gymnastik" : "person_doing_cartwheel",
  "homeshopping" : "shopping_trolley",
  "humor" : "face_with_tears_of_joy",
  "jugend" : "baby",
  "klassik" : "musical_note",
  "krankenhaus" : "ambulance",
  "krimi" : "police_officer",
  "motor + verkehr" : "racing_car",
  "motorsport" : "racing_car",
  "musik" : "musical_note",
  "mystery + horror" : "skull",
  "nachrichten" : "newspaper",
  "natur" : "elephant",
  "politik" : "ballot_box_with_ballot",
  "reise" : "airplane",
  "science fiction" : "extraterrestrial_alien",
  "spielshows" : "game_die",
  "talkshows" : "speaking_head_in_silhouette",
  "volksmusic" : "musical_note",
  "wassersport" : "swimmer",
  "zeichentrick" : "pencil" 

Hi Em,

I don't know the symbol repertoire, but your mapping looks good to me! :-)

I need to check when to activate the scraper ... did it an hour ago and it immediately killed my Kodi's :-(

Hi Em,

here we go!

Switched the scraper option back on again at 8:10 this morning. That triggered an XMLTV grabber run. Right after the data was processed my Kodi client in the living room was sent into death by the EPG change messages:

Nov 30 08:10:17 FlairTV tvheadend[28197]: xmltv: /usr/bin/tv_grab_eu_epgdata: grab /usr/bin/tv_grab_eu_epgdata
Nov 30 08:10:17 FlairTV tvheadend[28197]: spawn: Executing "/usr/bin/tv_grab_eu_epgdata" 
Nov 30 08:10:20 FlairTV tvheadend[28197]: spawn: Downloading include zip file
Nov 30 08:10:26 FlairTV tvheadend[28197]: spawn: Downloading zip file for day 1
Nov 30 08:10:28 FlairTV tvheadend[28197]: spawn: Downloading zip file for day 2
Nov 30 08:10:30 FlairTV tvheadend[28197]: spawn: Downloading zip file for day 3
Nov 30 08:10:33 FlairTV tvheadend[28197]: spawn: Downloading zip file for day 4
Nov 30 08:10:35 FlairTV tvheadend[28197]: spawn: Downloading zip file for day 5
Nov 30 08:10:37 FlairTV tvheadend[28197]: spawn: Downloading zip file for day 6
Nov 30 08:10:40 FlairTV tvheadend[28197]: spawn: Downloading zip file for day 7
Nov 30 08:10:44 FlairTV tvheadend[28197]: spawn: Downloading zip file for day 8
Nov 30 08:10:46 FlairTV tvheadend[28197]: spawn: Downloading zip file for day 9
Nov 30 08:10:48 FlairTV tvheadend[28197]: spawn: Downloading zip file for day 10
Nov 30 08:10:51 FlairTV tvheadend[28197]: spawn: Downloading zip file for day 11
Nov 30 08:10:55 FlairTV tvheadend[28197]: spawn: Downloading zip file for day 12
Nov 30 08:10:58 FlairTV tvheadend[28197]: spawn: Downloading zip file for day 13
Nov 30 08:10:58 FlairTV tvheadend[28197]: spawn: No more zip files available for download
Nov 30 08:10:58 FlairTV tvheadend[28197]: spawn: Your PIN will expire around Sun Apr 21 15:11:20 MEST 2019
Nov 30 08:11:02 FlairTV CRON[11005]: (hts) CMD (/home/hts/convert.sh >/dev/null 2>&1)
Nov 30 08:12:01 FlairTV CRON[11038]: (root) CMD (/opt/auto-mount.sh)
Nov 30 08:12:01 FlairTV CRON[11041]: (hts) CMD (/home/hts/convert.sh >/dev/null 2>&1)
Nov 30 08:13:01 FlairTV CRON[11073]: (hts) CMD (/home/hts/convert.sh >/dev/null 2>&1)
Nov 30 08:14:01 FlairTV CRON[11105]: (root) CMD (/opt/auto-mount.sh)
Nov 30 08:14:01 FlairTV CRON[11108]: (hts) CMD (/home/hts/convert.sh >/dev/null 2>&1)
Nov 30 08:15:01 FlairTV CRON[11139]: (hts) CMD (/home/hts/convert.sh >/dev/null 2>&1)
Nov 30 08:16:01 FlairTV CRON[11171]: (root) CMD (/opt/auto-mount.sh)
Nov 30 08:16:01 FlairTV CRON[11174]: (hts) CMD (/home/hts/convert.sh >/dev/null 2>&1)
Nov 30 08:16:49 FlairTV tvheadend[28197]: xmltv: /usr/bin/tv_grab_eu_epgdata: grab took 392 seconds
Nov 30 08:16:50 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ kodiwz | Kodi Media Center ]: Write error -- Broken pipe
Nov 30 08:16:50 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ kodiwz | Kodi Media Center ]: Disconnected
Nov 30 08:16:50 FlairTV tvheadend[28197]: htsp: Got connection from 10.0.6.15
Nov 30 08:16:50 FlairTV tvheadend[28197]: htsp: 10.0.6.15: Welcomed client software: Kodi Media Center (HTSPv29)
Nov 30 08:16:50 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ Kodi Media Center ]: Identified as user 'kodiwz'
Nov 30 08:16:50 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ kodiwz | Kodi Media Center ]: Privileges updated
Nov 30 08:16:50 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ kodiwz | Kodi Media Center ]: Write error -- Connection reset by peer
Nov 30 08:16:50 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ kodiwz | Kodi Media Center ]: Disconnected
Nov 30 08:16:50 FlairTV tvheadend[28197]: htsp: Got connection from 10.0.6.15
Nov 30 08:16:50 FlairTV tvheadend[28197]: htsp: 10.0.6.15: Welcomed client software: Kodi Media Center (HTSPv29)
Nov 30 08:16:50 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ Kodi Media Center ]: Identified as user 'kodiwz'
Nov 30 08:16:50 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ kodiwz | Kodi Media Center ]: Privileges updated
Nov 30 08:16:50 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ kodiwz | Kodi Media Center ]: Write error -- Connection reset by peer
Nov 30 08:16:50 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ kodiwz | Kodi Media Center ]: Disconnected
Nov 30 08:16:51 FlairTV tvheadend[28197]: htsp: Got connection from 10.0.6.15
Nov 30 08:16:51 FlairTV tvheadend[28197]: htsp: 10.0.6.15: Welcomed client software: Kodi Media Center (HTSPv29)
Nov 30 08:16:51 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ Kodi Media Center ]: Identified as user 'kodiwz'
Nov 30 08:16:51 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ kodiwz | Kodi Media Center ]: Privileges updated
Nov 30 08:16:51 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ kodiwz | Kodi Media Center ]: Write error -- Connection reset by peer
Nov 30 08:16:51 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ kodiwz | Kodi Media Center ]: Disconnected
Nov 30 08:16:51 FlairTV tvheadend[28197]: htsp: Got connection from 10.0.6.15
Nov 30 08:16:51 FlairTV tvheadend[28197]: htsp: 10.0.6.15: Welcomed client software: Kodi Media Center (HTSPv29)
Nov 30 08:16:51 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ Kodi Media Center ]: Identified as user 'kodiwz'
Nov 30 08:16:51 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ kodiwz | Kodi Media Center ]: Privileges updated
Nov 30 08:16:51 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ kodiwz | Kodi Media Center ]: Write error -- Broken pipe
Nov 30 08:16:51 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ kodiwz | Kodi Media Center ]: Disconnected
Nov 30 08:16:51 FlairTV tvheadend[28197]: htsp: Got connection from 10.0.6.15
Nov 30 08:16:51 FlairTV tvheadend[28197]: htsp: 10.0.6.15: Welcomed client software: Kodi Media Center (HTSPv29)
Nov 30 08:16:51 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ Kodi Media Center ]: Identified as user 'kodiwz'
Nov 30 08:16:51 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ kodiwz | Kodi Media Center ]: Privileges updated
Nov 30 08:16:52 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ kodiwz | Kodi Media Center ]: Write error -- Connection reset by peer
Nov 30 08:16:52 FlairTV tvheadend[28197]: htsp: 10.0.6.15 [ kodiwz | Kodi Media Center ]: Disconnected
... and so on (Kodi messages repeated around 20-30 times until Kodi finally dies) ...

The next epgdb snapshot run was started at 8:48 ... here is the TVH crash with the debug version:

Nov 30 08:48:19 FlairTV tvheadend[28197]: epgdb: snapshot start
Nov 30 08:48:19 FlairTV tvheadend[28197]: CRASH: Signal: 6 in PRG: /usr/bin/tvheadend (4.3-1567~g750c1e1) [32ea1c66e93a0222687c4941c49cb06747a7e5fa] CWD: /
Nov 30 08:48:19 FlairTV tvheadend[28197]: CRASH: Fault address 0x7000006e25 (N/A)
Nov 30 08:48:19 FlairTV tvheadend[28197]: CRASH: Loaded libraries: /usr/lib/x86_64-linux-gnu/libdvbcsa.so.1 /lib/x86_64-linux-gnu/libssl.so.1.0.0 /lib/x86_64-linux-gnu/libcrypto.so.1.0.0 /lib/x86_64-linux-gnu/libz.so.1 /usr/lib/x86_64-linux-gnu/libpcre2-8.so.0 /usr/lib/x86_64-linux-gnu/liburiparser.so.1 /usr/lib/x86_64-linux-gnu/libavahi-common.so.3 /usr/lib/x86_64-linux-gnu/libavahi-client.so.3 /lib/x86_64-linux-gnu/libdbus-1.so.3 /lib/x86_64-linux-gnu/libdl.so.2 /lib/x86_64-linux-gnu/libpthread.so.0 /lib/x86_64-linux-gnu/libm.so.6 /lib/x86_64-linux-gnu/librt.so.1 /usr/lib/x86_64-linux-gnu/libstdc++.so.6 /lib/x86_64-linux-gnu/libc.so.6 /lib/x86_64-linux-gnu/libsystemd.so.0 /lib64/ld-linux-x86-64.so.2 /lib/x86_64-linux-gnu/libgcc_s.so.1 /lib/x86_64-linux-gnu/libselinux.so.1 /lib/x86_64-linux-gnu/liblzma.so.5 /lib/x86_64-linux-gnu/libgcrypt.so.20 /lib/x86_64-linux-gnu/libpcre.so.3 /lib/x86_64-linux-gnu/libgpg-error.so.0 /lib/x86_64-linux-gnu/libnss_compat.so.2 /lib/x86_64-linux-gnu/libnsl.so.1 /lib/x86_64-linux-gnu/libnss_nis.so.2 /lib/x86_64-linux-g
Nov 30 08:48:19 FlairTV tvheadend[28197]: CRASH: Register dump [23]: 000055798ae9fd20ff092d63646b680000000000000000080000000000000202000000000000015b0000557987d00f90000000000000010000000000000008960000000000006e250000000000006e250000557987d00fba00007fe92a1ac0000000000000000006000000000000000000007fe92797042800007ffc62a1dfc800007fe9279704280000000000000202000000000000003300000000000000000000000000000000fffffffe7ffbba150000000000000000
Nov 30 08:48:19 FlairTV tvheadend[28197]: CRASH: STACKTRACE
Nov 30 08:48:20 FlairTV tvheadend[28197]: CRASH: /project/repo/checkout/src/trap.c:176 0x557986df5b6d 0x557986be6000
Nov 30 08:48:20 FlairTV tvheadend[28197]: CRASH: ??:0 0x7fe9285a9390 0x7fe928598000
Nov 30 08:48:20 FlairTV tvheadend[28197]: CRASH: gsignal+0x38  (/lib/x86_64-linux-gnu/libc.so.6)
Nov 30 08:48:20 FlairTV tvheadend[28197]: CRASH: abort+0x16a  (/lib/x86_64-linux-gnu/libc.so.6)
Nov 30 08:48:20 FlairTV tvheadend[28197]: CRASH: ??:0 0x7fe927968bd7 0x7fe92793b000
Nov 30 08:48:21 FlairTV tvheadend[28197]: CRASH: ??:0 0x7fe927968c82 0x7fe92793b000
Nov 30 08:48:21 FlairTV tvheadend[28197]: CRASH: /project/repo/checkout/src/htsmsg_binary2.c:347 0x557986defb5a 0x557986be6000
Nov 30 08:48:21 FlairTV tvheadend[28197]: CRASH: /project/repo/checkout/src/htsmsg_binary2.c:362 0x557986def9dc 0x557986be6000
Nov 30 08:48:21 FlairTV tvheadend[28197]: CRASH: /project/repo/checkout/src/htsmsg_binary2.c:438 0x557986defd9a 0x557986be6000
Nov 30 08:48:22 FlairTV tvheadend[28197]: CRASH: /project/repo/checkout/src/epgdb.c:274 0x557986dd02fa 0x557986be6000
Nov 30 08:48:22 FlairTV tvheadend[28197]: CRASH: /project/repo/checkout/src/epgdb.c:366 0x557986dd0f5b 0x557986be6000
Nov 30 08:48:22 FlairTV tvheadend[28197]: CRASH: /project/repo/checkout/src/main.c:711 0x557986da97ac 0x557986be6000
Nov 30 08:48:22 FlairTV tvheadend[28197]: CRASH: __libc_start_main+0xf0  (/lib/x86_64-linux-gnu/libc.so.6)
Nov 30 08:48:23 FlairTV tvheadend[28197]: CRASH: ??:0 0x557986dab3b9 0x557986be6000
Nov 30 08:49:01 FlairTV CRON[12458]: (hts) CMD (/home/hts/convert.sh >/dev/null 2>&1)
Nov 30 08:49:32 FlairTV systemd[1]: Created slice User Slice of root.
Nov 30 08:49:32 FlairTV systemd[1]: Starting User Manager for UID 0...
Nov 30 08:49:32 FlairTV systemd[1]: Started Session 12019 of user root.
Nov 30 08:49:32 FlairTV systemd[12477]: Reached target Timers.
Nov 30 08:49:32 FlairTV systemd[12477]: Reached target Sockets.
Nov 30 08:49:32 FlairTV systemd[12477]: Reached target Paths.
Nov 30 08:49:32 FlairTV systemd[12477]: Reached target Basic System.
Nov 30 08:49:32 FlairTV systemd[12477]: Reached target Default.
Nov 30 08:49:32 FlairTV systemd[12477]: Startup finished in 23ms.
Nov 30 08:49:32 FlairTV systemd[1]: Started User Manager for UID 0.

I hope this helps!

Perfect.

You're hitting an "assert" that says a field cannot be > 255 characters long. (I didn't know).

One of your programmes has a guest of:

Abgestimmt|BonnVoice|Chorgemeinschaft Voßwinkel-Höingen|ChoRleriker|Die Erben|DIN A5|ESG-Chor Bonn|FLOW|Friday on my mind|Gospelgruppe VAYROCANA|HERRENmitDAMEN|Kammerchor des Bischöflichen Gymnasiums St. Ursula|musical kids Rheinhausen|Schoenefeldt Chor

That's a couple of characters too long. So, I'm guessing that is causing the problems.

That programme ("The best choir") starts tonight, so hopefully tomorrow everything will start working again for you!

Obviously the bug needs fixing, but if you can confirm that tomorrow's grab all works well, then we'll have to have a "substring" check when parsing the xmltv data to handle grabbers that (incorrectly) put everything on one line.

That theory sounds very reasonable. In any case parsed data should be sanity checked before it can cause a write over array boundaries, regardless whether the source is violating specs or not ;-)

I've seen that this show is repeated on December, 2nd ... so we need to wait until Tuesday before we definitely know. But I'm pretty sure that's the root cause.

It also seems that it corrupts the stored EPG data in a way which also Kodi definitely do not like, causing the crashes there as well. Thank you very much for your help and analysis, Em!

Hi Em,

after the suspicious entry was not anymore in the EPG I've activated the scraper again and have rechecked everything. I can confirm that neither the Kodi's are crashing not the epgdb snapshot process crashes. That confirms that the excess of the 255 bytes length was the root cause of the issue.

Looking forward to the fix :-)

I imagine it's related to the error I reported in the discussion forum some time ago:
[[https://tvheadend.org/boards/14/topics/33106]]

Thanks for the update, I'm glad we got to the bottom of the problem being long strings.

It's not quite overwriting array boundaries, but when it sends or writes data, it stores the string length and then the actual string, but for this type of field the length is one byte so can only store up to 255, so the code realizes your string is longer than this and aborts.

It's quite possible the encoding logic for Kodi doesn't do the extra check that epg persist does so might store an incorrect length which then causes Kodi to misinterpret the data.

I should have time at the weekend to test truncating the string which will stop the problem.

@Em : It looks like that the data are assigned to the htsmsg name (key) instead the value in _xmltv_parse_credits():

htsmsg_add_str(*out_credits, str, htsmsg_field_name(f));

Isn't that wrong?

Just to clarify: The 'key' name is limited to 255 characters in htsmsg_binary2 format (I though that 255 characters are really fine).

Yes, unfortunately it's the "right" way around (#4441). My thinking at the time was that in the future it could go from mapping "Tom Cruise"->"actor" in to "Tom Cruise"->{"actor", "1962-07-03", "mugshot.jpg"}, or whatever info we found useful.

In retrospect I should've done it the other way around ("actor" > "Tom Cruise") and perhaps tried to have "actor>["Tom Cruise", "Cameron Diaz"]", "director->[c,d,e,f]".

Unfortunately, we push that format over htsp. If we swapped the field/key now then we'd be relatively ok (unlikely to be many actors called 'actor'), but it would break clients such as kodi and (at least) the iOS client which could no longer parse the fields.

If we truncate the fieldname then it's an easier work-around. In which case ideally we'd split the string at "|" symbols in to separate actors.

Em Smith wrote:

If we truncate the fieldname then it's an easier work-around. In which case ideally we'd split the string at "|" symbols in to separate actors.

The correct split is fine for me, too. I believe that the names with 255+ characters are not usual. I added the 255 check to htsmsg.c to catch this problem early. v4.3-1621-g42fd13d4c

It should be fixed in v4.3-1622-g5bea43b1a (added the split and trim) for the credit names.

Awesome! Thank you all for your efforts :-)

Updated to 1624 5 minutes ago