SongKong and Jaikoz Music Tagger Community Forum

jeromeip · 22 May 2020 08:26

Hi Paul,
I started yesterday evening a “delete duplicate” job on a large collection of files.
Eventually it stopped progressing and “pause”/“unpause” didn’t change anything.
Even “stop” button is not working.

Here is the key information I found in the log file. Of course I can join full files if needed.

21/05/2020 23.19.12:CEST:DeleteDuplicatesLoadFolderWorker:loadFiles:SEVERE: end:E:\Musique\#2 Singles classés\2000\Timbaland feat. Drake:13139:1:13139 21/05/2020 23.19.12:CEST:DeleteDuplicatesLoadFolderWorker:loadFiles:SEVERE: end:E:\Musique\#2 Singles classés\2000\Timbaland feat. Justin Timberlake:13140:1:13140 22/05/2020 00.08.50:CEST:DeleteDuplicatesController:waitForFoldersToBeProcessed:SEVERE: completedWaitForFoldersToBeProcessed 22/05/2020 00.08.50:CEST:DeleteDuplicatesController:start:SEVERE: RecNoCount:13140 22/05/2020 00.20.49:CEST:INFO: A checked-out resource is overdue, and will be destroyed: com.mchange.v2.c3p0.impl.NewPooledConnection@1bd17a85 22/05/2020 00.20.49:CEST:INFO: Logging the stack trace by which the overdue resource was checked-out. java.lang.Exception: DEBUG STACK TRACE: Overdue resource check-out stack trace. at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:555) at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutAndMarkConnectionInUse(C3P0PooledConnectionPool.java:755) at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:682) at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:140) at org.hibernate.c3p0.internal.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:90) at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380) at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228) at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171) at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:67) at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.begin(AbstractTransactionImpl.java:162) at org.hibernate.internal.SessionImpl.beginTransaction(SessionImpl.java:1471) at com.jthink.songlayer.hibernate.HibernateUtil.beginTransaction(HibernateUtil.java:224) at com.jthink.songkong.analyse.duplicates.DeleteDuplicatesLoadFolderWorker.loadFiles(DeleteDuplicatesLoadFolderWorker.java:83) at com.jthink.songkong.analyse.duplicates.DeleteDuplicatesLoadFolderWorker.call(DeleteDuplicatesLoadFolderWorker.java:57) at com.jthink.songkong.analyse.duplicates.DeleteDuplicatesLoadFolderWorker.call(DeleteDuplicatesLoadFolderWorker.java:29) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:834) 22/05/2020 00.20.49:CEST:INFO: A checked-out resource is overdue, and will be destroyed: com.mchange.v2.c3p0.impl.NewPooledConnection@2614ed22 22/05/2020 00.20.49:CEST:INFO: Logging the stack trace by which the overdue resource was checked-out. java.lang.Exception: DEBUG STACK TRACE: Overdue resource check-out stack trace. at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:555) at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutAndMarkConnectionInUse(C3P0PooledConnectionPool.java:755) at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:682) at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:140) at org.hibernate.c3p0.internal.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:90) at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380) at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228) at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171) at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:67) at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.begin(AbstractTransactionImpl.java:162) at org.hibernate.internal.SessionImpl.beginTransaction(SessionImpl.java:1471) at com.jthink.songlayer.hibernate.HibernateUtil.beginTransaction(HibernateUtil.java:224) at com.jthink.songkong.analyse.duplicates.DeleteDuplicatesLoadFolderWorker.loadFiles(DeleteDuplicatesLoadFolderWorker.java:83) at com.jthink.songkong.analyse.duplicates.DeleteDuplicatesLoadFolderWorker.call(DeleteDuplicatesLoadFolderWorker.java:57) at com.jthink.songkong.analyse.duplicates.DeleteDuplicatesLoadFolderWorker.call(DeleteDuplicatesLoadFolderWorker.java:29) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:834) 22/05/2020 00.20.49:CEST:INFO: A checked-out resource is overdue, and will be destroyed: com.mchange.v2.c3p0.impl.NewPooledConnection@499b80ec 22/05/2020 00.20.49:CEST:INFO: Logging the stack trace by which the overdue resource was checked-out. java.lang.Exception: DEBUG STACK TRACE: Overdue resource check-out stack trace. at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:555) at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutAndMarkConnectionInUse(C3P0PooledConnectionPool.java:755) at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:682) at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:140) at org.hibernate.c3p0.internal.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:90) at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380) at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228) at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171) at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:67) at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.begin(AbstractTransactionImpl.java:162) at org.hibernate.internal.SessionImpl.beginTransaction(SessionImpl.java:1471) at com.jthink.songlayer.hibernate.HibernateUtil.beginTransaction(HibernateUtil.java:224) at com.jthink.songkong.analyse.duplicates.DeleteDuplicatesLoadFolderWorker.loadFiles(DeleteDuplicatesLoadFolderWorker.java:83) at com.jthink.songkong.analyse.duplicates.DeleteDuplicatesLoadFolderWorker.call(DeleteDuplicatesLoadFolderWorker.java:57) at com.jthink.songkong.analyse.duplicates.DeleteDuplicatesLoadFolderWorker.call(DeleteDuplicatesLoadFolderWorker.java:29) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:834) 22/05/2020 00.20.49:CEST:INFO: A checked-out resource is overdue, and will be destroyed: com.mchange.v2.c3p0.impl.NewPooledConnection@45204f3a 22/05/2020 00.20.49:CEST:INFO: Logging the stack trace by which the overdue resource was checked-out. java.lang.Exception: DEBUG STACK TRACE: Overdue resource check-out stack trace. at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:555) at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutAndMarkConnectionInUse(C3P0PooledConnectionPool.java:755) at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:682) at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:140) at org.hibernate.c3p0.internal.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:90) at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380) at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228) at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171) at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:67) at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.begin(AbstractTransactionImpl.java:162) at org.hibernate.internal.SessionImpl.beginTransaction(SessionImpl.java:1471) at com.jthink.songlayer.hibernate.HibernateUtil.beginTransaction(HibernateUtil.java:224) at com.jthink.songkong.analyse.duplicates.DeleteDuplicatesLoadFolderWorker.loadFiles(DeleteDuplicatesLoadFolderWorker.java:83) at com.jthink.songkong.analyse.duplicates.DeleteDuplicatesLoadFolderWorker.call(DeleteDuplicatesLoadFolderWorker.java:57) at com.jthink.songkong.analyse.duplicates.DeleteDuplicatesLoadFolderWorker.call(DeleteDuplicatesLoadFolderWorker.java:29) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:834) 22/05/2020 10.15.34:CEST:TaskMonitor:setUserCancelled:SEVERE: ***********User Cancelled Task 22/05/2020 10.15.34:CEST:DeleteDuplicateSongsDialog$ReenableMainWindow:doInBackground:SEVERE: >>>>CheckingReportCreated 22/05/2020 10.15.36:CEST:DeleteDuplicateSongsDialog$ReenableMainWindow:doInBackground:SEVERE: >>>>CheckingReportCreated 22/05/2020 10.15.38:CEST:DeleteDuplicateSongsDialog$ReenableMainWindow:doInBackground:SEVERE: >>>>CheckingReportCreated 22/05/2020 10.15.40:CEST:DeleteDuplicateSongsDialog$ReenableMainWindow:doInBackground:SEVERE: >>>>CheckingReportCreated 22/05/2020 10.15.42:CEST:DeleteDuplicateSongsDialog$ReenableMainWindow:doInBackground:SEVERE: >>>>CheckingReportCreated 22/05/2020 10.15.44:CEST:DeleteDuplicateSongsDialog$ReenableMainWindow:doInBackground:SEVERE: >>>>CheckingReportCreated 22/05/2020 10.15.46:CEST:DeleteDuplicateSongsDialog$ReenableMainWindow:doInBackground:SEVERE: >>>>CheckingReportCreated 22/05/2020 10.15.48:CEST:DeleteDuplicateSongsDialog$ReenableMainWindow:doInBackground:SEVERE: >>>>CheckingReportCreated 22/05/2020 10.15.50:CEST:DeleteDuplicateSongsDialog$ReenableMainWindow:doInBackground:SEVERE: >>>>CheckingReportCreated 22/05/2020 10.15.52:CEST:DeleteDuplicateSongsDialog$ReenableMainWindow:doInBackground:SEVERE: >>>>CheckingReportCreated 22/05/2020 10.15.54:CEST:DeleteDuplicateSongsDialog$ReenableMainWindow:doInBackground:SEVERE: >>>>CheckingReportCreated 22/05/2020 10.15.56:CEST:DeleteDuplicateSongsDialog$ReenableMainWindow:doInBackground:SEVERE: >>>>CheckingReportCreated 22/05/2020 10.15.58:CEST:DeleteDuplicateSongsDialog$ReenableMainWindow:doInBackground:SEVERE: >>>>CheckingReportCreated 22/05/2020 10.16.00:CEST:DeleteDuplicateSongsDialog$ReenableMainWindow:doInBackground:SEVERE: >>>>CheckingReportCreated 22/05/2020 10.16.00:CEST:TaskMonitor:setReportCancelled:SEVERE: ***********User Cancelled Report Creation

