Strange issue with PBSKids plugin

[xs2inattar]

So, i wrote the plugin for PBSKids: viewtopic.php?f=20&t=7106

It seems to be workign fine. But for some clips the video would just end abruptly and i cant figure out why.

Below is log.

  Code:

2012-08-17 18:24:25,241 DEBUG [VideoDeliveryEngine] Delivering item '1000000001440001' for client 'IPAddress=/192.168.1.3, Profile=Generic DLNA profile'
2012-08-17 18:24:25,241 DEBUG [VideoDeliveryEngine] Delivering file 'rtmp://s3h56pp78s3goi.cloudfront.net/cfx/st/ playpath=mp4:PBS_CP_Curious_George/CUGE314_EpisodeB_web4x3.mp4?player=PreKplayer&mediaID=2223987701' using transcoding
2012-08-17 18:24:25,241 DEBUG [AbstractTranscodingDeliveryEngine] No suitable transcoding job exists yet, start one for client 'IPAddress=/192.168.1.3, Profile=Generic DLNA profile'
2012-08-17 18:24:25,242 DEBUG [FFMPEGWrapper] Invoking FFmpeg to transcode video file: rtmp://s3h56pp78s3goi.cloudfront.net/cfx/st/ playpath=mp4:PBS_CP_Curious_George/CUGE314_EpisodeB_web4x3.mp4?player=PreKplayer&mediaID=2223987701
2012-08-17 18:24:25,242 DEBUG [ProcessExecutor] Starting /volume1/@appstore/Serviio/bin/ffmpeg -fflags +genpts -i rtmp://s3h56pp78s3goi.cloudfront.net/cfx/st/ playpath=mp4:PBS_CP_Curious_George/CUGE314_EpisodeB_web4x3.mp4?player=PreKplayer&mediaID=2223987701 -y -copyts -c:v copy -vbsf h264_mp4toannexb -c:a ac3_fixed -b:a 384k -ac 2 -map 0:0 -map 0:1 -sn -f mpegts pipe:
2012-08-17 18:24:25,586 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth0 (eth0) and address 192.168.1.11, timeout = 0
2012-08-17 18:24:25,587 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 61cd396e-1894-3da9-91a2-e8090bcf4e54
2012-08-17 18:24:26,255 DEBUG [VideoDeliveryEngine] Found Format profile for transcoded file rtmp://s3h56pp78s3goi.cloudfront.net/cfx/st/ playpath=mp4:PBS_CP_Curious_George/CUGE314_EpisodeB_web4x3.mp4?player=PreKplayer&mediaID=2223987701: AVC_TS_MP_SD_AC3_ISO
2012-08-17 18:24:26,256 DEBUG [ResourceDeliveryProcessor] Stream entity has length: 50000000000
2012-08-17 18:24:26,256 DEBUG [ResourceDeliveryProcessor] Sending file back
2012-08-17 18:24:26,256 DEBUG [ResourceTransportRequestHandler] Creating entity with chunked transfer
2012-08-17 18:24:26,256 DEBUG [ResourceTransportRequestHandler] HTTP/1.1 200 OK, headers = [[Content-Type: video/mpeg,Date: Fri, 17 Aug 2012 22:24:26 GMT,Server: Linux, UPnP/1.0 DLNADOC/1.50, Serviio/1.0.1,Cache-control: no-cache,transferMode.dlna.org: Streaming]]
2012-08-17 18:24:27,565 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:00:45
2012-08-17 18:24:54,998 DEBUG [DiscoverySSDPMessageListener] Received a valid M-SEARCH message for search target upnp:rootdevice from address /192.168.1.3:2741
2012-08-17 18:24:54,998 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.3
2012-08-17 18:24:55,000 DEBUG [DiscoverySearchResponder] Sending 1 M-SEARCH response message(s) to /192.168.1.3:2741
2012-08-17 18:24:55,000 DEBUG [DiscoverySSDPMessageListener] Received a valid M-SEARCH message for search target upnp:rootdevice from address /192.168.1.3:2741
2012-08-17 18:24:55,001 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.3
2012-08-17 18:24:55,002 DEBUG [DiscoverySearchResponder] Sending 1 M-SEARCH response message(s) to /192.168.1.3:2741
2012-08-17 18:25:11,387 DEBUG [WebServer] I/O error: Connection reset
2012-08-17 18:25:13,006 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth0 (eth0) and address 192.168.1.11, timeout = 0
2012-08-17 18:25:13,007 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 61cd396e-1894-3da9-91a2-e8090bcf4e54
2012-08-17 18:25:14,985 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:00:46
2012-08-17 18:25:16,615 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-08-17 18:25:16,615 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-08-17 18:25:16,619 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 143)
2012-08-17 18:25:16,620 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 144)
2012-08-17 18:25:16,642 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 145)
2012-08-17 18:25:42,668 DEBUG [WebServer] Incoming connection from /192.168.1.3:29047
2012-08-17 18:25:42,668 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.3
2012-08-17 18:25:42,670 DEBUG [ResourceTransportRequestHandler] GET /resource/1000000001440001/MEDIA_ITEM/AVC_TS_MP_SD_AC3_ISO-0/ORIGINAL HTTP/1.1, headers = [Range: bytes=12285380-,User-Agent: XBMC/11.0 Git:20120321-14feb09 (Windows NT 6.1; http://www.xbmc.org),Host: 192.168.1.11:8895,Accept: */*,Connection: keep-alive]]
2012-08-17 18:25:42,670 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.3
2012-08-17 18:25:42,671 DEBUG [ResourceDeliveryProcessor] Resource request accepted. Using client 'IPAddress=/192.168.1.3, Profile=Generic DLNA profile'
2012-08-17 18:25:42,672 DEBUG [ResourceDeliveryProcessor] Request for resource 1000000001440001 and type 'MEDIA_ITEM' received
2012-08-17 18:25:42,672 DEBUG [MediaResourceRetrievalStrategy] Getting information about media item 1000000001440001 (online)
2012-08-17 18:25:42,672 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 144)
2012-08-17 18:25:42,673 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 144)
2012-08-17 18:25:42,675 DEBUG [VideoDeliveryEngine] Delivering item '1000000001440001' for client 'IPAddress=/192.168.1.3, Profile=Generic DLNA profile'
2012-08-17 18:25:42,675 DEBUG [VideoDeliveryEngine] Delivering file 'rtmp://s3h56pp78s3goi.cloudfront.net/cfx/st/ playpath=mp4:PBS_CP_Curious_George/CUGE314_EpisodeB_web4x3.mp4?player=PreKplayer&mediaID=2223987701' using transcoding
2012-08-17 18:25:42,676 DEBUG [AbstractTranscodingDeliveryEngine] A suitable transcoding job already exists, re-use it for client 'IPAddress=/192.168.1.3, Profile=Generic DLNA profile'
2012-08-17 18:25:43,685 DEBUG [StreamBasedTranscodingDeliveryStrategy] Transcoded stream is empty, connection may have been lost
2012-08-17 18:25:43,685 DEBUG [VideoDeliveryEngine] Found Format profile for transcoded file rtmp://s3h56pp78s3goi.cloudfront.net/cfx/st/ playpath=mp4:PBS_CP_Curious_George/CUGE314_EpisodeB_web4x3.mp4?player=PreKplayer&mediaID=2223987701: AVC_TS_MP_SD_AC3_ISO
2012-08-17 18:25:43,686 DEBUG [ResourceDeliveryProcessor] Stream entity has length: 50000000000
2012-08-17 18:25:43,686 DEBUG [ResourceDeliveryProcessor] Sending file back
2012-08-17 18:25:43,686 DEBUG [ResourceTransportRequestHandler] Creating entity with chunked transfer
2012-08-17 18:25:43,686 DEBUG [ResourceTransportRequestHandler] HTTP/1.1 200 OK, headers = [[Content-Type: video/mpeg,Date: Fri, 17 Aug 2012 22:25:43 GMT,Server: Linux, UPnP/1.0 DLNADOC/1.50, Serviio/1.0.1,Cache-control: no-cache,transferMode.dlna.org: Streaming]]
2012-08-17 18:25:43,972 DEBUG [WebServer] I/O error: Broken pipe
2012-08-17 18:25:43,972 DEBUG [NonClosingPipedInputStream] Scheduling stream stop to happen in 20 seconds if there is no traffic
2012-08-17 18:25:44,079 DEBUG [WebServer] I/O error: Broken pipe
2012-08-17 18:25:44,079 DEBUG [NonClosingPipedInputStream] Scheduling stream stop to happen in 20 seconds if there is no traffic
2012-08-17 18:25:49,589 DEBUG [DiscoverySSDPMessageListener] Received a valid M-SEARCH message for search target upnp:rootdevice from address /192.168.1.3:2741
2012-08-17 18:25:49,589 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.3
2012-08-17 18:25:49,591 DEBUG [DiscoverySearchResponder] Sending 1 M-SEARCH response message(s) to /192.168.1.3:2741
2012-08-17 18:25:49,592 DEBUG [DiscoverySSDPMessageListener] Received a valid M-SEARCH message for search target upnp:rootdevice from address /192.168.1.3:2741
2012-08-17 18:25:49,592 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.3
2012-08-17 18:25:49,594 DEBUG [DiscoverySearchResponder] Sending 1 M-SEARCH response message(s) to /192.168.1.3:2741
2012-08-17 18:26:01,416 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth0 (eth0) and address 192.168.1.11, timeout = 0
2012-08-17 18:26:01,416 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 61cd396e-1894-3da9-91a2-e8090bcf4e54
2012-08-17 18:26:03,395 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:00:52
2012-08-17 18:26:04,085 DEBUG [NonClosingPipedInputStream] Closing piped input stream and closing related feeder process
2012-08-17 18:26:04,085 DEBUG [ProcessExecutor] Stopping external process: Thread[Thread-1012,5,main]
2012-08-17 18:26:04,085 DEBUG [ProcessUtils] Sending kill -9 to the Unix process: 19421
2012-08-17 18:26:04,086 DEBUG [ProcessExecutor] Starting kill -9 19421
2012-08-17 18:26:04,094 WARN  [ProcessExecutor] Process /volume1/@appstore/Serviio/bin/ffmpeg has a return code of 137! This is a possible error.
2012-08-17 18:26:04,094 DEBUG [TranscodingJobListener] Transcoding finished; successful: false
2012-08-17 18:26:04,095 DEBUG [TranscodingJobListener] Transcoding finished; successful: true
2012-08-17 18:26:16,615 DEBUG [WebServer] Incoming connection from /192.168.1.3:29067
2012-08-17 18:26:16,616 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.3
2012-08-17 18:26:16,617 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#Browse"' from 192.168.1.3:
2012-08-17 18:26:16,617 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.3
2012-08-17 18:26:16,654 DEBUG [ContentDirectory] Browse() called for renderer Windows Media Player (profile 1) with parameters: objectID = V_OF^FOL_FD144, browseFlag = BrowseDirectChildren, filter = *, startIndex = 0, count = 30, sortCriteria =
2012-08-17 18:26:16,654 DEBUG [AccessGroupDAOImpl] Reading a AccessGroup (id = 1)
2012-08-17 18:26:16,676 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 144)
2012-08-17 18:26:16,678 DEBUG [VideoDeliveryEngine] Retrieving resource information for item 1000000001440001 and profile Generic DLNA profile
2012-08-17 18:26:16,678 DEBUG [VideoDeliveryEngine] Found Format profile for transcoded file rtmp://s3h56pp78s3goi.cloudfront.net/cfx/st/ playpath=mp4:PBS_CP_Curious_George/CUGE314_EpisodeB_web4x3.mp4?player=PreKplayer&mediaID=2223987701: AVC_TS_MP_SD_AC3_ISO
2012-08-17 18:26:16,680 DEBUG [VideoDeliveryEngine] Retrieving resource information for item 1000000001440002 and profile Generic DLNA profile
2012-08-17 18:26:16,680 DEBUG [VideoDeliveryEngine] Found Format profile for transcoded file rtmp://s3h56pp78s3goi.cloudfront.net/cfx/st/ playpath=mp4:PBS_CP_Curious_George/CUGE608_3_web16x9.mp4?player=PreKplayer&mediaID=2249082559: AVC_TS_MP_SD_AC3_ISO
2012-08-17 18:26:16,761 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 144)
2012-08-17 18:26:17,083 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2012-08-17 18:26:17,635 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-08-17 18:26:17,635 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-08-17 18:26:17,649 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 143)
2012-08-17 18:26:17,650 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 144)
2012-08-17 18:26:17,683 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 145)
2012-08-17 18:26:44,407 DEBUG [DiscoverySSDPMessageListener] Received a valid M-SEARCH message for search target upnp:rootdevice from address /192.168.1.3:2741
2012-08-17 18:26:44,408 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.3
2012-08-17 18:26:44,409 DEBUG [DiscoverySearchResponder] Sending 1 M-SEARCH response message(s) to /192.168.1.3:2741
2012-08-17 18:26:44,410 DEBUG [DiscoverySSDPMessageListener] Received a valid M-SEARCH message for search target upnp:rootdevice from address /192.168.1.3:2741
2012-08-17 18:26:44,410 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.3
2012-08-17 18:26:44,412 DEBUG [DiscoverySearchResponder] Sending 1 M-SEARCH response message(s) to /192.168.1.3:2741
2012-08-17 18:26:55,936 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth0 (eth0) and address 192.168.1.11, timeout = 0
2012-08-17 18:26:55,937 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 61cd396e-1894-3da9-91a2-e8090bcf4e54
2012-08-17 18:26:57,915 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:00:43



