Server 0.4.1 stops responding after a while

[stephendhill]

For some reason Serviio stops responding after a while. Both of my DLNA clients see this (Evoke Pure and Sammy B650). I have found that using the console to stop and start the server gets it working again. This problem never occurred on v0.4.0.
Looking in the log I see (which may or may not be related):

2010-07-08 19:25:13,060 INFO [EventDispatcher] Starting EventDispatcher
2010-07-08 19:25:21,088 INFO [ContentDirectoryDefinitionParser] Parsing ContentDirectory definition
2010-07-08 19:25:22,004 WARN [LibraryAdditionsCheckerThread] Cannot read metadata for file 05 Soul Suckin' Jerk.mp3. Message: Cannot check if media item exists: 05 Soul Suckin' Jerk.mp3
org.serviio.db.dao.PersistenceException: Cannot check if media item exists: 05 Soul Suckin' Jerk.mp3
at org.serviio.library.dao.MediaItemDAOImpl.isMediaItemPresent(MediaItemDAOImpl.java:89)
at org.serviio.library.service.MediaService.isMediaPresentInLibrary(MediaService.java:36)
at org.serviio.library.metadata.LibraryAdditionsCheckerThread.searchForNewFiles(LibraryAdditionsCheckerThread.java:147)
at org.serviio.library.metadata.LibraryAdditionsCheckerThread.searchForNewFiles(LibraryAdditionsCheckerThread.java:132)
at org.serviio.library.metadata.LibraryAdditionsCheckerThread.searchForNewFiles(LibraryAdditionsCheckerThread.java:132)
at org.serviio.library.metadata.LibraryAdditionsCheckerThread.run(LibraryAdditionsCheckerThread.java:78)
Caused by: java.sql.SQLTransactionRollbackException: A lock could not be obtained due to a deadlock, cycle of locks and waiters is:
Lock : TABLE, FOLDER, Tablelock
Waiting XID : {18527436, IS} , APP, SELECT media_item.file_name as file_name, media_item.folder_id as folder_id, repository.folder as root_folder FROM media_item, repository, folder WHERE folder.id = media_item.folder_id AND repository.id = folder.repository_id AND media_item.file_name = ?
Granted XID : {18527437, IX}
Lock : TABLE, MEDIA_ITEM, Tablelock
Waiting XID : {18527437, X} , APP, DELETE FROM folder WHERE id = ?
Granted XID : {18527436, IS}
. The selected victim is XID : 18527436.
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.executeQuery(Unknown Source)
at org.serviio.library.dao.MediaItemDAOImpl.isMediaItemPresent(MediaItemDAOImpl.java:68)
... 5 more
Caused by: java.sql.SQLException: A lock could not be obtained due to a deadlock, cycle of locks and waiters is:
Lock : TABLE, FOLDER, Tablelock
Waiting XID : {18527436, IS} , APP, SELECT media_item.file_name as file_name, media_item.folder_id as folder_id, repository.folder as root_folder FROM media_item, repository, folder WHERE folder.id = media_item.folder_id AND repository.id = folder.repository_id AND media_item.file_name = ?
Granted XID : {18527437, IX}
Lock : TABLE, MEDIA_ITEM, Tablelock
Waiting XID : {18527437, X} , APP, DELETE FROM folder WHERE id = ?
Granted XID : {18527436, IS}
. The selected victim is XID : 18527436.
at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(Unknown Source)
... 15 more
Caused by: ERROR 40001: A lock could not be obtained due to a deadlock, cycle of locks and waiters is:
Lock : TABLE, FOLDER, Tablelock
Waiting XID : {18527436, IS} , APP, SELECT media_item.file_name as file_name, media_item.folder_id as folder_id, repository.folder as root_folder FROM media_item, repository, folder WHERE folder.id = media_item.folder_id AND repository.id = folder.repository_id AND media_item.file_name = ?
Granted XID : {18527437, IX}
Lock : TABLE, MEDIA_ITEM, Tablelock
Waiting XID : {18527437, X} , APP, DELETE FROM folder WHERE id = ?
Granted XID : {18527436, IS}
. The selected victim is XID : 18527436.
at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
at org.apache.derby.impl.services.locks.Deadlock.buildException(Unknown Source)
at org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(Unknown Source)
at org.apache.derby.impl.services.locks.AbstractPool.lockObject(Unknown Source)
at org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(Unknown Source)
at org.apache.derby.impl.store.raw.xact.RowLocking2.lockContainer(Unknown Source)
at org.apache.derby.impl.store.raw.data.BaseContainerHandle.useContainer(Unknown Source)
at org.apache.derby.impl.store.raw.data.BaseDataFileFactory.openContainer(Unknown Source)
at org.apache.derby.impl.store.raw.data.BaseDataFileFactory.openContainer(Unknown Source)
at org.apache.derby.impl.store.raw.xact.Xact.openContainer(Unknown Source)
at org.apache.derby.impl.store.access.conglomerate.OpenConglomerate.init(Unknown Source)
at org.apache.derby.impl.store.access.heap.Heap.openScan(Unknown Source)
at org.apache.derby.impl.store.access.RAMTransaction.openScan(Unknown Source)
at org.apache.derby.impl.store.access.RAMTransaction.openScan(Unknown Source)
at org.apache.derby.impl.store.access.BackingStoreHashTableFromScan.<init>(Unknown Source)
at org.apache.derby.impl.store.access.RAMTransaction.createBackingStoreHashtableFromScan(Unknown Source)
at org.apache.derby.impl.sql.execute.HashScanResultSet.openCore(Unknown Source)
at org.apache.derby.impl.sql.execute.JoinResultSet.openRight(Unknown Source)
at org.apache.derby.impl.sql.execute.JoinResultSet.openCore(Unknown Source)
at org.apache.derby.impl.sql.execute.JoinResultSet.openCore(Unknown Source)
at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.openCore(Unknown Source)
at org.apache.derby.impl.sql.execute.BasicNoPutResultSetImpl.open(Unknown Source)
at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(Unknown Source)
at org.apache.derby.impl.sql.GenericPreparedStatement.execute(Unknown Source)
... 9 more
2010-07-08 19:25:26,222 INFO [LibraryUpdatesCheckerThread] Removing 'Caprica.S01E00.Pilot' from Library
2010-07-14 20:18:53,324 INFO [UpdateChecker] Checking if a new version is available
2010-07-14 20:19:25,660 INFO [WebServer] WebServer shutting down
2010-07-14 20:19:25,661 INFO [DiscoveryAdvertisementNotifier] Leaving DiscoveryAdvertisementNotifier
2010-07-14 20:19:25,661 INFO [EventSubscriptionExpirationChecker] Leaving EventSubscriptionExpirationChecker, removing all event subscriptions
2010-07-14 20:19:25,662 INFO [EventDispatcher] Leaving EventDispatcher
2010-07-14 20:19:25,819 INFO [DiscoverySearchListener] Leaving DiscoverySearchListener
2010-07-14 20:19:27,177 INFO [Device] Created UPnP Device with UUID: 539f0fb7-eebe-3300-8eec-48caabf3c39a, bound address: 192.168.10.2
2010-07-14 20:19:27,184 INFO [WebServer] WebServer starting on port 8895
2010-07-14 20:19:27,209 INFO [EventDispatcher] Starting EventDispatcher
2010-07-14 20:19:27,223 INFO [EventSubscriptionExpirationChecker] Starting EventSubscriptionExpirationChecker
2010-07-14 20:19:27,235 INFO [DiscoverySearchListener] Starting DiscoverySearchListener using interface 192.168.10.2
2010-07-14 20:19:27,236 INFO [DiscoveryAdvertisementNotifier] Starting DiscoveryAdvertisementNotifier
2010-07-17 15:48:30,626 WARN [OutputTextReader] Error reading output of an external command:Bad file descriptor
2010-07-17 15:48:37,595 INFO [LibraryAdditionsCheckerThread] Added file 'Nanny McPhee And The Big Bang.mkv' to Library
2010-07-17 16:35:42,215 WARN [ProcessExecutor] Process ffmpeg has a return code of 134! This is a possible error.
2010-07-17 16:35:42,576 ERROR [ResourceTransportRequestHandler] Error while processing resource, sending back 500 error. Message: FFmpeg execution failed

