Post Sat Nov 09, 2013 2:44 am

ffmpeg not retried for cached items

This post supports bug report 727 https://bitbucket.org/xnejp03/serviio/i ... ched-items
The following annotated log entries are self explanatory, and illustrate that when ffmpeg fails on an item after it has been item cached, that ffmpeg will not be run again for that cached item. The feed must be "force refreshed" in order to get ffmpeg to run again. As a result, streams which are not active when the item is first cached will remain unavailable in the menu after expiry refreshes even after the streams become active.

In this example channels 1, 7 and 8 remain missing from the menu even after multiple expiry refreshes however for clarity I have only shown the ch1 log entries. A "forced refresh" was necessary to restore them after they became active.

  Code:
FORCE REFRESH
2013-11-08 18:19:49,387 DEBUG [OnlineContentCacheDecorator] Removed online content 'http://www.skysports.plus?refresh=30&time=19' from cache (online_feeds)
2013-11-08 18:19:49,387 DEBUG [WebResourceParser] Removing all items from expiresImmediately cache for resource: http://www.skysports.plus?refresh=30&time=19
2013-11-08 18:19:49,387 DEBUG [SearchIndexer] Removing documents with 'onlineRepoId' of '128' from search index

PARSE IT
2013-11-08 18:20:09,803 DEBUG [OnlineLibraryManager] Resource http://www.skysports.plus?refresh=30&time=19 not in cache, (re)loading it
2013-11-08 18:20:09,803 DEBUG [WebResourceParser] Parsing web resource 'http://www.skysports.plus?refresh=30&time=19'
2013-11-08 18:20:09,803 DEBUG [WebResourceParser] Found matching url extractor (skysportsplus) for resource http://www.skysports.plus?refresh=30&time=19
2013-11-08 18:20:09,803 DEBUG [FeedItemUrlExtractor] skysportsplus: Starting parsing resource: http://www.skysports.plus?refresh=30&time=19