This abrupt end of the video happens at exactly the same time. for e.g. for one video it always occured between 1:48 to 1:51 in the video.

In my opinion the problem seems to be the following line from the above log.

  Code:

...
2012-08-17 18:25:43,972 DEBUG [NonClosingPipedInputStream] Scheduling stream stop to happen in 20 seconds if there is no traffic
2012-08-17 18:25:44,079 DEBUG [WebServer] I/O error: Broken pipe
2012-08-17 18:25:44,079 DEBUG [NonClosingPipedInputStream] Scheduling stream stop to happen in 20 seconds if there is no traffic
...
2012-08-17 18:26:04,085 DEBUG [NonClosingPipedInputStream] Closing piped input stream and closing related feeder process
2012-08-17 18:26:04,085 DEBUG [ProcessExecutor] Stopping external process: Thread[Thread-1012,5,main]
2012-08-17 18:26:04,085 DEBUG [ProcessUtils] Sending kill -9 to the Unix process: 19421
2012-08-17 18:26:04,086 DEBUG [ProcessExecutor] Starting kill -9 19421
2012-08-17 18:26:04,094 WARN  [ProcessExecutor] Process /volume1/@appstore/Serviio/bin/ffmpeg has a return code of 137! This is a possible error.
2012-08-17 18:26:04,094 DEBUG [TranscodingJobListener] Transcoding finished; successful: false
2012-08-17 18:26:04,095 DEBUG [TranscodingJobListener] Transcoding finished; successful: true
...


