Lucene Indexing problem...

[TheBlueVoice]

Hi All,

I've been running subsonic on an unraid server for a couple of months without problems until the last few days.

It won't index properly, The log shows:

[2012-08-30 13:07:08,935] INFO SearchService - Starting to create search index.
[2012-08-30 13:07:09,455] INFO SearchService - Created search index with 1000 entries.
[2012-08-30 13:07:09,939] INFO SearchService - Created search index with 2000 entries.
[2012-08-30 13:07:10,341] INFO SearchService - Created search index with 3000 entries.
[2012-08-30 13:07:10,671] INFO SearchService - Created search index with 4000 entries.
[2012-08-30 13:07:10,923] INFO SearchService - Created search index with 5000 entries.
[2012-08-30 13:07:11,260] INFO SearchService - Created search index with 6000 entries.
[2012-08-30 13:07:11,795] INFO SearchService - Created search index with 7000 entries.
[2012-08-30 13:07:12,027] INFO SearchService - Created search index with 8000 entries.
[2012-08-30 13:07:12,392] INFO SearchService - Created search index with 9000 entries.
[2012-08-30 13:07:12,804] INFO SearchService - Created search index with 10000 entries.
[2012-08-30 13:07:13,267] INFO SearchService - Updating Lucene search index.
[2012-08-30 13:07:23,218] ERROR LuceneSearchService - Failed to create Lucene search index.
org.apache.lucene.index.CorruptIndexException: checksum mismatch in segments file
at org.apache.lucene.index.SegmentInfos.read(SegmentInfos.java:284)
at org.apache.lucene.index.IndexFileDeleter.<init>(IndexFileDeleter.java:171)
at org.apache.lucene.index.IndexWriter.init(IndexWriter.java:1130)
at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:888)
at net.sourceforge.subsonic.service.LuceneSearchService.createIndexWriter(LuceneSearchService.java:140)
at net.sourceforge.subsonic.service.LuceneSearchService.createIndex(LuceneSearchService.java:91)
at net.sourceforge.subsonic.service.SearchService.doCreateIndex(SearchService.java:163)
at net.sourceforge.subsonic.service.SearchService.access$000(SearchService.java:62)
at net.sourceforge.subsonic.service.SearchService$1.run(SearchService.java:115)

[2012-08-30 13:07:23,219] INFO SearchService - Created search index with 10799 entries.

I've increased the maxmem to 500meg and removed some recently added files to see if it was stopping at a particular file (how to check?)

Any ideas greatfully received!

[hakko]

You could always try deleting C:/subsonic/lucene* and re-index. (or equivalent)

[TheBlueVoice]

Ah ha!

That seems to have done the trick! Cheers!

What was going on then with the index? Why does that fix it?

[hakko]

I won't be able to give a satisfying answer, but well, some bug in Lucene/Subsonic created a corrupt index. By deleting that index, we force Lucene to create a completely new one. There's no guarantee here that it'll work forever, it's just a fix. Like restarting a device that doesn't work.

[TheBlueVoice]

Cheers

[mbro]

I'm seeing something similar too. Searching for specific tracks in subsonic netted intermittent results - some were found (by track/album/artist names, some are not).

Updated to subsonic 4.9, and saw this issue before and after. I tried deleting the /var/subsonic/lucene2 directory and restarting subsonic (running on Debian). I triggered a re-index from the web UI, and here's the log segment that it generated:

