serviio 0.6.0.1 on WHS with HP mediaconnect

Hi,

I only recently started using serviio, last week I installed version 0.5.2 on my WHS and using a preconfigured profile I was able to get it working transcoding mkv to my HP mediasmart connect. Today, I finally had some time and was attempting to create a profile that would better match the abilities of my particular device. I noticed that there was a new version (0.6.0.1) out and decided to try to install it, it installed without a problem and was able to find my mediasmart connect. My mediasmart connect also sees the serviio server which is running on the same machine as other servers that are working just fine, the problem is when I try to access serviio I get "not authorized to view this server". I have never seen that error message before. When uninstall 0.6.0.1 and revert to the older version it works just fine. Any thoughts?

[zip]

can you post detailed log? (see my signature on how to enable it)

I would be happy to, I will re-install 0.6.0.1 when I get home from work and turn on detailed logging.

I have the same problem with my mediasmart connect. Install latest release 0.6.2, recognizes my mediasmart connect device on the network, I go to select the serviio server in the mediasmart connect device's "Servers" list, it shows up, but is grayed out. Select it and the message "You are not authorized to browse this server".

I am Running Win7 Ultimate, my usual Windows Media Player Sharing (which is located on the same system that I installed serviio onto) shows up and works fine, as usual.

Version 0.6.2 is the first version I have tried, I uninstalled and will install 0.5.2 to see if it works, as reported above.

update: version 0.5.2 works perfectly. Reinstall 0.6.2 and same symptoms as above.

[serviio-buddy]

Have you setup your Home Group options on Win 7 ?

Home group options on win7 - yes, that is a basic requirement to get the player to connect, even to enable basic Windows Media Player Sharing.

[serviio-buddy]

Which profile are you using for your HP MediaSmart Connect device?

Can you enable detailed logging in Serviio - instructions are here: viewtopic.php?f=5&t=7

Please post the details here.

GENERIC DLNA profile

Should I uninstall 0.5.2 and reinstall 0.6.2 to create the trace log?

[serviio-buddy]

It's good that you installed 0.5.2 to confirm it works ok with the HP MediaSmart Connect.

Unfortunately, there is no Online Folder support in version 0.5.2.

Yes, uninstall 0.5.2 and reinstall 0.6.2 so we can look at the log file and see if we can maybe get some detailed insight into this problem.

When you do post the relevant parts of the log file you think may be helpful, please use the "Code" function while editing your post so it will display as shown below:

  Code:

Put the log file here

Also, is the error you reported as "You are not authorized to browse this server" the exact wording that the HP MediaSmart Connect reports when the "Servers" list appears as grayed-out ?

OK will do the reinstall. I moved from my "production" Win7 system to a vanilla, test Vista system, just to rule out any unwanted software interactions. The Vista (Ultimate) system has a fresh install of Java (done by the serviio installer), and the original factory MediaSmart Connect (HPMSC) software. I verified that vanilla HPMSC configuration works fine for this setup. I can connect to the Vista HPMSC server, list media, and stream media, as normal. I verified that serviio 0.5.2 likewise can connect and stream the same media. I verified that the HPMSC still shows the serviio 0.6.2 server as grayed out. When I select the grayed out serviio server, an error message is displayed.
The exact wording of the message displayed on my TV by the HPMSC unit is

Not authorized to browse this server

For reference, I activated logging for both serviio 0.5.2 and 0.6.2 experiments.

Here is the 0.5.2 log:

  Code:

2012-03-17 12:45:10,415 INFO  [MediaServer] ------------------------------------------------------------------------
2012-03-17 12:45:10,416 INFO  [MediaServer] Serviio DLNA media streaming server v 0.5.2 (rev. 4e3210bd9ff3)
2012-03-17 12:45:10,416 INFO  [MediaServer] Petr Nejedly 2009-2011
2012-03-17 12:45:10,416 INFO  [MediaServer] http://www.serviio.org
2012-03-17 12:45:10,416 INFO  [MediaServer]
2012-03-17 12:45:10,416 INFO  [MediaServer] Java 1.6.0_23-Sun Microsystems Inc.
2012-03-17 12:45:10,416 INFO  [MediaServer] OS Windows Vista x86 6.0
2012-03-17 12:45:10,416 INFO  [MediaServer] File encoding: windows-1252
2012-03-17 12:45:10,416 INFO  [MediaServer] ------------------------------------------------------------------------
2012-03-17 12:45:10,542 INFO  [RestletServer] Starting Restlet server exposed on localhost:23423
2012-03-17 12:45:10,602 INFO  [DBSchemaUpdateExecutor] Checking if DB schema needs to be updated
2012-03-17 12:45:15,104 INFO  [DBSchemaUpdateExecutor] Updating DB schema
2012-03-17 12:45:17,348 INFO  [ProfilesDefinitionParser] Parsing Profiles definition
2012-03-17 12:45:17,782 INFO  [ProfilesDefinitionParser] Added profile 'Generic DLNA profile' (id=1)
2012-03-17 12:45:18,012 INFO  [ProfilesDefinitionParser] Added profile 'Samsung TV (B-series)' (id=2)
2012-03-17 12:45:18,127 INFO  [ProfilesDefinitionParser] Added profile 'XBox 360' (id=3)
2012-03-17 12:45:18,214 INFO  [ProfilesDefinitionParser] Added profile 'Playstation 3' (id=4)
2012-03-17 12:45:18,330 INFO  [ProfilesDefinitionParser] Added profile 'Samsung TV (A-series)' (id=5)
2012-03-17 12:45:18,408 INFO  [ProfilesDefinitionParser] Added profile 'DirecTV HD-DVR' (id=6)
2012-03-17 12:45:18,589 INFO  [ProfilesDefinitionParser] Added profile 'Samsung TV / player (C/D-series)' (id=7)
2012-03-17 12:45:18,635 INFO  [ProfilesDefinitionParser] Added profile 'LG BD player' (id=8)
2012-03-17 12:45:18,894 INFO  [ProfilesDefinitionParser] Added profile 'Sony Bravia TV' (id=9)
2012-03-17 12:45:19,328 INFO  [ProfilesDefinitionParser] Added profile 'Sony BD Player' (id=10)
2012-03-17 12:45:19,442 INFO  [ProfilesDefinitionParser] Added profile 'Panasonic Viera' (id=12)
2012-03-17 12:45:19,526 INFO  [ProfilesDefinitionParser] Added profile 'Toshiba Rezga' (id=13)
2012-03-17 12:45:19,625 INFO  [AbstractTranscodingDeliveryEngine] Cleaning transcode engine and its data
2012-03-17 12:45:19,654 INFO  [WebServer] Socket buffer set to 65535 bytes
2012-03-17 12:45:19,688 INFO  [WebServer] WebServer starting on port 8895
2012-03-17 12:45:19,858 INFO  [Device] Created UPnP Device with UUID: 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3, bound address: 192.168.0.112
2012-03-17 12:45:19,883 INFO  [CompositeCacheManager] Creating cache manager from config file: /cache.ccf
2012-03-17 12:45:19,890 INFO  [ThreadPoolManager] thread_pool.default PoolConfiguration = useBoundary = [true] boundarySize = [2000] maximumPoolSize = [150] minimumPoolSize = [4] keepAliveTime = [300000] whenBlockedPolicy = [RUN] startUpSize = [4]
2012-03-17 12:45:19,893 INFO  [CompositeCacheConfigurator] Setting default auxiliaries to null
2012-03-17 12:45:19,894 INFO  [CompositeCacheConfigurator] No special CompositeCacheAttributes class defined for key [jcs.default.cacheattributes], using default class.
2012-03-17 12:45:19,895 INFO  [CompositeCacheConfigurator] setting defaultCompositeCacheAttributes to [ useLateral = true, useRemote = true, useDisk = true, maxObjs = 100, maxSpoolPerRun = -1, diskUsagePattern = 0 ]
2012-03-17 12:45:19,896 INFO  [CompositeCacheConfigurator] No special ElementAttribute class defined for key [jcs.default.elementattributes], using default class.
2012-03-17 12:45:19,896 INFO  [CompositeCacheConfigurator] setting defaultElementAttributes to [ IS_LATERAL = true, IS_SPOOL = true, IS_REMOTE = true, IS_ETERNAL = true, MaxLifeSeconds = -1, IdleTime = -1, CreateTime = 1332013519896, LastAccessTime = 1332013519896, getTimeToLiveSeconds() = -1, createTime = 1332013519896 ]
2012-03-17 12:45:19,898 INFO  [CompositeCacheConfigurator] No special ElementAttribute class defined for key [jcs.region.local_resetafterplay.elementattributes], using default class.
2012-03-17 12:45:19,914 INFO  [LRUMemoryCache] initialized LRUMemoryCache for local_resetafterplay
2012-03-17 12:45:19,914 INFO  [CompositeCache] Constructed cache with name [local_resetafterplay] and cache attributes [ useLateral = true, useRemote = true, useDisk = true, maxObjs = 1000, maxSpoolPerRun = -1, diskUsagePattern = 0 ]
2012-03-17 12:45:19,914 INFO  [CompositeCacheConfigurator] No special ElementAttribute class defined for key [jcs.region.local_default.elementattributes], using default class.
2012-03-17 12:45:19,914 INFO  [LRUMemoryCache] initialized LRUMemoryCache for local_default
2012-03-17 12:45:19,914 INFO  [CompositeCache] Constructed cache with name [local_default] and cache attributes [ useLateral = true, useRemote = true, useDisk = true, maxObjs = 1000, maxSpoolPerRun = -1, diskUsagePattern = 0 ]
2012-03-17 12:45:19,914 INFO  [CompositeCacheConfigurator] Parsed regions [local_resetafterplay, local_default]
2012-03-17 12:45:19,914 INFO  [CompositeCacheConfigurator] Finished configuration in 22 ms.
2012-03-17 12:45:19,917 INFO  [EventSubscriptionExpirationChecker] Starting EventSubscriptionExpirationChecker
2012-03-17 12:45:19,919 INFO  [EventDispatcher] Starting EventDispatcher
2012-03-17 12:45:19,919 INFO  [DiscoveryAdvertisementNotifier] Starting DiscoveryAdvertisementNotifier
2012-03-17 12:45:19,925 INFO  [RendererExpirationChecker] Starting RendererExpirationChecker
2012-03-17 12:45:19,925 INFO  [RendererSearchSender] Searching for Renderer devices
2012-03-17 12:45:19,942 INFO  [DiscoverySSDPMessageListener] Starting DiscoverySSDPMessageListener using interface eth2 (NVIDIA nForce 10/100 Mbps Ethernet ) and address 192.168.0.112, timeout = 0
2012-03-17 12:45:20,204 INFO  [RendererManager] Stored a new renderer: uuid='93a3d94d-dddd-46c8-97e9-8a0475003683', name = 'Unrecognized device', ipAddress='192.168.0.112', profile = '1'
2012-03-17 12:45:20,761 INFO  [RendererManager] Stored a new renderer: uuid='4194dbcd-4f6f-4e93-bcd3-0fa21ebccf43', name = 'Unrecognized device', ipAddress='192.168.0.116', profile = '1'
2012-03-17 12:45:23,201 INFO  [RendererManager] Stored a new renderer: uuid='258b05d8-1dd2-11b2-9f85-001f29112166', name = 'HP MediaSmart Connect', ipAddress='192.168.0.116', profile = '1'
2012-03-17 12:45:46,163 INFO  [LibraryAdditionsCheckerThread] Started looking for newly added files
2012-03-17 12:45:46,179 INFO  [LibraryUpdatesCheckerThread] Started looking for updates to currently shared files
2012-03-17 12:46:44,163 DEBUG [ServiioConsole] Initializing Serviio Console
2012-03-17 12:46:44,184 DEBUG [ApplicationInstanceManager] Listening for application instances on socket 44332
2012-03-17 12:46:44,186 INFO  [ServiioConsole] Starting Serviio Console
2012-03-17 12:46:44,219 DEBUG [SwingHelper] Choosing java look and feel: com.sun.java.swing.plaf.windows.WindowsLookAndFeel
2012-03-17 12:46:44,253 INFO  [ServiioConsole] Connecting to Serviio REST on localhost:23423
2012-03-17 12:46:45,617 INFO  [Messages] Loaded console message bundle for locale: en
2012-03-17 12:46:45,866 DEBUG [ServiioConsole] Retrieving preferred console language
2012-03-17 12:46:46,383 DEBUG [ServiioConsole] Setting console locale to be: en
2012-03-17 12:46:46,384 INFO  [Messages] Loaded console message bundle for locale: en
2012-03-17 12:46:46,502 INFO  [UpdateChecker] Checking if a new version is available
2012-03-17 12:46:47,100 DEBUG [ServiioFrameView] Initializing main frame
2012-03-17 12:46:47,105 DEBUG [ServiioFrameView] System tray is supported
2012-03-17 12:46:51,980 INFO  [ContentDirectoryDefinitionParser] Parsing ContentDirectory definition
2012-03-17 12:46:52,524 INFO  [BrowsingCategoriesMessages] Loaded browsing categories message bundle for locale: en
2012-03-17 12:46:54,285 DEBUG [ServiioConsole] Found a new version: 0.6.2
2012-03-17 12:47:31,964 INFO  [LibraryAdditionsCheckerThread] Finished looking for newly added files
2012-03-17 12:47:35,373 INFO  [LibraryAdditionsCheckerThread] Started looking for newly added files
2012-03-17 12:47:35,374 INFO  [LibraryUpdatesCheckerThread] Started looking for updates to currently shared files
2012-03-17 12:47:42,258 INFO  [LibraryAdditionsCheckerThread] Added file 'GLORIOUS_39.avi' (title: Glorious 39) to Library
2012-03-17 12:47:52,677 INFO  [LibraryAdditionsCheckerThread] Added file 'hugo.2011.bdrip.xvid.ac3.hq.hive-cm8.avi' (title: Hugo) to Library
2012-03-17 12:48:47,793 INFO  [LibraryAdditionsCheckerThread] Added file 'Indiana.Jones.and.the.Kingdom.of.the.Crystal.Skull.2008.720p.BluRay.DTS.x264-ESiR.mkv' (title: Indiana Jones and the Kingdom of the Crystal Skull) to Library
2012-03-17 12:48:51,533 WARN  [EventDispatcher] Error 412 received from event subscriber
2012-03-17 12:48:54,883 INFO  [LibraryAdditionsCheckerThread] Added file 'The Thin Red Line (1998).Nick Nolte,Sean Penn.avi' (title: The Thin Red Line) to Library
2012-03-17 12:48:55,189 WARN  [VideoExtractionStrategy] Couldn't resolve H264 profile/level for file 'The.River.S01E05.Peaches.720p.WEB-DL.DD5.1.H.264-CtrlHD.mpg' because Sequence parameter set header was not recognized
2012-03-17 12:48:56,538 WARN  [EventDispatcher] Error 412 received from event subscriber
2012-03-17 12:49:32,738 INFO  [LibraryAdditionsCheckerThread] Added file 'The.River.S01E05.Peaches.720p.WEB-DL.DD5.1.H.264-CtrlHD.mpg' (title: Episode 5) to Library
2012-03-17 12:49:32,979 WARN  [VideoExtractionStrategy] Couldn't resolve H264 profile/level for file 'The.River.S01E06.Doctor.Emmet.Cole.720p.WEB-DL.DD5.1.H.264-CtrlHD.mpg' because Sequence parameter set header was not recognized
2012-03-17 12:50:08,712 INFO  [LibraryAdditionsCheckerThread] Added file 'The.River.S01E06.Doctor.Emmet.Cole.720p.WEB-DL.DD5.1.H.264-CtrlHD.mpg' (title: Episode 6) to Library
2012-03-17 12:50:08,713 INFO  [LibraryAdditionsCheckerThread] Finished looking for newly added files
2012-03-17 12:50:18,816 INFO  [EventSubscriptionExpirationChecker] Leaving EventSubscriptionExpirationChecker, removing all event subscriptions
2012-03-17 12:50:18,816 INFO  [WebServer] WebServer shutting down
2012-03-17 12:50:18,816 INFO  [EventDispatcher] Leaving EventDispatcher
2012-03-17 12:50:18,816 INFO  [DiscoveryAdvertisementNotifier] Leaving DiscoveryAdvertisementNotifier
2012-03-17 12:50:18,963 INFO  [DiscoverySSDPMessageListener] Leaving DiscoverySSDPMessageListener
2012-03-17 12:50:19,988 INFO  [RendererExpirationChecker] Leaving RendererExpirationChecker
2012-03-17 12:50:25,343 INFO  [ServiioConsole] Leaving Serviio Console
2012-03-17 12:50:25,361 INFO  [DatabaseManager] Shutting down database
2012-03-17 12:50:25,549 INFO  [AbstractTranscodingDeliveryEngine] Cleaning transcode engine and its data


