Opened 12 years ago

Closed 12 years ago

Last modified 12 years ago

#11224 closed Bug Report - General (fixed)

Duplicate recordings without manual resched - 0.26 regression

Reported by: Bradley Baetz <bbaetz@…> Owned by: gigem
Priority: minor Milestone: 0.26.1
Component: MythTV - Scheduling Version: 0.26-fixes
Severity: medium Keywords:
Cc: Ticket locked: no

Description

I have a number of shows that show during prime time, and then repeat the next day.

Before the first showing, the scheduler correctly identifies the first showing as the one to tape, and the second one is ignored as "earlier". The recording rule is to record all showings, and check for duplicates in 'All recordings'

However, once the first showing has finished being recorded, the second showing is then also incorrectly scheduled to record. This lasts until I force a reschedule (Eg mythutil --resched, have a completed mythfilldatabase run, etc)

This only started with the upgrade from 0.25 to 0.26. The only patches I have locally are to the perl bindings (#11079)

Note that my mythfilldatabase runs hourly via cron, but tv_grab_au is set up to fail except for once a day. If you're running mythfilldatabase hourly (or use EIT), I guess you may not see this because that would trigger the resched before you notice?

Example (FWIW my timezone is GMT+11):

During the recording (forgot to get this before the recording, but mythweb showed much the same)

$ mythbackend --printsched | grep Moral 2012-11-06 20:12:25.540082 I Yes, Minister - The Moral Dimensio 90 GEM 06 19:59-20:30 1 2 2 A 2 -50 2012-11-06 20:12:25.540828 I Yes, Minister - The Moral Dimensio 90 GEM 07 16:30-17:00 1 0 0 A E -50

After 8:30 (end of recording, but before end of the 10 minute soft padding):

$ mythbackend --printsched | grep Moral 2012-11-06 20:30:55.635870 I Yes, Minister - The Moral Dimensio 90 GEM 07 16:30-17:00 1 0 0 A E -50

After the recording is completely finished:

$ mythbackend --printsched | grep Moral 2012-11-06 20:40:53.150762 I Yes, Minister - The Moral Dimensio 90 GEM 07 16:30-17:00 1 2 2 A 2 -50

$ mythutil --resched .... 2012-11-06 20:41:12.522020 I Reschedule command sent to master $ mythbackend --printsched | grep Moral 2012-11-06 20:41:15.419157 I Yes, Minister - The Moral Dimensio 90 GEM 07 16:30-17:00 1 0 0 A R -50

In the logs - notice the "Reschedule interrupted":

Nov 6 20:40:00 guava mythlogserver: mythbackend[3407]: I TVRecEvent tv_rec.cpp:1043 (HandleStateChange?) TVRec(2): Changing from RecordingOnly? to None Nov 6 20:40:00 guava mythlogserver: mythbackend[3407]: I CoreContext? scheduler.cpp:655 (UpdateRecStatus?) Updating status for "Yes, Minister":"The Moral Dimension" on cardid 2 (Recording => Recorded) Nov 6 20:40:00 guava mythlogserver: mythbackend[3407]: I TVRecEvent recordinginfo.cpp:1131 (FinishedRecording?) Finished recording Yes, Minister "The Moral Dimension": channel 1090 Nov 6 20:40:00 guava mythlogserver: mythbackend[3407]: I Scheduler scheduler.cpp:2126 (HandleReschedule?) Reschedule requested for CHECK -3 295 0 UpdateRecStatus2 | Yes, Minister | The Moral Dimension | Jim is forced to back down about exposing bribery used to obtain a lucrative foreign contract when Bernard allows a valuable vase from a foreign government to be undervalued. | Nov 6 20:40:00 guava mythlogserver: mythbackend[3407]: E CoreContext? mainserver.cpp:915 (customEvent) MainServer?: PREVIEW_SUCCESS but no receivers. Nov 6 20:40:01 guava mythlogserver: mythbackend[3407]: I Scheduler scheduler.cpp:2230 (HandleReschedule?) Reschedule interrupted, will retry Nov 6 20:40:01 guava mythlogserver: mythbackend[3407]: I Scheduler scheduler.cpp:2126 (HandleReschedule?) Reschedule requested for PLACE Interrupted Nov 6 20:40:02 guava mythlogserver: mythbackend[3407]: I Scheduler scheduler.cpp:2239 (HandleReschedule?) Scheduled 72 items in 0.7 = 0.00 match + 0.00 check + 0.73 place

Nov 6 20:41:12 guava mythlogserver: mythbackend[3407]: I Scheduler scheduler.cpp:2126 (HandleReschedule?) Reschedule requested for MATCH 0 0 0 - MythUtilCommand? Nov 6 20:41:13 guava mythlogserver: mythbackend[3407]: I Scheduler scheduler.cpp:2239 (HandleReschedule?) Scheduled 72 items in 0.8 = 0.07 match + 0.05 check + 0.68 place

DB rules:

mysql> select * from record where title = 'Yes, Minister'\G * 1. row *

recordid: 295

type: 4

chanid: 1090

starttime: 09:00:00 startdate: 2012-11-06

endtime: 09:30:00 enddate: 2012-11-06

title: Yes, Minister

subtitle: The Moral Dimension

description: Jim is forced to back down about exposing bribery used to obtain a lucrative foreign contract when Bernard allows a valuable vase from a foreign government to be undervalued.

season: 3

episode: 4

category: comedy

profile: Default

recpriority: -50

autoexpire: 1

maxepisodes: 0

maxnewest: 0

startoffset: 0

endoffset: 0

recgroup: Default

dupmethod: 8

dupin: 15

station: GEM

seriesid: 26562466

programid:

inetref: 76829

search: 0

autotranscode: 1

autocommflag: 1 autouserjob1: 0 autouserjob2: 0 autouserjob3: 0 autouserjob4: 0 autometadata: 1

findday: 3

findtime: 20:00:00

findid: 735178

inactive: 0 parentid: 0

transcoder: 70

playgroup: Default prefinput: 0

next_record: 2012-11-06 09:00:00 last_record: 0000-00-00 00:00:00 last_delete: 0000-00-00 00:00:00

storagegroup: Default

avg_delay: 100

filter: 0

Before the recording starts:

mysql> select * from program where subtitle = 'The Moral Dimension' order by starttime\G * 1. row *

chanid: 1090

starttime: 2012-11-06 09:00:00

endtime: 2012-11-06 09:30:00

title: Yes, Minister

subtitle: The Moral Dimension

description: Jim is forced to back down about exposing bribery used to obtain a lucrative foreign contract when Bernard allows a valuable vase from a foreign government to be undervalued.

category: comedy

category_type:

airdate: 1982

stars: 0

previouslyshown: 1 title_pronounce:

stereo: 0

subtitled: 0

hdtv: 0

closecaptioned: 0

partnumber: 0

parttotal: 0

seriesid: 26562466

originalairdate: NULL

showtype:

colorcode:

syndicatedepisodenumber:

programid:

manualid: 0

generic: 0

listingsource: 4

first: 1

last: 0

audioprop:

subtitletypes:

videoprop: WIDESCREEN

* 2. row *

chanid: 1090

starttime: 2012-11-07 05:30:00

endtime: 2012-11-07 06:00:00

title: Yes, Minister

subtitle: The Moral Dimension

description: Jim is forced to back down about exposing bribery used to obtain a lucrative foreign contract when Bernard allows a valuable vase from a foreign government to be undervalued.

category: comedy

category_type:

airdate: 1982

stars: 0

previouslyshown: 1 title_pronounce:

stereo: 0

subtitled: 0

hdtv: 0

closecaptioned: 0

partnumber: 0

parttotal: 0

seriesid: 26562466

originalairdate: NULL

showtype:

colorcode:

syndicatedepisodenumber:

programid:

manualid: 0

generic: 0

listingsource: 4

first: 0

last: 1

audioprop:

subtitletypes:

videoprop: WIDESCREEN

2 rows in set (0.00 sec)

Attachments (6)

mythbackend.log (17.5 KB) - added by Bradley Baetz <bbaetz@…> 12 years ago.
backend log with debugging
mythtv.recschedfix.patch (898 bytes) - added by Bradley Baetz <bbaetz@…> 12 years ago.
Patch that was applied.
11224-debug1.patch (2.2 KB) - added by gigem 12 years ago.
mythbackend.2.log (55.2 KB) - added by Bradley Baetz <bbaetz@…> 12 years ago.
Latest log file
mythbackend.log.gz (268.4 KB) - added by Bradley Baetz <bbaetz@…> 12 years ago.
Another log file
11224-debug2.patch (3.3 KB) - added by gigem 12 years ago.

Download all attachments as: .zip

Change History (29)

comment:1 Changed 12 years ago by gigem

Status: newassigned

I'm hoping this is a simple race condition. In TVRec::FinishedRecording?(), you should see the following two chunks of code:

    // send out UPDATE_RECORDING_STATUS message
    if (recgrp != "LiveTV")
    {
        MythEvent me(QString("UPDATE_RECORDING_STATUS %1 %2 %3 %4 %5")
                     .arg(curRec->GetCardID())
                     .arg(curRec->GetChanID())
                     .arg(curRec->GetScheduledStartTime(MythDate::ISODate))
                     .arg(curRec->GetRecordingStatus())
                     .arg(curRec->GetRecordingEndTime(MythDate::ISODate)));
        gCoreContext->dispatch(me);
    }

    // store recording in recorded table
    curRec->FinishedRecording(!is_good || (recgrp == "LiveTV"));

Please try reversing the order of them. When you do that, please also run the backend with -v schedule.

comment:2 Changed 12 years ago by bbaetz@…

Doesn't help.

I had a cron job running this evening. The MASH episode finished at 22:05 local time (with another 10 mintues soft-padding). From the logs:

Sat Nov 10 22:00:02 EST 2012 2012-11-10 22:00:10.860948 I M*A*S*H - Farewell, Goodbye and Am 1 ONE 10 19:27-22:05 1 1 1 O 1 0 2012-11-10 22:00:10.861213 I M*A*S*H - Farewell, Goodbye and Am 1 ONE 11 14:58-17:35 1 0 0 A E -10 Sat Nov 10 22:05:02 EST 2012 2012-11-10 22:05:03.227644 I M*A*S*H - Farewell, Goodbye and Am 1 ONE 11 14:58-17:35 1 0 0 A E -10 Sat Nov 10 22:10:02 EST 2012 2012-11-10 22:10:12.699623 I M*A*S*H - Farewell, Goodbye and Am 1 ONE 11 14:58-17:35 1 0 0 A E -10 Sat Nov 10 22:15:03 EST 2012 2012-11-10 22:15:16.663201 I M*A*S*H - Farewell, Goodbye and Am 1 ONE 11 14:58-17:35 1 1 1 A 1 -10

So it was correct at 22:05, but broke at 22:15. There were other recordings going on, but none that finished in the meantime. I'll attach the patch I was using, just to confirm that it was the correct one.

Note that other shows have finished since then, but I still see the repeat of the episode being scheduled to report at 3pm tomorrow.

Will also attach the mythbackend log.

Changed 12 years ago by Bradley Baetz <bbaetz@…>

Attachment: mythbackend.log added

backend log with debugging

Changed 12 years ago by Bradley Baetz <bbaetz@…>

Attachment: mythtv.recschedfix.patch added

Patch that was applied.

Changed 12 years ago by gigem

Attachment: 11224-debug1.patch added

comment:3 Changed 12 years ago by gigem

Hmm. I know what has to be happening on one level, but not why. Please apply this new patch and replace "<myrecordid>" with the value for one of your rules that is showing the problem. This should confirm the what and hopefully shed some light on the why.

When you run this, please also dump the applicable record and oldrecorded entries while the first showing is recording, after it has finished and the problem exists and after you manually force a reschedule to correct the problem.

comment:4 Changed 12 years ago by Bradley Baetz <bbaetz@…>

OK, applied (on top of the previous patch). I looked in the guide for something that should trigger this, and created a new rule for JAG (id 298). The episode is scheduled for 1pm today with a repeat at 1am tomorrow (UTC+11). (There are also some other records for every other day in the week that you'll see in the logs, but note that these don't have any repeats scheduled)

I'll attach the backend log too.

Before the recording started:

mysql> select * from record where recordid=298\G
*************************** 1. row ***************************
     recordid: 298
         type: 4
       chanid: 1011
    starttime: 02:00:00
    startdate: 2012-11-11
      endtime: 03:00:00
      enddate: 2012-11-11
        title: JAG
     subtitle: Baby, It's Cold Outside
  description: Former fighter pilot Captain Harmon 'Harm' Rabb and his team of lawyers are charged with the duty of investigating and litigating crimes committed by marine and navy personnel.
       season: 6
      episode: 11
     category: drama
      profile: Default
  recpriority: 0
   autoexpire: 1
  maxepisodes: 0
    maxnewest: 0
  startoffset: 0
    endoffset: 0
     recgroup: Default
    dupmethod: 8
        dupin: 15
      station: ELEVEN
     seriesid: 20055
    programid: 
      inetref: 73710
       search: 0
autotranscode: 0
 autocommflag: 0
 autouserjob1: 0
 autouserjob2: 0
 autouserjob3: 0
 autouserjob4: 0
 autometadata: 1
      findday: 1
     findtime: 13:00:00
       findid: 735183
     inactive: 0
     parentid: 0
   transcoder: 70
    playgroup: Default
    prefinput: 0
  next_record: 2012-11-11 02:00:00
  last_record: 0000-00-00 00:00:00
  last_delete: 0000-00-00 00:00:00
 storagegroup: Default
    avg_delay: 100
       filter: 0
1 row in set (0.00 sec)

mysql> select recordid, chanid, starttime, manualid, oldrecduplicate, recduplicate, findduplicate, oldrecstatus, findid from recordmatch where recordid=298 order by starttime, chanid;
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
| recordid | chanid | starttime           | manualid | oldrecduplicate | recduplicate | findduplicate | oldrecstatus | findid |
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
|      298 |   1011 | 2012-11-11 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-11 14:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-12 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-13 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-14 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-15 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-16 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-17 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-18 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
9 rows in set (0.00 sec)

mysql> select * from record where title='JAG' and subtitle = "Baby, It's Cold Outside"\G*************************** 1. row ***************************
     recordid: 298
         type: 4
       chanid: 1011
    starttime: 02:00:00
    startdate: 2012-11-11
      endtime: 03:00:00
      enddate: 2012-11-11
        title: JAG
     subtitle: Baby, It's Cold Outside
  description: Former fighter pilot Captain Harmon 'Harm' Rabb and his team of lawyers are charged with the duty of investigating and litigating crimes committed by marine and navy personnel.
       season: 6
      episode: 11
     category: drama
      profile: Default
  recpriority: 0
   autoexpire: 1
  maxepisodes: 0
    maxnewest: 0
  startoffset: 0
    endoffset: 0
     recgroup: Default
    dupmethod: 8
        dupin: 15
      station: ELEVEN
     seriesid: 20055
    programid: 
      inetref: 73710
       search: 0
autotranscode: 0
 autocommflag: 0
 autouserjob1: 0
 autouserjob2: 0
 autouserjob3: 0
 autouserjob4: 0
 autometadata: 1
      findday: 1
     findtime: 13:00:00
       findid: 735183
     inactive: 0
     parentid: 0
   transcoder: 70
    playgroup: Default
    prefinput: 0
  next_record: 2012-11-11 02:00:00
  last_record: 0000-00-00 00:00:00
  last_delete: 0000-00-00 00:00:00
 storagegroup: Default
    avg_delay: 100
       filter: 0
1 row in set (0.00 sec)

mysql> select * from oldrecorded where title='JAG' and subtitle = "Baby, It's Cold Outside"\G*************************** 1. row ***************************
     chanid: 1011
  starttime: 2012-11-11 02:00:00
    endtime: 2012-11-11 03:00:00
      title: JAG
   subtitle: Baby, It's Cold Outside
description: Former fighter pilot Captain Harmon 'Harm' Rabb and his team of lawyers are charged with the duty of investigating and litigating crimes committed by marine and navy personnel.
     season: 0
    episode: 0
   category: drama
   seriesid: 20055
  programid: 
    inetref: 73710
     findid: 0
   recordid: 298
    station: ELEVEN
    rectype: 4
  duplicate: 0
  recstatus: -1
 reactivate: 0
    generic: 0
     future: 1
*************************** 2. row ***************************
     chanid: 1011
  starttime: 2012-11-11 14:00:00
    endtime: 2012-11-11 15:00:00
      title: JAG
   subtitle: Baby, It's Cold Outside
description: Former fighter pilot Captain Harmon 'Harm' Rabb and his team of lawyers are charged with the duty of investigating and litigating crimes committed by marine and navy personnel.
     season: 0
    episode: 0
   category: drama
   seriesid: 20055
  programid: 
    inetref: 73710
     findid: 0
   recordid: 298
    station: ELEVEN
    rectype: 4
  duplicate: 0
  recstatus: 4
 reactivate: 0
    generic: 0
     future: 1
2 rows in set (0.01 sec)

$ mythbackend --printsched | grep "Baby, It's Cold"
2012-11-11 12:43:22.903779 I  JAG - Baby, It's Cold Outside        11 ELEVEN  11 13:00-14:00  1 1 1  A 1 0
2012-11-11 12:43:22.904373 I  JAG - Baby, It's Cold Outside        11 ELEVEN  12 01:00-02:00  1 0 0  A E 0

After recording has started:

mysql> select recordid, chanid, starttime, manualid, oldrecduplicate, recduplicate, findduplicate, oldrecstatus, findid from recordmatch where recordid=298 order by starttime, chanid;
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
| recordid | chanid | starttime           | manualid | oldrecduplicate | recduplicate | findduplicate | oldrecstatus | findid |
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
|      298 |   1011 | 2012-11-11 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-11 14:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-12 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-13 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-14 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-15 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-16 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-17 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-18 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
9 rows in set (0.00 sec)

mysql> select * from record where title='JAG' and subtitle = "Baby, It's Cold Outside"\G*************************** 1. row ***************************
     recordid: 298
         type: 4
       chanid: 1011
    starttime: 02:00:00
    startdate: 2012-11-11
      endtime: 03:00:00
      enddate: 2012-11-11
        title: JAG
     subtitle: Baby, It's Cold Outside
  description: Former fighter pilot Captain Harmon 'Harm' Rabb and his team of lawyers are charged with the duty of investigating and litigating crimes committed by marine and navy personnel.
       season: 6
      episode: 11
     category: drama
      profile: Default
  recpriority: 0
   autoexpire: 1
  maxepisodes: 0
    maxnewest: 0
  startoffset: 0
    endoffset: 0
     recgroup: Default
    dupmethod: 8
        dupin: 15
      station: ELEVEN
     seriesid: 20055
    programid: 
      inetref: 73710
       search: 0
autotranscode: 0
 autocommflag: 0
 autouserjob1: 0
 autouserjob2: 0
 autouserjob3: 0
 autouserjob4: 0
 autometadata: 1
      findday: 1
     findtime: 13:00:00
       findid: 735183
     inactive: 0
     parentid: 0
   transcoder: 70
    playgroup: Default
    prefinput: 0
  next_record: 2012-11-12 02:00:00
  last_record: 2012-11-11 01:58:58
  last_delete: 0000-00-00 00:00:00
 storagegroup: Default
    avg_delay: 100
       filter: 0
1 row in set (0.00 sec)

mysql> select * from oldrecorded where title='JAG' and subtitle = "Baby, It's Cold Outside"\G*************************** 1. row ***************************
     chanid: 1011
  starttime: 2012-11-11 02:00:00
    endtime: 2012-11-11 03:00:00
      title: JAG
   subtitle: Baby, It's Cold Outside
description: Former fighter pilot Captain Harmon 'Harm' Rabb and his team of lawyers are charged with the duty of investigating and litigating crimes committed by marine and navy personnel.
     season: 0
    episode: 0
   category: drama
   seriesid: 20055
  programid: 
    inetref: 73710
     findid: 0
   recordid: 298
    station: ELEVEN
    rectype: 4
  duplicate: 0
  recstatus: -2
 reactivate: 0
    generic: 0
     future: 0
*************************** 2. row ***************************
     chanid: 1011
  starttime: 2012-11-11 14:00:00
    endtime: 2012-11-11 15:00:00
      title: JAG
   subtitle: Baby, It's Cold Outside
description: Former fighter pilot Captain Harmon 'Harm' Rabb and his team of lawyers are charged with the duty of investigating and litigating crimes committed by marine and navy personnel.
     season: 0
    episode: 0
   category: drama
   seriesid: 20055
  programid: 
    inetref: 73710
     findid: 0
   recordid: 298
    station: ELEVEN
    rectype: 4
  duplicate: 0
  recstatus: 4
 reactivate: 0
    generic: 0
     future: 1
2 rows in set (0.00 sec)

$ mythbackend --printsched | grep "Baby, It's Cold"
2012-11-11 13:02:06.816920 I  JAG - Baby, It's Cold Outside        11 ELEVEN  11 12:59-14:00  1 1 1  A 1 0
2012-11-11 13:02:06.817448 I  JAG - Baby, It's Cold Outside        11 ELEVEN  12 01:00-02:00  1 0 0  A E 0

After its finished:

mysql> select * from record where title='JAG' and subtitle = "Baby, It's Cold Outside"\G
*************************** 1. row ***************************
     recordid: 298
         type: 4
       chanid: 1011
    starttime: 02:00:00
    startdate: 2012-11-11
      endtime: 03:00:00
      enddate: 2012-11-11
        title: JAG
     subtitle: Baby, It's Cold Outside
  description: Former fighter pilot Captain Harmon 'Harm' Rabb and his team of lawyers are charged with the duty of investigating and litigating crimes committed by marine and navy personnel.
       season: 6
      episode: 11
     category: drama
      profile: Default
  recpriority: 0
   autoexpire: 1
  maxepisodes: 0
    maxnewest: 0
  startoffset: 0
    endoffset: 0
     recgroup: Default
    dupmethod: 8
        dupin: 15
      station: ELEVEN
     seriesid: 20055
    programid: 
      inetref: 73710
       search: 0
autotranscode: 0
 autocommflag: 0
 autouserjob1: 0
 autouserjob2: 0
 autouserjob3: 0
 autouserjob4: 0
 autometadata: 1
      findday: 1
     findtime: 13:00:00
       findid: 735183
     inactive: 0
     parentid: 0
   transcoder: 70
    playgroup: Default
    prefinput: 0
  next_record: 2012-11-11 14:00:00
  last_record: 2012-11-11 01:58:58
  last_delete: 0000-00-00 00:00:00
 storagegroup: Default
    avg_delay: 100
       filter: 0
1 row in set (0.00 sec)

mysql> select * from oldrecorded where title='JAG' and subtitle = "Baby, It's Cold Outside"\G
*************************** 1. row ***************************
     chanid: 1011
  starttime: 2012-11-11 02:00:00
    endtime: 2012-11-11 03:00:00
      title: JAG
   subtitle: Baby, It's Cold Outside
description: Former fighter pilot Captain Harmon 'Harm' Rabb and his team of lawyers are charged with the duty of investigating and litigating crimes committed by marine and navy personnel.
     season: 0
    episode: 0
   category: drama
   seriesid: 20055
  programid: 
    inetref: 73710
     findid: 0
   recordid: 298
    station: ELEVEN
    rectype: 4
  duplicate: 1
  recstatus: -3
 reactivate: 0
    generic: 0
     future: 0
*************************** 2. row ***************************
     chanid: 1011
  starttime: 2012-11-11 14:00:00
    endtime: 2012-11-11 15:00:00
      title: JAG
   subtitle: Baby, It's Cold Outside
description: Former fighter pilot Captain Harmon 'Harm' Rabb and his team of lawyers are charged with the duty of investigating and litigating crimes committed by marine and navy personnel.
     season: 0
    episode: 0
   category: drama
   seriesid: 20055
  programid: 
    inetref: 73710
     findid: 0
   recordid: 298
    station: ELEVEN
    rectype: 4
  duplicate: 0
  recstatus: -1
 reactivate: 0
    generic: 0
     future: 1
2 rows in set (0.00 sec)

mysql> select recordid, chanid, starttime, manualid, oldrecduplicate, recduplicate, findduplicate, oldrecstatus, findid from recordmatch where recordid=298 order by starttime, chanid;
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
| recordid | chanid | starttime           | manualid | oldrecduplicate | recduplicate | findduplicate | oldrecstatus | findid |
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
|      298 |   1011 | 2012-11-11 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-11 14:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-12 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-13 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-14 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-15 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-16 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-17 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-18 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
9 rows in set (0.00 sec)

$ mythbackend --printsched | grep "Baby, It's Cold"
2012-11-11 14:45:48.501864 I  JAG - Baby, It's Cold Outside        11 ELEVEN  12 01:00-02:00  1 1 1  A 1 0


After a resched:

mysql> select recordid, chanid, starttime, manualid, oldrecduplicate, recduplicate, findduplicate, oldrecstatus, findid from recordmatch where recordid=298 order by starttime, chanid;
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
| recordid | chanid | starttime           | manualid | oldrecduplicate | recduplicate | findduplicate | oldrecstatus | findid |
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
|      298 |   1011 | 2012-11-11 02:00:00 |        0 |               1 |            1 |             0 |           -3 |      0 |
|      298 |   1011 | 2012-11-11 14:00:00 |        0 |               1 |            1 |             0 |           -3 |      0 |
|      298 |   1011 | 2012-11-12 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-13 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-14 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-15 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-16 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-17 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      298 |   1011 | 2012-11-18 02:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
9 rows in set (0.00 sec)

mysql> select * from record where title='JAG' and subtitle = "Baby, It's Cold Outside"\G*************************** 1. row ***************************
     recordid: 298
         type: 4
       chanid: 1011
    starttime: 02:00:00
    startdate: 2012-11-11
      endtime: 03:00:00
      enddate: 2012-11-11
        title: JAG
     subtitle: Baby, It's Cold Outside
  description: Former fighter pilot Captain Harmon 'Harm' Rabb and his team of lawyers are charged with the duty of investigating and litigating crimes committed by marine and navy personnel.
       season: 6
      episode: 11
     category: drama
      profile: Default
  recpriority: 0
   autoexpire: 1
  maxepisodes: 0
    maxnewest: 0
  startoffset: 0
    endoffset: 0
     recgroup: Default
    dupmethod: 8
        dupin: 15
      station: ELEVEN
     seriesid: 20055
    programid: 
      inetref: 73710
       search: 0
autotranscode: 0
 autocommflag: 0
 autouserjob1: 0
 autouserjob2: 0
 autouserjob3: 0
 autouserjob4: 0
 autometadata: 1
      findday: 1
     findtime: 13:00:00
       findid: 735183
     inactive: 0
     parentid: 0
   transcoder: 70
    playgroup: Default
    prefinput: 0
  next_record: 2012-11-12 02:00:00
  last_record: 2012-11-11 01:58:58
  last_delete: 0000-00-00 00:00:00
 storagegroup: Default
    avg_delay: 100
       filter: 0
1 row in set (0.00 sec)

mysql> select * from oldrecorded where title='JAG' and subtitle = "Baby, It's Cold Outside"\G*************************** 1. row ***************************
     chanid: 1011
  starttime: 2012-11-11 02:00:00
    endtime: 2012-11-11 03:00:00
      title: JAG
   subtitle: Baby, It's Cold Outside
description: Former fighter pilot Captain Harmon 'Harm' Rabb and his team of lawyers are charged with the duty of investigating and litigating crimes committed by marine and navy personnel.
     season: 0
    episode: 0
   category: drama
   seriesid: 20055
  programid: 
    inetref: 73710
     findid: 0
   recordid: 298
    station: ELEVEN
    rectype: 4
  duplicate: 1
  recstatus: -3
 reactivate: 0
    generic: 0
     future: 0
*************************** 2. row ***************************
     chanid: 1011
  starttime: 2012-11-11 14:00:00
    endtime: 2012-11-11 15:00:00
      title: JAG
   subtitle: Baby, It's Cold Outside
description: Former fighter pilot Captain Harmon 'Harm' Rabb and his team of lawyers are charged with the duty of investigating and litigating crimes committed by marine and navy personnel.
     season: 0
    episode: 0
   category: drama
   seriesid: 20055
  programid: 
    inetref: 73710
     findid: 0
   recordid: 298
    station: ELEVEN
    rectype: 4
  duplicate: 0
  recstatus: 3
 reactivate: 0
    generic: 0
     future: 1
2 rows in set (0.00 sec)

$ mythbackend --printsched | grep "Baby, It's Cold"
2012-11-11 14:46:55.556292 I  JAG - Baby, It's Cold Outside        11 ELEVEN  12 01:00-02:00  1 0 0  A R 0

Changed 12 years ago by Bradley Baetz <bbaetz@…>

Attachment: mythbackend.2.log added

Latest log file

comment:5 Changed 12 years ago by gigem

Okay, here's the smoking gun right where I expected it.

Nov 11 14:10:00 guava mythlogserver: mythbackend[30793]: I Scheduler scheduler.cpp:2156 (HandleReschedule) Reschedule requested for CHECK -3 298 0 UpdateRecStatus2 | JAG | Baby, It's Cold Outside | Former fighter pilot Captain Harmon 'Harm' Rabb and his team of lawyers are charged with the duty of investigating and litigating crimes committed by marine and navy personnel. | 
Nov 11 14:10:00 guava mythlogserver: mythbackend[30793]: I Scheduler scheduler.cpp:2231 (HandleReschedule) CreateTempTables...
Nov 11 14:10:00 guava mythlogserver: mythbackend[30793]: I Scheduler scheduler.cpp:2237 (HandleReschedule) UpdateDuplicates...
Nov 11 14:10:00 guava mythlogserver: mythbackend[30793]: I Scheduler scheduler.cpp:58 (DumpRecordMatch) Dumping recordmatch Before UpdateDuplicates()
Nov 11 14:10:00 guava mythlogserver: mythbackend[30793]: I Scheduler scheduler.cpp:80 (DumpRecordMatch) rid=298, chid=1011, st=Sun Nov 11 02:00:00 2012, mid=0, ord=0, rd=0, fd=0, ors=0, fid=0
Nov 11 14:10:00 guava mythlogserver: mythbackend[30793]: I Scheduler scheduler.cpp:80 (DumpRecordMatch) rid=298, chid=1011, st=Sun Nov 11 14:00:00 2012, mid=0, ord=0, rd=0, fd=0, ors=0, fid=0

ord should be -1 for any programs matching the CHECK reschedule request, but they are being left at 0. That causes them to not be considered for the following duplicate update. So the question is why isn't ord being set to -1. It's not obvious to me why this is happening. Perhaps there's something unique in your guide data or configuration or the scheduler logic is just faulty.

Can you please add "database" to your backend logging to see the actual query being used? Then, try running the query manually in mysql and perhaps see why it's not working as intended.

comment:6 Changed 12 years ago by Bradley Baetz <bbaetz@…>

Have set this up for this evening (with a different show, so tweaked the debug patch). I also had to add --logLevel debug to get the specific SQL statements in the logs

Only thing odd with my program data (.au) is that none of the TV shows will have program IDs. Also, none of the tv shows have season/episode ids, but by the time the post-show reschedule happens they will (this is because the metadata job runs at the end of the program time, but the resched only runs after the soft-padding is over)

comment:7 Changed 12 years ago by Bradley Baetz <bbaetz@…>

I'll attach the logs. Note that at 18:03 and 19:03 mythfilldatabase ran (I forgot to turn that off), so I didn't manage to run any of the queries manually while it was broken.

The 18:03 logs seem to show that oldrecduplicate is being set to -1 for all episodes, at least temporarily, but then its reset later? Looking at the code, this is because the description is generic in the guide data and the db update sets it to -1 if the description matches. This was also the case for yesterday's JAG example, but I'll trigger another case overnight where the description isn't the same for every single episode.

Then something resets it to 0 later and it stays like that.

Currently:

mysql> select recordid, chanid, starttime, manualid, oldrecduplicate, recduplicate, findduplicate, oldrecstatus, findid from recordmatch where recordid=125 order by starttime, chanid;
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
| recordid | chanid | starttime           | manualid | oldrecduplicate | recduplicate | findduplicate | oldrecstatus | findid |
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
|      125 |   1001 | 2012-11-12 07:00:00 |        0 |               1 |            1 |             0 |           -3 |      0 |
|      125 |   1001 | 2012-11-12 15:40:00 |        0 |               1 |            1 |             0 |           -3 |      0 |
|      125 |   1001 | 2012-11-13 07:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      125 |   1001 | 2012-11-13 14:10:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      125 |   1001 | 2012-11-14 07:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      125 |   1001 | 2012-11-15 07:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      125 |   1001 | 2012-11-15 15:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      125 |   1001 | 2012-11-16 07:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      125 |   1001 | 2012-11-17 05:30:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      125 |   1001 | 2012-11-17 08:30:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      125 |   1001 | 2012-11-17 09:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      125 |   1001 | 2012-11-18 05:30:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      125 |   1001 | 2012-11-18 06:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      125 |   1001 | 2012-11-19 07:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      125 |   1001 | 2012-11-20 07:00:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
15 rows in set (0.00 sec)

Changed 12 years ago by Bradley Baetz <bbaetz@…>

Attachment: mythbackend.log.gz added

Another log file

comment:8 Changed 12 years ago by gigem

Okay. Please try to trigger another case, then. We really need to figure why the update recordmatch query isn't working and you trying things manually while the problem exists is our best bet at this point.

oldrecduplicate will never be left to -1 for long. It's merely a special value to tell the following code to recalculate the correct value. This is an optimization added in MythTV 0.26. Calculating oldrecduplicate is pretty expensive, so the code now tries to avoid doing it when the value shouldn't have changed.

Yes, I noticed you had good subtitles and generic descriptions and no programids. I don't think that should be a problem, but we'll see.

comment:9 Changed 12 years ago by Bradley Baetz <bbaetz@…>

OK, have another one. Breaking bad was shown at 12:03 am today. Its now incorrectly scheduled again for 1:15am on Sat.

mysql> select * from record where recordid=249\G
*************************** 1. row ***************************
     recordid: 249
         type: 4
       chanid: 0
    starttime: 14:13:00
    startdate: 2012-10-01
      endtime: 15:00:00
      enddate: 2012-10-01
        title: Breaking Bad
     subtitle: Mas
  description: As Skyler reconsiders her objections to him living back at home, Walt mulls over an offer to return to the drug trade. Meanwhile, Hank's obsession with nailing Heisenberg promises trouble for Jesse.
       season: 3
      episode: 5
     category: drama
      profile: Default
  recpriority: -10
   autoexpire: 1
  maxepisodes: 0
    maxnewest: 0
  startoffset: 0
    endoffset: 0
     recgroup: Default
    dupmethod: 8
        dupin: 15
      station: 
     seriesid: 215085156
    programid: 
      inetref: 81189
       search: 0
autotranscode: 1
 autocommflag: 1
 autouserjob1: 0
 autouserjob2: 0
 autouserjob3: 1
 autouserjob4: 0
 autometadata: 1
      findday: 3
     findtime: 00:13:00
       findid: 735143
     inactive: 0
     parentid: 0
   transcoder: 70
    playgroup: Default
    prefinput: 0
  next_record: 2012-11-16 14:15:00
  last_record: 2012-11-12 13:01:59
  last_delete: 0000-00-00 00:00:00
 storagegroup: Default
    avg_delay: 100
       filter: 0
1 row in set (0.00 sec)

mysql> select recordid, chanid, starttime, manualid, oldrecduplicate, recduplicate, findduplicate, oldrecstatus, findid from recordmatch where recordid=249 order by starttime, chanid;
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
| recordid | chanid | starttime           | manualid | oldrecduplicate | recduplicate | findduplicate | oldrecstatus | findid |
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
|      249 |   1022 | 2012-11-12 13:03:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      249 |   1022 | 2012-11-16 14:15:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
|      249 |   1022 | 2012-11-19 12:59:00 |        0 |               0 |            0 |             0 |         NULL |      0 |
+----------+--------+---------------------+----------+-----------------+--------------+---------------+--------------+--------+
3 rows in set (0.00 sec)

mysql> select * from program where title = 'Breaking Bad' and subtitle = 'Abq' order by starttime\G
*************************** 1. row ***************************
                 chanid: 1022
              starttime: 2012-11-12 13:03:00
                endtime: 2012-11-12 13:50:00
                  title: Breaking Bad
               subtitle: Abq
            description: As Hank is unhappy with the pace of his recovery, and Skyler questions Saul's money-laundering scheme, Jesse falls for a fellow rehab patient who he learns is tied to the murder of his late friend, Combo.
               category: drama
          category_type: 
                airdate: 2012
                  stars: 0
        previouslyshown: 1
        title_pronounce: 
                 stereo: 0
              subtitled: 1
                   hdtv: 0
         closecaptioned: 0
             partnumber: 0
              parttotal: 0
               seriesid: 215085156
        originalairdate: NULL
               showtype: 
              colorcode: 
syndicatedepisodenumber: 
              programid: 
               manualid: 0
                generic: 0
          listingsource: 4
                  first: 1
                   last: 0
              audioprop: 
          subtitletypes: NORMAL
              videoprop: WIDESCREEN
*************************** 2. row ***************************
                 chanid: 1022
              starttime: 2012-11-16 14:15:00
                endtime: 2012-11-16 15:00:00
                  title: Breaking Bad
               subtitle: Abq
            description: As Hank is unhappy with the pace of his recovery, and Skyler questions Saul's money-laundering scheme, Jesse falls for a fellow rehab patient who he learns is tied to the murder of his late friend, Combo.
               category: drama
          category_type: 
                airdate: 2012
                  stars: 0
        previouslyshown: 1
        title_pronounce: 
                 stereo: 0
              subtitled: 1
                   hdtv: 0
         closecaptioned: 0
             partnumber: 0
              parttotal: 0
               seriesid: 215085156
        originalairdate: NULL
               showtype: 
              colorcode: 
syndicatedepisodenumber: 
              programid: 
               manualid: 0
                generic: 0
          listingsource: 4
                  first: 0
                   last: 1
              audioprop: 
          subtitletypes: NORMAL
              videoprop: WIDESCREEN
2 rows in set (0.02 sec)

mysql> select * from oldrecorded where title = 'Breaking Bad' and subtitle = 'Abq' order by starttime\G
*************************** 1. row ***************************
     chanid: 1022
  starttime: 2012-11-12 13:03:00
    endtime: 2012-11-12 13:50:00
      title: Breaking Bad
   subtitle: Abq
description: As Hank is unhappy with the pace of his recovery, and Skyler questions Saul's money-laundering scheme, Jesse falls for a fellow rehab patient who he learns is tied to the murder of his late friend, Combo.
     season: 0
    episode: 0
   category: drama
   seriesid: 215085156
  programid: 
    inetref: 81189
     findid: 0
   recordid: 249
    station: ABC2 / ABC4
    rectype: 4
  duplicate: 1
  recstatus: -3
 reactivate: 0
    generic: 0
     future: 0
*************************** 2. row ***************************
     chanid: 1022
  starttime: 2012-11-16 14:15:00
    endtime: 2012-11-16 15:00:00
      title: Breaking Bad
   subtitle: Abq
description: As Hank is unhappy with the pace of his recovery, and Skyler questions Saul's money-laundering scheme, Jesse falls for a fellow rehab patient who he learns is tied to the murder of his late friend, Combo.
     season: 0
    episode: 0
   category: drama
   seriesid: 215085156
  programid: 
    inetref: 81189
     findid: 0
   recordid: 249
    station: ABC2 / ABC4
    rectype: 4
  duplicate: 0
  recstatus: -1
 reactivate: 0
    generic: 0
     future: 1
2 rows in set (0.04 sec)

comment:10 Changed 12 years ago by Bradley Baetz <bbaetz@…>

I had to reconstruct the update query from the source, because the debug doesn't display the bound params, but the select query does seem to return rows. (I didn't run the update so that I can get extra info if you want)

