MySQL Error when submitting a non-valid timestamp

[SchapplM]

As reported in Forum post No. 202, incorrect timestamps in queries lead to errors in the default settings of newer mySQL installations.

Solution: Add a check for validity of the timestamp before submitting the query.

[Urlryn]

Reinstalled Kodi (libreelec) this week with watchedlist and when you mark something watched 90% of the time it marks it fine. The other 10% is a error saying it can't connect to SQL (mariadb) error. Try and set it as "unwatched" and I get the error with the non-valid time stamp every time. I can go back in and mark it as watched right afterwards with no errors.

My other app doesn't have any issues talking to SQL which queries it a lot more often.

[fabquenneville]

Hi,

I have the same issue where marking something as unwatched gives me an incorrect date error.

[fabquenneville]

I am trying to debug this as I really want to mark some shows unwatched. Here is some information that could help:

Here is the relevant error in the kodi.log 2021-07-28 20:08:05.649 T:1259 INFO : service.watchedlist: Notification. Watchedlist: Error: Writing the WL-database file (1292 (22007): Incorrect datetime value: '1970-01-01 00:00:00' for column WatchedList.episode_watched.lastPlayed at row 5438)

Looking at the code it seems to be how the dates are handled in _wl_update_media().

I am still confused as I can't find the information in question in the databases. Not sure what its referring to

[SchapplM]

Thanks for looking into this. I just tested the code you submitted and it works in principle. However, the code leads to a complete rewrite of the existing Kodi database when running the database update. I get in the log for each movie:

2021-08-01 10:41:49.762 T:12104 DEBUG : Mysql execute: update files set playCount=1,lastPlayed='2013-12-07 19:18:42' where idFile=59 2021-08-01 10:41:49.769 T:12104 INFO : service.watchedlist: write_xbmc_wdata: Kodi database updated for (500) Days of Summer (2009). playcount: {1 -> 1}, lastplayed: {"2013-12-07 18:18:42" -> "2013-12-07 19:18:42"} (movieid=16) 2021-08-01 10:41:49.769 T:12104 INFO : service.watchedlist: Notification. Set as watched (Kodi-DB): (500) Days of Summer (2009) 2021-08-01 10:41:52.835 T:12104 DEBUG : Mysql execute: update files set playCount=1,lastPlayed='2013-06-04 12:30:12' where idFile=928 2021-08-01 10:41:52.840 T:12104 INFO : service.watchedlist: write_xbmc_wdata: Kodi database updated for (T)Raumschiff Surprise - Periode 1 (2004). playcount: {1 -> 1}, lastplayed: {"2013-06-04 10:30:12" -> "2013-06-04 12:30:12"} (movieid=885) 2021-08-01 10:41:52.840 T:12104 INFO : service.watchedlist: Notification. Set as watched (Kodi-DB): (T)Raumschiff Surprise - Periode 1 (2004)

Movies watched in winter (first entry) are moved 1h into the future and movies watched in the summer (second entry) are moved by 2h. I am not sure if your assumption "timestamps coming from the SQL are in utc and need conversion" is correct. I think the SQL timestamp (or rather string) is the local time. Is there a possibility to fix the original bug without having to rewrite the whole database and change all time stamps?

[fabquenneville]

Hello Moritz,

are you sure you are using the right commit / pull requests as I have done two. The first one did the behavior you describe and I thought I had cancelled (the pull request) and the second one should not do that. The right commit should be 0495a41

It is the one I am using and and tested successfully, extensively without issues.

Here is the timeline https://github.com/fabquenneville/xbmc-addon-service-watchedlist/commits/master

Cheers Fabrice

[SchapplM]

Hi Fabrice, I used the commit you referenced. One reason could be that I am in time zone UTC+2 (Germany, DST) and you are (probably) in time zone UTC-5 (Canada, Montréal). So if you run the update with your patch, your local time is behind the stored time stamp and no update is necessary. If I run the update, the addon thinks that I watched the same movie again 2h later (from the WL DB) and has to update the Kodi DB to synchronize the databases again. On the other hand, the addon might shift your WL db into the future. But I guess this is not the case. Otherwise you would have encountered this. Can you test with a timezone positive related to UTC?