[2014-02-16 14:19:30,241] INFO MediaScannerService - Scanned media library with 18750 entries.
[2014-02-16 14:19:31,997] INFO MediaScannerService - Scanned media library with 19000 entries.
[2014-02-16 14:19:33,117] INFO MediaScannerService - Scanned media library with 19250 entries.
[2014-02-16 14:19:34,209] INFO MediaScannerService - Scanned media library with 19500 entries.
[2014-02-16 14:19:35,149] ERROR MediaScannerService - Failed to scan media library.
org.springframework.dao.TransientDataAccessResourceException: PreparedStatementCallback; SQL [update media_file set present=?, last_scanned=? where path=?]; S1000 General error java.lang.NullPointerException in statement [update media_file set present=?, last_scanned=? where path=?]; nested exception is java.sql.SQLException: S1000 General error java.lang.NullPointerException in statement [update media_file set present=?, last_scanned=? where path=?]
at org.springframework.jdbc.support.SQLStateSQLExceptionTranslator.doTranslate(SQLStateSQLExceptionTranslator.java:106)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:80)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:80)
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:607)
at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:792)
at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:850)
at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:858)
at net.sourceforge.subsonic.dao.AbstractDao.update(AbstractDao.java:71)
at net.sourceforge.subsonic.dao.MediaFileDao.markPresent(MediaFileDao.java:327)
at net.sourceforge.subsonic.service.MediaScannerService.scanFile(MediaScannerService.java:241)
at net.sourceforge.subsonic.service.MediaScannerService.scanFile(MediaScannerService.java:229)
at net.sourceforge.subsonic.service.MediaScannerService.scanFile(MediaScannerService.java:232)
at net.sourceforge.subsonic.service.MediaScannerService.scanFile(MediaScannerService.java:232)
at net.sourceforge.subsonic.service.MediaScannerService.doScanLibrary(MediaScannerService.java:178)
at net.sourceforge.subsonic.service.MediaScannerService.access$000(MediaScannerService.java:48)
at net.sourceforge.subsonic.service.MediaScannerService$2.run(MediaScannerService.java:147)
Caused by: java.sql.SQLException: S1000 General error java.lang.NullPointerException in statement [update media_file set present=?, last_scanned=? where path=?]
at org.hsqldb.jdbc.Util.throwError(Unknown Source)
at org.hsqldb.jdbc.jdbcPreparedStatement.executeUpdate(Unknown Source)
at org.springframework.jdbc.core.JdbcTemplate$2.doInPreparedStatement(JdbcTemplate.java:798)
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:591)
... 12 more

[2014-02-16 14:19:36,278] INFO PlaylistService - Starting playlist import.
[2014-02-16 14:19:36,279] INFO PlaylistService - Completed playlist import.
[2014-02-16 14:19:36,279] INFO PlaylistService - Starting playlist statistics update.
[2014-02-16 14:19:36,280] INFO PlaylistService - Completed playlist statistics update.
[2014-02-16 14:21:10,963] INFO PodcastService - Starting scheduled Podcast refresh.
[2014-02-16 14:21:10,963] INFO PodcastService - Completed scheduled Podcast refresh.



I have also increased memory allocation (contents of /etc/default/subsonic:)


#
# This is the configuration file for the Subsonic service
# (/etc/init.d/subsonic)
#
# To change the startup parameters of Subsonic, modify
# the SUBSONIC_ARGS variable below.
#
# Type "subsonic --help" on the command line to read an
# explanation of the different options.
#
# For example, to specify that Subsonic should use port 80 (for http)
# and 443 (for https), and use a Java memory heap size of 200 MB, use
# the following:
#
# SUBSONIC_ARGS="--port=80 --https-port=443 --max-memory=200"

SUBSONIC_ARGS="--max-memory=500"
#was 150

# The user which should run the Subsonic process. Default "root".
# Note that non-root users are by default not allowed to use ports
# below 1024. Also make sure to grant the user write permissions in
# the music directories, otherwise changing album art and tags will fail.

SUBSONIC_USER=root

Anybody got any good ideas?

[mbro]

I'm wondering if there's a way to put lucene2 into a more detailed logging mode to debug what its doing. Or is it Subsonic that I should put into more detailed logging mode? Anybody???

[mbro]

Ok, I think I figured out a solution to this problem. I don't have a DBA background, but here's my guess at things. Sindre can probably confirm if this is the case or not...

When the media scanner runs, it builds a database of the media that it finds. When the indexer runs, it may contain references to the media database (unique key of some sort)? In any case, if the database gets rebuilt without rebuilding the search index at the same time, this is when these problems seem to arise. So to fix this, here's what I did... My subsonic runs on a small linux desktop type box, so this is all linux specific. Directory paths and procedure would be the same for whatever you run Subsonic on...

1) Stop subsonic. sudo service subsonic stop
2) delete /var/subsonic/db, /var/subsonic/lucene2, /var/subsonic/jetty, /var/subsonic/thumbs, /var/subsonic/subsonic.log.

3) Start subsonic. Because the db was deleted, you have also deleted the usage history of your media, users that were defined, etc. Effectively, this is a fresh subsonic install (which the previous posts about a wholesale removal and re-install triggered this test, but this is shorter).
4) Login as admin/admin, define users, add your media path and initiate the first media scan. This will take a while...

So what made me think about doing this? I tried deleting and recreating the database, but the media scanner seemed to have the same issue. I also tried deleting the search index (/var/subsonic/lucene2), but similar results - it would gack part way through a media scan and my search results would be incomplete. I went through these 4 steps and now I have a fresh database, complete search index, and the media indexer runs and completes now instead of failing part way through. Super sweet!