[zip]

For some reason Serviio stops responding after a while.

What do you mean by that? The TV cannot see it anymore?

[stephendhill]

Yes. Both my Sammy and Evoke Pure cannot see it.

[Brammers]

I too have this issue from my Sony S370 Blu-ray player.

Pressing "Stop server" and then "start server" from the console brings it back to life immediately.

Serviio 0.4.1 running on W7 x64, Java 1.6.0_20. Wired LAN between S370 and PC.

J

[Brammers]

I have managed to capture my (this?) issue in debug-level logs, unfortunately I don't know what I'm looking for.

The logs I have run from service startup (at around 7 am) until it failed to stream a file at 7pm, when I did a stop-start from a remote console and then streamed a file just fine. All this is in the logs. 61MB of them (2mb RARed).

If you would like them zip, drop me a message (or reply) and I'll email them.

I do get a lot of these though which don't look good:

2010-07-29 08:21:03,953 WARN [LibraryUpdatesCheckerThread] Cannot search for updated metadata for title Avalanche!. Message: null
java.lang.NullPointerException
at org.serviio.library.metadata.extractor.embedded.EmbeddedMetadataExtractor.isMetadataUpdated(EmbeddedMetadataExtractor.java:82)
at org.serviio.library.metadata.LibraryUpdatesCheckerThread.searchForRemovedAndUpdatedFiles(LibraryUpdatesCheckerThread.java:193)
at org.serviio.library.metadata.LibraryUpdatesCheckerThread.run(LibraryUpdatesCheckerThread.java:97)

HTH
J

[zip]

Hi, create a issue on bitbucket.org and attach the zipped logs there, thanks.
The error you're seeing is known and will be fixed in 0.4.2 - but has nothing to do with your original problem.

[Brammers]

Issue created with logs.

Can I ask if you have decided on a release timeframe for 0.4.2 yet?

Thanks
J

[zip]

As soom as I fix subtitles on Samsungs... could be next week or next month

[SRG]

I really think that you should quickly release 0.4.2 (maybe postponing samsung subtitles fix for 0.4.3), the "java.lang.NullPointerException" exception while adding files is really annoying...

[stephendhill]

I'm seeing:
"2010-08-01 09:06:13,856 INFO [AbstractModel] Remote exception occured, removing the listener: CORBA COMM_FAILURE 1398079689 No; nested exception is: org.omg.CORBA.COMM_FAILURE: vmcid: SUN minor code: 201 completed: No"

I don't know if this is related.