Improper insertion of jobs through MythWeb can block future commflag jobs

[Ken Emerson <kenneth.emerson@…>]

MythWeb has no protection insertion of new jobs into the jobqueue table. If two instances of the details page are opened and the same job run twice, or the user hits the back button triggering a repeat submission, a duplicate job can be added to the table. This results in the second copy of the job being left in the queue indefinitely, confusing subsequent host selection of tasks.

This will be rendered a non-issue by the jobqueue rewrite, if not fixed by the time that gets merged in.

[cpinkham]

What's the status of these orphaned jobs? I looked at the code, and we should set the status to one of JOB_ERRORED, JOB_ABORTED, or JOB_FINISHED, no matter what reason mythcommflag exitted. If it's not errored and not aborted, then we mark it as finished. Can you also tell me what is in the comment field for these jobs? Does that get updated or does it still indicate flagging is underway.

[Ken Emerson <kenneth.emerson@…>]

Status = 4

Comment = "99% Completed @ 450.573 fps. "

I had already deleted the two others, but looking back in my DB backup from last night the status for them was also 4 with similar "99% Completed" comments. I have one recording now that consistently produces a segfault when commflagging. After running (and failing) I have the following entry in the jobqueue table:

id chanid starttime inserttime type cmds flags status statustime hostname args comment schedruntime

7905 1081 2010-10-27 21:01:00 2010-10-29 13:29:27 2 0 4 4 2010-10-29 13:37:35 mythtv [BLOB - 0B] 99% Completed @ 450.573 fps. 2010-10-29 13:29:27

[cpinkham]

Please paste in the relevant portion of your backend logs when mythcommflag starts and when it segfaults. Specifically, I'm looking for some lines that have the word "PID" on them, but include at least 30-40 lines around that when mythcommflag segfaults. There should be a PID line when mythcommflag starts and another one when mythcommflag segfaults showing that the process ended.

[Ken Emerson <kenneth.emerson@…>]

Requested backend log file of commflag start and segfault

[Ken Emerson <kenneth.emerson@…>]

Interestingly enough, when I deleted the entry in the jobqueue table and restarted the commflag job, it still segfaulted but did not remain incomplete in the jobqueue. I've attached the snippet from the original job (on the 27th), although it looks identical to all the others.

[beirdo]

That log snippet shows the process ending, although we misinterpreted the result as being 139 commercials. I would venture a guess that you are using ubuntu, as I have seen the same weirdness of return value there (it should say that it was killed with signal 11). However, it doesn't look like anything that is hanging on the myth_system side.

I guess we need to investigate more. I assume this is repeatable in your setup?

[Ken Emerson <kenneth.emerson@…>]

I am running Ubuntu 10.4. This particular recording will not complete a commflag job (always segfaults); therefore, yes it is repeatable. This recording must have something seriously wrong with it. I will keep it around until you tell me you are done with it.

[beirdo]

The recording is likely corrupt. There's not much that can be done in that case, but however, the job shouldn't be staying in the jobqueue, and that's the core of this bug.

[cpinkham]

The fact that the preview generator ran indicates that the JobQueue? does see mythcommflag end and the JobQueue? starts it's cleanup work. The preview generator is run after we've updated the job status in the database though, so I don't see how the status would have been left at 'running' with the given log file.

If you can reproduce the issue where the job is left in a '4' (running) status, then please attach backend logs of around the time mythcommflag dies. Run the backend with "-v jobqueue,database,extra" so that I can see what the JobQueue? is doing and what SQL commands and being sent and their results. You can start the log where the segfault occurs and please include at least 200 lines after that point.

[Ken Emerson <kenneth.emerson@…>]

I had to run the commflag job twice to get the output you asked for. Interesting results: The first run, the process segfaulted but completed; the second run, the process did not segfault, found six commercial breaks (seems reasonable), AND got stuck in the job queue with a status of 4. Log file attached.

[Ken Emerson <kenneth.emerson@…>]