I've disabled mythfilldatabase, and since the next recording of this is Sat, this should give time to run any queries that you want.

The logging for update also doesn't seem to log how many rows were updated, but the debug logs seem to show that no rows are updated.

Nov 13 01:00:01 guava mythlogserver: mythbackend[20229]: D Scheduler mythdbcon.
cpp:689 (exec) MSqlQuery::exec(SchedCon) ''U''P''D''A''T''E'' ''r''e''c''o''r''
d''m''a''t''c''h'' ''r''m'' ''I''N''N''E''R'' ''J''O''I''N'' ''r''e''c''o''r''d
'' ''r'' '' '' '' '' '' '' ''O''N'' ''r''m''.''r''e''c''o''r''d''i''d'' ''='' '
'r''.''r''e''c''o''r''d''i''d'' ''I''N''N''E''R'' ''J''O''I''N'' ''p''r''o''g''
r''a''m'' ''p'' '' '' '' '' '' '' ''O''N'' ''r''m''.''c''h''a''n''i''d'' ''='' 
''p''.''c''h''a''n''i''d'' '' '' '' '' '' '' '' '' '' ''A''N''D'' ''r''m''.''s'
't''a''r''t''t''i''m''e'' ''='' ''p''.''s''t''a''r''t''t''i''m''e'' '' '' '' ''
 '' '' '' '' '' ''A''N''D'' ''r''m''.''m''a''n''u''a''l''i''d'' ''='' ''p''.''m''a''n''u''a''l''i''d'' ''S''E''T'' ''o''l''d''r''e''c''d''u''p''l''i''c''a''t''e'' ''='' ''-''1'' ''W''H''E''R''E'' ''p''.''g''e''n''e''r''i''c'' ''='' ''0'' '' '' '' '' '' '' ''A''N''D'' ''r''.''t''y''p''e'' ''N''O''T'' ''I''N'' ''(''1'','' ''7'','' ''8'')'' ''A''N''D'' ''p''.''t''i''t''l''e'' ''='' '':''T''I''T''L''E'' ''A''N''D'' ''(''0'' ''O''R'' ''p''.''s''u''b''t''i''t''l''e'' ''='' '':''S''U''B''T''I''T''L''E'' ''O''R'' ''p''.''d''e''s''c''r''i''p''t''i''o''n'' ''='' '':''S''U''B''T''I''T''L''E'' ''O''R'' ''p''.''d''e''s''c''r''i''p''t''i''o''n'' ''='' '':''D''E''S''C''R''I''P'' ''O''R'' ''p''.''s''u''b''t''i''t''l''e'' ''='' '':''D''E''S''C''R''I''P'' '')'' ''