More general: This patch seems to work more on the symptoms of the bug and not on the cause. In my opinion, if I look at the phpmyAdmin view of the time stamps in the tables of Kodi (myVideos/files/lastPlayed) and WL (movie_watched/lastplayed), the values should be identical. So I think all values in the database are assumed in local time zone. I don't think Kodi assumes UTC when storing time stamps. If they are integer timestamps in the SQLite database file, I guess they are just assumed to be local time zone and not UTC. I am not really into the code any more. Does this make sense?

[fabquenneville]

Hi again Moritz,

So I made the the code timezone agnostic (no timezone is hard-coded) and using system timezone for the local data . as you can see with the line

int(sqlDateTime.replace(tzinfo=datetime.timezone.utc).astimezone(tz=None).timestamp()) in mixToLocalTimeStamp:

• .replace(tzinfo=datetime.timezone.utc) tells the system that the received datetime object was UTC
• .astimezone(tz=None) realigns the datetime object to you system time
• timestamp() extracts the timestamp.

On the other hand, the addon might shift your WL db into the future.

my WL database has always been in the future but converted back on retrieval

Looking at a backup from before I even looked into this issue shows me an episode as:

• 2021-07-27 22:21:58 in Kodi's video database
• 2021-07-28 02:21:58 in watchedlist's database

And that's before I even started working on it. I assumed it was intentional in order to sync multiple computers on different time zones

Can you test with a timezone positive related to UTC?

That would be complicated as I would have to simulate a lot of data.

• Computer / database server with that timezone
• Saved Kodi database from that timezone
• Watchedlist DB generated by the code before my changes

This patch seems to work more on the symptoms of the bug and not on the cause.

The root cause of the problem is the use of timestamps I believe and FROM_UNIXTIME / UNIX_TIMESTAMP that cant handle NULL:

• FROM_UNIXTIME and UNIX_TIMESTAMP that converted when writing or retrieving what should have been NULL dates to the unix 0 date '1970-01-01 00:00:00'
• FROM_UNIXTIME and UNIX_TIMESTAMP that assume that the timestamp is UTC when the timestamp used by WatchedList is already adjusted to a timezone (It took me awhile to understand this one)
• The lack of a filter when writing and retrieving NULL / 0 / '1970-01-01 00:00:00' datetimes
• The fact that timestamps are supposed to be in UTC and are used by WatchedList as local

Because the same bug is always present to both write and retrieve dates the '1970-01-01 00:00:00' date returned to 0 so that didn't crash anything and also FROM_UNIXTIME and UNIX_TIMESTAMP realigned the timezones on writing and retrieval so it was not an issue.

So this patch fixes the issue at the problem area before data insertion and after retrieval. WatchedList needs to be able to write NULL in watched time columns like KODI does and for Unix time that would be 0 ( '1970-01-01 00:00:00' ) an invalid date in SQL.

One way to remove that problem at the source would be to use Datetime objects everywhere:

• It would allow datetimes before '1970-01-01 00:00:00' even if technically they shouldn't be needed because no one watched something before then
• It makes it easy to manipulate time zones / is timezone aware
• It would remove conversions of unixtime to datetime everywhere as Kodi's database and SQL both use datetime but now the watchedlist code.

But I am not willing / have time to rewrite the addon. The fix (at least for me) completely fixed the issues unless I would travel in time and have a watch time before the 1970's. So if we can just find why the results are different on your setup its not worth rewriting the add-on (at least in my opinion).

I don't think Kodi assumes UTC when storing time stamps.

That's the problem, Unix time is UTC but the code converts the datetime's received by the databases into timestamps stripping the timezone awareness of Kodi and the databases in the process.