No idea why it keeps killing the ffmpeg process when the video is still running.

[zip]

is that a live stream? Looks like it, it checks if there is no read for 20 seconds it kills the live stream.

[xs2inattar]

These are short online clips ranging from 2 - 12 mins.

So based on your comment since this is not a livestream and just a short clip, i removed live=true from the content item. But after doing that the stream does not even start.

Logs and ffmpeg results are as follows.

CLIP-1
Log:

  Code:

2012-08-18 09:54:43,462 DEBUG [VideoDeliveryEngine] Delivering item '1000000001440001' for client 'IPAddress=/192.168.1.3, Profile=Generic DLNA profile'
2012-08-18 09:54:43,462 DEBUG [VideoDeliveryEngine] Delivering file 'rtmp://s3h56pp78s3goi.cloudfront.net/cfx/st/ playpath=mp4:PBS_CP_Curious_George/CUGE314_EpisodeB_web4x3.mp4?player=PreKplayer&mediaID=2223987701' using transcoding
2012-08-18 09:54:43,463 DEBUG [AbstractTranscodingDeliveryEngine] No suitable transcoding job exists yet, start one for client 'IPAddress=/192.168.1.3, Profile=Generic DLNA profile'
2012-08-18 09:54:43,463 DEBUG [VideoDeliveryEngine] Extracting new URL for the expired feed item
2012-08-18 09:54:43,463 DEBUG [FeedItemUrlExtractor] pbskids.org: Starting extraction of url for item: Something New Under the Sun
2012-08-18 09:54:43,654 DEBUG [FeedItemUrlExtractor] pbskids.org: Finished extraction of url: ContentURLContainer [fileType=VIDEO, contentUrl=rtmp://s3h56pp78s3goi.cloudfront.net/cfx/st/ playpath=mp4:PBS_CP_Curious_George/CUGE314_EpisodeB_web4x3.mp4?player=PreKplayer&mediaID=2223987701, thumbnailUrl=http://www-tc.pbs.org/cove-media/http/PBS_CP_Curious_George/73/983/CUGE314_EpisodeB_web4x3_69x53_2223993445.jpg, expiresImmediately=true, cacheKey=PBSKids_XlFVm6a07q1rJBjRiL6UImmRuYr2v2Ny, live=false, ]
2012-08-18 09:54:43,654 DEBUG [VideoDeliveryEngine] Successfully set new URL for the feed item
2012-08-18 09:54:43,655 DEBUG [FFMPEGWrapper] Invoking FFmpeg to transcode video file: rtmp://s3h56pp78s3goi.cloudfront.net/cfx/st/ playpath=mp4:PBS_CP_Curious_George/CUGE314_EpisodeB_web4x3.mp4?player=PreKplayer&mediaID=2223987701 buffer=100000000
2012-08-18 09:54:43,656 DEBUG [ProcessExecutor] Starting /volume1/@appstore/Serviio/bin/ffmpeg -fflags +genpts -i rtmp://s3h56pp78s3goi.cloudfront.net/cfx/st/ playpath=mp4:PBS_CP_Curious_George/CUGE314_EpisodeB_web4x3.mp4?player=PreKplayer&mediaID=2223987701 buffer=100000000 -y -copyts -c:v copy -vbsf h264_mp4toannexb -c:a ac3_fixed -b:a 384k -ac 2 -map 0:0 -map 0:1 -sn -f mpegts /.tmp/Serviio/transcoding-temp-1000000001440001-1-ORIGINAL.stf
2012-08-18 09:54:45,027 WARN  [ProcessExecutor] Process /volume1/@appstore/Serviio/bin/ffmpeg has a return code of 1! This is a possible error.
2012-08-18 09:54:45,027 DEBUG [TranscodingJobListener] Transcoding finished; successful: false
2012-08-18 09:54:45,294 ERROR [ResourceTransportRequestHandler] Error while processing resource, sending back 500 error. Message: FFmpeg execution failed
java.io.IOException: FFmpeg execution failed
   at org.serviio.delivery.resource.transcode.FileBasedTranscodingDeliveryStrategy.createInputStream(FileBasedTranscodingDeliveryStrategy.java:47)
   at org.serviio.delivery.resource.transcode.AbstractTranscodingDeliveryEngine.retrieveTranscodedResource(AbstractTranscodingDeliveryEngine.java:125)
   at org.serviio.delivery.resource.AbstractDeliveryEngine.deliver(AbstractDeliveryEngine.java:95)
   at org.serviio.delivery.MediaResourceRetrievalStrategy.retrieveResource(MediaResourceRetrievalStrategy.java:120)
   at org.serviio.delivery.ResourceDeliveryProcessor.deliverContent(ResourceDeliveryProcessor.java:84)
   at org.serviio.upnp.webserver.ResourceTransportRequestHandler.handleRequest(ResourceTransportRequestHandler.java:79)
   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:58)
   at org.apache.http.protocol.HttpService.handleRequest(HttpService.java:212)
   at org.serviio.upnp.webserver.WebServer$WorkerThread.run(WebServer.java:191)


