Fri May 24, 2013 10:12 am
Transcoding of vts_01_1.vob has some issues
Hi guys,
I've observed an quite annoying behavior when it comes to .vob file transcoding. Stangely, when I want to watch a movie from the beginning (so vob filename is vts_01_1.vob), I always receive an error from my iPhone playback software (I nned to transcode to lower bitrate and resolution as otherwise, 8player stutters during playback on my iPhone 4. Don't ask). As I played a little bit araound today and also changed the log level in log4j.xml to TRACE, I found the following output in my log files:
Got that behavior on multiple "first files" of a movie. The the question certainly was: Hey, same thing with all files of a movie? Well, that was not the case. It instantly played files vts_01_2.vob. vts_01_3.vob, etc. as you can see below:
So I continued playing. Looked like the issue was not reproducable that easily. Then I saw that on my NAS, the ffmpeg process was still running. Killed it and tried again with vts_01_1.vob... All good. Next try: Killed ffmpeg process again + emptied my transcoding folder and the was that issue again with vts_01_1.vob.
So as to my impression, Serviio has some difficulties trying to transcode vts_01_1.vob files if no previous transcoded file is present in the transcoding folder.
Happy if someone could test/verify as well.
@zip: Your view on this would be highly appreciated!
Some info on my specs:
Serviio is running on my QNAP 459 Pro+ NAS with latest ffmpeg compiled and I also have tons of free space for my transcoding folder
I've observed an quite annoying behavior when it comes to .vob file transcoding. Stangely, when I want to watch a movie from the beginning (so vob filename is vts_01_1.vob), I always receive an error from my iPhone playback software (I nned to transcode to lower bitrate and resolution as otherwise, 8player stutters during playback on my iPhone 4. Don't ask). As I played a little bit araound today and also changed the log level in log4j.xml to TRACE, I found the following output in my log files:
- Code:
2013-05-24 11:19:44,008 DEBUG [ServiioHttpService] Incoming request from /192.168.99.104:49200: GET /resource/1885/MEDIA_ITEM/MPEG_PS_PAL-0/ORIGINAL HTTP/1.1, headers = [User-Agent: Lavf54.29.104,Accept: */*,Range: bytes=0-,Connection: close,Host: 192.168.99.117:8895]]
2013-05-24 11:19:44,008 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.99.104
2013-05-24 11:19:44,008 TRACE [DBConnectionPool] Getting pooled connection from pool Serviio DB Pool
2013-05-24 11:19:44,009 TRACE [DBConnectionPool] Releasing connection from pool Serviio DB Pool
2013-05-24 11:19:44,009 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.99.104
2013-05-24 11:19:44,009 TRACE [DBConnectionPool] Getting pooled connection from pool Serviio DB Pool
2013-05-24 11:19:44,010 TRACE [DBConnectionPool] Releasing connection from pool Serviio DB Pool
2013-05-24 11:19:44,010 DEBUG [ResourceDeliveryProcessor] Resource request accepted. Using client 'Identifier=192.168.99.104, Profile=8player'
2013-05-24 11:19:44,010 DEBUG [ResourceDeliveryProcessor] Request for resource 1885 and type 'MEDIA_ITEM' received
2013-05-24 11:19:44,010 DEBUG [MediaResourceRetrievalStrategy] Getting information about media item 1885 (local)
2013-05-24 11:19:44,010 DEBUG [MediaItemDAOImpl] Reading a MediaItem (id = 1885)
2013-05-24 11:19:44,010 TRACE [DBConnectionPool] Getting pooled connection from pool Serviio DB Pool
2013-05-24 11:19:44,011 TRACE [DBConnectionPool] Releasing connection from pool Serviio DB Pool
2013-05-24 11:19:44,011 DEBUG [VideoDAOImpl] Reading a Video (id = 1885)
2013-05-24 11:19:44,011 TRACE [DBConnectionPool] Getting pooled connection from pool Serviio DB Pool
2013-05-24 11:19:44,012 TRACE [DBConnectionPool] Releasing connection from pool Serviio DB Pool
2013-05-24 11:19:44,012 DEBUG [VideoDeliveryEngine] Retrieving resource information for item 1885, format MPEG_PS_PAL and profile 8player
2013-05-24 11:19:44,012 DEBUG [AbstractTranscodingDeliveryEngine] Getting media info for transcoded version of file vts_01_10.vob
2013-05-24 11:19:44,012 DEBUG [VideoDeliveryEngine] Found Format profile for transcoded file vts_01_10.vob: MPEG_PS_PAL
2013-05-24 11:19:44,012 DEBUG [VideoDeliveryEngine] Found Format profile for transcoded file vts_01_10.vob: MPEG_PS_NTSC
2013-05-24 11:19:44,012 DEBUG [MediaResourceRetrievalStrategy] Getting information about media item 1885 (local)
2013-05-24 11:19:44,013 DEBUG [MediaItemDAOImpl] Reading a MediaItem (id = 1885)
2013-05-24 11:19:44,013 TRACE [DBConnectionPool] Getting pooled connection from pool Serviio DB Pool
2013-05-24 11:19:44,013 TRACE [DBConnectionPool] Releasing connection from pool Serviio DB Pool
2013-05-24 11:19:44,013 DEBUG [VideoDAOImpl] Reading a Video (id = 1885)
2013-05-24 11:19:44,013 TRACE [DBConnectionPool] Getting pooled connection from pool Serviio DB Pool
2013-05-24 11:19:44,014 TRACE [DBConnectionPool] Releasing connection from pool Serviio DB Pool
2013-05-24 11:19:44,014 DEBUG [VideoDeliveryEngine] Delivering item '1885' for client 'Identifier=192.168.99.104, Profile=8player'
2013-05-24 11:19:44,014 DEBUG [VideoDeliveryEngine] Delivering file 'vts_01_10.vob' using transcoding
2013-05-24 11:19:44,015 DEBUG [AbstractTranscodingDeliveryEngine] A suitable transcoding job already exists, re-use it for client 'Identifier=192.168.99.104, Profile=8player'
2013-05-24 11:19:44,015 ERROR [ResourceTransportRequestHandler] Error while processing resource, sending back 500 error. Message: Transcoded file '/share/MD0_DATA/.qpkg/Serviio/streaming/Serviio/transcoding-temp-1885-30-ORIGINAL.stf' cannot be found, FFmpeg execution probably failed
java.io.IOException: Transcoded file '/share/MD0_DATA/.qpkg/Serviio/streaming/Serviio/transcoding-temp-1885-30-ORIGINAL.stf' cannot be found, FFmpeg execution probably failed
at org.serviio.delivery.resource.transcode.FileBasedTranscodingDeliveryStrategy.createInputStream(FileBasedTranscodingDeliveryStrategy.java:45)
at org.serviio.delivery.resource.transcode.AbstractTranscodingDeliveryEngine.retrieveTranscodedResource(AbstractTranscodingDeliveryEngine.java:131)
at org.serviio.delivery.resource.AbstractDeliveryEngine.deliver(AbstractDeliveryEngine.java:108)
at org.serviio.delivery.MediaResourceRetrievalStrategy.retrieveResource(MediaResourceRetrievalStrategy.java:120)
at org.serviio.delivery.GETMethodProcessor.retrieveResource(GETMethodProcessor.java:120)
at org.serviio.delivery.GETMethodProcessor.buildDeliveryContainer(GETMethodProcessor.java:48)
at org.serviio.delivery.AbstractMethodProcessor.handleRequest(AbstractMethodProcessor.java:90)
at org.serviio.delivery.ResourceDeliveryProcessor.deliverContent(ResourceDeliveryProcessor.java:80)
at org.serviio.upnp.webserver.ResourceTransportRequestHandler.handleRequest(ResourceTransportRequestHandler.java:85)
at org.serviio.upnp.webserver.AbstractRequestHandler.handle(AbstractRequestHandler.java:61)
at org.apache.http.protocol.HttpService.doService(HttpService.java:293)
at org.serviio.upnp.webserver.ServiioHttpService.doService(ServiioHttpService.java:77)
at org.apache.http.protocol.HttpService.handleRequest(HttpService.java:212)
at org.serviio.upnp.webserver.WebServer$WorkerThread.run(WebServer.java:192)
2013-05-24 11:19:46,635 DEBUG [RendererDAOImpl] Retrieving list of all stored renderers
2013-05-24 11:19:46,635 TRACE [DBConnectionPool] Getting pooled connection from pool Serviio DB Pool
2013-05-24 11:19:46,636 TRACE [DBConnectionPool] Releasing connection from pool Serviio DB Pool
Got that behavior on multiple "first files" of a movie. The the question certainly was: Hey, same thing with all files of a movie? Well, that was not the case. It instantly played files vts_01_2.vob. vts_01_3.vob, etc. as you can see below:
- Code:
2013-05-24 11:20:42,957 DEBUG [ServiioHttpService] Incoming request from /192.168.99.104:49201: GET /resource/1881/MEDIA_ITEM/MPEG_PS_PAL-0/ORIGINAL HTTP/1.1, headers = [User-Agent: Lavf54.29.104,Accept: */*,Range: bytes=0-,Connection: close,Host: 192.168.99.117:8895]]
2013-05-24 11:20:42,958 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.99.104
2013-05-24 11:20:42,958 TRACE [DBConnectionPool] Getting pooled connection from pool Serviio DB Pool
2013-05-24 11:20:42,958 TRACE [DBConnectionPool] Releasing connection from pool Serviio DB Pool
2013-05-24 11:20:42,958 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.99.104
2013-05-24 11:20:42,958 TRACE [DBConnectionPool] Getting pooled connection from pool Serviio DB Pool
2013-05-24 11:20:42,959 TRACE [DBConnectionPool] Releasing connection from pool Serviio DB Pool
2013-05-24 11:20:42,959 DEBUG [ResourceDeliveryProcessor] Resource request accepted. Using client 'Identifier=192.168.99.104, Profile=8player'
2013-05-24 11:20:42,959 DEBUG [ResourceDeliveryProcessor] Request for resource 1881 and type 'MEDIA_ITEM' received
2013-05-24 11:20:42,960 DEBUG [MediaResourceRetrievalStrategy] Getting information about media item 1881 (local)
2013-05-24 11:20:42,960 DEBUG [MediaItemDAOImpl] Reading a MediaItem (id = 1881)
2013-05-24 11:20:42,960 TRACE [DBConnectionPool] Getting pooled connection from pool Serviio DB Pool
2013-05-24 11:20:42,960 TRACE [DBConnectionPool] Releasing connection from pool Serviio DB Pool
2013-05-24 11:20:42,960 DEBUG [VideoDAOImpl] Reading a Video (id = 1881)
2013-05-24 11:20:42,960 TRACE [DBConnectionPool] Getting pooled connection from pool Serviio DB Pool
2013-05-24 11:20:42,961 TRACE [DBConnectionPool] Releasing connection from pool Serviio DB Pool
2013-05-24 11:20:42,961 DEBUG [VideoDeliveryEngine] Retrieving resource information for item 1881, format MPEG_PS_PAL and profile 8player
2013-05-24 11:20:42,961 DEBUG [AbstractTranscodingDeliveryEngine] Getting media info for transcoded version of file vts_01_2.vob
2013-05-24 11:20:42,962 DEBUG [VideoDeliveryEngine] Found Format profile for transcoded file vts_01_2.vob: MPEG_PS_PAL
2013-05-24 11:20:42,962 DEBUG [VideoDeliveryEngine] Found Format profile for transcoded file vts_01_2.vob: MPEG_PS_NTSC
2013-05-24 11:20:42,962 DEBUG [MediaResourceRetrievalStrategy] Getting information about media item 1881 (local)
2013-05-24 11:20:42,962 DEBUG [MediaItemDAOImpl] Reading a MediaItem (id = 1881)
2013-05-24 11:20:42,962 TRACE [DBConnectionPool] Getting pooled connection from pool Serviio DB Pool
2013-05-24 11:20:42,963 TRACE [DBConnectionPool] Releasing connection from pool Serviio DB Pool
2013-05-24 11:20:42,963 DEBUG [VideoDAOImpl] Reading a Video (id = 1881)
2013-05-24 11:20:42,963 TRACE [DBConnectionPool] Getting pooled connection from pool Serviio DB Pool
2013-05-24 11:20:42,963 TRACE [DBConnectionPool] Releasing connection from pool Serviio DB Pool
2013-05-24 11:20:42,964 DEBUG [VideoDeliveryEngine] Delivering item '1881' for client 'Identifier=192.168.99.104, Profile=8player'
2013-05-24 11:20:42,964 DEBUG [VideoDeliveryEngine] Delivering file 'vts_01_2.vob' using transcoding
2013-05-24 11:20:42,964 DEBUG [AbstractTranscodingDeliveryEngine] No other client uses transcoding job of file 'transcoding-temp-1885-30-ORIGINAL.stf', will stop the job
2013-05-24 11:20:42,964 DEBUG [AbstractTranscodingDeliveryEngine] Stopping previous transcoding job of file 'transcoding-temp-1885-30-ORIGINAL.stf'
2013-05-24 11:20:42,964 DEBUG [TranscodingJobListener] Deleted temp file '/share/MD0_DATA/.qpkg/Serviio/streaming/Serviio/transcoding-temp-1885-30-ORIGINAL.stf': false
2013-05-24 11:20:42,964 DEBUG [AbstractTranscodingDeliveryEngine] No suitable transcoding job exists yet, start one for client 'Identifier=192.168.99.104, Profile=8player'
2013-05-24 11:20:42,965 DEBUG [MediaItemDAOImpl] Getting file of media item 1881
2013-05-24 11:20:42,965 TRACE [DBConnectionPool] Getting pooled connection from pool Serviio DB Pool
2013-05-24 11:20:42,965 TRACE [DBConnectionPool] Releasing connection from pool Serviio DB Pool
2013-05-24 11:20:42,965 DEBUG [FFMPEGWrapper] Invoking FFmpeg to transcode video file: /share/Multimedia/Hackers/vts_01_2.vob
2013-05-24 11:20:42,966 DEBUG [ProcessExecutor] Starting /share/MD0_DATA/.qpkg/Serviio/opt/bin/ffmpeg -threads 4 -i /share/Multimedia/Hackers/vts_01_2.vob -y -c:v mpeg2video -b:v 700k -maxrate:v 700k -bufsize:v 700k -vf scale=300:240 -r 25 -g 15 -c:a copy -map 0:0 -map 0:1 -sn -f vob /share/MD0_DATA/.qpkg/Serviio/streaming/Serviio/transcoding-temp-1881-30-ORIGINAL.stf
2013-05-24 11:20:43,541 TRACE [OutputTextReader] ffmpeg version N-53304-g2187600 Copyright (c) 2000-2013 the FFmpeg developers
2013-05-24 11:20:43,541 TRACE [OutputTextReader] built on May 20 2013 18:06:15 with gcc 4.2.1 (GCC)
2013-05-24 11:20:43,541 TRACE [OutputTextReader] configuration: --prefix=/share/MD0_DATA/.qpkg/Serviio/opt --libdir=/share/MD0_DATA/.qpkg/Serviio/opt/lib --disable-shared --enable-static --disable-ffserver --disable-ffplay --enable-libmp3lame --enable-libfaac --enable-libfreetype --enable-libtheora --enable-libvorbis --enable-libvpx --enable-libx264 --enable-libxvid --enable-librtmp --enable-libass --enable-gpl --enable-nonfree --extra-cflags=-I/opt/include --extra-ldflags=-L/opt/lib
2013-05-24 11:20:43,541 TRACE [OutputTextReader] libavutil 52. 33.100 / 52. 33.100
2013-05-24 11:20:43,541 TRACE [OutputTextReader] libavcodec 55. 10.101 / 55. 10.101
2013-05-24 11:20:43,541 TRACE [OutputTextReader] libavformat 55. 7.100 / 55. 7.100
2013-05-24 11:20:43,541 TRACE [OutputTextReader] libavdevice 55. 1.100 / 55. 1.100
2013-05-24 11:20:43,541 TRACE [OutputTextReader] libavfilter 3. 68.101 / 3. 68.101
2013-05-24 11:20:43,541 TRACE [OutputTextReader] libswscale 2. 3.100 / 2. 3.100
2013-05-24 11:20:43,541 TRACE [OutputTextReader] libswresample 0. 17.102 / 0. 17.102
2013-05-24 11:20:43,541 TRACE [OutputTextReader] libpostproc 52. 3.100 / 52. 3.100
2013-05-24 11:20:43,710 TRACE [OutputTextReader] [mpeg2video @ 0x910e880] Invalid frame dimensions 0x0.
2013-05-24 11:20:43,965 TRACE [OutputTextReader] Last message repeated 8 times
2013-05-24 11:20:43,965 TRACE [OutputTextReader] [mpeg @ 0x910df60] max_analyze_duration 5000000 reached at 5024000 microseconds
2013-05-24 11:20:44,002 TRACE [OutputTextReader] Input #0, mpeg, from '/share/Multimedia/Hackers/vts_01_2.vob':
2013-05-24 11:20:44,002 TRACE [OutputTextReader] Duration: 26:29:39.63, start: 142.059378, bitrate: 90 kb/s
2013-05-24 11:20:44,002 TRACE [OutputTextReader] Stream #0:0[0x1e0]: Video: mpeg2video (Main), yuv420p, 720x576 [SAR 16:15 DAR 4:3], 25 fps, 25 tbr, 90k tbn, 50 tbc
2013-05-24 11:20:44,002 TRACE [OutputTextReader] Stream #0:1[0x83]: Audio: ac3, 48000 Hz, 5.1(side), fltp, 384 kb/s
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:2[0x84]: Audio: ac3, 48000 Hz, 5.1(side), fltp, 384 kb/s
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:3[0x80]: Audio: ac3, 48000 Hz, 5.1(side), fltp, 384 kb/s
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:4[0x81]: Audio: ac3, 48000 Hz, 5.1(side), fltp, 384 kb/s
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:5[0x82]: Audio: ac3, 48000 Hz, 5.1(side), fltp, 384 kb/s
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:6[0x1bf]: Data: dvd_nav_packet
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:7[0x20]: Subtitle: dvd_subtitle
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:8[0x21]: Subtitle: dvd_subtitle
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:9[0x22]: Subtitle: dvd_subtitle
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:10[0x23]: Subtitle: dvd_subtitle
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:11[0x24]: Subtitle: dvd_subtitle
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:12[0x25]: Subtitle: dvd_subtitle
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:13[0x26]: Subtitle: dvd_subtitle
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:14[0x2c]: Subtitle: dvd_subtitle
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:15[0x2d]: Subtitle: dvd_subtitle
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:16[0x2b]: Subtitle: dvd_subtitle
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:17[0x27]: Subtitle: dvd_subtitle
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:18[0x28]: Subtitle: dvd_subtitle
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:19[0x29]: Subtitle: dvd_subtitle
2013-05-24 11:20:44,003 TRACE [OutputTextReader] Stream #0:20[0x2a]: Subtitle: dvd_subtitle
2013-05-24 11:20:44,021 TRACE [OutputTextReader] [mpeg2video @ 0x9114300] impossible bitrate constraints, this will fail
2013-05-24 11:20:44,023 TRACE [OutputTextReader] Output #0, vob, to '/share/MD0_DATA/.qpkg/Serviio/streaming/Serviio/transcoding-temp-1881-30-ORIGINAL.stf':
2013-05-24 11:20:44,024 TRACE [OutputTextReader] Metadata:
2013-05-24 11:20:44,024 TRACE [OutputTextReader] encoder : Lavf55.7.100
2013-05-24 11:20:44,024 TRACE [OutputTextReader] Stream #0:0: Video: mpeg2video, yuv420p, 300x240 [SAR 16:15 DAR 4:3], q=2-31, 700 kb/s, 90k tbn, 25 tbc
2013-05-24 11:20:44,024 TRACE [OutputTextReader] Stream #0:1: Audio: ac3, 48000 Hz, 5.1(side), 384 kb/s
2013-05-24 11:20:44,024 TRACE [OutputTextReader] Stream mapping:
2013-05-24 11:20:44,024 TRACE [OutputTextReader] Stream #0:0 -> #0:0 (mpeg2video -> mpeg2video)
2013-05-24 11:20:44,024 TRACE [OutputTextReader] Stream #0:1 -> #0:1 (copy)
2013-05-24 11:20:44,024 TRACE [OutputTextReader] Press [q] to stop, [?] for help
2013-05-24 11:20:44,128 TRACE [OutputTextReader] [vob @ 0x9560ac0] buffer underflow i=1 bufi=1238 size=1536
2013-05-24 11:20:44,148 TRACE [OutputTextReader] Last message repeated 4 times
2013-05-24 11:20:44,148 TRACE [OutputTextReader] [vob @ 0x9560ac0] buffer underflow i=1 bufi=181 size=1536
2013-05-24 11:20:44,467 DEBUG [FileBasedTranscodingDeliveryStrategy] Sending transcoding stream
2013-05-24 11:20:44,467 DEBUG [VideoDeliveryEngine] Found Format profile for transcoded file vts_01_2.vob: MPEG_PS_PAL
2013-05-24 11:20:44,467 DEBUG [VideoDeliveryEngine] Found Format profile for transcoded file vts_01_2.vob: MPEG_PS_NTSC
So I continued playing. Looked like the issue was not reproducable that easily. Then I saw that on my NAS, the ffmpeg process was still running. Killed it and tried again with vts_01_1.vob... All good. Next try: Killed ffmpeg process again + emptied my transcoding folder and the was that issue again with vts_01_1.vob.
So as to my impression, Serviio has some difficulties trying to transcode vts_01_1.vob files if no previous transcoded file is present in the transcoding folder.
Happy if someone could test/verify as well.
@zip: Your view on this would be highly appreciated!
Some info on my specs:
Serviio is running on my QNAP 459 Pro+ NAS with latest ffmpeg compiled and I also have tons of free space for my transcoding folder
