Ticket #1532 (new defect)

Opened 6 months ago

Last modified 3 months ago

HTTP access: cannot seek AVI (video length : 0, "broken avi")

Reported by: thannoy Assigned to:
Priority: normal Milestone: Bugs paradize
Component: Network Version:
Severity: normal Keywords:
Cc: Platform(s): all
Difficulty: easy Work status: Not started

Description

( ticket related to http://forum.videolan.org/viewtopic.php?f=4&t=31645 )

While playing an avi file locally (mrl=/home/...video.avi) works just fine. But playing the same avi file through http make seeking not working.

Using VLC desktop frontend :

popup "AVI file is broken" message read video, zero length (like TV streaming..)

Using mozilla plugin :

read input.length is zero

You can try with http://streams.videolan.org/streams-videolan/reference/avi/shrekaraoke-DivX-AC3.avi

I have used vlc git-0.9 (20080319) and according to the forum post, this occurs also in 0.8.5

Attachments

avi_through_http.output.txt (26.0 kB) - added by thannoy on 03/20/08 12:01:52.
output given for "vlc -vvv http://streams.videolan.org/streams-videolan/reference/avi/shrekaraoke-DivX-AC3.avi"
vlc-0.8.6g.diff (1.9 kB) - added by docbill on 06/04/08 23:50:27.
Patch to fix this bug in the 0.8.6g version of vlc.
vlc-0.9.0-git.diff (1.9 kB) - added by docbill on 06/05/08 12:44:57.
patch for vlc-snapshot-20080602
vlc-http-seek.patch (11.8 kB) - added by docbill on 06/12/08 05:48:55.
patch to improve http seek performance - further optimized

Change History

03/20/08 12:01:52 changed by thannoy

  • attachment avi_through_http.output.txt added.

output given for "vlc -vvv http://streams.videolan.org/streams-videolan/reference/avi/shrekaraoke-DivX-AC3.avi"

(follow-up: ↓ 2 ) 03/20/08 12:15:38 changed by thannoy

maybe those infos are related with the problem, I don't know

r2080 | fenrir | 2002-07-10 00:18:23 +0200 (mer, 10 jui 2002) | 7 lines

plugins/avi/avi.c : now you can see avi over http (true interleaved file only), and seek is allowed (but with great unsynchronisation, and sometimes it fails). But in order to make it working, I have to limit the number of bytes I read at a time. It's strange since in previous version of vlc, I don't need to do that ... ( it segfaults in input_SplitBuffer but not always on the same frame )

r2779 | fenrir | 2002-11-16 23:25:07 +0100 (sam, 16 nov 2002) | 2 lines

(I can give diff for those commits if needed)

ticket:964

(in reply to: ↑ 1 ) 03/20/08 12:18:21 changed by thannoy

and maybe ticket:981

(follow-up: ↓ 5 ) 03/20/08 17:31:45 changed by courmisch

Using an HTTP proxy? What is the HTTP version provided by the server? What does the VLC http access plugin log says?

03/20/08 17:32:40 changed by courmisch

  • keywords changed from avi http seek to moreinfo.
  • summary changed from avi over http fail to seek (video length : 0, "broken avi") to HTTP access: cannot seek AVI (video length : 0, "broken avi").
  • milestone set to Bugs paradize.

(in reply to: ↑ 3 ) 03/20/08 18:06:50 changed by thannoy

Not sure I have understood all your request, feel free to reask :)

No HTTP proxy, directly connected to the internet or http://127.0.0.1/.

HTTP version is 1.1 : 

HTTP/1.1 206 Partial Content

GET /streams-videolan/reference/ts/BShi-aac3.2.1.ts HTTP/1.1

http access outputs (filtered "http" from -vvv output, let me know if it is not the good way to get it) : 