FFmpeg:

  Code:

RR-DS212plus> /volume1/@appstore/Serviio/bin/ffmpeg -fflags +genpts -i "rtmp://s3h56pp78s3goi.cloudfront.net/cfx/st/ playpath=mp4:PBS_CP_Curious_George/CUGE3
14_EpisodeB_web4x3.mp4?player=PreKplayer&mediaID=2223987701 buffer=100000000" -y -copyts -c:v copy -vbsf h264_mp4toannexb -c:a ac3_fixed -b:a 384k -ac 2
-map 0:0 -map 0:1 -sn -f mpegts /.tmp/Serviio/transcoding-temp-1000000001440001-1-ORIGINAL.stf
ffmpeg version N-42368-gbf53863-Serviio Copyright (c) 2000-2012 the FFmpeg developers
  built on Jul 11 2012 01:45:53 with gcc 4.2.3
  configuration: --arch=arm --enable-armv5te --prefix=/opt --extra-cflags=-I/opt/include --extra-ldflags=-L/tmp/lib --enable-static --disable-shared --disable-ffplay --disable-ffserver --enable-pthreads --enable-libmp3lame --enable-librtmp --extra-version=Serviio
  libavutil      51. 64.100 / 51. 64.100
  libavcodec     54. 33.100 / 54. 33.100
  libavformat    54. 15.102 / 54. 15.102
  libavdevice    54.  1.100 / 54.  1.100
  libavfilter     3.  1.100 /  3.  1.100
  libswscale      2.  1.100 /  2.  1.100
  libswresample   0. 15.100 /  0. 15.100
