Strange issue with PBSKids plugin
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.