The 2 functions I made replicated that exact same conversion with the difference of being able to handle NULL values.

In my setup there's no rewrite of all Kodi entries, once retrieved, Kodi and Watched list see the time as the same even if its not the same in both DB's.

Here is a script I wrote to remove this problem from the Add-on and just focus on that problem, maybe it can help us find why you are getting different results than me.

• Save it in lib/watchedlist as .py
• Enter your database information
• play with the commented sections
• run it in a terminal to print the info you need before and after conversions and maybe it will help. It helped me understand the time difference between the two DB's and the add-on.

A command like this will save it to .txt:

./wldbtests.py > ../../testoutputs/nounixoutput2.txt

Also a note : that the DB is saved in UTC is a good thing (I think) as it would allow computers on different time zones sync in their local time like Kodi saved the data. Anyway that's the only reason that explained why you had converted the dates in the Watchedlist database which I thought was intentional.

Fabrice

[SchapplM]

Unfortunately I have to postpone testing this due to other obligations. Your explanations seem reasonable and valid. However I would like to have this tested further before rolling this out in the official repository. I don't want to create a scenario were the databases of many people are changed without good reason or are even updated permanently on every startup. I am not sure, how this patch might interact with a mix of mySQL and SQLite databases on different devices or with the DropBox synchronization via SQLite database file.

[fabquenneville]

Definitely don't push this if it had the previously mentioned side effect.

As for SQLite I believed i had made an appropriate exception for that but I did not test it.

But that I could test easily, I just have to disconnect my MySQL db, do a watchedlist run on the Watchedlist of before my change and rerun it with my changes.

When you have time to run tests contact me and if I have time we can chat over discord or something to run tests in the two timeszones.

I will test SQLite at some point and give an update.

At least I was able to unwatch my shows!

[HASCHKAKERLAKE]

First time i write a comment on github so please be nice to me.. :)

I experienced the same issue and compared it with a friend of mine. The problem belongs to the timezone which set at the mysql server as it converts given timestamps (in queries) to UTC for internal operation on the filesystem. This issue seems to last really long now so i modified my watchedlist.py manually to overcome this problem as it doesnt look as it is getting fixxed soon.

The (quick and dirty) fix which worked nice on my side: Open watchedlist.py, goto line 1414 which looks like this:

            if int(utils.getSetting("db_format")) != 1:  # sqlite3
                sql = QUERY_EP_UPDATE_SQLITE
            else:  # mysql
                sql = QUERY_EP_UPDATE_MYSQL
            values = list([playcount_xbmc, lastplayed_new, lastchange_new, imdbId, season, episode])

Now modify it like so:

            if int(utils.getSetting("db_format")) != 1:  # sqlite3
                sql = QUERY_EP_UPDATE_SQLITE
            else:  # mysql
                sql = QUERY_EP_UPDATE_MYSQL
                if lastplayed_new == 0: # UPDATE/INSERT FIX FOR TIMEZONE timestamp
                    lastplayed_new = 1
                if lastchange_new == 0: # UPDATE/INSERT FIX FOR TIMEZONE timestamp
                    lastchange_new = 1
            values = list([playcount_xbmc, lastplayed_new, lastchange_new, imdbId, season, episode])

Little more info: My mysql server runs at CET (germany, currently at +1 hour due to winter time). So if i run a SELECT FROM_UNIXTIMESTAMP(0) it will return '1970-01-01 01:00:00'. This value will be internally converted to UTC which results in '1970-01-01 00:00:00' which is 1 second below the allowed values for a TIMESTAMP column in mysql. So by replacing the (given) 0-value for FROM_UNIXTIMESTMAP() by 1, it will hit the requirements and the query will succeed. This isnt a beautiful fix i know, but its a quick and easy fix to get this addon working again. Hopefully it will also work for other people

[SchapplM]

Your workaround looks good to me and should not pose any risks of messing up the database. It is merged into the official repo. If the problem still persists, just re-open this issue.