Metadata:
  duration              744.48
  moovPosition          66783343.00
  width                 480.00
  height                360.00
  videocodecid          avc1
  audiocodecid          mp4a
  avcprofile            77.00
  avclevel              31.00
  aacaot                2.00
  videoframerate        15.00
  audiosamplerate       44100.00
  audiochannels         2.00
trackinfo:
  length                11167000.00
  timescale             15000.00
  language              und
sampledescription:
  sampletype            avc1
  length                32831488.00
  timescale             44100.00
  language              eng
sampledescription:
  sampletype            mp4a
Input #0, flv, from 'rtmp://s3h56pp78s3goi.cloudfront.net/cfx/st/ playpath=mp4:PBS_CP_Curious_George/CUGE314_EpisodeB_web4x3.mp4?player=PreKplayer&mediaID=2223987701 buffer=100000000':
  Metadata:
    moovPosition    : 66783343
    avcprofile      : 77
    avclevel        : 31
    aacaot          : 2
    videoframerate  : 15
    audiochannels   : 2
  Duration: 00:12:24.47, start: 0.000000, bitrate: N/A
    Stream #0:0: Video: h264 (Main), yuv420p, 480x360, 15 tbr, 1k tbn, 30 tbc
    Stream #0:1: Audio: aac, 44100 Hz, stereo, s16