paultaylor · 22 May 2020 10:13

First response would be please try again, may just be a one-off

jeromeip · 22 May 2020 11:24

Sure I did. Killing the process has been difficult and Songkong didn’t restart well either until I reboot my PC.
Second attempt ran smoothly

Maybe it’s not necessary to spend time understanding the root cause of this issue, however I would recommand some improvement in the error handling so that the job ends in a clean way with an error message rather than looping with no possible exit.
Regards,
Jérôme

paultaylor · 22 May 2020 12:37

Yes sure, well please run Create Support Files since that wil help me better understand why the issue is occurring.

jeromeip · 22 May 2020 13:08

Done.
Let me know if you need any additional information.

jeromeip · 23 May 2020 16:30

I got the issue again today, again while processing a large amount of files (24k files in 9k folders).
I had to kill the process.
Then when restarting, I was asked to recreate database, said yes but Songkong was not responding again, until I reboot my PC.

paultaylor · 3 June 2020 19:06

I have raised https://jthink.atlassian.net/browse/SONGKONG-2066 for this. I can see an error that can cause it to hang, but I cannot yet work out what is causing the error in the first place.

Have you tried to rerun Delete Duplicates against the same files since, and if so did it work second time round ?

jeromeip · 5 June 2020 08:24

I can’t remember exactly what I did, but I think yes: I relaunched the batch with the same parameters as suggested in your first answer and it worked well.

Not sure, but it might be related to the other issue with 2 desynchronized threads.
Have you in your software a main thread that monitors all sub-threads and watches for blockings / too long processing time?..

paultaylor · 5 June 2020 09:30

Yes I do, and one thread had ran for too long , but unlike Fix Songs the processing with Delete Duplicates is simple so I cannot understand why it had timed out.

jeromeip · 5 June 2020 13:43

My files are located on an external HDD.
I don’t know if that helps… It can be an I/O error… Or possibly some network timeout?..

Duplicate batch getting stucked