I de-installed 0.5.2, reinstalled 0.6.2, turned on logging. Here is the 0.6.2 log:

  Code:

2012-03-17 12:26:26,769 INFO  [MediaServer] ------------------------------------------------------------------------
2012-03-17 12:26:26,844 INFO  [MediaServer] Serviio DLNA media streaming server v 0.6.2 (rev. aec3abd196d6+)
2012-03-17 12:26:26,844 INFO  [MediaServer] Petr Nejedly 2009-2011
2012-03-17 12:26:26,844 INFO  [MediaServer] http://www.serviio.org
2012-03-17 12:26:26,844 INFO  [MediaServer]
2012-03-17 12:26:26,844 INFO  [MediaServer] Java 1.6.0_23-Sun Microsystems Inc.
2012-03-17 12:26:26,844 INFO  [MediaServer] OS Windows Vista x86 6.0
2012-03-17 12:26:26,844 INFO  [MediaServer] File encoding: windows-1252
2012-03-17 12:26:26,860 INFO  [MediaServer] Headless mode enabled: true
2012-03-17 12:26:26,860 INFO  [MediaServer] User home dir: C:\
2012-03-17 12:26:26,860 INFO  [MediaServer] Temp dir: C:\Windows\TEMP\
2012-03-17 12:26:26,860 INFO  [MediaServer] ------------------------------------------------------------------------
2012-03-17 12:26:27,067 INFO  [RestletServer] Starting Restlet server exposed on port 23423
2012-03-17 12:26:27,249 INFO  [DBSchemaUpdateExecutor] Checking if DB schema needs to be updated
2012-03-17 12:26:30,837 INFO  [DBSchemaUpdateExecutor] Updating DB schema
2012-03-17 12:26:39,962 INFO  [ProfilesDefinitionParser] Parsing Profiles definition
2012-03-17 12:26:40,604 INFO  [ProfilesDefinitionParser] Added profile 'Generic DLNA profile' (id=1)
2012-03-17 12:26:41,033 INFO  [ProfilesDefinitionParser] Added profile 'Samsung TV (B-series)' (id=2)
2012-03-17 12:26:41,275 INFO  [ProfilesDefinitionParser] Added profile 'Xbox 360' (id=3)
2012-03-17 12:26:41,587 INFO  [ProfilesDefinitionParser] Added profile 'Playstation 3' (id=4)
2012-03-17 12:26:41,769 INFO  [ProfilesDefinitionParser] Added profile 'Samsung TV (A-series)' (id=5)
2012-03-17 12:26:41,888 INFO  [ProfilesDefinitionParser] Added profile 'DirecTV HD-DVR' (id=6)
2012-03-17 12:26:42,524 INFO  [ProfilesDefinitionParser] Added profile 'Samsung TV / player (C/D-series)' (id=7)
2012-03-17 12:26:42,576 INFO  [ProfilesDefinitionParser] Added profile 'LG TV / player' (id=8)
2012-03-17 12:26:43,101 INFO  [ProfilesDefinitionParser] Added profile 'Sony Bravia TV (2011)' (id=9)
2012-03-17 12:26:43,900 INFO  [ProfilesDefinitionParser] Added profile 'Sony BD Player / SMP' (id=10)
2012-03-17 12:26:44,263 INFO  [ProfilesDefinitionParser] Added profile 'Panasonic Viera' (id=12)
2012-03-17 12:26:44,579 INFO  [ProfilesDefinitionParser] Added profile 'Toshiba REGZA' (id=13)
2012-03-17 12:26:44,767 INFO  [ProfilesDefinitionParser] Added profile 'WDTV Live' (id=14)
2012-03-17 12:26:44,808 INFO  [ProfilesDefinitionParser] Added profile 'LaCie LaCinema Media Player' (id=15)
2012-03-17 12:26:44,959 INFO  [ProfilesDefinitionParser] Added profile 'Manta WIFI Centre' (id=16)
2012-03-17 12:26:45,027 INFO  [ProfilesDefinitionParser] Added profile 'Pure Flow' (id=17)
2012-03-17 12:26:45,265 INFO  [ProfilesDefinitionParser] Added profile 'Sharp Aquos' (id=18)
2012-03-17 12:26:45,383 INFO  [ProfilesDefinitionParser] Added profile 'Sony Bravia TV (2010)' (id=19)
2012-03-17 12:26:45,695 INFO  [ProfilesDefinitionParser] Added profile 'Philips' (id=20)
2012-03-17 12:26:45,880 INFO  [ProfilesDefinitionParser] Added profile 'Sony Bravia TV (2009)' (id=21)
2012-03-17 12:26:46,351 INFO  [WebServer] Socket buffer set to 65535 bytes
2012-03-17 12:26:46,392 INFO  [Device] Created UPnP Device with UUID: 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3, bound address: 192.168.0.112
2012-03-17 12:26:46,427 INFO  [PluginCompilerThread] Looking for plugins at C:\Program Files\Serviio\bin\..\plugins
2012-03-17 12:26:46,427 INFO  [PluginCompilerThread] Started looking for plugins
2012-03-17 12:26:46,646 INFO  [AbstractTranscodingDeliveryEngine] Cleaning transcode engine and its data
2012-03-17 12:26:46,700 INFO  [WebServer] WebServer starting on port 8895
2012-03-17 12:26:46,713 INFO  [EventSubscriptionExpirationChecker] Starting EventSubscriptionExpirationChecker
2012-03-17 12:26:46,716 INFO  [DiscoveryAdvertisementNotifier] Starting DiscoveryAdvertisementNotifier
2012-03-17 12:26:46,713 INFO  [EventDispatcher] Starting EventDispatcher
2012-03-17 12:26:46,719 INFO  [RendererSearchSender] Searching for Renderer devices
2012-03-17 12:26:46,719 INFO  [RendererExpirationChecker] Starting RendererExpirationChecker
2012-03-17 12:26:46,741 INFO  [DiscoverySSDPMessageListener] Starting DiscoverySSDPMessageListener using interface eth2 (NVIDIA nForce 10/100 Mbps Ethernet ) and address 192.168.0.112, timeout = 0
2012-03-17 12:26:47,053 INFO  [RendererManager] Stored a new renderer: uuid='17bcd074-9247-441f-915f-04ee2e0672ed', name = 'Unrecognized device', ipAddress='192.168.0.112', profile = '1'
2012-03-17 12:26:47,643 INFO  [RendererManager] Stored a new renderer: uuid='5ce9d3ab-665d-424e-a6dd-98401e969318', name = 'Unrecognized device', ipAddress='192.168.0.116', profile = '1'
2012-03-17 12:26:48,276 INFO  [RendererManager] Stored a new renderer: uuid='258b05d8-1dd2-11b2-9f85-001f29112166', name = 'HP MediaSmart Connect', ipAddress='192.168.0.116', profile = '1'
2012-03-17 12:27:12,976 INFO  [FeedUpdaterThread] Started looking for information about online resources
2012-03-17 12:27:13,112 INFO  [LibraryAdditionsCheckerThread] Started looking for newly added files
2012-03-17 12:27:13,137 INFO  [LibraryUpdatesCheckerThread] Started looking for updates to currently shared files
2012-03-17 12:28:17,146 DEBUG [ServiioConsole] Initializing Serviio Console
2012-03-17 12:28:17,170 DEBUG [ApplicationInstanceManager] Listening for application instances on socket 44332
2012-03-17 12:28:17,172 INFO  [ServiioConsole] Starting Serviio Console
2012-03-17 12:28:17,267 DEBUG [SwingHelper] Choosing java look and feel: com.sun.java.swing.plaf.windows.WindowsLookAndFeel
2012-03-17 12:28:17,408 INFO  [ServiioConsole] Connecting to Serviio REST on localhost:23423
2012-03-17 12:28:18,107 DEBUG [ServiioConsole] Retrieving preferred console language
2012-03-17 12:28:18,150 DEBUG [ServiioConsole] Setting console locale to be: en
2012-03-17 12:28:18,157 INFO  [Messages] Loaded console message bundle for locale: en
2012-03-17 12:28:18,216 INFO  [UpdateChecker] Checking if a new version is available
2012-03-17 12:28:19,467 DEBUG [ServiioFrameView] Initializing main frame
2012-03-17 12:28:19,549 DEBUG [ServiioFrameView] System tray is supported
2012-03-17 12:28:20,728 INFO  [ContentDirectoryDefinitionParser] Parsing ContentDirectory definition
2012-03-17 12:28:21,350 INFO  [BrowsingCategoriesMessages] Loaded browsing categories message bundle for locale: en
2012-03-17 12:28:21,795 DEBUG [RepositoryView$LibraryStatusCheckerThread] Starting library status checking thread
2012-03-17 12:29:31,362 INFO  [LibraryAdditionsCheckerThread] Finished looking for newly added files
2012-03-17 12:29:31,462 INFO  [LibraryUpdatesCheckerThread] Finished looking for updates to currently shared files
2012-03-17 12:29:34,552 INFO  [LibraryAdditionsCheckerThread] Started looking for newly added files
2012-03-17 12:29:34,553 INFO  [LibraryUpdatesCheckerThread] Started looking for updates to currently shared files
2012-03-17 12:29:34,576 INFO  [LibraryAdditionsCheckerThread] Finished looking for newly added files
2012-03-17 12:29:34,646 INFO  [LibraryUpdatesCheckerThread] Finished looking for updates to currently shared files
2012-03-17 12:29:54,139 INFO  [LibraryAdditionsCheckerThread] Started looking for newly added files
2012-03-17 12:29:54,141 INFO  [LibraryUpdatesCheckerThread] Started looking for updates to currently shared files
2012-03-17 12:29:54,149 INFO  [LibraryUpdatesCheckerThread] Finished looking for updates to currently shared files
2012-03-17 12:29:56,312 WARN  [LibraryAdditionsCheckerThread] An error occured while scanning for item to be added, will continue
org.serviio.db.dao.PersistenceException: Cannot mark Repository with id 1 as scanned
   at org.serviio.library.dao.RepositoryDAOImpl.markRepositoryAsScanned(RepositoryDAOImpl.java:159)
   at org.serviio.library.local.service.RepositoryService.markRepositoryAsScanned(RepositoryService.java:108)
   at org.serviio.library.local.metadata.LibraryAdditionsCheckerThread.run(LibraryAdditionsCheckerThread.java:79)