[graph 0 input from stream 0:1 @ 0x1056be0] tb:1/44100 samplefmt:s16 samplerate:44100 chlayout:0x3
[mpegts @ 0x107f370] muxrate VBR, pcr every 1 pkts, sdt every 200, pat/pmt every 40 pkts
Output #0, mpegts, to '/.tmp/Serviio/transcoding-temp-1000000001440001-1-ORIGINAL.stf':
  Metadata:
    moovPosition    : 66783343
    avcprofile      : 77
    avclevel        : 31
    aacaot          : 2
    videoframerate  : 15
    audiochannels   : 2
    encoder         : Lavf54.15.102
    Stream #0:0: Video: h264, yuv420p, 480x360, q=2-31, 90k tbn, 15 tbc
    Stream #0:1: Audio: ac3, 44100 Hz, stereo, s16, 384 kb/s
Stream mapping:
  Stream #0:0 -> #0:0 (copy)
  Stream #0:1 -> #0:1 (aac -> ac3_fixed)
Press [q] to stop, [?] for help
frame=  705 fps= 67 q=-1.0 Lsize=    5192kB time=00:00:46.99 bitrate= 904.9kbits/s
video:2311kB audio:2204kB subtitle:0 global headers:0kB muxing overhead 15.000715%



CLIP-2
Log:

  Code:

2012-08-18 09:59:33,572 DEBUG [VideoDeliveryEngine] Delivering item '1000000001450001' for client 'IPAddress=/192.168.1.3, Profile=Generic DLNA profile'
2012-08-18 09:59:33,572 DEBUG [VideoDeliveryEngine] Delivering file 'http://www-tc.pbs.org/cove-media/http/PBS_CP_Angelina_Ballerina/68/594/ABAL505_1_web16x9.mp4' using transcoding
2012-08-18 09:59:33,573 DEBUG [AbstractTranscodingDeliveryEngine] No other client uses transcoding job of file 'transcoding-temp-1000000001440001-1-ORIGINAL.stf', will stop the job
2012-08-18 09:59:33,573 DEBUG [AbstractTranscodingDeliveryEngine] Stopping previous transcoding job of file 'transcoding-temp-1000000001440001-1-ORIGINAL.stf'
2012-08-18 09:59:33,573 DEBUG [TranscodingJobListener] Deleted temp file '/.tmp/Serviio/transcoding-temp-1000000001440001-1-ORIGINAL.stf': true
2012-08-18 09:59:33,573 DEBUG [AbstractTranscodingDeliveryEngine] No suitable transcoding job exists yet, start one for client 'IPAddress=/192.168.1.3, Profile=Generic DLNA profile'
2012-08-18 09:59:33,573 DEBUG [VideoDeliveryEngine] Extracting new URL for the expired feed item
2012-08-18 09:59:33,574 DEBUG [FeedItemUrlExtractor] pbskids.org: Starting extraction of url for item: Ballet Pantomime
2012-08-18 09:59:33,766 DEBUG [FeedItemUrlExtractor] pbskids.org: Finished extraction of url: ContentURLContainer [fileType=VIDEO, contentUrl=http://www-tc.pbs.org/cove-media/http/PBS_CP_Angelina_Ballerina/68/594/ABAL505_1_web16x9.mp4, thumbnailUrl=http://www-tc.pbs.org/cove-media/http/PBS_CP_Angelina_Ballerina/68/594/ABAL505_1_web16x9_69x53_2218393679.jpg, expiresImmediately=true, cacheKey=PBSKids_tW0_qpfdJftq2Nb1EK5wWbSN06xxTpVO, live=false, ]
2012-08-18 09:59:33,766 DEBUG [VideoDeliveryEngine] Successfully set new URL for the feed item
2012-08-18 09:59:33,767 DEBUG [FFMPEGWrapper] Invoking FFmpeg to transcode video file: http://www-tc.pbs.org/cove-media/http/PBS_CP_Angelina_Ballerina/68/594/ABAL505_1_web16x9.mp4
2012-08-18 09:59:33,768 DEBUG [ProcessExecutor] Starting /volume1/@appstore/Serviio/bin/ffmpeg -fflags +genpts -i http://www-tc.pbs.org/cove-media/http/PBS_CP_Angelina_Ballerina/68/594/ABAL505_1_web16x9.mp4 -y -copyts -c:v copy -vbsf h264_mp4toannexb -c:a ac3_fixed -b:a 384k -ac 2 -map 0:0 -map 0:1 -sn -f mpegts /.tmp/Serviio/transcoding-temp-1000000001450001-1-ORIGINAL.stf
2012-08-18 09:59:34,675 WARN  [ProcessExecutor] Process /volume1/@appstore/Serviio/bin/ffmpeg has a return code of 1! This is a possible error.
2012-08-18 09:59:34,675 DEBUG [TranscodingJobListener] Transcoding finished; successful: false
2012-08-18 09:59:34,784 ERROR [ResourceTransportRequestHandler] Error while processing resource, sending back 500 error. Message: FFmpeg execution failed
java.io.IOException: FFmpeg execution failed
   at org.serviio.delivery.resource.transcode.FileBasedTranscodingDeliveryStrategy.createInputStream(FileBasedTranscodingDeliveryStrategy.java:47)
   at org.serviio.delivery.resource.transcode.AbstractTranscodingDeliveryEngine.retrieveTranscodedResource(AbstractTranscodingDeliveryEngine.java:125)
   at org.serviio.delivery.resource.AbstractDeliveryEngine.deliver(AbstractDeliveryEngine.java:95)
   at org.serviio.delivery.MediaResourceRetrievalStrategy.retrieveResource(MediaResourceRetrievalStrategy.java:120)
   at org.serviio.delivery.ResourceDeliveryProcessor.deliverContent(ResourceDeliveryProcessor.java:84)
   at org.serviio.upnp.webserver.ResourceTransportRequestHandler.handleRequest(ResourceTransportRequestHandler.java:79)
   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:58)
   at org.apache.http.protocol.HttpService.handleRequest(HttpService.java:212)
   at org.serviio.upnp.webserver.WebServer$WorkerThread.run(WebServer.java:191)


FFmpeg:

  Code:

RR-DS212plus> /volume1/@appstore/Serviio/bin/ffmpeg -fflags +genpts -i "http://www-tc.pbs.org/cove-media/http/PBS_CP_Angelina_Ballerina/68/594/ABAL505_1_web1
6x9.mp4" -y -copyts -c:v copy -vbsf h264_mp4toannexb -c:a ac3_fixed -b:a 384k -ac 2 -map 0:0 -map 0:1 -sn -f mpegts /.tmp/Serviio/transcoding-temp-1000000001
450001-1-ORIGINAL.stf
ffmpeg version N-42368-gbf53863-Serviio Copyright (c) 2000-2012 the FFmpeg developers
  built on Jul 11 2012 01:45:53 with gcc 4.2.3
  configuration: --arch=arm --enable-armv5te --prefix=/opt --extra-cflags=-I/opt/include --extra-ldflags=-L/tmp/lib --enable-static --disable-shared --disable-ffplay --disable-ffserver --enable-pthreads --enable-libmp3lame --enable-librtmp --extra-version=Serviio
  libavutil      51. 64.100 / 51. 64.100
  libavcodec     54. 33.100 / 54. 33.100
  libavformat    54. 15.102 / 54. 15.102
  libavdevice    54.  1.100 / 54.  1.100
  libavfilter     3.  1.100 /  3.  1.100
  libswscale      2.  1.100 /  2.  1.100
  libswresample   0. 15.100 /  0. 15.100
Input #0, mov,mp4,m4a,3gp,3g2,mj2, from 'http://www-tc.pbs.org/cove-media/http/PBS_CP_Angelina_Ballerina/68/594/ABAL505_1_web16x9.mp4':
  Metadata:
    major_brand     : M4V
    minor_version   : 1
    compatible_brands: isomavc1mp42
    creation_time   : 1942-02-22 01:02:34
  Duration: 00:01:40.68, start: 0.066667, bitrate: 721 kb/s
    Stream #0:0(und): Video: h264 (Main) (avc1 / 0x31637661), yuv420p, 512x288, 399 kb/s, SAR 1:1 DAR 16:9, 15 fps, 15 tbr, 15k tbn, 30 tbc
    Metadata:
      creation_time   : 1942-02-22 01:02:34
      handler_name    : ETI ISO Video Media Handler
    Stream #0:1(eng): Audio: aac (mp4a / 0x6134706D), 44100 Hz, stereo, s16, 318 kb/s
    Metadata:
      creation_time   : 1942-02-22 01:02:34
      handler_name    : ETI ISO Audio Media Handler
[graph 0 input from stream 0:1 @ 0xf8f270] tb:1/44100 samplefmt:s16 samplerate:44100 chlayout:0x3
[mpegts @ 0xf9ad20] muxrate VBR, pcr every 1 pkts, sdt every 200, pat/pmt every 40 pkts
Output #0, mpegts, to '/.tmp/Serviio/transcoding-temp-1000000001450001-1-ORIGINAL.stf':
  Metadata:
    major_brand     : M4V
    minor_version   : 1
    compatible_brands: isomavc1mp42
    encoder         : Lavf54.15.102
    Stream #0:0(und): Video: h264 (avc1 / 0x31637661), yuv420p, 512x288 [SAR 1:1 DAR 16:9], q=2-31, 399 kb/s, 15 fps, 90k tbn, 15 tbc
    Metadata:
      creation_time   : 1942-02-22 01:02:34
      handler_name    : ETI ISO Video Media Handler
    Stream #0:1(eng): Audio: ac3, 44100 Hz, stereo, s16, 384 kb/s
    Metadata:
      creation_time   : 1942-02-22 01:02:34
      handler_name    : ETI ISO Audio Media Handler
Stream mapping:
  Stream #0:0 -> #0:0 (copy)
  Stream #0:1 -> #0:1 (aac -> ac3_fixed)
Press [q] to stop, [?] for help
frame=  214 fps= 89 q=-1.0 Lsize=    1600kB time=00:00:14.10 bitrate= 929.6kbits/s
video:730kB audio:661kB subtitle:0 global headers:0kB muxing overhead 14.991125%


I am not sure whats wrong here. Everything seems to be fine but serviio keeps failing on ffmpeg for these clips.

[zip]

is it using the same ffmpeg as you when run manually? Is it not the write access to the temp folder?

[xs2inattar]

Petr, rights to the tmp folder are setup correctly.

Any ideas what might be the issue here?

[zip]

NO, it looks like it runs all the way if you run the ffmpeg command manually.... in that case it's either looking at another ffmpeg or the write access is not right.

[xs2inattar]

OK so deleting the tmp folder, and restarting Serviio allowing it to create a new tmp folder fixed the issue.

But still ocnfused.

[zip]

I'm not sure how the NAS manages users/access rights. Usually this doesn't happen.