mysql> select * from recordmatch rm INNER JOIN record r ON rm.recordid=r.recordid inner join program p on rm.chanid=p.chanid and rm.starttime=p.starttime and rm.manualid=p.manualid where p.generic=0 and r.type not in (1,7,8) and p.title='Breaking Bad' AND (0 or p.subtitle='Abq' or p.description='Abq')\G
*************************** 1. row ***************************
               recordid: 249
                 chanid: 1022
              starttime: 2012-11-12 13:03:00
               manualid: 0
        oldrecduplicate: 0
           recduplicate: 0
          findduplicate: 0
           oldrecstatus: NULL
                 findid: 0
               recordid: 249
                   type: 4
                 chanid: 0
              starttime: 14:13:00
              startdate: 2012-10-01
                endtime: 15:00:00
                enddate: 2012-10-01
                  title: Breaking Bad
               subtitle: Mas
            description: As Skyler reconsiders her objections to him living back at home, Walt mulls over an offer to return to the drug trade. Meanwhile, Hank's obsession with nailing Heisenberg promises trouble for Jesse.
                 season: 3
                episode: 5
               category: drama
                profile: Default
            recpriority: -10
             autoexpire: 1
            maxepisodes: 0
              maxnewest: 0
            startoffset: 0
              endoffset: 0
               recgroup: Default
              dupmethod: 8
                  dupin: 15
                station: 
               seriesid: 215085156
              programid: 
                inetref: 81189
                 search: 0
          autotranscode: 1
           autocommflag: 1
           autouserjob1: 0
           autouserjob2: 0
           autouserjob3: 1
           autouserjob4: 0
           autometadata: 1
                findday: 3
               findtime: 00:13:00
                 findid: 735143
               inactive: 0
               parentid: 0
             transcoder: 70
              playgroup: Default
              prefinput: 0
            next_record: 2012-11-16 14:15:00
            last_record: 2012-11-12 13:01:59
            last_delete: 0000-00-00 00:00:00
           storagegroup: Default
              avg_delay: 100
                 filter: 0
                 chanid: 1022
              starttime: 2012-11-12 13:03:00
                endtime: 2012-11-12 13:50:00
                  title: Breaking Bad
               subtitle: Abq
            description: As Hank is unhappy with the pace of his recovery, and Skyler questions Saul's money-laundering scheme, Jesse falls for a fellow rehab patient who he learns is tied to the murder of his late friend, Combo.
               category: drama
          category_type: 
                airdate: 2012
                  stars: 0
        previouslyshown: 1
        title_pronounce: 
                 stereo: 0
              subtitled: 1
                   hdtv: 0
         closecaptioned: 0
             partnumber: 0
              parttotal: 0
               seriesid: 215085156
        originalairdate: NULL
               showtype: 
              colorcode: 
