Crash in Recorded.getProgram() for recordings without bookmark after upgrade to 0.28

[Fred Fettinger <fettinge@…>]

My backend is running on a banana pi, I'm using the compiled myth packages from deb-multimedia.org: deb ​http://www.deb-multimedia.org jessie main non-free deb ​http://www.deb-multimedia.org jessie-backports main

mythtv-backend and related packages all have the version 0.28-dmo6~bpo8+2

I encountered this crash after upgrading from 0.27 to 0.28 in a script I use which exports shows as a video and then deletes the original program, since Recorded.delete() calls Recorded.getProgram(). But, you can essentially simplify this down to the following, which will fail for any recording where a bookmark has not been set.

db = MythDB()
rec = Recorded((chanid, starttime), db=db)
rec.getProgram()

I get the following error message:

  File "/etc/mythtv/mythvidexport.py", line 71, in __init__
    self.rec.getProgram()
  File "/usr/lib/python2.7/dist-packages/MythTV/dataheap.py", line 377, in getProgram
    return Program.fromRecorded(self)
  File "/usr/lib/python2.7/dist-packages/MythTV/mythproto.py", line 946, in fromRecorded
    return be.getRecording(rec.chanid, rec.starttime)
  File "/usr/lib/python2.7/dist-packages/MythTV/mythproto.py", line 647, in getRecording
    return Program(res[1:], db=self.db)
  File "/usr/lib/python2.7/dist-packages/MythTV/mythproto.py", line 875, in __init__
    DictData.__init__(self, raw)
  File "/usr/lib/python2.7/dist-packages/MythTV/altdict.py", line 147, in __init__
    data = self._process(data)
  File "/usr/lib/python2.7/dist-packages/MythTV/altdict.py", line 164, in _process
    data[i] = self._trans[self._field_type[i]](v)
  File "/usr/lib/python2.7/dist-packages/MythTV/altdict.py", line 103, in <lambda>
    lambda x: datetime.fromtimestamp(x, datetime.UTCTZ())\
  File "/usr/lib/python2.7/dist-packages/MythTV/utility/dt.py", line 304, in fromtimestamp
    obj = super(datetime, cls).fromtimestamp(float(timestamp), tz)
ValueError: timestamp out of range for platform time_t

As of MYTH_PROTO_VERSION 88, bookmarkupdate is the last item in the response to QUERY_RECORDING TIMESLOT. For some reason, this is always '4294967295' (0xffffffff) for any recordings without bookmarks on my setup, despite the fact that the bookmarkupdate column is 0 for these programs in the database.

Is there any logging that I can enable in mythbackend to find the cause? I did a quick check of the libmyth source code but I didn't see anything suspicious.

[Richard Fearn <richardfearn@…>]

I am also affected by this, since doing a double Ubuntu upgrade to 16.04 a couple of weeks ago.

In my case, I'm using my ​mythcal script, and getting the list of upcoming recordings fails with the "timestamp out of range" error.

I will try and figure out what the problem might be as and when I have time.

[Richard Fearn <richardfearn@…>]

I looked into this tonight. The backend is returning data to the Python bindings that looks like this:

0[]:[]1[]:[]Wallander[]:[]A Lesson in Love[]:[]Detective drama. The body of a woman is discovered in the forest. When it transpires that the victim's daughter is missing, Wallander must act quickly.[]:[]0[]:[]0[]:[]0[]:[][]:[]Drama[]:[]1001[]:[]1[]:[]BBC ONE Oxford[]:[]BBC ONE Oxford[]:[][]:[]0[]:[]1464552000[]:[]1464557400[]:[]0[]:[]mythtv[]:[]1[]:[]1[]:[]1[]:[]0[]:[]-1[]:[]1257[]:[]1[]:[]15[]:[]8[]:[]1464552000[]:[]1464557400[]:[]0[]:[]Default[]:[][]:[]fp.bbc.co.uk/nuj0fe[]:[]fp.bbc.co.uk/1ftwy6[]:[][]:[]1464546156[]:[]0[]:[][]:[]Default[]:[]0[]:[]0[]:[]Default[]:[]33[]:[]66[]:[]0[]:[]0[]:[]0[]:[]0[]:[]2[]:[]0[]:[]~[]:[]4294967295