backend logfile with job stuck in jobqueue with status=4

[Ken Emerson <kenneth.emerson@…>]

Sometime after this (can't say how long, noticed the next day), the jobqueue did get cleaned up and the "stuck" job disappeared.

[Raymond Wagner]

The offending code will end up getting replaced by the jobqueue scheduler as part of #7990.

[Raymond Wagner]

Are you still having this problem after the MythSystem? rewrite in December?

[Ken Emerson <kenneth.emerson@…>]

I recently upgraded to master (5/18). Soon after that I had many commflag jobs fail. The failures occurred mainly on two TV series: The Burns and Allen Show (Antenna TV OTA) and Wheel of Fortune (NBC OTA). I believe the Burns and Allen Show was the first time I'd recorded on that channel and the recordings that had failed commflag jobs also would not play without segfaulting; however, the Wheel of Fortune shows played fine. With all of these failed jobs in the job queue, it appeared that no more commflag jobs were being scheduled (at one time there were as many as 8 or 9 failed jobs in the queue). When I manually cleared out the queue, commflag jobs began to be queued once again.

Currently I have 11 entries in the jobqueue table (mythweb only shows 6). Three of these are failed commflag jobs that date back to 6/23. I am still getting new jobs queued. I don't know if there is an upper limit of jobs in this queue that causes further queuing to cease. If you wish, I will leave the queue alone and wait for more failed jobs to be entered to see what happens.

[Raymond Wagner]

There is no limit to the size of the jobqueue table. The only thing that prevents a job from being queued is if the same type of job is already running on that recording. The display in MythWeb is just passthrough from the backend. All errored and queued jobs should be listed, but completed jobs will only be shown for the past four hours.

I don't see anything in the code that would cause this, but I'll leave it open for now. Let me know if the behavior starts up again. If nothing else, it will be fixed automatically when the rewrite goes in.

[Ken Emerson <kenneth.emerson@…>]

OK. After reading your explanation, I may have to admit to causing the problem via mythweb. I would select a recording from the RECORDINGS page and tell it to queue a commflag job. Instead of waiting for it to return, I would use the browser's back button to select another recording. Somehow, this queued two jobs for each of two recordings which then confused the scheduler leaving the second job of each recording in the queue forever. When I deleted these and carefully added more jobs, some of which always failed, the scheduler worked correctly. I'd say you can close this ticket as fixed (and color me embarrassed).

[Ken Emerson <kenneth.emerson@…>]

Some additional (and more useful) information. I was wrong about the browser back button (or at least this isn't what caused the duplicate entries in the job queue). The problem is repeatable:

If you have an entry in the job queue for commflagging that has error'ed out and then go to that recording in the "Recorded Programs" web page and requeue a commflag job (for the same episode), a new entry is placed in the job queue. When the scheduler sees the new job, both the new entry and the error'ed out entry become active. When the commflag job completes, one of the active entries remains active (i.e. shows green and says 95% complete). This entry does not go away which could eventually (if enough of these happen) block new jobs from running.

Attaching contents of jobqueue.

[Ken Emerson <kenneth.emerson@…>]

Then entry of 6/24/2011 14:30 is currently running. The entry of 6/27/2011 14:30 is an orphan.

[stuartm]

If we required jobs to be added through the protocol and not added directly to the database we could ensure that the input was validated and not a duplicate of an existing entry.

[Raymond Wagner]

Replying to stuartm:

If we required jobs to be added through the protocol and not added directly to the database we could ensure that the input was validated and not a duplicate of an existing entry.

Unless someone else wants to fix it directly, I'll take this as part of #7990, since the above is one of the intended goals.

[Stuart Auchterlonie]

Moving unresolved tickets to next point release

[Stuart Auchterlonie]

Moving remaining open 0.28.1 tickets to 0.28.2

[Stuart Auchterlonie]

Closing any remaining tickets for 0.28, if the issue persists, feel free to reopen and align to v29 or master