Caused by: java.sql.SQLNonTransientConnectionException: Connection closed by unknown interrupt.
   at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(Unknown Source)
   at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source)
   at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown Source)
   at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown Source)
   at org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown Source)
   at org.apache.derby.impl.jdbc.ConnectionChild.handleException(Unknown Source)
   at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(Unknown Source)
   at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(Unknown Source)
   at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeUpdate(Unknown Source)
   at org.serviio.library.dao.RepositoryDAOImpl.markRepositoryAsScanned(RepositoryDAOImpl.java:157)
   ... 2 more
Caused by: java.sql.SQLException: Connection closed by unknown interrupt.
   at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
   at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(Unknown Source)
   ... 12 more
Caused by: ERROR 08000: Connection closed by unknown interrupt.
   at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
   at org.apache.derby.iapi.util.InterruptStatus.setInterrupted(Unknown Source)
   at org.apache.derby.iapi.util.InterruptStatus.throwIf(Unknown Source)
   at org.apache.derby.impl.sql.execute.BasicNoPutResultSetImpl.checkCancellationFlag(Unknown Source)
   at org.apache.derby.impl.sql.execute.TableScanResultSet.getNextRowCore(Unknown Source)
   at org.apache.derby.impl.sql.execute.IndexRowToBaseRowResultSet.getNextRowCore(Unknown Source)
   at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore(Unknown Source)
   at org.apache.derby.impl.sql.execute.NormalizeResultSet.getNextRowCore(Unknown Source)
   at org.apache.derby.impl.sql.execute.DMLWriteResultSet.getNextRowCore(Unknown Source)
   at org.apache.derby.impl.sql.execute.UpdateResultSet.collectAffectedRows(Unknown Source)
   at org.apache.derby.impl.sql.execute.UpdateResultSet.open(Unknown Source)
   at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(Unknown Source)
   at org.apache.derby.impl.sql.GenericPreparedStatement.execute(Unknown Source)
   ... 6 more
2012-03-17 12:29:56,315 INFO  [LibraryAdditionsCheckerThread] Finished looking for newly added files
2012-03-17 12:29:56,407 INFO  [LibraryAdditionsCheckerThread] Started looking for newly added files
2012-03-17 12:29:56,408 INFO  [LibraryUpdatesCheckerThread] Started looking for updates to currently shared files
2012-03-17 12:29:56,413 INFO  [LibraryUpdatesCheckerThread] Finished looking for updates to currently shared files
2012-03-17 12:29:58,301 INFO  [LibraryAdditionsCheckerThread] Added file 'GLORIOUS_39.avi' (title: Glorious 39) to Library
2012-03-17 12:30:01,147 INFO  [LibraryAdditionsCheckerThread] Added file 'hugo.2011.bdrip.xvid.ac3.hq.hive-cm8.avi' (title: Hugo) to Library
2012-03-17 12:30:03,269 WARN  [EventDispatcher] Error 412 received from event subscriber
2012-03-17 12:30:03,308 INFO  [LibraryAdditionsCheckerThread] Added file 'Indiana.Jones.and.the.Kingdom.of.the.Crystal.Skull.2008.720p.BluRay.DTS.x264-ESiR.mkv' (title: Indiana Jones and the Kingdom of the Crystal Skull) to Library
2012-03-17 12:30:05,932 INFO  [LibraryAdditionsCheckerThread] Added file 'The Thin Red Line (1998).Nick Nolte,Sean Penn.avi' (title: The Thin Red Line) to Library
2012-03-17 12:30:44,108 INFO  [LibraryAdditionsCheckerThread] Added file 'The.River.S01E05.Peaches.720p.WEB-DL.DD5.1.H.264-CtrlHD.mpg' (title: Episode 5) to Library
2012-03-17 12:31:20,715 INFO  [LibraryAdditionsCheckerThread] Added file 'The.River.S01E06.Doctor.Emmet.Cole.720p.WEB-DL.DD5.1.H.264-CtrlHD.mpg' (title: Episode 6) to Library
2012-03-17 12:31:20,716 INFO  [LibraryAdditionsCheckerThread] Finished looking for newly added files
2012-03-17 12:35:04,225 INFO  [DiscoveryAdvertisementNotifier] Leaving DiscoveryAdvertisementNotifier
2012-03-17 12:35:04,225 INFO  [WebServer] WebServer shutting down
2012-03-17 12:35:04,225 INFO  [EventDispatcher] Leaving EventDispatcher
2012-03-17 12:35:04,226 INFO  [EventSubscriptionExpirationChecker] Leaving EventSubscriptionExpirationChecker, removing all event subscriptions
2012-03-17 12:35:04,372 INFO  [DiscoverySSDPMessageListener] Leaving DiscoverySSDPMessageListener
2012-03-17 12:35:06,719 INFO  [RendererExpirationChecker] Leaving RendererExpirationChecker
2012-03-17 12:35:11,599 WARN  [IndexedDiskCache] Region [thumbnails] Disk cache not shutdown properly, shutting down now.
2012-03-17 12:35:11,600 WARN  [IndexedDiskCache] Region [online_technical_metadata] Disk cache not shutdown properly, shutting down now.
2012-03-17 12:35:11,602 INFO  [FeedUpdaterThread] Finished looking for online resources information
2012-03-17 12:35:11,699 INFO  [PluginCompilerThread] Finished looking for plugins
2012-03-17 12:35:11,799 INFO  [DatabaseManager] Shutting down database
2012-03-17 12:35:12,000 INFO  [AbstractTranscodingDeliveryEngine] Cleaning transcode engine and its data
2012-03-17 12:35:13,310 DEBUG [RepositoryView] Instructing LibraryCheckingThread to stop
2012-03-17 12:35:13,311 INFO  [ServiioConsole] Leaving Serviio Console


[serviio-buddy]

Thanks. I searched on the internet for that error, but not much comes up other than it says to share the folders thru Windows Media Player. Do you have the folders that Serviio serves marked as shared in the Windows Media Player sharing section too? The MediaSmart Connect information that I found mentioned this, but I'm not sure if that is necessary.

Yes, I use the same folder in both Windows Media sharing and serviio.

I do not think it is anything to do with the library. If I remove all media/library sharing from both the original MediaSmart Connect configuration, and from Serviio, the same symptoms occur. In other words, if I only have the client and server environments established, but zero media files of any kind, the serviio 0.6.2 server still shows grayed out, while 0.5.2 is normal/browsable, with zero media files. If needed I can create logs of this case too, with zero media files shared.

My instinct tells me the problem lies is in the establishment of the uPnp device, or the interaction with the web server. The serviio server is grayed out immediately when it is discovered by the HPMSC, not after some interaction. The HPMSC doesn't do anything with the library media until after the server is selected and I navigate to the part of the library I want to stream. With serviio grayed out, I'm getting stopped by the HPMSC long before it would interact with the media library. Did you change web servers between 0.5.2 and 0.6.2? Or anything in how the uPnp is established?

I'm hopeful we'll solve this. At least I have a known configuration (0.5.2) that works! That's should offer some clues.

[serviio-buddy]

I will continue to look at this problem, but nothing new to report now.

[serviio-buddy]

I just saw you posted the logs. I will look at them and see if we can get some clues to resolve this for you.

[serviio-buddy]

On the 0.5.2 and 0.6.2 logs, it shows 2 devices at the same ip address 192.168.0.116 but with different uuids:

  Code:

2012-03-17 12:26:47,643 INFO  [RendererManager] Stored a new renderer: uuid='5ce9d3ab-665d-424e-a6dd-98401e969318', name = 'Unrecognized device', ipAddress='192.168.0.116', profile = '1'
2012-03-17 12:26:48,276 INFO  [RendererManager] Stored a new renderer: uuid='258b05d8-1dd2-11b2-9f85-001f29112166', name = 'HP MediaSmart Connect', ipAddress='192.168.0.116', profile = '1'

On the Serviio Console Status screen, does it show 2 devices connected at the same ip address or does it even show the MediaSmart Connect device on 192.168.0.116 ?

Please list all the device's status, ip address, device name and profile from the Serviio Console Status screen.

Also, on another forum, some people are reporting Serviio not working anymore after they installed the latest Win 7 updates. Here's the forum link: viewtopic.php?f=5&t=5677

One more thing: try installing VLC 2.0.0 on your Vista Serviio PC and see if you can see all the Serviio folders thru there to confirm it is serving up files. On VLC, go to View --> Playlist --> Local Network --> Universal Plug'n'Play, wait a few seconds and you should see the Serviio folder appear.

Serviio console shows only HPMSC on IP 192.168.0.116... See screenshot. Now, at the time I took the logs that I posted, there were two other devices listed on the console as "Unknown", at different IP addresses. I see the reference you mentioned to two devices with the same IP address, that is weird, because if they would have the same IP address in the console, I would have noticed it. I reinstalled 0.6.2 to get a fresh setup. I installed and ran VLC 2.0.0, and it shows the media being served up. See also screenshot. IP Address 192.168.0.112 is my localhost VISTA running serviio and VLC.



In the following log, I filtered out the following messages and truncated the log at around 500 entries:
[PersonDAOImpl], [VideoDAOImpl], [Library*], [TheMovie*], [ContentDirectory*]

  Code:

2012-03-18 11:42:08,563 INFO  [MediaServer] ------------------------------------------------------------------------
2012-03-18 11:42:08,564 INFO  [MediaServer] Serviio DLNA media streaming server v 0.6.2 (rev. aec3abd196d6+)
2012-03-18 11:42:08,564 INFO  [MediaServer] Petr Nejedly 2009-2011
2012-03-18 11:42:08,564 INFO  [MediaServer] http://www.serviio.org
2012-03-18 11:42:08,564 INFO  [MediaServer]
2012-03-18 11:42:08,564 INFO  [MediaServer] Java 1.6.0_23-Sun Microsystems Inc.
2012-03-18 11:42:08,564 INFO  [MediaServer] OS Windows Vista x86 6.0
2012-03-18 11:42:08,564 INFO  [MediaServer] File encoding: windows-1252
2012-03-18 11:42:08,564 INFO  [MediaServer] Headless mode enabled: true
2012-03-18 11:42:08,564 INFO  [MediaServer] User home dir: C:\
2012-03-18 11:42:08,565 INFO  [MediaServer] Temp dir: C:\Windows\TEMP\
2012-03-18 11:42:08,565 INFO  [MediaServer] ------------------------------------------------------------------------
2012-03-18 11:42:08,701 INFO  [RestletServer] Starting Restlet server exposed on port 23423
2012-03-18 11:42:08,762 INFO  [DBSchemaUpdateExecutor] Checking if DB schema needs to be updated
2012-03-18 11:42:08,770 DEBUG [DBLogDAOImpl] Checking if script 'script-0.1.sql' has been run
2012-03-18 11:42:09,859 DEBUG [DBLogDAOImpl] Checking if script 'script-0.1.1.sql' has been run
2012-03-18 11:42:09,860 DEBUG [DBLogDAOImpl] Checking if script 'script-0.2.sql' has been run
2012-03-18 11:42:09,861 DEBUG [DBLogDAOImpl] Checking if script 'script-0.3.1.sql' has been run
2012-03-18 11:42:09,862 DEBUG [DBLogDAOImpl] Checking if script 'script-0.4.sql' has been run
2012-03-18 11:42:09,863 DEBUG [DBLogDAOImpl] Checking if script 'script-0.4.1.sql' has been run
2012-03-18 11:42:09,864 DEBUG [DBLogDAOImpl] Checking if script 'script-0.4.2.sql' has been run
2012-03-18 11:42:09,865 DEBUG [DBLogDAOImpl] Checking if script 'script-0.5.sql' has been run
2012-03-18 11:42:09,866 DEBUG [DBLogDAOImpl] Checking if script 'script-0.5.1.sql' has been run
2012-03-18 11:42:09,867 DEBUG [DBLogDAOImpl] Checking if script 'script-0.6.sql' has been run
2012-03-18 11:42:09,868 DEBUG [DBLogDAOImpl] Checking if script 'script-0.6.1.sql' has been run
2012-03-18 11:42:09,869 DEBUG [DBLogDAOImpl] Checking if script 'script-0.6.2.sql' has been run
2012-03-18 11:42:10,083 INFO  [ProfilesDefinitionParser] Parsing Profiles definition
2012-03-18 11:42:10,125 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 1
2012-03-18 11:42:10,693 INFO  [ProfilesDefinitionParser] Added profile 'Generic DLNA profile' (id=1)
2012-03-18 11:42:10,695 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 2
2012-03-18 11:42:11,131 INFO  [ProfilesDefinitionParser] Added profile 'Samsung TV (B-series)' (id=2)
2012-03-18 11:42:11,133 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 3
2012-03-18 11:42:11,392 INFO  [ProfilesDefinitionParser] Added profile 'Xbox 360' (id=3)
2012-03-18 11:42:11,394 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 4
2012-03-18 11:42:11,728 INFO  [ProfilesDefinitionParser] Added profile 'Playstation 3' (id=4)
2012-03-18 11:42:11,729 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 5
2012-03-18 11:42:11,924 INFO  [ProfilesDefinitionParser] Added profile 'Samsung TV (A-series)' (id=5)
2012-03-18 11:42:11,926 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 6
2012-03-18 11:42:12,054 INFO  [ProfilesDefinitionParser] Added profile 'DirecTV HD-DVR' (id=6)
2012-03-18 11:42:12,055 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 7
2012-03-18 11:42:12,628 INFO  [ProfilesDefinitionParser] Added profile 'Samsung TV / player (C/D-series)' (id=7)
2012-03-18 11:42:12,630 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 8
2012-03-18 11:42:12,669 INFO  [ProfilesDefinitionParser] Added profile 'LG TV / player' (id=8)
2012-03-18 11:42:12,671 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 9
2012-03-18 11:42:13,211 INFO  [ProfilesDefinitionParser] Added profile 'Sony Bravia TV (2011)' (id=9)
2012-03-18 11:42:13,213 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 10
2012-03-18 11:42:14,058 INFO  [ProfilesDefinitionParser] Added profile 'Sony BD Player / SMP' (id=10)
2012-03-18 11:42:14,061 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 12
2012-03-18 11:42:14,449 INFO  [ProfilesDefinitionParser] Added profile 'Panasonic Viera' (id=12)
2012-03-18 11:42:14,451 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 13
2012-03-18 11:42:14,790 INFO  [ProfilesDefinitionParser] Added profile 'Toshiba REGZA' (id=13)
2012-03-18 11:42:14,792 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 14
2012-03-18 11:42:14,996 INFO  [ProfilesDefinitionParser] Added profile 'WDTV Live' (id=14)
2012-03-18 11:42:14,998 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 15
2012-03-18 11:42:15,040 INFO  [ProfilesDefinitionParser] Added profile 'LaCie LaCinema Media Player' (id=15)
2012-03-18 11:42:15,043 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 16
2012-03-18 11:42:15,204 INFO  [ProfilesDefinitionParser] Added profile 'Manta WIFI Centre' (id=16)
2012-03-18 11:42:15,206 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 17
2012-03-18 11:42:15,280 INFO  [ProfilesDefinitionParser] Added profile 'Pure Flow' (id=17)
2012-03-18 11:42:15,282 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 18
2012-03-18 11:42:15,537 INFO  [ProfilesDefinitionParser] Added profile 'Sharp Aquos' (id=18)
2012-03-18 11:42:15,540 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 19
2012-03-18 11:42:15,665 INFO  [ProfilesDefinitionParser] Added profile 'Sony Bravia TV (2010)' (id=19)
2012-03-18 11:42:15,667 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 20
2012-03-18 11:42:15,999 INFO  [ProfilesDefinitionParser] Added profile 'Philips' (id=20)
2012-03-18 11:42:16,002 DEBUG [ProfilesDefinitionParser] Parsing profile definition for profile 21
2012-03-18 11:42:16,203 INFO  [ProfilesDefinitionParser] Added profile 'Sony Bravia TV (2009)' (id=21)
2012-03-18 11:42:16,325 DEBUG [ConfigEntryDAOImpl] Reading all ConfigEntries
2012-03-18 11:42:16,505 INFO  [WebServer] Socket buffer set to 65535 bytes
2012-03-18 11:42:16,506 INFO  [Device] Created UPnP Device with UUID: 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3, bound address: 192.168.0.112
2012-03-18 11:42:16,531 INFO  [PluginCompilerThread] Looking for plugins at C:\Program Files\Serviio\bin\..\plugins
2012-03-18 11:42:16,532 INFO  [PluginCompilerThread] Started looking for plugins
2012-03-18 11:42:16,537 DEBUG [FFMPEGWrapper] Invoking FFMPEG to check if it exists of path C:\Program Files\Serviio\bin\\..\lib/ffmpeg.exe
2012-03-18 11:42:16,541 DEBUG [ProcessExecutor] Starting C:\Program Files\Serviio\bin\\..\lib/ffmpeg.exe
2012-03-18 11:42:16,597 INFO  [AbstractTranscodingDeliveryEngine] Cleaning transcode engine and its data
2012-03-18 11:42:16,597 DEBUG [AbstractTranscodingDeliveryEngine] Deleting temporary transcoded files from: C:\Windows\TEMP\Serviio
2012-03-18 11:42:16,731 INFO  [WebServer] WebServer starting on port 8895
2012-03-18 11:42:16,735 DEBUG [DiscoveryManager] UPNP device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3 (192.168.0.112) is available
2012-03-18 11:42:16,739 INFO  [EventDispatcher] Starting EventDispatcher
2012-03-18 11:42:16,741 INFO  [RendererSearchSender] Searching for Renderer devices
2012-03-18 11:42:16,741 INFO  [RendererExpirationChecker] Starting RendererExpirationChecker
2012-03-18 11:42:16,742 INFO  [EventSubscriptionExpirationChecker] Starting EventSubscriptionExpirationChecker
2012-03-18 11:42:16,742 INFO  [DiscoveryAdvertisementNotifier] Starting DiscoveryAdvertisementNotifier
2012-03-18 11:42:16,762 INFO  [DiscoverySSDPMessageListener] Starting DiscoverySSDPMessageListener using interface eth2 (NVIDIA nForce 10/100 Mbps Ethernet ) and address 192.168.0.112, timeout = 0
2012-03-18 11:42:16,985 DEBUG [RendererSearchSender] Multicasting SSDP M-SEARCH using interface eth2 (NVIDIA nForce 10/100 Mbps Ethernet ) and address 192.168.0.112, timeout = 0
2012-03-18 11:42:17,005 DEBUG [RendererSearchSender] Sending 1 'm-search' messages
2012-03-18 11:42:17,010 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth2 (NVIDIA nForce 10/100 Mbps Ethernet ) and address 192.168.0.112, timeout = 0
2012-03-18 11:42:17,011 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3
2012-03-18 11:42:17,015 DEBUG [DiscoverySSDPMessageListener] Received a valid M-SEARCH message for search target urn:schemas-upnp-org:device:MediaRenderer:1 from address /192.168.0.112:60111
2012-03-18 11:42:17,020 DEBUG [DiscoverySSDPMessageListener] Received a valid M-SEARCH message for search target urn:schemas-upnp-org:device:MediaRenderer:1 from address /192.168.0.112:60111
2012-03-18 11:42:17,020 DEBUG [DiscoverySSDPMessageListener] Received a valid M-SEARCH message for search target urn:schemas-upnp-org:device:MediaRenderer:1 from address /192.168.0.112:60111
2012-03-18 11:42:17,033 DEBUG [WebServer] Incoming connection from /192.168.0.112:50097
2012-03-18 11:42:17,040 DEBUG [DeviceDescriptionRequestHandler] DeviceDescription request received for device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3 from 192.168.0.112 (headers = [HOST: 192.168.0.112:8895,Content-Length: 0])
2012-03-18 11:42:17,040 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.112
2012-03-18 11:42:17,064 DEBUG [RendererManager] Looking for a renderer profile for Http headers: [HOST: 192.168.0.112:8895,Content-Length: 0]
2012-03-18 11:42:17,064 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.112
2012-03-18 11:42:17,337 DEBUG [DeviceDescriptionRequestHandler] Sending DeviceDescription XML back using profile 'Generic DLNA profile'
2012-03-18 11:42:17,353 DEBUG [ServiceDescriptionRequestHandler] ServiceDescription request received for service X_MS_MediaReceiverRegistrar
2012-03-18 11:42:17,362 DEBUG [ServiceDescriptionRequestHandler] Sending ServiceDescription XML back
2012-03-18 11:42:17,364 DEBUG [ServiceDescriptionRequestHandler] ServiceDescription request received for service ConnectionManager
2012-03-18 11:42:17,375 DEBUG [ServiceDescriptionRequestHandler] Sending ServiceDescription XML back
2012-03-18 11:42:17,393 DEBUG [WebServer] Incoming connection from /192.168.0.112:50099
2012-03-18 11:42:17,394 DEBUG [ServiceDescriptionRequestHandler] Sending ServiceDescription XML back
2012-03-18 11:42:17,395 DEBUG [WebServer] Incoming connection from /192.168.0.112:50101
2012-03-18 11:42:17,396 DEBUG [WebServer] Incoming connection from /192.168.0.112:50100
2012-03-18 11:42:17,396 DEBUG [UPnPIconRequestHandler] UPnP icon request received for icon largePNG
2012-03-18 11:42:17,410 DEBUG [WebServer] Incoming connection from /192.168.0.112:50098
2012-03-18 11:42:17,455 DEBUG [UPnPIconRequestHandler] UPnP icon request received for icon largeJPG
2012-03-18 11:42:17,456 DEBUG [UPnPIconRequestHandler] UPnP icon request received for icon smallJPG
2012-03-18 11:42:17,465 DEBUG [UPnPIconRequestHandler] UPnP icon request received for icon smallPNG
2012-03-18 11:42:17,480 DEBUG [ServiioConsole] Initializing Serviio Console
2012-03-18 11:42:17,503 DEBUG [ApplicationInstanceManager] Listening for application instances on socket 44332
2012-03-18 11:42:17,505 INFO  [ServiioConsole] Starting Serviio Console
2012-03-18 11:42:17,561 DEBUG [SwingHelper] Choosing java look and feel: com.sun.java.swing.plaf.windows.WindowsLookAndFeel
2012-03-18 11:42:17,620 DEBUG [WebServer] Incoming connection from /192.168.0.116:2069
2012-03-18 11:42:17,621 DEBUG [DeviceDescriptionRequestHandler] DeviceDescription request received for device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3 from 192.168.0.116 (headers = [HOST: 192.168.0.112:8895,CONNECTION: close])
2012-03-18 11:42:17,621 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 11:42:17,622 DEBUG [RendererManager] Looking for a renderer profile for Http headers: [HOST: 192.168.0.112:8895,CONNECTION: close]
2012-03-18 11:42:17,623 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 11:42:17,626 DEBUG [DeviceDescriptionRequestHandler] Sending DeviceDescription XML back using profile 'Generic DLNA profile'
2012-03-18 11:42:17,630 INFO  [ServiioConsole] Connecting to Serviio REST on localhost:23423
2012-03-18 11:42:17,665 DEBUG [WebServer] Incoming connection from /192.168.0.116:2070
2012-03-18 11:42:17,668 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 11:42:17,763 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2012-03-18 11:42:17,772 DEBUG [WebServer] Incoming connection from /192.168.0.116:2071
2012-03-18 11:42:17,774 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 11:42:17,784 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2012-03-18 11:42:17,795 DEBUG [WebServer] Incoming connection from /192.168.0.116:2072
2012-03-18 11:42:17,804 DEBUG [WebServer] Incoming connection from /192.168.0.116:2073
2012-03-18 11:42:17,807 DEBUG [ServiceEventSubscriptionRequestHandler] ServiceEvent subscription request received for service X_MS_MediaReceiverRegistrar
2012-03-18 11:42:17,807 DEBUG [ServiceEventSubscriptionRequestHandler] Event subscription registered (uuid=831cebc6-edcd-4bc3-9bd3-90a05c6f5e79) for service urn:microsoft.com:serviceId:X_MS_MediaReceiverRegistrar reporting to http://192.168.0.116:40001/
2012-03-18 11:42:18,264 DEBUG [EventDispatcher] Sending event notification #0 for subscription c8a371aa-1325-4775-b043-eed159dbb5f1 to endpoint http://192.168.0.116:40001/
2012-03-18 11:42:18,285 DEBUG [RequestExecutor] Sending HTTP request to 192.168.0.116:40001
2012-03-18 11:42:18,297 DEBUG [EventDispatcher] Event notification sent and received successfully
2012-03-18 11:42:18,816 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:00:10
2012-03-18 11:42:19,725 DEBUG [RendererSearchSender] Received search response: location: http://192.168.0.116:30104/, st: urn:schemas-upnp-org:device:MediaRenderer:1
2012-03-18 11:42:19,725 DEBUG [RendererSearchSender] Received a valid M-SEARCH response from Renderer 258b05d8-1dd2-11b2-9f85-001f29112166 from address /192.168.0.116:1900
2012-03-18 11:42:19,727 DEBUG [RendererSearchSender] Received search response: location: http://192.168.0.116:30104/, st: urn:schemas-upnp-org:device:MediaRenderer:1
2012-03-18 11:42:19,727 DEBUG [RendererSearchSender] Received a valid M-SEARCH response from Renderer 258b05d8-1dd2-11b2-9f85-001f29112166 from address /192.168.0.116:1900
2012-03-18 11:42:19,728 DEBUG [RendererSearchSender] Received search response: location: http://192.168.0.116:30104/, st: urn:schemas-upnp-org:device:MediaRenderer:1
2012-03-18 11:42:19,728 DEBUG [RendererSearchSender] Received a valid M-SEARCH response from Renderer 258b05d8-1dd2-11b2-9f85-001f29112166 from address /192.168.0.116:1900
2012-03-18 11:42:19,739 DEBUG [RendererManager] Adding renderer Renderer [uuid=258b05d8-1dd2-11b2-9f85-001f29112166, ipAddress=192.168.0.116, name=HP MediaSmart Connect, profileId=1, manuallyAdded=false, forcedProfile=false] to list of active renderers
2012-03-18 11:42:23,005 DEBUG [RendererSearchSender] Finished searching for Renderer devices
2012-03-18 11:42:23,497 DEBUG [ServiioConsole] Retrieving preferred console language
2012-03-18 11:42:23,560 DEBUG [ServiioConsole] Setting console locale to be: en
2012-03-18 11:42:23,566 INFO  [Messages] Loaded console message bundle for locale: en
2012-03-18 11:42:23,640 INFO  [UpdateChecker] Checking if a new version is available
2012-03-18 11:42:24,592 DEBUG [ServiioFrameView] Initializing main frame
2012-03-18 11:42:24,634 DEBUG [ServiioFrameView] System tray is supported
2012-03-18 11:42:24,883 DEBUG [RepositoryDAOImpl] Reading all Repositories
2012-03-18 11:42:24,920 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:42:25,014 DEBUG [RendererDAOImpl] Retrieving list of all stored renderers
2012-03-18 11:42:25,374 DEBUG [MetadataExtractorConfigDAOImpl] Reading a list of Extractor configuration for type AUDIO
2012-03-18 11:42:25,401 DEBUG [MetadataExtractorConfigDAOImpl] Reading a list of Extractor configuration for type VIDEO
2012-03-18 11:42:26,431 INFO  [BrowsingCategoriesMessages] Loaded browsing categories message bundle for locale: en
2012-03-18 11:42:26,786 DEBUG [RepositoryDAOImpl] Reading all Repositories
2012-03-18 11:42:26,787 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:42:26,803 DEBUG [RepositoryView$LibraryStatusCheckerThread] Starting library status checking thread
2012-03-18 11:42:28,959 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth2 (NVIDIA nForce 10/100 Mbps Ethernet ) and address 192.168.0.112, timeout = 0
2012-03-18 11:42:28,960 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3
2012-03-18 11:42:30,761 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:00:10
2012-03-18 11:42:40,905 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth2 (NVIDIA nForce 10/100 Mbps Ethernet ) and address 192.168.0.112, timeout = 0
2012-03-18 11:42:40,906 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3
2012-03-18 11:42:42,706 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:01:24
2012-03-18 11:42:43,009 INFO  [FeedUpdaterThread] Started looking for information about online resources
2012-03-18 11:42:43,009 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-03-18 11:42:43,009 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:42:43,010 DEBUG [RepositoryDAOImpl] Reading all Repositories
2012-03-18 11:42:43,012 DEBUG [RepositoryDAOImpl] Reading all Repositories
2012-03-18 11:43:43,014 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-03-18 11:43:43,014 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:44:07,143 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth2 (NVIDIA nForce 10/100 Mbps Ethernet ) and address 192.168.0.112, timeout = 0
2012-03-18 11:44:07,144 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3
2012-03-18 11:44:08,944 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:01:09
2012-03-18 11:44:43,015 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-03-18 11:44:43,015 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:44:53,313 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:44:53,315 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-03-18 11:44:53,315 DEBUG [ConfigEntryDAOImpl] Reading a ConfigEntry (name = search_hidden_files)
2012-03-18 11:44:53,315 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:44:53,323 DEBUG [ConfigEntryDAOImpl] Creating a new ConfigEntry (name = search_hidden_files, value = false)
2012-03-18 11:44:53,408 DEBUG [ConfigEntryDAOImpl] Reading a ConfigEntry (name = search_updated_files)
2012-03-18 11:44:53,409 DEBUG [ConfigEntryDAOImpl] Creating a new ConfigEntry (name = search_updated_files, value = true)
2012-03-18 11:44:53,411 DEBUG [ConfigEntryDAOImpl] Reading a ConfigEntry (name = repository_automatic_check)
2012-03-18 11:44:53,412 DEBUG [ConfigEntryDAOImpl] Creating a new ConfigEntry (name = repository_automatic_check, value = false)
2012-03-18 11:44:53,414 DEBUG [ConfigEntryDAOImpl] Reading a ConfigEntry (name = online_feed_max_num_items)
2012-03-18 11:44:53,415 DEBUG [ConfigEntryDAOImpl] Creating a new ConfigEntry (name = online_feed_max_num_items, value = 20)
2012-03-18 11:44:53,417 DEBUG [ConfigEntryDAOImpl] Reading a ConfigEntry (name = online_feed_expiry_interval)
2012-03-18 11:44:53,417 DEBUG [ConfigEntryDAOImpl] Creating a new ConfigEntry (name = online_feed_expiry_interval, value = 24)
2012-03-18 11:44:53,620 DEBUG [RepositoryServerResource] Updating repository with values: Repository [id=null, folder=J:\Movies Recent\By Request, keepScanningForUpdates=true, lastScanned=null, supportedFileTypes=[], supportsOnlineMetadata=false]
2012-03-18 11:44:53,621 DEBUG [RepositoryDAOImpl] Reading all Repositories
2012-03-18 11:44:53,621 DEBUG [RepositoryService] Found 0 repositories to be removed
2012-03-18 11:44:53,622 DEBUG [RepositoryDAOImpl] Creating a new Repository (folder = J:\Movies Recent\By Request)
2012-03-18 11:44:53,674 DEBUG [RepositoryDAOImpl] Reading all Repositories
2012-03-18 11:44:53,675 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:44:53,774 DEBUG [RepositoryDAOImpl] Reading all Repositories
2012-03-18 11:44:53,775 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:44:55,826 DEBUG [ActionsServerResource] Action with name 'forceLibraryRefresh' was requested
2012-03-18 11:44:55,828 DEBUG [RepositoryDAOImpl] Reading all Repositories
2012-03-18 11:44:55,830 DEBUG [RepositoryDAOImpl] Reading all Repositories
2012-03-18 11:44:55,831 DEBUG [RepositoryDAOImpl] Marking Repository 1 as scanned with current timestamp
2012-03-18 11:44:55,843 DEBUG [MediaItemDAOImpl] Reading MediaItems for Repository (id = 1)
2012-03-18 11:44:55,925 DEBUG [MediaItemDAOImpl] Reading dirty MediaItems for Repository (id = 1)
2012-03-18 11:44:55,976 DEBUG [RepositoryDAOImpl] Marking Repository 1 as scanned with current timestamp
2012-03-18 11:45:01,826 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:45:01,827 DEBUG [ConfigEntryDAOImpl] Reading a ConfigEntry (name = search_hidden_files)
2012-03-18 11:45:01,827 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-03-18 11:45:01,828 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:45:01,828 DEBUG [ConfigEntryDAOImpl] Updating ConfigEntry (name = search_hidden_files, value = false)
2012-03-18 11:45:01,839 DEBUG [ConfigEntryDAOImpl] Reading a ConfigEntry (name = search_updated_files)
2012-03-18 11:45:01,840 DEBUG [ConfigEntryDAOImpl] Updating ConfigEntry (name = search_updated_files, value = true)
2012-03-18 11:45:01,841 DEBUG [ConfigEntryDAOImpl] Reading a ConfigEntry (name = repository_automatic_check)
2012-03-18 11:45:01,842 DEBUG [ConfigEntryDAOImpl] Updating ConfigEntry (name = repository_automatic_check, value = false)
2012-03-18 11:45:01,844 DEBUG [ConfigEntryDAOImpl] Reading a ConfigEntry (name = online_feed_max_num_items)
2012-03-18 11:45:01,844 DEBUG [ConfigEntryDAOImpl] Updating ConfigEntry (name = online_feed_max_num_items, value = 20)
2012-03-18 11:45:01,846 DEBUG [ConfigEntryDAOImpl] Reading a ConfigEntry (name = online_feed_expiry_interval)
2012-03-18 11:45:01,846 DEBUG [ConfigEntryDAOImpl] Updating ConfigEntry (name = online_feed_expiry_interval, value = 24)
2012-03-18 11:45:01,849 DEBUG [RepositoryServerResource] Updating repository with values: Repository [id=1, folder=J:\Movies Recent\By Request, keepScanningForUpdates=true, lastScanned=null, supportedFileTypes=[VIDEO], supportsOnlineMetadata=true]
2012-03-18 11:45:01,849 DEBUG [RepositoryDAOImpl] Reading all Repositories
2012-03-18 11:45:01,850 DEBUG [RepositoryService] Found 0 repositories to be removed
2012-03-18 11:45:01,850 DEBUG [RepositoryDAOImpl] Reading a Repository (id = 1)
2012-03-18 11:45:01,857 DEBUG [MediaItemDAOImpl] Reading MediaItems for Repository (id = 1)
2012-03-18 11:45:01,858 DEBUG [RepositoryDAOImpl] Updating Repository (id = 1)
2012-03-18 11:45:01,884 DEBUG [RepositoryDAOImpl] Reading all Repositories
2012-03-18 11:45:01,885 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:45:08,913 DEBUG [ActionsServerResource] Action with name 'forceLibraryRefresh' was requested
2012-03-18 11:45:08,914 DEBUG [RepositoryDAOImpl] Reading all Repositories
2012-03-18 11:45:08,916 DEBUG [RepositoryDAOImpl] Reading all Repositories
2012-03-18 11:45:08,917 DEBUG [MediaItemDAOImpl] Reading MediaItems for Repository (id = 1)
2012-03-18 11:45:08,918 DEBUG [MediaItemDAOImpl] Reading dirty MediaItems for Repository (id = 1)
2012-03-18 11:45:08,922 DEBUG [RepositoryDAOImpl] Marking Repository 1 as scanned with current timestamp
2012-03-18 11:45:08,936 DEBUG [MediaItemDAOImpl] Checking if DB already contains media item GLORIOUS_39.avi
2012-03-18 11:45:08,957 DEBUG [MediaItemDAOImpl] Media item GLORIOUS_39.avi doesn't exist in DB yet
2012-03-18 11:45:08,966 DEBUG [MetadataExtractorConfigDAOImpl] Reading a list of Extractor configuration for type AUDIO
2012-03-18 11:45:08,968 DEBUG [MetadataExtractorConfigDAOImpl] Reading a list of Extractor configuration for type VIDEO
2012-03-18 11:45:08,970 DEBUG [MetadataExtractorConfigDAOImpl] Reading a list of Extractor configuration for type IMAGE
2012-03-18 11:45:08,974 DEBUG [VideoExtractionStrategy] Extracting metadata of video file: J:\Movies Recent\By Request\GLORIOUS_39.avi
2012-03-18 11:45:08,976 DEBUG [FFMPEGWrapper] Invoking FFMPEG to retrieve media information for file: J:\Movies Recent\By Request\GLORIOUS_39.avi
2012-03-18 11:45:08,976 DEBUG [ProcessExecutor] Starting C:\Program Files\Serviio\bin\\..\lib/ffmpeg.exe -i J:\Movies Recent\By Request\GLORIOUS_39.avi
2012-03-18 11:45:09,252 DEBUG [FFMPEGWrapper] Invoking FFMPEG to retrieve thumbnail for file: J:\Movies Recent\By Request\GLORIOUS_39.avi
2012-03-18 11:45:09,252 DEBUG [ProcessExecutor] Starting C:\Program Files\Serviio\bin\\..\lib/ffmpeg.exe -ss 120 -i J:\Movies Recent\By Request\GLORIOUS_39.avi -an -vframes 1 -f image2 pipe:
2012-03-18 11:45:10,874 DEBUG [VideoService] Adding video into database: Glorious 39
2012-03-18 11:45:10,904 DEBUG [GenreDAOImpl] Reading a Genre (name = Drama)
2012-03-18 11:45:10,913 DEBUG [GenreService] Genre Drama not found, creating a new one
2012-03-18 11:45:10,914 DEBUG [GenreDAOImpl] Creating a new Genre (name = Drama)
2012-03-18 11:45:10,920 DEBUG [CoverImageService] Resizing and storing cover art image
2012-03-18 11:45:10,923 DEBUG [ImageUtils] Starting image resize, size = 23442 bytes
2012-03-18 11:45:11,072 DEBUG [ImageUtils] Returning resized image, size = 5753 bytes
2012-03-18 11:45:11,072 DEBUG [CoverImageService] Image successfully resized
2012-03-18 11:45:11,074 DEBUG [CoverImageDAOImpl] Creating a new ImageCover (length = 5753)
2012-03-18 11:45:11,468 DEBUG [MetadataDescriptorDAOImpl] Creating a new MetadataDescriptor (type = ONLINE_VIDEO_SOURCES, mediaItemId = 1)
2012-03-18 11:45:11,481 DEBUG [MetadataDescriptorDAOImpl] Creating a new MetadataDescriptor (type = EMBEDDED, mediaItemId = 1)
2012-03-18 11:45:11,503 DEBUG [MediaItemDAOImpl] Checking if DB already contains media item HANOVER_STREET_DVD.mpg
2012-03-18 11:45:11,503 DEBUG [MediaItemDAOImpl] Media item HANOVER_STREET_DVD.mpg doesn't exist in DB yet
2012-03-18 11:45:11,504 DEBUG [VideoExtractionStrategy] Extracting metadata of video file: J:\Movies Recent\By Request\HANOVER_STREET_DVD.mpg
2012-03-18 11:45:11,504 DEBUG [FFMPEGWrapper] Invoking FFMPEG to retrieve media information for file: J:\Movies Recent\By Request\HANOVER_STREET_DVD.mpg
2012-03-18 11:45:11,504 DEBUG [ProcessExecutor] Starting C:\Program Files\Serviio\bin\\..\lib/ffmpeg.exe -i J:\Movies Recent\By Request\HANOVER_STREET_DVD.mpg
2012-03-18 11:45:11,721 DEBUG [FFMPEGWrapper] Invoking FFMPEG to retrieve thumbnail for file: J:\Movies Recent\By Request\HANOVER_STREET_DVD.mpg
2012-03-18 11:45:11,722 DEBUG [ProcessExecutor] Starting C:\Program Files\Serviio\bin\\..\lib/ffmpeg.exe -i J:\Movies Recent\By Request\HANOVER_STREET_DVD.mpg -ss 120 -an -vframes 1 -f image2 pipe:
2012-03-18 11:45:11,875 DEBUG [AbstractCDSLibraryIndexingListener] Library updated, notifying CDS
2012-03-18 11:45:11,876 DEBUG [LocalContentCacheDecorator] Cleared cache (local_resetafterplay)
2012-03-18 11:45:11,876 DEBUG [LocalContentCacheDecorator] Cleared cache (local_default)
2012-03-18 11:45:12,302 DEBUG [EventDispatcher] Sending event notification #1 for subscription c8a371aa-1325-4775-b043-eed159dbb5f1 to endpoint http://192.168.0.116:40001/
2012-03-18 11:45:12,304 DEBUG [RequestExecutor] Sending HTTP request to 192.168.0.116:40001
2012-03-18 11:45:12,308 DEBUG [EventDispatcher] Event notification sent and received successfully
2012-03-18 11:45:17,981 DEBUG [RendererManager] Retrieve device description from http://192.168.0.112:2869/upnphost/udhisapi.dll?content=uuid:733f3962-6393-4458-a89f-5ddaba37df9f
2012-03-18 11:45:18,003 DEBUG [RendererManager] Looking for a renderer profile for: friendly name = 'movieserver', model name= 'Windows Media Player', model number = '11', manufacturer = 'Microsoft', product code = 'null', server name = 'Microsoft-Windows-NT/5.1 UPnP/1.0 UPnP-Device-Host/1.0'
2012-03-18 11:45:18,004 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.112
2012-03-18 11:45:18,005 DEBUG [RendererDAOImpl] Deleting a Renderer (uuid = 73fe9cf7-4d42-4208-a58a-551fa0824e2d)
2012-03-18 11:45:18,028 DEBUG [RendererDAOImpl] Creating a new Renderer (uuid = 733f3962-6393-4458-a89f-5ddaba37df9f)
2012-03-18 11:45:18,035 INFO  [RendererManager] Stored a new renderer: uuid='733f3962-6393-4458-a89f-5ddaba37df9f', name = 'Windows Media Player', ipAddress='192.168.0.112', profile = '1'
2012-03-18 11:45:18,035 DEBUG [RendererManager] Adding renderer Renderer [uuid=733f3962-6393-4458-a89f-5ddaba37df9f, ipAddress=192.168.0.112, name=Windows Media Player, profileId=1, manuallyAdded=false, forcedProfile=false] to list of active renderers
2012-03-18 11:45:18,782 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth2 (NVIDIA nForce 10/100 Mbps Ethernet ) and address 192.168.0.112, timeout = 0
2012-03-18 11:45:18,782 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3
2012-03-18 11:45:19,389 DEBUG [WebServer] Incoming connection from /192.168.0.116:2080
2012-03-18 11:45:19,390 DEBUG [DeviceDescriptionRequestHandler] DeviceDescription request received for device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3 from 192.168.0.116 (headers = [HOST: 192.168.0.112:8895,CONNECTION: close])
2012-03-18 11:45:19,391 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 11:45:19,391 DEBUG [RendererManager] Looking for a renderer profile for Http headers: [HOST: 192.168.0.112:8895,CONNECTION: close]
2012-03-18 11:45:19,392 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 11:45:19,402 DEBUG [DeviceDescriptionRequestHandler] Sending DeviceDescription XML back using profile 'Generic DLNA profile'
2012-03-18 11:45:19,447 DEBUG [WebServer] Incoming connection from /192.168.0.116:2081
2012-03-18 11:45:19,454 DEBUG [WebServer] Incoming connection from /192.168.0.116:2082
2012-03-18 11:45:19,455 DEBUG [ServiceEventSubscriptionRequestHandler] ServiceEvent renewal request received for service X_MS_MediaReceiverRegistrar and subscription uuid:831cebc6-edcd-4bc3-9bd3-90a05c6f5e79
2012-03-18 11:45:19,455 DEBUG [ServiceEventSubscriptionRequestHandler] Event subscription renewed for service urn:microsoft.com:serviceId:X_MS_MediaReceiverRegistrar and subscription 831cebc6-edcd-4bc3-9bd3-90a05c6f5e79
2012-03-18 11:45:20,583 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:01:24
2012-03-18 11:45:23,160 DEBUG [CoverImageInFolderExtractor] Found cover image HANOVER_STREET_DVD.jpg
2012-03-18 11:45:23,197 DEBUG [VideoService] Adding video into database: Hanover Street
2012-03-18 11:45:23,198 DEBUG [GenreDAOImpl] Reading a Genre (name = Drama)
2012-03-18 11:45:23,199 DEBUG [GenreService] Genre Drama found
2012-03-18 11:45:23,199 DEBUG [CoverImageService] Resizing and storing cover art image
2012-03-18 11:45:23,199 DEBUG [ImageUtils] Starting image resize, size = 41063 bytes
2012-03-18 11:45:23,227 DEBUG [ImageUtils] Returning resized image, size = 6871 bytes
2012-03-18 11:45:23,227 DEBUG [CoverImageService] Image successfully resized
2012-03-18 11:45:23,228 DEBUG [CoverImageDAOImpl] Creating a new ImageCover (length = 6871)
2012-03-18 11:45:23,276 DEBUG [MetadataDescriptorDAOImpl] Creating a new MetadataDescriptor (type = COVER_IMAGE_IN_FOLDER, mediaItemId = 2)
2012-03-18 11:45:23,278 DEBUG [MetadataDescriptorDAOImpl] Creating a new MetadataDescriptor (type = ONLINE_VIDEO_SOURCES, mediaItemId = 2)
2012-03-18 11:45:23,280 DEBUG [MetadataDescriptorDAOImpl] Creating a new MetadataDescriptor (type = EMBEDDED, mediaItemId = 2)
2012-03-18 11:45:23,303 DEBUG [MediaItemDAOImpl] Checking if DB already contains media item THUNDER_ROCK_480P_DVD_PAL.mkv
2012-03-18 11:45:23,304 DEBUG [MediaItemDAOImpl] Media item THUNDER_ROCK_480P_DVD_PAL.mkv doesn't exist in DB yet
2012-03-18 11:45:23,304 DEBUG [VideoExtractionStrategy] Extracting metadata of video file: J:\Movies Recent\By Request\THUNDER_ROCK_480P_DVD_PAL.mkv
2012-03-18 11:45:23,304 DEBUG [FFMPEGWrapper] Invoking FFMPEG to retrieve media information for file: J:\Movies Recent\By Request\THUNDER_ROCK_480P_DVD_PAL.mkv
2012-03-18 11:45:23,305 DEBUG [ProcessExecutor] Starting C:\Program Files\Serviio\bin\\..\lib/ffmpeg.exe -i J:\Movies Recent\By Request\THUNDER_ROCK_480P_DVD_PAL.mkv
2012-03-18 11:45:23,482 DEBUG [FFmpegMetadataRetriever] Retrieving H264 profile/level for file 'J:\Movies Recent\By Request\THUNDER_ROCK_480P_DVD_PAL.mkv'
2012-03-18 11:45:23,483 DEBUG [FFMPEGWrapper] Invoking FFMPEG to retrieve H264 header for file: J:\Movies Recent\By Request\THUNDER_ROCK_480P_DVD_PAL.mkv
2012-03-18 11:45:23,483 DEBUG [ProcessExecutor] Starting C:\Program Files\Serviio\bin\\..\lib/ffmpeg.exe -i J:\Movies Recent\By Request\THUNDER_ROCK_480P_DVD_PAL.mkv -vframes 1 -vcodec copy -f h264 -vbsf h264_mp4toannexb -an pipe:
2012-03-18 11:45:23,618 DEBUG [FFmpegMetadataRetriever] H264 Level value stored in the AVC header (3.1) is different than one based on ref_frames value (2.2), the higher will be stored
2012-03-18 11:45:23,619 DEBUG [FFmpegMetadataRetriever] File 'J:\Movies Recent\By Request\THUNDER_ROCK_480P_DVD_PAL.mkv' has H264 profile HIGH, level 3.1 and 4 ref frames
2012-03-18 11:45:23,619 DEBUG [FFMPEGWrapper] Invoking FFMPEG to retrieve thumbnail for file: J:\Movies Recent\By Request\THUNDER_ROCK_480P_DVD_PAL.mkv
2012-03-18 11:45:23,619 DEBUG [ProcessExecutor] Starting C:\Program Files\Serviio\bin\\..\lib/ffmpeg.exe -ss 120 -i J:\Movies Recent\By Request\THUNDER_ROCK_480P_DVD_PAL.mkv -an -vframes 1 -f image2 pipe:
2012-03-18 11:45:26,876 DEBUG [AbstractCDSLibraryIndexingListener] Library updated, notifying CDS
2012-03-18 11:45:26,876 DEBUG [LocalContentCacheDecorator] Cleared cache (local_resetafterplay)
2012-03-18 11:45:26,876 DEBUG [LocalContentCacheDecorator] Cleared cache (local_default)
2012-03-18 11:45:27,309 DEBUG [EventDispatcher] Sending event notification #2 for subscription c8a371aa-1325-4775-b043-eed159dbb5f1 to endpoint http://192.168.0.116:40001/
2012-03-18 11:45:27,311 DEBUG [RequestExecutor] Sending HTTP request to 192.168.0.116:40001
2012-03-18 11:45:27,314 DEBUG [EventDispatcher] Event notification sent and received successfully
2012-03-18 11:45:28,922 DEBUG [VideoService] Adding video into database: Thor
2012-03-18 11:45:28,923 DEBUG [GenreDAOImpl] Reading a Genre (name = Fantasy)
2012-03-18 11:45:28,924 DEBUG [GenreService] Genre Fantasy not found, creating a new one
2012-03-18 11:45:28,924 DEBUG [GenreDAOImpl] Creating a new Genre (name = Fantasy)
2012-03-18 11:45:28,927 DEBUG [CoverImageService] Resizing and storing cover art image
2012-03-18 11:45:28,927 DEBUG [ImageUtils] Starting image resize, size = 26651 bytes
2012-03-18 11:45:28,945 DEBUG [ImageUtils] Returning resized image, size = 5622 bytes
2012-03-18 11:45:28,945 DEBUG [CoverImageService] Image successfully resized
2012-03-18 11:45:28,945 DEBUG [CoverImageDAOImpl] Creating a new ImageCover (length = 5622)
2012-03-18 11:45:29,041 DEBUG [MetadataDescriptorDAOImpl] Creating a new MetadataDescriptor (type = ONLINE_VIDEO_SOURCES, mediaItemId = 3)
2012-03-18 11:45:29,043 DEBUG [MetadataDescriptorDAOImpl] Creating a new MetadataDescriptor (type = EMBEDDED, mediaItemId = 3)
2012-03-18 11:45:29,045 DEBUG [RepositoryDAOImpl] Marking Repository 1 as scanned with current timestamp
2012-03-18 11:45:31,876 DEBUG [AbstractCDSLibraryIndexingListener] Library updated, notifying CDS
2012-03-18 11:45:31,877 DEBUG [LocalContentCacheDecorator] Cleared cache (local_resetafterplay)
2012-03-18 11:45:31,877 DEBUG [LocalContentCacheDecorator] Cleared cache (local_default)
2012-03-18 11:45:32,314 DEBUG [EventDispatcher] Sending event notification #3 for subscription c8a371aa-1325-4775-b043-eed159dbb5f1 to endpoint http://192.168.0.116:40001/
2012-03-18 11:45:32,316 DEBUG [RequestExecutor] Sending HTTP request to 192.168.0.116:40001
2012-03-18 11:45:32,320 DEBUG [EventDispatcher] Event notification sent and received successfully
2012-03-18 11:46:01,828 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-03-18 11:46:01,828 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:46:44,769 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth2 (NVIDIA nForce 10/100 Mbps Ethernet ) and address 192.168.0.112, timeout = 0
2012-03-18 11:46:44,769 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3
2012-03-18 11:46:46,570 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:01:11
2012-03-18 11:47:01,830 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-03-18 11:47:01,830 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:47:18,271 DEBUG [DiscoverySSDPMessageListener] Received a valid M-SEARCH message for search target upnp:rootdevice from address /192.168.0.112:55254
2012-03-18 11:47:18,275 DEBUG [DiscoverySearchResponder] Sending 1 M-SEARCH response message(s) to /192.168.0.112:55254
2012-03-18 11:47:19,134 DEBUG [WebServer] Incoming connection from /192.168.0.112:50239
2012-03-18 11:47:19,135 DEBUG [DeviceDescriptionRequestHandler] DeviceDescription request received for device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3 from 192.168.0.112 (headers = [Accept: text/xml, application/xml,User-Agent: FDSSDP,Host: 192.168.0.112:8895,Connection: Keep-Alive,Cache-Control: no-cache,Pragma: no-cache])
2012-03-18 11:47:19,135 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.112
2012-03-18 11:47:19,136 DEBUG [RendererManager] Looking for a renderer profile for Http headers: [Accept: text/xml, application/xml,User-Agent: FDSSDP,Host: 192.168.0.112:8895,Connection: Keep-Alive,Cache-Control: no-cache,Pragma: no-cache]
2012-03-18 11:47:19,136 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.112
2012-03-18 11:47:19,139 DEBUG [DeviceDescriptionRequestHandler] Sending DeviceDescription XML back using profile 'Generic DLNA profile'
2012-03-18 11:47:21,273 DEBUG [DiscoverySSDPMessageListener] Received a valid M-SEARCH message for search target upnp:rootdevice from address /192.168.0.112:55254
2012-03-18 11:47:21,275 DEBUG [DiscoverySearchResponder] Sending 1 M-SEARCH response message(s) to /192.168.0.112:55254
2012-03-18 11:47:21,712 DEBUG [WebServer] Incoming connection from /192.168.0.112:50244
2012-03-18 11:47:21,713 DEBUG [DeviceDescriptionRequestHandler] DeviceDescription request received for device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3 from 192.168.0.112 (headers = [Accept: text/xml, application/xml,Host: 192.168.0.112,User-Agent: Mozilla/4.0 (compatible; UPnP/1.0; Windows NT/5.1),Connection: Close,Cache-Control: no-cache,Pragma: no-cache])
2012-03-18 11:47:21,713 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.112
2012-03-18 11:47:21,713 DEBUG [RendererManager] Looking for a renderer profile for Http headers: [Accept: text/xml, application/xml,Host: 192.168.0.112,User-Agent: Mozilla/4.0 (compatible; UPnP/1.0; Windows NT/5.1),Connection: Close,Cache-Control: no-cache,Pragma: no-cache]
2012-03-18 11:47:21,714 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.112
2012-03-18 11:47:21,717 DEBUG [DeviceDescriptionRequestHandler] Sending DeviceDescription XML back using profile 'Generic DLNA profile'
2012-03-18 11:47:24,274 DEBUG [DiscoverySSDPMessageListener] Received a valid M-SEARCH message for search target upnp:rootdevice from address /192.168.0.112:55254
2012-03-18 11:47:24,274 DEBUG [DiscoverySearchResponder] Sending 1 M-SEARCH response message(s) to /192.168.0.112:55254
2012-03-18 11:47:58,120 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth2 (NVIDIA nForce 10/100 Mbps Ethernet ) and address 192.168.0.112, timeout = 0
2012-03-18 11:47:58,121 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3
2012-03-18 11:47:59,921 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:01:07
2012-03-18 11:48:01,830 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-03-18 11:48:01,830 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:48:48,297 DEBUG [WebServer] I/O error: Connection reset
2012-03-18 11:49:01,831 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-03-18 11:49:01,831 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:49:07,129 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth2 (NVIDIA nForce 10/100 Mbps Ethernet ) and address 192.168.0.112, timeout = 0
2012-03-18 11:49:07,129 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3
2012-03-18 11:49:07,738 DEBUG [WebServer] Incoming connection from /192.168.0.116:2086
2012-03-18 11:49:07,738 DEBUG [DeviceDescriptionRequestHandler] DeviceDescription request received for device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3 from 192.168.0.116 (headers = [HOST: 192.168.0.112:8895,CONNECTION: close])
2012-03-18 11:49:07,739 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 11:49:07,739 DEBUG [RendererManager] Looking for a renderer profile for Http headers: [HOST: 192.168.0.112:8895,CONNECTION: close]
2012-03-18 11:49:07,739 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 11:49:07,743 DEBUG [DeviceDescriptionRequestHandler] Sending DeviceDescription XML back using profile 'Generic DLNA profile'
2012-03-18 11:49:07,778 DEBUG [WebServer] Incoming connection from /192.168.0.116:2087
2012-03-18 11:49:07,778 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 11:49:07,784 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2012-03-18 11:49:07,792 DEBUG [WebServer] Incoming connection from /192.168.0.116:2088
2012-03-18 11:49:07,792 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 11:49:07,797 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2012-03-18 11:49:07,809 DEBUG [WebServer] Incoming connection from /192.168.0.116:2089
2012-03-18 11:49:07,815 DEBUG [WebServer] Incoming connection from /192.168.0.116:2090
2012-03-18 11:49:07,816 DEBUG [ServiceEventSubscriptionRequestHandler] ServiceEvent subscription request received for service X_MS_MediaReceiverRegistrar
2012-03-18 11:49:07,816 DEBUG [ServiceEventSubscriptionRequestHandler] Event subscription reused (uuid=831cebc6-edcd-4bc3-9bd3-90a05c6f5e79) for service urn:microsoft.com:serviceId:X_MS_MediaReceiverRegistrar reporting to http://192.168.0.116:40001/
2012-03-18 11:49:07,824 DEBUG [EventDispatcher] Sending event notification #4 for subscription c8a371aa-1325-4775-b043-eed159dbb5f1 to endpoint http://192.168.0.116:40001/
2012-03-18 11:49:07,825 DEBUG [RequestExecutor] Sending HTTP request to 192.168.0.116:40001
2012-03-18 11:49:07,829 DEBUG [EventDispatcher] Event notification sent and received successfully
2012-03-18 11:49:07,840 DEBUG [WebServer] Incoming connection from /192.168.0.116:2091
2012-03-18 11:49:07,852 DEBUG [WebServer] Incoming connection from /192.168.0.116:2092
2012-03-18 11:49:08,329 DEBUG [EventDispatcher] Sending event notification #0 for subscription edc6a1d1-940f-4a55-8028-ffbf86f6e0c7 to endpoint http://192.168.0.116:40001/
2012-03-18 11:49:08,329 DEBUG [RequestExecutor] Sending HTTP request to 192.168.0.116:40001
2012-03-18 11:49:08,336 DEBUG [EventDispatcher] Event notification sent and received successfully
2012-03-18 11:49:08,930 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:01:18
2012-03-18 11:50:01,832 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-03-18 11:50:01,832 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:50:20,864 DEBUG [EventSubscriptionExpirationChecker] Removed expired subscription 831cebc6-edcd-4bc3-9bd3-90a05c6f5e79 from service urn:microsoft.com:serviceId:X_MS_MediaReceiverRegistrar
2012-03-18 11:50:27,874 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth2 (NVIDIA nForce 10/100 Mbps Ethernet ) and address 192.168.0.112, timeout = 0
2012-03-18 11:50:27,875 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3
2012-03-18 11:50:29,675 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:01:25
2012-03-18 11:51:01,832 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-03-18 11:51:01,832 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:51:55,442 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth2 (NVIDIA nForce 10/100 Mbps Ethernet ) and address 192.168.0.112, timeout = 0
2012-03-18 11:51:55,443 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3
2012-03-18 11:51:57,243 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:01:23
2012-03-18 11:52:01,833 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-03-18 11:52:01,833 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:53:01,833 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-03-18 11:53:01,833 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:53:20,523 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth2 (NVIDIA nForce 10/100 Mbps Ethernet ) and address 192.168.0.112, timeout = 0
2012-03-18 11:53:20,523 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3
2012-03-18 11:53:21,129 DEBUG [WebServer] Incoming connection from /192.168.0.116:2100
2012-03-18 11:53:21,130 DEBUG [DeviceDescriptionRequestHandler] DeviceDescription request received for device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3 from 192.168.0.116 (headers = [HOST: 192.168.0.112:8895,CONNECTION: close])
2012-03-18 11:53:21,130 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 11:53:21,130 DEBUG [RendererManager] Looking for a renderer profile for Http headers: [HOST: 192.168.0.112:8895,CONNECTION: close]
2012-03-18 11:53:21,130 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 11:53:21,137 DEBUG [DeviceDescriptionRequestHandler] Sending DeviceDescription XML back using profile 'Generic DLNA profile'
2012-03-18 11:53:21,175 DEBUG [WebServer] Incoming connection from /192.168.0.116:2101
2012-03-18 11:53:21,176 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 11:53:21,181 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2012-03-18 11:53:21,191 DEBUG [WebServer] Incoming connection from /192.168.0.116:2102
2012-03-18 11:53:21,191 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 11:53:21,196 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2012-03-18 11:53:21,208 DEBUG [WebServer] Incoming connection from /192.168.0.116:2103
2012-03-18 11:53:21,214 DEBUG [WebServer] Incoming connection from /192.168.0.116:2104
2012-03-18 11:53:21,214 DEBUG [ServiceEventSubscriptionRequestHandler] ServiceEvent subscription request received for service X_MS_MediaReceiverRegistrar
2012-03-18 11:53:21,215 DEBUG [ServiceEventSubscriptionRequestHandler] Event subscription registered (uuid=d293dea8-b57c-443d-ade7-a8092b8d7c97) for service urn:microsoft.com:serviceId:X_MS_MediaReceiverRegistrar reporting to http://192.168.0.116:40001/
2012-03-18 11:53:21,336 DEBUG [EventDispatcher] Sending event notification #1 for subscription edc6a1d1-940f-4a55-8028-ffbf86f6e0c7 to endpoint http://192.168.0.116:40001/
2012-03-18 11:53:21,338 DEBUG [RequestExecutor] Sending HTTP request to 192.168.0.116:40001
2012-03-18 11:53:21,341 DEBUG [EventDispatcher] Event notification sent and received successfully
2012-03-18 11:53:22,323 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:01:21
2012-03-18 11:53:22,492 DEBUG [DiscoverySSDPMessageListener] Received a valid M-SEARCH message for search target upnp:rootdevice from address /192.168.0.112:51396
2012-03-18 11:53:22,493 DEBUG [DiscoverySearchResponder] Sending 1 M-SEARCH response message(s) to /192.168.0.112:51396
2012-03-18 11:53:22,494 DEBUG [DiscoverySSDPMessageListener] Received a valid M-SEARCH message for search target upnp:rootdevice from address /192.168.0.112:51396
2012-03-18 11:53:22,494 DEBUG [DiscoverySearchResponder] Sending 1 M-SEARCH response message(s) to /192.168.0.112:51396
2012-03-18 11:54:01,834 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-03-18 11:54:01,834 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:54:43,814 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth2 (NVIDIA nForce 10/100 Mbps Ethernet ) and address 192.168.0.112, timeout = 0
2012-03-18 11:54:43,815 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3
2012-03-18 11:54:45,615 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:01:06
2012-03-18 11:55:01,835 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-03-18 11:55:01,835 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:55:51,796 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth2 (NVIDIA nForce 10/100 Mbps Ethernet ) and address 192.168.0.112, timeout = 0
2012-03-18 11:55:51,796 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3
2012-03-18 11:55:53,597 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:01:04
2012-03-18 11:56:01,836 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-03-18 11:56:01,836 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-03-18 11:56:03,919 DEBUG [DiscoverySSDPMessageListener] Received a valid M-SEARCH message for search target urn:schemas-upnp-org:device:MediaServer:1 from address /192.168.0.112:51415
2012-03-18 11:56:03,920 DEBUG [DiscoverySearchResponder] Sending 1 M-SEARCH response message(s) to /192.168.0.112:51415
2012-03-18 11:56:04,019 DEBUG [DiscoverySSDPMessageListener] Received a valid M-SEARCH message for search target urn:schemas-upnp-org:device:MediaServer:1 from address /192.168.0.112:51415
2012-03-18 11:56:04,019 DEBUG [DiscoverySearchResponder] Sending 1 M-SEARCH response message(s) to /192.168.0.112:51415
2012-03-18 11:56:06,696 DEBUG [WebServer] Incoming connection from /192.168.0.112:50376
2012-03-18 11:56:06,697 DEBUG [DeviceDescriptionRequestHandler] DeviceDescription request received for device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3 from 192.168.0.112 (headers = [HOST: 192.168.0.112:8895,DATE: Sun, 18 Mar 2012 18:56:06 GMT,CONNECTION: close,USER-AGENT: 6.0.6002 2/Service Pack 2, UPnP/1.0, Portable SDK for UPnP devices/1.6.14])
2012-03-18 11:56:06,697 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.112
2012-03-18 11:56:06,698 DEBUG [RendererManager] Looking for a renderer profile for Http headers: [HOST: 192.168.0.112:8895,DATE: Sun, 18 Mar 2012 18:56:06 GMT,CONNECTION: close,USER-AGENT: 6.0.6002 2/Service Pack 2, UPnP/1.0, Portable SDK for UPnP devices/1.6.14]
2012-03-18 11:56:06,698 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.112
2012-03-18 11:56:06,704 DEBUG [DeviceDescriptionRequestHandler] Sending DeviceDescription XML back using profile 'Generic DLNA profile'
2012-03-18 11:56:06,709 DEBUG [WebServer] Incoming connection from /192.168.0.112:50377
2012-03-18 11:56:06,721 DEBUG [WebServer] Incoming connection from /192.168.0.112:50378
2012-03-18 11:56:06,722 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.112
2012-03-18 11:56:06,761 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2012-03-18 11:56:06,763 DEBUG [WebServer] Incoming connection from /192.168.0.112:50379
2012-03-18 11:56:06,763 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.112
2012-03-18 11:56:06,791 DEBUG [RepositoryDAOImpl] Retrieving number of repositories for AUDIO
2012-03-18 11:56:06,801 DEBUG [GenreDAOImpl] Retrieving number of genres for AUDIO
2012-03-18 11:56:06,820 DEBUG [MusicTrackDAOImpl] Retrieving number of music track initials
2012-03-18 11:56:06,835 DEBUG [MusicTrackDAOImpl] Retrieving number of random music tracks
2012-03-18 11:56:06,841 DEBUG [EventDispatcher] Sending event notification #0 for subscription 0bb43bd0-2a1d-4042-b4cd-0027c8e5c161 to endpoint http://192.168.0.112:0/
2012-03-18 11:56:06,844 DEBUG [RequestExecutor] Sending HTTP request to 192.168.0.112:0
2012-03-18 11:56:06,844 WARN  [EventDispatcher] Couldn't send event message for subscription 0bb43bd0-2a1d-4042-b4cd-0027c8e5c161, will keep trying until subscription expires
2012-03-18 11:56:06,846 DEBUG [OnlineRepositoryDAOImpl] Retrieving list of [FEED, WEB_RESOURCE] OnlineRepositories for AUDIO
2012-03-18 11:56:06,858 DEBUG [OnlineRepositoryDAOImpl] Retrieving list of [LIVE_STREAM] OnlineRepositories for AUDIO
2012-03-18 11:56:06,872 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2012-03-18 11:56:06,875 DEBUG [WebServer] Incoming connection from /192.168.0.112:50381
2012-03-18 11:56:06,876 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.112
2012-03-18 11:56:06,901 DEBUG [LocalContentCacheDecorator] Stored entry in the cache (local_default), returning it
2012-03-18 11:56:06,904 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2012-03-18 11:56:06,906 DEBUG [WebServer] Incoming connection from /192.168.0.112:50382
2012-03-18 11:56:06,907 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.112
2012-03-18 11:56:06,913 DEBUG [LocalContentCacheDecorator] Stored entry in the cache (local_default), returning it
2012-03-18 11:56:06,916 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2012-03-18 11:56:06,918 DEBUG [WebServer] Incoming connection from /192.168.0.112:50383
2012-03-18 11:56:06,918 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.112
2012-03-18 11:56:06,923 DEBUG [RepositoryDAOImpl] Retrieving list of Repositories for AUDIO (from=0, count=2147483647)
2012-03-18 11:56:06,929 DEBUG [RepositoryDAOImpl] Retrieving number of repositories for AUDIO
2012-03-18 11:56:06,930 DEBUG [LocalContentCacheDecorator] Stored entry in the cache (local_default), returning it
2012-03-18 11:56:06,933 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2012-03-18 11:56:06,936 DEBUG [WebServer] Incoming connection from /192.168.0.112:50384
2012-03-18 11:56:06,936 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.112
2012-03-18 11:56:06,941 DEBUG [GenreDAOImpl] Retrieving list of genres for AUDIO (from=0, count=2147483647)
2012-03-18 11:56:06,955 DEBUG [GenreDAOImpl] Retrieving number of genres for AUDIO
2012-03-18 11:56:06,956 DEBUG [LocalContentCacheDecorator] Stored entry in the cache (local_default), returning it
2012-03-18 11:56:06,959 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2012-03-18 11:56:06,961 DEBUG [WebServer] Incoming connection from /192.168.0.112:50385


