The root run is not done yet (and I haven't tried the apache run yet) but looking at the interim output from root, I noticed something very interesting:


11955 open("/etc/passwd", O_RDONLY) = 3
11955 fcntl64(3, F_GETFD) = 0
11955 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
11955 fstat64(3, {st_mode=S_IFREG|0644, st_size=1797, ...}) = 0
11955 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f59000
11955 read(3, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1797
11955 close(3) = 0
11955 munmap(0xb7f59000, 4096) = 0
11955 open("/local/video/mythburn/temp/1056_20050407083000_20050407090000.nuv", O_RDONLY|O_LARGEFILE) = 3
11955 fstat64(3, {st_mode=S_IFREG|0644, st_size=1121472512, ...}) = 0
11955 open("/root/.dvdcss/CACHEDIR.TAG", O_RDWR|O_CREAT|O_LARGEFILE, 0644) = 4
11955 write(4, "Signature: 8a477f597d28d172789f0"..., 199) = 199
11955 close(4) = 0
11955 read(3, "\0\0\1\272D\0\4\0\4\1\1\211\303\370\0\0\1\273\0\22\200"..., 2048) = 2048
11955 _llseek(3, 0, [0], SEEK_SET) = 0
11955 _llseek(3, 524288, [524288], SEEK_SET) = 0
11955 read(3, "\0\0\1\272D\0\r\22LU\1\211\303\370\0\0\1\340\7\354\201"..., 2048) = 2048
11955 close(3) = 0


It looks like someone looks up the current user's homedir, and then tries to read/update some crib notes it stores in the $HOMEDIR/.dvdcss directory.

The apache user's homedir is /var/www...so I'll bet that is failing trying to open the non-existent /var/www/.dvdcss directory. I'll further guess that if it doesn't find that directory, it tries to create it. Guess what? /var/www is rwxr-xr-x and owned by root:root, so it is not writeable by apache. Can't read the directory...can't create the directory...can't write cribnotes there...boom.

I'm going to let the root execution of mythtvburn.sh complete, then I'll run it as apache, and let it fail so I have the hard data in the strace log to compare for sure. After that, I bet that if I create a /var/www/.dvdcss directory, and make it writeable by apache, it'll start working...

I'll further bet that different distros (I'm using FC4) have slightly different rules on the apache homedir, and that others are set up so that the apache user *can* write there, and those don't run into this problem. That would explain why only some users (only FC users?) seem to be running into this.

Stay tuned...I feel good about this one...

...or not.

It did create the /var/www/.dvdcss/CACHEDIR.TAG file...but I still get green thumbnails.

I did notice this sequence in the ptrace log:

apache:

25105 open("/local/video/mythburn/temp/1056_20050407083000_20050407090000.nuv", O_RDONLY|O_LARGEFILE) = 13
25105 _llseek(13, 0, [0], SEEK_CUR) = 0
25105 _llseek(13, 0, [0], SEEK_SET) = 0
25105 read(13, "\0\0\1\272", 4) = 4
25105 _llseek(13, 0, [0], SEEK_SET) = 0
25105 read(13, "\0\0\1\272", 4) = 4
25105 _llseek(13, 0, [0], SEEK_SET) = 0
25105 read(13, "\0\0\1\272", 4) = 4
25105 _llseek(13, 0, [0], SEEK_SET) = 0
25105 write(2, "[tcprobe] MPEG program stream (P"..., 35) = 35
25105 fcntl64(3, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
25105 fstat64(3, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
25105 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f11000
25105 _llseek(3, 0, 0xbfe10c3c, SEEK_CUR) = -1 ESPIPE (Illegal seek)
25105 read(3, 0x807bdc0, 262144) = -1 ENOTCONN (Transport endpoint is not connected)
25105 write(2, "att0=0, att1=0\n", 15) = 15


root:

12729 open("/local/video/mythburn/temp/1056_20050407083000_20050407090000.nuv", O_RDONLY|O_LARGEFILE) = 3
12729 _llseek(3, 0, [0], SEEK_CUR) = 0
12729 _llseek(3, 0, [0], SEEK_SET) = 0
12729 read(3, "\0\0\1\272", 4) = 4
12729 _llseek(3, 0, [0], SEEK_SET) = 0
12729 read(3, "\0\0\1\272", 4) = 4
12729 _llseek(3, 0, [0], SEEK_SET) = 0
12729 read(3, "\0\0\1\272", 4) = 4
12729 _llseek(3, 0, [0], SEEK_SET) = 0
12729 read(3, "\0\0\1\272", 4) = 4
12729 _llseek(3, 0, [0], SEEK_SET) = 0
12729 write(2, "[tcprobe] MPEG program stream (P"..., 35) = 35
12729 fcntl64(3, F_GETFL) = 0x8000 (flags O_RDONLY|O_LARGEFILE)
12729 fstat64(3, {st_mode=S_IFREG|0644, st_size=1121472512, ...}) = 0
12729 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f98000
12729 _llseek(3, 0, [0], SEEK_CUR) = 0
12729 read(3, "\0\0\1\272D\0\4\0\4\1\1\211\303\370\0\0\1\273\0\22\200"..., 262144) = 262144
12729 write(2, "SCR= 0 ( 0) unit=0 @"..., 57) = 57



In the apache sequence, it does an fopen of the video file...as filehandle 13, then goes on to query the size and seek...of filehandle 3, which fails. I'm not sure why it decided it was filehandle 3 in this case.

The root sequence does an fopen of the video file as filehandle 3, and then does the size query, which works, and seeks to end of filehandle 3, which works.


Puzzling...

What's interesting is that it happily opens on FD3 but uses 13 for the call to fcntl.

Now, what I know about *nix system calls ain't much. I'm just an academic bureaucrat these days. These may be stupid conjectures indeed. But I wonder if what we're seeing doesn't have to do with getting two descriptors back for a pipe, with no permission to write on the pipe. But even if fcntl needs write permissions to set flags, I don't understand why it then tries to read from 13. Or maybe it's a bug: if the flag-setting adventure fails, then the state of the thing is left bollixed.

Were you running that as the apache user with shell access, or actually from inside apache? Because if it's the latter, I again suspect that apache might not be too happy with things that try to open bidirectional pipes in out of the way places. Kinda says "excuse me, sir, but will you step aside while I overflow your buffers for some evil purpose".

Somehow it comes up with the right answer for the filetype, and then invokes the wrong filter on it.

12729 read(3, "\0\0\1\272", 4) = 4
12729 _llseek(3, 0, [0], SEEK_SET) = 0
12729 write(2, "[tcprobe] MPEG program stream (P"..., 35) = 35

The read sequence is getting 4 bytes, and then seeking back to the beginning of the file. The repeats are the different 'if' test clauses in transcode/import/fileinfo.c being triggered until one matches. The printed data is in octal, so that works out to 0x00 0x00 0x01 0xba in hex...which matches the TC_MAGIC_VOB value from transcode/import/magic.h, so that much makes sense. fileinfo() will return "MPEG program stream (PS)"

The next line is the printing of the return value of fileinfo, along with the tcprobe tag. That comes from import/tcprobe.c at line 322 or so. After that, the next function called is tcprobe_thread, which does the actual parsing of the input file based on the magic number passed in.

The fcntl call under tcprobe_thread is where things start going wrong. The correct parser does an open with O_RDONLY|O_LARGEFILE. The incorrect one uses O_RDONLY|O_NONBLOCK. The only reference to O_NONBLOCK I can find anywhere in the code is in the vnc input parser. Of course that makes no sense, since TC_MAGIC_VNC is completely different than TC_MAGIC_VOB.

HOWEVER...because it's trying to do the operation on filehandle 3, instead of 13, I can believe that it read some random trash (or read nothing leaving an uninitialized variable) that happened to match TC_MAGIC_VNC.

SO...the question becomes...how can the filehandle be right for the filetype() call, but wrong for the tcprobe_thread() call? I need to stare at the code some more...I gave it the once over and it looks like stream_magic gets used for filetype(), and istream.magic gets used for tcprobe_thread(), but it looked to me like istream.magic gets set from stream_magic anyway, so they should be the same. (looking at transcode/import/tcprobe.c)

To gather these traces, I instrumented tcprobe with the script wedge, then I ran the mythtvburn.sh script from a root console prompt. Then I saved the strace logfile off, and then invoked the identical mythtvburn.sh operation using the web interface. So...it was running under apache, not at an apache shell prompt.

Interesting point about apache and multiple descriptors...hafta think on that one for a while...

Did this ever get resolved? I have the same problem (green highlights), but I'm not as smart as you guys so I can't solve it myself. Running it on the command line as root works, but this seems to be a non-optimal solution. I guess I could just write a bash script to automate that...

Is this issue present in 0.19? I assume so, if it's a transcode issue and not a mythburn/tv issue.

Anyway, I appreciate you guys looking into this and posting your findings. If nothing else, I now know that I'm not the only one with this problem.

so i was able to reproduce the same symptoms -- including the strace which switches file descriptors.

after looking at the source I cam to the conclusion it looked a LOT like memory corruption or a bad build -- where one object saw a different .h describing info_t.

So I saw freshrpms had a transcode package in addition to atrpms. I installed that one instead. Now I get good thumbnails under apache, but the log has a HUGE number of (for each transcode call):



Note that from an xterm I DON'T get these.

So, there's still something not quite right, but I got rid of the green thumbnails.

David.

Good find. Interesting theory on the structure mis-interpretation...but why does the UID matter? (although I'm beginning to think it's not a different UID, it's the difference between running it under Apache, and running it from a shell)

I started to build transcode from scratch, then got sidetracked trying to find all of the co-requisites as well. Looks like it's time to do my own build after all.

my structure theory was wrong...

it turns out there is a bug in libxio in transcode, it abstracts the filedescriptors and returns it own internal file descriptor. So, if the open() call inside libxio doesn't return the same file descriptior number a later fdopen() call on the libxio handle will have unpredictable results.

To work around you can compile transcode --disable-xio (freshrpms appears to do that, but atrpms uses --enable-xio). Then the thumbnails come out correctly, but there are the broken pipe messages. I'm still debugging the broken pipe messages. Other than filling the logfile they seem to not hurt anything.

David.

Having same issues. Latest mythburn on 0.19 with latest versions of all required software. And I am nowhere as smart as the other people here. Hope someone figures it out and puts a solution here.

Thanks

well, i have a workaround for now.

1. build transcode-1.0.2 with --disable-xio (or use freshrpms .rpm).

This fixes the problem with libxio and fdopen() by not using libxio. I've reported the problem to transcode-devel -- its being looked at.

2. add -M 0 to the transcode line in extractthumbnail.sh

This avoids the broken pipe messages by saying don't try and sync audio to video (it is the synchronizing pipelines which "break"). Doesn't matter because we're just extracting .jpgs anyway -- the audio doesn't matter. I'm still not really sure why the broken pipes happen, but I got tired of working on it.

With those two things applied I get correct thumbnails without messy logfiles.

David.

Is the current CVS of MythBurn supposed to work with Myth 0.19 ? I keep getting projectX problems, looks a sif it is looking in the wrong directories for things....

>Is the current CVS of MythBurn supposed to work with Myth 0.19 ?
Yes, it works for me at least, just checked it out and installed.
It doesn't provide any feedback, view of the logfile, information as to whether it's busy or the opportunity to cancel in progress job however.
Still, I'm very happy to have it back ! Many thanks for the updates.

As the developer of http://www.mythdora.com/pointed out to me: if you use transcode-0.6.14 from FC3 repositories, everything works well too.

David.

Brilliant! Just tried that, and...it worked!!!



Thanks!!!

Grrr...spoke too soon. It worked fine for the 5 minute test recording that I've been using, but when I queued up four 30-minute shows...back to the green images again.

On to try the freshrpms transcode-1.0.2 RPM with the -M 0 switch...