[00000329] main playlist debug: adding item `http://streams.videolan.org/streams-videolan/reference/avi/shrekaraoke-DivX-AC3.avi' ( http://streams.videolan.org/streams-videolan/reference/avi/shrekaraoke-DivX-AC3.avi )
[00000364] main input debug: `http://streams.videolan.org/streams-videolan/reference/avi/shrekaraoke-DivX-AC3.avi' gives access `http' demux `' path `streams.videolan.org/streams-videolan/reference/avi/shrekaraoke-DivX-AC3.avi'
[00000364] main input debug: creating demux: access='http' demux='' path='streams.videolan.org/streams-videolan/reference/avi/shrekaraoke-DivX-AC3.avi'
[00000365] main demuxer warning: no access_demux module matched "http"
[00000364] main input debug: creating access 'http' path='streams.videolan.org/streams-videolan/reference/avi/shrekaraoke-DivX-AC3.avi'
[00000366] access_http access debug: http: server='streams.videolan.org' port=80 file='/streams-videolan/reference/avi/shrekaraoke-DivX-AC3.avi
[00000366] access_http access debug: protocol 'HTTP' answer code 206
[00000366] access_http access debug: Server: Apache/2.2.6 (Unix) mod_ssl/2.2.6 OpenSSL/0.9.7l DAV/2
[00000366] access_http access debug: stream size=40966144
[00000366] access_http access debug: Content-Type: video/x-msvideo
[00000366] main access debug: using access2 module "access_http"
[00000364] main input debug: creating demux: access='http' demux='' path='streams.videolan.org/streams-videolan/reference/avi/shrekaraoke-DivX-AC3.avi'
[00000364] main input debug: `http://streams.videolan.org/streams-videolan/reference/avi/shrekaraoke-DivX-AC3.avi' successfully opened
[00000366] main access debug: removing module "access_http"

Replying to courmisch:

Using an HTTP proxy? What is the HTTP version provided by the server? What does the VLC http access plugin log says?

03/20/08 18:15:34 changed by courmisch

  • owner deleted.

No idea, cannot even see any error message there.

06/04/08 20:28:18 changed by docbill

  • severity changed from normal to critical.

It seems this problem is worse in the nightly build, as the error message never pops up, but instead vlc freezes... For that reason, I am upgrading the bug severity.

I've cut and pasted relevant output when reading from the HTTP stream:

[00000436] main access debug: connection succeeded (socket = 10) [00000436] access_http access debug: protocol 'HTTP' answer code 206 [00000436] access_http access debug: Server: Apache/2.2.3 (Debian) [00000436] access_http access debug: stream size=1536601840 [00000436] access_http access debug: Content-Type: video/x-msvideo [00000436] main access debug: using access module "access_http" [00000436] main access debug: TIMER module_Need() : 35.604 ms - Total 35.604 ms / 1 intvls (Avg 35.604 ms) [00000438] main stream debug: pre-buffering... [00000438] main stream debug: received first data for our buffer [00000438] main stream debug: pre-buffering done 591272 bytes in 0s - 5527 kbytes/s [00000434] main input debug: creating demux: access='http' demux= path='cisco1.local/Videos/0-9A-Z/0-9/6th%20Day,%20The/(2000)%20The%206th%20Day.avi' [00000439] main demux debug: looking for demux module: 57 candidates [00000438] avi stream debug: found Chunk fourcc:46464952 (RIFF) size:1536601832 pos:0 [00000438] avi stream debug: found LIST chunk: 'AVI ' [00000438] avi stream debug: <list 'AVI '> [00000438] avi stream debug: found Chunk fourcc:5453494c (LIST) size:586 pos:12 [00000438] avi stream debug: found LIST chunk: 'hdrl' [00000438] avi stream debug: <list 'hdrl'> [00000438] avi stream debug: found Chunk fourcc:68697661 (avih) size:56 pos:24 [00000438] avi stream debug: avih: streams:2 flags: HAS_INDEX IS_INTERLEAVED 720x304 [00000438] avi stream debug: found Chunk fourcc:5453494c (LIST) size:130 pos:88 [00000438] avi stream debug: found LIST chunk: 'strl' [00000438] avi stream debug: <list 'strl'> [00000438] avi stream debug: found Chunk fourcc:68727473 (strh) size:56 pos:100 [00000438] avi stream debug: strh: type:vids handler:0x78766964 samplesize:0 23.98fps [00000438] avi stream debug: found Chunk fourcc:66727473 (strf) size:40 pos:164 [00000438] avi stream debug: strf: video:DX50 720x304 planes:1 24bpp [00000438] avi stream debug: found Chunk fourcc:6e727473 (strn) size:6 pos:212 [00000438] avi stream debug: strn: stream name : Video [00000438] avi stream debug: </list 'strl'> [00000438] avi stream debug: found Chunk fourcc:5453494c (LIST) size:108 pos:226 [00000438] avi stream debug: found LIST chunk: 'strl' [00000438] avi stream debug: <list 'strl'> [00000438] avi stream debug: found Chunk fourcc:68727473 (strh) size:56 pos:238 [00000438] avi stream debug: strh: type:auds handler:0x00000000 samplesize:1 56000.00fps [00000438] avi stream debug: found Chunk fourcc:66727473 (strf) size:18 pos:302 [00000438] avi stream debug: strf: audio:0x2000 channels:5 48000Hz 0bits/sample 437kb/s [00000438] avi stream debug: found Chunk fourcc:6e727473 (strn) size:6 pos:328 [00000438] avi stream debug: strn: stream name : Audio [00000438] avi stream debug: </list 'strl'> [00000438] avi stream debug: found Chunk fourcc:5453494c (LIST) size:256 pos:342 [00000438] avi stream debug: found LIST chunk: 'odml' [00000438] avi stream debug: <list 'odml'> [00000438] avi stream debug: found Chunk fourcc:686c6d64 (dmlh) size:244 pos:354 [00000438] avi stream warning: unknown chunk (not loaded) [00000438] avi stream debug: </list 'odml'> [00000438] avi stream debug: </list 'hdrl'> [00000438] avi stream debug: found Chunk fourcc:4b4e554a (JUNK) size:1434 pos:606 [00000438] avi stream debug: found Chunk fourcc:5453494c (LIST) size:1530911344 pos:2048 [00000438] avi stream debug: skipping movi chunk [00000438] avi stream debug: </list 'AVI '> [00000438] avi stream debug: * LIST-root size:1536601840 pos:0 [00000438] avi stream debug: + RIFF-AVI size:1536601832 pos:0 [00000438] avi stream debug: | + LIST-hdrl size:586 pos:12 [00000438] avi stream debug: | | + avih size:56 pos:24 [00000438] avi stream debug: | | + LIST-strl size:130 pos:88 [00000438] avi stream debug: | | | + strh size:56 pos:100 [00000438] avi stream debug: | | | + strf size:40 pos:164 [00000438] avi stream debug: | | | + strn size:6 pos:212 [00000438] avi stream debug: | | + LIST-strl size:108 pos:226 [00000438] avi stream debug: | | | + strh size:56 pos:238 [00000438] avi stream debug: | | | + strf size:18 pos:302 [00000438] avi stream debug: | | | + strn size:6 pos:328 [00000438] avi stream debug: | | + LIST-odml size:256 pos:342 [00000438] avi stream debug: | | | + dmlh size:244 pos:354 [00000438] avi stream debug: | + JUNK size:1434 pos:606 [00000438] avi stream debug: | + LIST-movi size:1530911344 pos:2048 [00000439] avi demux debug: AVIH: 2 stream, flags HAS_INDEX IS_INTERLEAVED [00000439] avi demux debug: stream[0] rate:24000 scale:1001 samplesize:0 [00000439] avi demux debug: stream[0] video(DX50) 720x304 24bpp 23.976025fps [00000434] main input debug: selecting program id=0 [00000439] avi demux debug: stream[1] rate:56000 scale:1 samplesize:1 [00000439] avi demux debug: stream[1] audio(0x2000) 5 channels 48000Hz 0bits [00000439] avi demux warning: cannot find idx1 chunk, no index defined [00000439] avi demux warning: cannot find indx (misdetect/broken OpenDML file?) [00000439] avi demux warning: cannot find indx (misdetect/broken OpenDML file?) [00000439] avi demux debug: stream[0] created 0 index entries [00000439] avi demux debug: stream[1] created 0 index entries [00000439] avi demux warning: broken or missing index, 'seek' will be axproximative or will have strange behaviour [00000431] main interface debug: thread ended

For comparison, this is what happens with the same file, when reading from nfs:

00767] access_mmap access debug: opening file /share/Videos/0-9A-Z/0-9/6th Day, The/(2000) The 6th Day.avi [00000767] main access debug: using access module "access_mmap" [00000767] main access debug: TIMER module_Need() : 30.168 ms - Total 30.168 ms / 1 intvls (Avg 30.168 ms) [00000768] main stream debug: pre buffering [00000768] main stream debug: received first data for our buffer [00000768] main stream debug: prebuffering done 1048576 bytes in 0s - 7366906 kbytes/s [00000765] main input debug: creating demux: access= demux= path='/share/Videos/0-9A-Z/0-9/6th Day, The/(2000) The 6th Day.avi' [00000769] main demux debug: looking for demux module: 57 candidates [00000768] avi stream debug: found Chunk fourcc:46464952 (RIFF) size:1536601832 pos:0 [00000768] avi stream debug: found LIST chunk: 'AVI ' [00000768] avi stream debug: <list 'AVI '> [00000768] avi stream debug: found Chunk fourcc:5453494c (LIST) size:586 pos:12 [00000768] avi stream debug: found LIST chunk: 'hdrl' [00000768] avi stream debug: <list 'hdrl'> [00000768] avi stream debug: found Chunk fourcc:68697661 (avih) size:56 pos:24 [00000768] avi stream debug: avih: streams:2 flags: HAS_INDEX IS_INTERLEAVED 720x304 [00000768] avi stream debug: found Chunk fourcc:5453494c (LIST) size:130 pos:88 [00000768] avi stream debug: found LIST chunk: 'strl' [00000768] avi stream debug: <list 'strl'> [00000768] avi stream debug: found Chunk fourcc:68727473 (strh) size:56 pos:100 [00000768] avi stream debug: strh: type:vids handler:0x78766964 samplesize:0 23.98fps [00000768] avi stream debug: found Chunk fourcc:66727473 (strf) size:40 pos:164 [00000768] avi stream debug: strf: video:DX50 720x304 planes:1 24bpp [00000768] avi stream debug: found Chunk fourcc:6e727473 (strn) size:6 pos:212 [00000768] avi stream debug: strn: stream name : Video [00000768] avi stream debug: </list 'strl'> [00000768] avi stream debug: found Chunk fourcc:5453494c (LIST) size:108 pos:226 [00000768] avi stream debug: found LIST chunk: 'strl' [00000768] avi stream debug: <list 'strl'> [00000768] avi stream debug: found Chunk fourcc:68727473 (strh) size:56 pos:238 [00000768] avi stream debug: strh: type:auds handler:0x00000000 samplesize:1 56000.00fps [00000768] avi stream debug: found Chunk fourcc:66727473 (strf) size:18 pos:302 [00000768] avi stream debug: strf: audio:0x2000 channels:5 48000Hz 0bits/sample 437kb/s [00000768] avi stream debug: found Chunk fourcc:6e727473 (strn) size:6 pos:328 [00000768] avi stream debug: strn: stream name : Audio [00000768] avi stream debug: </list 'strl'> [00000768] avi stream debug: found Chunk fourcc:5453494c (LIST) size:256 pos:342 [00000768] avi stream debug: found LIST chunk: 'odml' [00000768] avi stream debug: <list 'odml'> [00000768] avi stream debug: found Chunk fourcc:686c6d64 (dmlh) size:244 pos:354 [00000768] avi stream warning: unknown chunk (not loaded) [00000768] avi stream debug: </list 'odml'> [00000768] avi stream debug: </list 'hdrl'> [00000768] avi stream debug: found Chunk fourcc:4b4e554a (JUNK) size:1434 pos:606 [00000768] avi stream debug: found Chunk fourcc:5453494c (LIST) size:1530911344 pos:2048 [00000768] avi stream debug: skipping movi chunk [00000768] main stream debug: b_seek=1 th*avg=1048576 skip=1529864824 [00000768] avi stream debug: found Chunk fourcc:31786469 (idx1) size:5688432 pos:1530913400 [00000767] access_mmap access debug: at end of memory mapped file [00000768] avi stream debug: idx1: index entry:355527 [00000768] avi stream debug: </list 'AVI '> [00000768] avi stream debug: * LIST-root size:1536601840 pos:0 [00000768] avi stream debug: + RIFF-AVI size:1536601832 pos:0 [00000768] avi stream debug: | + LIST-hdrl size:586 pos:12 [00000768] avi stream debug: | | + avih size:56 pos:24 [00000768] avi stream debug: | | + LIST-strl size:130 pos:88 [00000768] avi stream debug: | | | + strh size:56 pos:100 [00000768] avi stream debug: | | | + strf size:40 pos:164 [00000768] avi stream debug: | | | + strn size:6 pos:212 [00000768] avi stream debug: | | + LIST-strl size:108 pos:226 [00000768] avi stream debug: | | | + strh size:56 pos:238 [00000768] avi stream debug: | | | + strf size:18 pos:302 [00000768] avi stream debug: | | | + strn size:6 pos:328 [00000768] avi stream debug: | | + LIST-odml size:256 pos:342 [00000768] avi stream debug: | | | + dmlh size:244 pos:354 [00000768] avi stream debug: | + JUNK size:1434 pos:606 [00000768] avi stream debug: | + LIST-movi size:1530911344 pos:2048 [00000768] avi stream debug: | + idx1 size:5688432 pos:1530913400 [00000769] avi demux debug: AVIH: 2 stream, flags HAS_INDEX IS_INTERLEAVED [00000769] avi demux debug: stream[0] rate:24000 scale:1001 samplesize:0 [00000769] avi demux debug: stream[0] video(DX50) 720x304 24bpp 23.976025fps [00000765] main input debug: selecting program id=0 [00000769] avi demux debug: stream[1] rate:56000 scale:1 samplesize:1 [00000769] avi demux debug: stream[1] audio(0x2000) 5 channels 48000Hz 0bits [00000769] avi demux debug: stream[0] created 177768 index entries [00000769] avi demux debug: stream[1] created 177759 index entries [00000769] avi demux debug: stream[0] length:7414 (based on index) [00000769] avi demux debug: stream[1] length:7414 (based on index) [00000769] main demux debug: using demux module "avi" [00000769] main demux debug: TIMER module_Need() : 1052.014 ms - Total 1052.014 ms / 1 intvls (Avg 1052.014 ms) [00000765] main input debug: looking for a subtitle file in /share/Videos/0-9A-Z/0-9/6th Day, The/ [00000765] main input debug: autodetected subtitle: /share/Videos/0-9A-Z/0-9/6th Day, The/(2000) The 6th Day.idx with priority 4 [00000765] main input debug: autodetected subtitle: /share/Videos/0-9A-Z/0-9/6th Day, The/(2000) The 6th Day.sub with priority 4 [00000765] main input debug: /share/Videos/0-9A-Z/0-9/6th Day, The/(2000) The 6th Day.idx' gives access ' demux ' path /share/Videos/0-9A-Z/0-9/6th Day, The/(2000) The 6th Day.idx' [00000765] main input debug: creating access path='/share/Videos/0-9A-Z/0-9/6th Day, The/(2000) The 6th Day.idx' [00000770] main access debug: looking for access module: 9 candidates [00000770] vcd access debug: trying .cue file: /share/Videos/0-9A-Z/0-9/6th Day, The/(2000) The 6th Day.cue

06/04/08 23:50:27 changed by docbill

  • attachment vlc-0.8.6g.diff added.

Patch to fix this bug in the 0.8.6g version of vlc.

06/04/08 23:56:06 changed by docbill

  • difficulty changed from unknown to easy.

I just attached a patch for 0.8.6g. I suspect the same patch will work with the current code base, but I was afraid applying it would hide the error of vlc nightly build failing to play sources which are not fast seekable. (I also experienced rendering problems with the newer version of vlc.)

06/05/08 12:44:57 changed by docbill

  • attachment vlc-0.9.0-git.diff added.

patch for vlc-snapshot-20080602

06/05/08 12:50:52 changed by docbill

  • severity changed from critical to normal.

I opened a separate bug #1610 for the blocking problem that occurs in the 0.9.0, as that problem appears to be a separate problem. So this bug can be lowered back to normal severity.

Note: The patch also resolves #1610 for http connections, but probably not for other types of streams.

06/10/08 20:38:39 changed by docbill

BTW. How well this fix works varies by your network speed. In reality "FASTSEEK" should really be "FAST CONNECTION". If I use it to seek videos streamed over my local network, they work great. If I use it to seek in the example file provided in this bug across a slow internet connection, it works lousy. But really no worse than if I were to access the a movie on a remote NFS mount...

However, the fix always resolves the problem of the video being reported as corrupt.

I would suggest applying this fix, and as a future enhancement add a mechanism to determine the connection speed and throttle seeking, and other such options accordingly.

06/10/08 20:50:56 changed by courmisch

Well... files I/O is always non-blocking, even if the filesystem is remote. Your system is totally screwed if you mount a slow network share, as much as if you mount a dead local hard drive.

In principle, access plugins are free to return a "varying" result for FASTSEEK, so long as they don't turn it off by surprise during the lifetime of an instance (this would confuse downstream demultiplexers and streams). But there is not much way to know if the network is fast. HTTP is usually slow when it comes to seeking.

06/10/08 21:53:48 changed by docbill

Yes. The seeking could be done faster. The main problem is the http module requests all the data each time. In that case, it must close the connection and establish a new connection to perform the seek operation. Unfortunately, sometimes establishing a new connection can be a very slow operation. A better way to do it, is just to request a reasonable size of data block each time. That way when a seek operation is desired, the address for the next request's offset address can simply be adjusted. That actually equivalent to what happens when using SAMBA, NFS, or any other network file system.

That is actually the technique I apply in JavaDjVu?:

Encyclopedia Example

As you can see, it works very well.

If it is desirable, I can write a patch which does the same thing. It is not necessary for this bug, but it would be a nice enhancement.

06/12/08 00:41:50 changed by docbill

I just added vlc-http-seek.patch. This patch goes beyond the previous 0.9.0-git patch, in that it not only fixes the error, but it also improves seek performance.

The basic idea is it is faster to read a small amount of data than it is to close a connection and reopen for the sake of doing a seek. In theory if we read 32k size blocks, we would have equivalent performance to nfs. Only NFS will cache blocks, so for lots of little seeks, NFS still wins.

However, we can improve on seek performance by using an even smaller block size. This is at a cost of more overhead. To balance these two factors, I made the blocksize grow each consecutive read. So if you do many seeks with small data reads, all the reads are the minimum blocksize. If you do few seeks, with large data reads, then the blocksize keeps growing, so the overhead from doing multiple reads becomes insignificant.

There are three parameters to control this: HTTP_MIN_BLOCKSIZE HTTP_SEEK_BLOCKSIZE HTTP_MAX_BLOCKSIZE

I set MIN_BLOCKSIZE to 4096, because that is typically the size of one filesystem blocksize. I set the SEEK_BLOCKSIZE to 32k, because that is were I expect equivalent to NFS performance. I set MAX_BLOCKSIZE to a fairly large number, because if we are just reading data linearly, seek speed doesn't really matter.

06/12/08 01:10:38 changed by docbill

It occurred to me I can compare the number of remaining bytes in the current block with HTTP_SEEK_BLOCKSIZE for even better results.

06/12/08 05:48:55 changed by docbill

  • attachment vlc-http-seek.patch added.

patch to improve http seek performance - further optimized

06/15/08 12:18:32 changed by courmisch

  • keywords changed from moreinfo to unreproducible.

The sample URL seems to play fine with master, whether I click Repair or Don't repair.

06/16/08 16:01:21 changed by docbill

  • keywords deleted.

Please re-read the bug description. Nobody ever said the AVI does not play. Just that it is reported as needing repairing when it doesn't.

Bill

06/16/08 16:04:54 changed by docbill

BTW. The cause of the freeze referenced in my 06/04/08 comment is bug #1610. When I figured that out and opened it as a separate bug, I downgraded the severity of this bug back to the original value.