[serviio-buddy]

Green light on MediaSmart Connect within Serviio Console is good.
Only 1 ip address shows in console with 192.168.0.116 is good.
VLC shows MediaSmart Connect which is good.
VLC shows Serviio Server working ok.

Reading thru the serviio.log, couldn't really see anything other than a "close" statement sometimes with 192.168.0.116.

Maybe try updating Java to the latest release, then restart your Serviio Server.

Uh... Serviio installer installed the version of Java I am running. Is that not the latest version? I did not have Java installed before I installed Serviio.

(Btw, when we finally get this working, I have created a proper profile for HPMSC that transcodes unsupported formats correctly, I'll be happy to send it to you.)

[serviio-buddy]

Serviio Log says you have Java 1.6.0_23 installed.
Newest verision is 1.7.0_03.

To verify and update Java version on your computer, go here: http://www.java.com/en/download/installed.jsp

Install update, then restart computer and see if this makes a difference.

I don't have the MediaSmart Connect device, but have read about it a lot on the internet. I'm sure your revisions to the profile will be greatly appreciated here for other users with the same device.

The devices I have are listed below (on my signature).

I updated to the latest Java ver. 7 and it made no difference. So I dropped back to the 1.6.0_31, the most recent ver. 6 recommended at the Java website.

I carefully ran some additional tests to compare 0.5.2 and 0.6.2 interactions and flow related to the HPMSC, and I found some key differences in the message and event flows in the two logs, when I look at them side-by-side. The log segments below are the first "n" interactions between Serviio and the HPMSC, first with 0.5.2 and then with 0.6.2. The 0.6.2 introduces some additional events - and therefore a different flow.

0.5.2 flow:

  Code:

2012-03-18 14:31:53,099 DEBUG [WebServer] Incoming connection from /192.168.0.116:1531
2012-03-18 14:31:53,100 DEBUG [DeviceDescriptionRequestHandler] DeviceDescription request received for device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3 from 192.168.0.116 (headers = [HOST: 192.168.0.112:8895,CONNECTION: close])
2012-03-18 14:31:53,100 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 14:31:53,101 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 14:31:53,128 DEBUG [WebServer] Incoming connection from /192.168.0.116:1532
2012-03-18 14:31:53,130 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#GetSearchCapabilities"' from 192.168.0.116:
2012-03-18 14:31:53,130 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 14:31:53,208 DEBUG [WebServer] Incoming connection from /192.168.0.116:1533
2012-03-18 14:31:53,209 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#GetSortCapabilities"' from 192.168.0.116:
2012-03-18 14:31:53,209 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 14:31:53,230 DEBUG [WebServer] Incoming connection from /192.168.0.116:1534
2012-03-18 14:31:53,232 DEBUG [ServiceEventSubscriptionRequestHandler] Event subscription registered (uuid=174caf11-ccac-40b6-907c-23e5b77c5e9b) for service urn:upnp-org:serviceId:ContentDirectory reporting to http://192.168.0.116:40001/
2012-03-18 14:31:53,237 DEBUG [EventDispatcher] Sending event notification #0 for subscription 174caf11-ccac-40b6-907c-23e5b77c5e9b to endpoint http://192.168.0.116:40001/
2012-03-18 14:31:53,248 DEBUG [RequestExecutor] Sending HTTP request to 192.168.0.116:40001
2012-03-18 14:31:54,971 DEBUG [RendererSearchSender] Received search response: location: http://192.168.0.116:30104/, st: urn:schemas-upnp-org:device:MediaRenderer:1
2012-03-18 14:31:54,971 DEBUG [RendererSearchSender] Received a valid M-SEARCH response from Renderer 258b05d8-1dd2-11b2-9f85-001f29112166 from address /192.168.0.116:1900
2012-03-18 14:31:54,973 DEBUG [RendererSearchSender] Received search response: location: http://192.168.0.116:30104/, st: urn:schemas-upnp-org:device:MediaRenderer:1
2012-03-18 14:31:54,973 DEBUG [RendererSearchSender] Received a valid M-SEARCH response from Renderer 258b05d8-1dd2-11b2-9f85-001f29112166 from address /192.168.0.116:1900
2012-03-18 14:31:54,974 DEBUG [RendererSearchSender] Received search response: location: http://192.168.0.116:30104/, st: urn:schemas-upnp-org:device:MediaRenderer:1
2012-03-18 14:31:54,974 DEBUG [RendererSearchSender] Received a valid M-SEARCH response from Renderer 258b05d8-1dd2-11b2-9f85-001f29112166 from address /192.168.0.116:1900
2012-03-18 14:31:55,003 DEBUG [RendererManager] Adding renderer Renderer [uuid=258b05d8-1dd2-11b2-9f85-001f29112166, ipAddress=192.168.0.116, name=HP MediaSmart Connect, profileId=1, manuallyAdded=false] to list of active renderers


0.6.2 flow:

  Code:

2012-03-18 13:29:30,213 DEBUG [WebServer] Incoming connection from /192.168.0.116:2697
2012-03-18 13:29:30,214 DEBUG [DeviceDescriptionRequestHandler] DeviceDescription request received for device 72a61a5b-bda0-323c-a24f-3fdcaa6fc7d3 from 192.168.0.116 (headers = [HOST: 192.168.0.112:8895,CONNECTION: close])
2012-03-18 13:29:30,214 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 13:29:30,215 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 13:29:30,258 DEBUG [WebServer] Incoming connection from /192.168.0.116:2698
2012-03-18 13:29:30,261 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#GetSearchCapabilities"' from 192.168.0.116:
2012-03-18 13:29:30,261 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 13:29:30,347 DEBUG [WebServer] Incoming connection from /192.168.0.116:2699
2012-03-18 13:29:30,348 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#GetSortCapabilities"' from 192.168.0.116:
2012-03-18 13:29:30,348 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.0.116
2012-03-18 13:29:30,366 DEBUG [WebServer] Incoming connection from /192.168.0.116:2700
2012-03-18 13:29:30,368 DEBUG [ServiceEventSubscriptionRequestHandler] Event subscription registered (uuid=df101890-50ec-492f-94ca-7e436d1f3a0c) for service urn:upnp-org:serviceId:ContentDirectory reporting to http://192.168.0.116:40001/
2012-03-18 13:29:30,375 DEBUG [WebServer] Incoming connection from /192.168.0.116:2701
2012-03-18 13:29:30,376 DEBUG [ServiceEventSubscriptionRequestHandler] Event subscription registered (uuid=647c7657-8c30-420e-9533-ea61de3c7f2f) for service urn:microsoft.com:serviceId:X_MS_MediaReceiverRegistrar reporting to http://192.168.0.116:40001/
2012-03-18 13:29:30,825 DEBUG [EventDispatcher] Sending event notification #0 for subscription df101890-50ec-492f-94ca-7e436d1f3a0c to endpoint http://192.168.0.116:40001/
2012-03-18 13:29:30,837 DEBUG [RequestExecutor] Sending HTTP request to 192.168.0.116:40001
2012-03-18 13:29:32,260 DEBUG [RendererSearchSender] Received search response: location: http://192.168.0.116:30104/, st: urn:schemas-upnp-org:device:MediaRenderer:1
2012-03-18 13:29:32,260 DEBUG [RendererSearchSender] Received a valid M-SEARCH response from Renderer 258b05d8-1dd2-11b2-9f85-001f29112166 from address /192.168.0.116:1900
2012-03-18 13:29:32,273 DEBUG [RendererManager] Adding renderer Renderer [uuid=258b05d8-1dd2-11b2-9f85-001f29112166, ipAddress=192.168.0.116, name=HP MediaSmart Connect, profileId=1, manuallyAdded=false, forcedProfile=false] to list of active renderers

Notice the extra event in 0.6.2, linked to the HPMSC at 192.168.0.116, that is not present in ver 0.5.2. Specifically:

  Code:

2012-03-18 13:29:30,376 DEBUG [ServiceEventSubscriptionRequestHandler] Event subscription registered (uuid=647c7657-8c30-420e-9533-ea61de3c7f2f) for service urn:microsoft.com:serviceId:X_MS_MediaReceiverRegistrar reporting to http://192.168.0.116:40001/   

This is the only difference I have found between the two versions in the the flow of events related to the HPMSC.
Is it related to this uPnP authorization dialog? http://msdn.microsoft.com/en-us/library/ff632510(v=prot.10).aspx