The last value 4294967295 is the bookmarkupdate field. This value makes its way through the Python bindings to the _process function in altdict.py, so I've temporarily patched {{altdict.py}} to handle this value:

--- altdict.py.ORIGINAL	2016-04-13 04:15:30.000000000 +0100
+++ altdict.py	2016-05-29 19:32:01.198800782 +0100
@@ -160,7 +160,10 @@
                 if v == '':
                     data[i] = None
                 else:
-                    data[i] = self._trans[self._field_type[i]](v)
+                    if (self._field_order[i] == "bookmarkupdate") and (v == "4294967295"):
+                        data[i] = None
+                    else:
+                        data[i] = self._trans[self._field_type[i]](v)
         return dict(zip(self._field_order,data))
 
     def _deprocess(self):

[Fred Fettinger <fettinge@…>]

That's pretty much what I ended up doing as a workaround also. Since I wasn't sure whether this bug was specific to bookmarkupdate or not, I patched the general timestamp handler as shown below.

mythtv/bindings/python/MythTV/altdict.py
@@ -83,41 +83,41 @@ class OrdDict( dict ):
     _trans = [  int,
                 locale.atof,
                 bool,
                 lambda x: x,
-                lambda x: datetime.fromtimestamp(x, datetime.UTCTZ())\
+                lambda x: datetime.fromtimestamp(x if x != '4294967295' else '0', datetime.UTCTZ())\
                                   .astimezone(datetime.localTZ()),
                 lambda x: date(*[int(y) for y in x.split('-')]),
                 lambda x: datetime.fromRfc(x, datetime.UTCTZ())\

[Roger Siddons]

Is this still an issue with 0.28/fixes ?

Sounds like it could be a duplicate of #12947, (tested with MySql 5.7.18)

[Richard Fearn <richardfearn@…>]

This still seems to be a problem with MythTV 29. I upgraded yesterday to Ubuntu 17.04. altdict.py, which I had manually patched, was reset to the version shipped in the libmyth-python package, and this problem came back.

#12947 is different because that seems to be about storing a row in the database, where 0 is an invalid value for bookmarkupdate:

MythTV.exceptions.MythDBError: MySQL error 1292: Incorrect datetime value: '0' for column 'bookmarkupdate' at row 1

In this case though, data is being read from the database, and the backend seems to be returning the value 4294967295 when the bookmarkupdate value is 0000-00-00 00:00:00.

I guess this is due to something trying to store -1 in an unsigned 32-bit integer.

While diagnosing this I put these two lines in DictData.__init__ in altdict.py:

print self._field_order
print self._field_type
print data

which shows that the last item of data is bookmarkupdate, the type is 4, and the value is u'4294967295'.

In the database, the bookmarkupdate column in the recorded table has this definition:

+-----------------+------------------+------+-----+---------------------+-----------------------------+
| Field           | Type             | Null | Key | Default             | Extra                       |
+-----------------+------------------+------+-----+---------------------+-----------------------------+
| bookmarkupdate  | timestamp        | NO   |     | 0000-00-00 00:00:00 |                             |
+-----------------+------------------+------+-----+---------------------+-----------------------------+

so the value can't be NULL. Most of the rows in there have that default value, 0000-00-00 00:00:00.

I'm not sure how the backend reads data from the database and returns it to the Python bindings, but it looks like somehow 0000-00-00 00:00:00 is being converted to -1, then held as an unsigned integer, and becomes 4294967295 by the time it gets to the Python bindings.

[dizygotheca]

Some discussion at ​https://lists.gt.net/mythtv/users/620715

Reassigning to a Python guru; I've forgotten the little I knew.

[Fred Fettinger <fettinge@…>]

In 5c3257e1d/mythtv:

Python bindings: on 32 bit systems, handle 0000-00-00 00:00:00 timestamps

(they're becoming: 4294967295 (0xffffffff))

Fixes #12772

Signed-off-by: Bill Meek <billmeek@…>