EXTRACT CH1
2013-11-08 18:21:00,005 DEBUG [FeedItemUrlExtractor] skysportsplus: Starting extraction of url for item: ch1*1+19:00*Knicks at Bobcats *21:00*Nuggets at Suns
2013-11-08 18:21:01,853 DEBUG [FeedItemUrlExtractor] skysportsplus: call reyhq
2013-11-08 18:21:02,622 DEBUG [FeedItemUrlExtractor] skysportsplus: Extracted Url for ch1*1+19:00*Knicks at Bobcats *21:00*Nuggets at Suns
2013-11-08 18:21:02,623 DEBUG [FeedItemUrlExtractor] skysportsplus: Finished extraction of url: ContentURLContainer [fileType=VIDEO, contentUrl=rtmp://31.220.0.86:443/redirect playpath=ch1x pageUrl=http://reyhq.com swfUrl=http://www.udemy.com/static/flash/player5.9.swf live=1, thumbnailUrl=https://sites.google.com/site/serviiorss/ch1.png, expiresImmediately=true, cacheKey=SkysportsPlus_ch1_ch1x, live=true, ]
2013-11-08 18:21:02,623 DEBUG [WebResourceParser] Stored item with key 'SkysportsPlus_ch1*1+19:00*Knicks at Bobcats *21:00*Nuggets at Suns ' to cache
2013-11-08 18:21:02,623 DEBUG [WebResourceParser] Added resource item 19: 'ch1*1+19:00*Knicks at Bobcats *21:00*Nuggets at Suns' (rtmp://31.220.0.86:443/redirect playpath=ch1x pageUrl=http://reyhq.com swfUrl=http://www.udemy.com/static/flash/player5.9.swf live=1)

FFMPEG FOR CH1
2013-11-08 18:27:31,729 DEBUG [FeedUpdaterThread] Retrieving information about the video stream 'ch1*1+19:00*Knicks at Bobcats *21:00*Nuggets at Suns'
2013-11-08 18:27:31,729 DEBUG [FFMPEGWrapper] Invoking FFMPEG to retrieve media information for file: rtmp://31.220.0.86:443/redirect playpath=ch1x pageUrl=http://reyhq.com swfUrl=http://www.udemy.com/static/flash/player5.9.swf live=1
2013-11-08 18:27:31,729 DEBUG [ProcessExecutor] Starting C:\Program Files\Serviio\lib\ffdump.bat -analyzeduration 10000000 -i rtmp://31.220.0.86:443/redirect playpath=ch1x pageUrl=http://reyhq.com swfUrl=http://www.udemy.com/static/flash/player5.9.swf live=1
2013-11-08 18:27:37,015 DEBUG [FeedUpdaterThread] Cannot get information about the URL, it might have expired already. Trying again.
2013-11-08 18:27:37,015 DEBUG [FeedItemUrlExtractor] skysportsplus: Starting extraction of url for item: ch1*1+19:00*Knicks at Bobcats *21:00*Nuggets at Suns
2013-11-08 18:27:38,985 DEBUG [FeedItemUrlExtractor] skysportsplus: call reyhq
2013-11-08 18:27:39,923 DEBUG [FeedItemUrlExtractor] skysportsplus: Extracted Url for ch1*1+19:00*Knicks at Bobcats *21:00*Nuggets at Suns
2013-11-08 18:27:39,923 DEBUG [FeedItemUrlExtractor] skysportsplus: Finished extraction of url: ContentURLContainer [fileType=VIDEO, contentUrl=rtmp://31.220.0.86:443/redirect playpath=ch1x pageUrl=http://reyhq.com swfUrl=http://www.udemy.com/static/flash/player5.9.swf live=1, thumbnailUrl=https://sites.google.com/site/serviiorss/ch1.png, expiresImmediately=true, cacheKey=SkysportsPlus_ch1_ch1x, live=true, ]
2013-11-08 18:27:39,924 DEBUG [FFMPEGWrapper] Invoking FFMPEG to retrieve media information for file: rtmp://31.220.0.86:443/redirect playpath=ch1x pageUrl=http://reyhq.com swfUrl=http://www.udemy.com/static/flash/player5.9.swf live=1
2013-11-08 18:27:39,925 DEBUG [ProcessExecutor] Starting C:\Program Files\Serviio\lib\ffdump.bat -analyzeduration 10000000 -i rtmp://31.220.0.86:443/redirect playpath=ch1x pageUrl=http://reyhq.com swfUrl=http://www.udemy.com/static/flash/player5.9.swf live=1

FFMPEG FAILS FOR CH1
2013-11-08 18:28:39,966 WARN  [FeedUpdaterThread] Failed to retrieve online item information for rtmp://31.220.0.86:443/redirect playpath=ch1x pageUrl=http://reyhq.com swfUrl=http://www.udemy.com/static/flash/player5.9.swf live=1. It might not play.

REFRESH ON EXPIRY
2013-11-08 18:50:30,275 DEBUG [OnlineLibraryManager] Online resource http://www.skysports.plus?refresh=30&time=19 expired, will reload it
2013-11-08 18:50:30,275 DEBUG [OnlineLibraryManager] Resource http://www.skysports.plus?refresh=30&time=19 not in cache, (re)loading it
2013-11-08 18:50:30,275 DEBUG [WebResourceParser] Parsing web resource 'http://www.skysports.plus?refresh=30&time=19'
2013-11-08 18:50:30,275 DEBUG [WebResourceParser] Found matching url extractor (skysportsplus) for resource http://www.skysports.plus?refresh=30&time=19
2013-11-08 18:50:30,275 DEBUG [FeedItemUrlExtractor] skysportsplus: Starting parsing resource: http://www.skysports.plus?refresh=30&time=19

CH1 ERRONEOUSLY TAKEN FROM CACHE
2013-11-08 18:50:37,881 DEBUG [WebResourceParser] Item with key 'SkysportsPlus_ch1*1+19:00*Knicks at Bobcats *21:00*Nuggets at Suns ' already found in the cache, skipping URL extraction
2013-11-08 18:50:37,881 DEBUG [WebResourceParser] Added cached resource item 19: 'ch1*1+19:00*Knicks at Bobcats *21:00*Nuggets at Suns' (rtmp://31.220.0.86:443/redirect playpath=ch1x pageUrl=http://reyhq.com swfUrl=http://www.udemy.com/static/flash/player5.9.swf live=1)

PARSING COMPLETES WITH NO ATTEMPT TO RUN FFMPEG ON CH1 AGAIN
2013-11-08 18:50:43,480 DEBUG [OnlineContentCacheDecorator] Stored online content 'http://www.skysports.plus?refresh=30&time=19' in the cache (online_feeds), returning it
2013-11-08 18:50:43,480 DEBUG [SearchIndexer] Removing documents with 'onlineRepoId' of '128' from search index
2013-11-08 18:50:43,480 DEBUG [OnlineLibraryManager] Resource http://www.skysports.plus?refresh=30&time=19 will expire in the cache on Fri Nov 08 19:25:00 EST 2013
2013-11-08 18:50:43,484 DEBUG [SearchIndexer] Adding term 'sca*1+14:45*Inter Milan vs Livorno' to search index
2013-11-08 18:50:43,485 DEBUG [SearchIndexer] Adding term 'SkysportsPlus' to search index
2013-11-08 18:50:43,488 DEBUG [SearchIndexer] Adding term 'ch2*1+19:00*Raptors at Pacers *1+10:00*Liverpool vs Fulham' to search index
2013-11-08 18:50:43,489 DEBUG [SearchIndexer] Adding term 'SkysportsPlus' to search index
2013-11-08 18:50:43,490 DEBUG [SearchIndexer] Adding term 'ch3*1+19:00*Nets at Wizards *1+10:00*Southampton vs Hull City' to search index
2013-11-08 18:50:43,491 DEBUG [SearchIndexer] Adding term 'SkysportsPlus' to search index
2013-11-08 18:50:43,492 DEBUG [SearchIndexer] Adding term 'ch4*1+19:00*Celtics at Magic *1+10:00*Aston Villa vs Cardiff City' to search index
2013-11-08 18:50:43,493 DEBUG [SearchIndexer] Adding term 'SkysportsPlus' to search index
2013-11-08 18:50:43,496 DEBUG [SearchIndexer] Adding term 'Next Refresh at 19:20 on Fri 11/08/2013' to search index
2013-11-08 18:50:43,497 DEBUG [SearchIndexer] Adding term 'SkysportsPlus' to search index
2013-11-08 18:50:43,497 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 228)
2013-11-08 18:50:43,498 DEBUG [OnlineLibraryManager] Online resource http://www.youtube.com/embed/doN4t5NKW-k expired, will reload it
Attachments
missing channels.jpg
missing channels.jpg (200.29 KiB) Viewed 8280 times