syndicatedepisodenumber: 
              programid: 
               manualid: 0
                generic: 0
          listingsource: 4
                  first: 1
                   last: 0
              audioprop: 
          subtitletypes: NORMAL
              videoprop: WIDESCREEN
*************************** 2. row ***************************
               recordid: 249
                 chanid: 1022
              starttime: 2012-11-16 14:15:00
               manualid: 0
        oldrecduplicate: 0
           recduplicate: 0
          findduplicate: 0
           oldrecstatus: NULL
                 findid: 0
               recordid: 249
                   type: 4
                 chanid: 0
              starttime: 14:13:00
              startdate: 2012-10-01
                endtime: 15:00:00
                enddate: 2012-10-01
                  title: Breaking Bad
               subtitle: Mas
            description: As Skyler reconsiders her objections to him living back at home, Walt mulls over an offer to return to the drug trade. Meanwhile, Hank's obsession with nailing Heisenberg promises trouble for Jesse.
                 season: 3
                episode: 5
               category: drama
                profile: Default
            recpriority: -10
             autoexpire: 1
            maxepisodes: 0
              maxnewest: 0
            startoffset: 0
              endoffset: 0
               recgroup: Default
              dupmethod: 8
                  dupin: 15
                station: 
               seriesid: 215085156
              programid: 
                inetref: 81189
                 search: 0
          autotranscode: 1
           autocommflag: 1
           autouserjob1: 0
           autouserjob2: 0
           autouserjob3: 1
           autouserjob4: 0
           autometadata: 1
                findday: 3
               findtime: 00:13:00
                 findid: 735143
               inactive: 0
               parentid: 0
             transcoder: 70
              playgroup: Default
              prefinput: 0
            next_record: 2012-11-16 14:15:00
            last_record: 2012-11-12 13:01:59
            last_delete: 0000-00-00 00:00:00
           storagegroup: Default
              avg_delay: 100
                 filter: 0
                 chanid: 1022
              starttime: 2012-11-16 14:15:00
                endtime: 2012-11-16 15:00:00
                  title: Breaking Bad
               subtitle: Abq
            description: As Hank is unhappy with the pace of his recovery, and Skyler questions Saul's money-laundering scheme, Jesse falls for a fellow rehab patient who he learns is tied to the murder of his late friend, Combo.
               category: drama
          category_type: 
                airdate: 2012
                  stars: 0
        previouslyshown: 1
        title_pronounce: 
                 stereo: 0
              subtitled: 1
                   hdtv: 0
         closecaptioned: 0
             partnumber: 0
              parttotal: 0
               seriesid: 215085156
        originalairdate: NULL
               showtype: 
              colorcode: 
syndicatedepisodenumber: 
              programid: 
               manualid: 0
                generic: 0
          listingsource: 4
                  first: 0
                   last: 1
              audioprop: 
          subtitletypes: NORMAL
              videoprop: WIDESCREEN
2 rows in set (0.00 sec)

comment:11 Changed 12 years ago by Bradley Baetz <bbaetz@…>

Actually, looking at my other logs and the code, bind values *are* meant to be substituted. So it looks like the issue might be that the bound values aren't being applied? I'm not familiar with the QT mysql bindings, but nothing immediately looks wrong (although I'm not sure why MSqlBindings is used rather than just setting values on the query object directly - currently the cost sets up the bindings, then iterates through to apply them to the object, and then on ->exec the msql class just does the same thing

In case it matters, I'm running ubuntu 12.04

comment:12 Changed 12 years ago by gigem

I think you've found it. I vaguely recall that Qt is pretty anal about the bindings, including not liking a binding to be used more than once. Please try 11224-debug2.patch. IIRC and it is the problem, this patch should fix it.

Changed 12 years ago by gigem

Attachment: 11224-debug2.patch added

comment:13 Changed 12 years ago by Bradley Baetz <bbaetz@…>

Yeah, that's it. I set up a recording that hasn't started yet so I can't be sure, but I deleted a show, and I've noticed that that caused a CHECK that has now the correct query in the logs (ie with params)

That also explains why noone else saw this - most of the rest of the world uses programids.

(Side note - deleting a show triggers the CHECK reschedule but undeleting it doesn't - is that a separate bug?)

Will update this evening when the recording in question has finished

comment:14 Changed 12 years ago by Bradley Baetz <bbaetz@…>

Yeah, that fixed it:

Nov 13 12:10:00 guava mythlogserver: mythbackend[18663]: I Scheduler scheduler.cpp:2159 (HandleReschedule) Reschedule requested for CHECK -3 300 0 UpdateRecStatus2 | The Love Boat | The Lady from Laramie | All aboard, the Love Boat is ready to set sail! What madcap misadventures and romantic rendezvous await the crew and passengers of the Pacific Princess? | 
Nov 13 12:10:00 guava mythlogserver: mythbackend[18663]: D Scheduler mythdbcon.cpp:689 (exec) MSqlQuery::exec(SchedCon) UPDATE recordmatch rm INNER JOIN record r       ON rm.recordid = r.recordid INNER JOIN program p       ON rm.chanid = p.chanid          AND rm.starttime = p.starttime          AND rm.manualid = p.manualid SET oldrecduplicate = -1 WHERE p.generic = 0       AND r.type NOT IN (1, 7, 8) AND p.title = 'The Love Boat' AND (0 OR p.subtitle = 'The Lady from Laramie' OR p.description = 'The Lady from Laramie' OR p.description = 'All aboard, the Love Boat is ready to set sail! What madcap misadventures and romantic rendezvous await the crew and passengers of the Pacific Princess?' OR p.subtitle = 'All aboard, the Love Boat is ready to set sail! What madcap misadventures and romantic rendezvous await the crew and passengers of the Pacific Princess?' ) 

without the odd per-character quoting too.

and the "Before UpdateDuplicates?()" debug dump has:

Nov 13 12:10:00 guava mythlogserver: mythbackend[18663]: I Scheduler scheduler.cpp:81 (DumpRecordMatch) rid=300, chid=1011, st=Mon Nov 12 15:00:00 2012, mid=0, ord=-1, rd=0, fd=0, ors=0, fid=0
Nov 13 12:10:00 guava mythlogserver: mythbackend[18663]: D Scheduler mythdbcon.cpp:759 (seekDebug) MSqlQuery::next(DBManager32) Result: "recordid = 300, chanid = 1011, starttime = 2012-11-13T00:00:00, manualid = 0, oldrecduplicate = -1, recduplicate = 0, findduplicate = 0, oldrecstatus = 0, findid = 0"
Nov 13 12:10:00 guava mythlogserver: mythbackend[18663]: I Scheduler scheduler.cpp:81 (DumpRecordMatch) rid=300, chid=1011, st=Tue Nov 13 00:00:00 2012, mid=0, ord=-1, rd=0, fd=0, ors=0, fid=0
Nov 13 12:10:00 guava mythlogserver: mythbackend[18663]: D Scheduler mythdbcon.cpp:759 (seekDebug) MSqlQuery::next(DBManager32) Result: "recordid = 300, chanid = 1011, starttime = 2012-11-13T15:00:00, manualid = 0, oldrecduplicate = -1, recduplicate = 0, findduplicate = 0, oldrecstatus = 0, findid = 0"

as expected.

comment:15 in reply to:  13 Changed 12 years ago by gigem

Replying to Bradley Baetz <bbaetz@…>:

(Side note - deleting a show triggers the CHECK reschedule but undeleting it doesn't - is that a separate bug?)

Yes, that's a separate bug.

Replying to Bradley Baetz <bbaetz@…>:

Yeah, that fixed it:

Yay.

without the odd per-character quoting too.

Cool. I was wondering why that was happening.

I'll commit the fixes shortly.

comment:16 Changed 12 years ago by David Engel <dengel@…>

Resolution: fixed
Status: assignedclosed

In 6a147ecf09aea985f95d8dcbe4edacc9e18f4a38/mythtv:

Error: Processor CommitTicketReference failed
GIT backend not available

comment:17 Changed 12 years ago by David Engel <dengel@…>

In 729e3d56d3e984d35b4fecd249da7c3e1bdcbfb9/mythtv:

Error: Processor CommitTicketReference failed
GIT backend not available

comment:18 Changed 12 years ago by David Engel <dengel@…>

In 5e1c14e8c295fb00a3f2e359021be026104863db/mythtv:

Error: Processor CommitTicketReference failed
GIT backend not available

comment:19 Changed 12 years ago by David Engel <dengel@…>

In 1618035441204b0a0f58e8b1f87f369c04df5527/mythtv:

Error: Processor CommitTicketReference failed
GIT backend not available

comment:20 Changed 12 years ago by David Engel <dengel@…>

In c57b92740ac15e708bd8a68eb767b484d8b26f4a/mythtv:

Error: Processor CommitTicketReference failed
GIT backend not available

comment:21 Changed 12 years ago by David Engel <dengel@…>

In 81e8fa5175436ab2487944cc66de95c509e8cbc5/mythtv:

Error: Processor CommitTicketReference failed
GIT backend not available

comment:22 Changed 12 years ago by Bradley Baetz <bbaetz@…>

Thanks - latest fixes/0.26 works for me without patches

comment:23 Changed 12 years ago by gigem

Milestone: unknown0.26.1
Note: See TracTickets for help on using tickets.