[Topic] Agile Track Server Logs are Massive

I’m have just realised why my machine running agile track server is running so slow. The agiletrack.log file is over 1.5 gig!!! I renamed and created a new one, I’m now watching it grow to over 8 meg in under an 40 mins. A snippet of the log is below. I hope someone has some idea as how to fix the exception which is being thrown and possibly explanations as to why it has, in the last few weeks decided to error.

Error Log

INFO | jvm 2 | 2007/07/24 10:58:41 | org.apache.lucene.store.jdbc.JdbcStoreException: Failed to execute sql [insert into lucene_index (name_, value_, size_, lf_, deleted_) values ( ?, ?, ?, current_timestamp, ? )]; nested exception is com.mysql.jdbc.exceptions.MySQLIntegrityConstraintViolationException: Duplicate entry '_ct9.fnm' for key 1
INFO | jvm 2 | 2007/07/24 10:58:41 | com.mysql.jdbc.exceptions.MySQLIntegrityConstraintViolationException: Duplicate entry '_ct9.fnm' for key 1
INFO | jvm 2 | 2007/07/24 10:58:41 | at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:931)
INFO | jvm 2 | 2007/07/24 10:58:41 | at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2870)
INFO | jvm 2 | 2007/07/24 10:58:41 | at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1573)
INFO | jvm 2 | 2007/07/24 10:58:41 | at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1665)
INFO | jvm 2 | 2007/07/24 10:58:41 | at com.mysql.jdbc.Connection.execSQL(Connection.java:3176)
INFO | jvm 2 | 2007/07/24 10:58:41 | at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1153)
INFO | jvm 2 | 2007/07/24 10:58:41 | at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1404)
INFO | jvm 2 | 2007/07/24 10:58:41 | at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1318)
INFO | jvm 2 | 2007/07/24 10:58:41 | at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1303)
INFO | jvm 2 | 2007/07/24 10:58:41 | at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:101)
INFO | jvm 2 | 2007/07/24 10:58:41 | at org.apache.lucene.store.jdbc.support.JdbcTemplate.executeUpdate(JdbcTemplate.java:159)
INFO | jvm 2 | 2007/07/24 10:58:41 | at org.apache.lucene.store.jdbc.index.AbstractJdbcIndexOutput.close(AbstractJdbcIndexOutput.java:47)
INFO | jvm 2 | 2007/07/24 10:58:41 | at org.apache.lucene.index.FieldInfos.write(FieldInfos.java:259)
INFO | jvm 2 | 2007/07/24 10:58:41 | at org.apache.lucene.index.SegmentMerger.mergeFields(SegmentMerger.java:176)
INFO | jvm 2 | 2007/07/24 10:58:41 | at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:88)
INFO | jvm 2 | 2007/07/24 10:58:41 | at org.apache.lucene.index.IndexWriter.mergeSegments(IndexWriter.java:709)
INFO | jvm 2 | 2007/07/24 10:58:41 | at org.apache.lucene.index.IndexWriter.mergeSegments(IndexWriter.java:686)
INFO | jvm 2 | 2007/07/24 10:58:41 | at org.apache.lucene.index.IndexWriter.flushRamSegments(IndexWriter.java:656)
INFO | jvm 2 | 2007/07/24 10:58:41 | at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:402)
INFO | jvm 2 | 2007/07/24 10:58:41 | at agiletrack.server.persistence.GenericFullTextIndexer.closeWriter(GenericFullTextIndexer.java:70)
INFO | jvm 2 | 2007/07/24 10:58:41 | at agiletrack.server.persistence.GenericFullTextIndexer.getReader(GenericFullTextIndexer.java:197)
INFO | jvm 2 | 2007/07/24 10:58:41 | at agiletrack.server.persistence.GenericFullTextIndexer.updateIndex(GenericFullTextIndexer.java:367)
INFO | jvm 2 | 2007/07/24 10:58:41 | at agiletrack.server.persistence.GenericFullTextIndexer.access$300(GenericFullTextIndexer.java:37)
INFO | jvm 2 | 2007/07/24 10:58:41 | at agiletrack.server.persistence.GenericFullTextIndexer$1.run(GenericFullTextIndexer.java:134)
INFO | jvm 2 | 2007/07/24 10:58:41 | at java.lang.Thread.run(Thread.java:595)
INFO | jvm 2 | 2007/07/24 10:58:42 | org.apache.lucene.store.jdbc.JdbcStoreException: Failed to execute sql [insert into lucene_index (name_, value_, size_, lf_, deleted_) values ( ?, ?, ?, current_timestamp, ? )]; nested exception is com.mysql.jdbc.exceptions.MySQLIntegrityConstraintViolationException: Duplicate entry '_ctb.fnm' for key 1
INFO | jvm 2 | 2007/07/24 10:58:42 | com.mysql.jdbc.exceptions.MySQLIntegrityConstraintViolationException: Duplicate entry '_ctb.fnm' for key 1
INFO | jvm 2 | 2007/07/24 10:58:42 | at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:931)
INFO | jvm 2 | 2007/07/24 10:58:42 | at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2870)
INFO | jvm 2 | 2007/07/24 10:58:42 | at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1573)
INFO | jvm 2 | 2007/07/24 10:58:42 | at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1665)
INFO | jvm 2 | 2007/07/24 10:58:42 | at com.mysql.jdbc.Connection.execSQL(Connection.java:3176)
INFO | jvm 2 | 2007/07/24 10:58:42 | at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1153)
INFO | jvm 2 | 2007/07/24 10:58:42 | at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1404)
INFO | jvm 2 | 2007/07/24 10:58:42 | at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1318)
INFO | jvm 2 | 2007/07/24 10:58:42 | at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1303)
INFO | jvm 2 | 2007/07/24 10:58:42 | at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:101)
INFO | jvm 2 | 2007/07/24 10:58:42 | at org.apache.lucene.store.jdbc.support.JdbcTemplate.executeUpdate(JdbcTemplate.java:159)
INFO | jvm 2 | 2007/07/24 10:58:42 | at org.apache.lucene.store.jdbc.index.AbstractJdbcIndexOutput.close(AbstractJdbcIndexOutput.java:47)
INFO | jvm 2 | 2007/07/24 10:58:42 | at org.apache.lucene.index.FieldInfos.write(FieldInfos.java:259)
INFO | jvm 2 | 2007/07/24 10:58:42 | at org.apache.lucene.index.SegmentMerger.mergeFields(SegmentMerger.java:176)
INFO | jvm 2 | 2007/07/24 10:58:42 | at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:88)
INFO | jvm 2 | 2007/07/24 10:58:42 | at org.apache.lucene.index.IndexWriter.mergeSegments(IndexWriter.java:709)
INFO | jvm 2 | 2007/07/24 10:58:42 | at org.apache.lucene.index.IndexWriter.mergeSegments(IndexWriter.java:686)
INFO | jvm 2 | 2007/07/24 10:58:42 | at org.apache.lucene.index.IndexWriter.flushRamSegments(IndexWriter.java:656)
INFO | jvm 2 | 2007/07/24 10:58:42 | at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:402)
INFO | jvm 2 | 2007/07/24 10:58:42 | at agiletrack.server.persistence.GenericFullTextIndexer.closeWriter(GenericFullTextIndexer.java:70)
INFO | jvm 2 | 2007/07/24 10:58:42 | at agiletrack.server.persistence.GenericFullTextIndexer.getReader(GenericFullTextIndexer.java:197)
INFO | jvm 2 | 2007/07/24 10:58:42 | at agiletrack.server.persistence.GenericFullTextIndexer.updateIndex(GenericFullTextIndexer.java:367)
INFO | jvm 2 | 2007/07/24 10:58:42 | at agiletrack.server.persistence.GenericFullTextIndexer.access$300(GenericFullTextIndexer.java:37)
INFO | jvm 2 | 2007/07/24 10:58:42 | at agiletrack.server.persistence.GenericFullTextIndexer$1.run(GenericFullTextIndexer.java:134)
INFO | jvm 2 | 2007/07/24 10:58:42 | at java.lang.Thread.run(Thread.java:595)
INFO | jvm 2 | 2007/07/24 10:58:43 | org.apache.lucene.store.jdbc.JdbcStoreException: Failed to execute sql [insert into lucene_index (name_, value_, size_, lf_, deleted_) values ( ?, ?, ?, current_timestamp, ? )]; nested exception is com.mysql.jdbc.exceptions.MySQLIntegrityConstraintViolationException: Duplicate entry '_ctd.fnm' for key 1
INFO | jvm 2 | 2007/07/24 10:58:43 | com.mysql.jdbc.exceptions.MySQLIntegrityConstraintViolationException: Duplicate entry '_ctd.fnm' for key 1
INFO | jvm 2 | 2007/07/24 10:58:43 | at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:931)
INFO | jvm 2 | 2007/07/24 10:58:43 | at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2870)
INFO | jvm 2 | 2007/07/24 10:58:43 | at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1573)
INFO | jvm 2 | 2007/07/24 10:58:43 | at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1665)
INFO | jvm 2 | 2007/07/24 10:58:43 | at com.mysql.jdbc.Connection.execSQL(Connection.java:3176)
INFO | jvm 2 | 2007/07/24 10:58:43 | at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1153)
INFO | jvm 2 | 2007/07/24 10:58:43 | at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1404)
INFO | jvm 2 | 2007/07/24 10:58:43 | at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1318)
INFO | jvm 2 | 2007/07/24 10:58:43 | at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1303)
INFO | jvm 2 | 2007/07/24 10:58:43 | at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:101)
INFO | jvm 2 | 2007/07/24 10:58:43 | at org.apache.lucene.store.jdbc.support.JdbcTemplate.executeUpdate(JdbcTemplate.java:159)
INFO | jvm 2 | 2007/07/24 10:58:43 | at org.apache.lucene.store.jdbc.index.AbstractJdbcIndexOutput.close(AbstractJdbcIndexOutput.java:47)
INFO | jvm 2 | 2007/07/24 10:58:43 | at org.apache.lucene.index.FieldInfos.write(FieldInfos.java:259)
INFO | jvm 2 | 2007/07/24 10:58:43 | at org.apache.lucene.index.SegmentMerger.mergeFields(SegmentMerger.java:176)
INFO | jvm 2 | 2007/07/24 10:58:43 | at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:88)
INFO | jvm 2 | 2007/07/24 10:58:43 | at org.apache.lucene.index.IndexWriter.mergeSegments(IndexWriter.java:709)
INFO | jvm 2 | 2007/07/24 10:58:43 | at org.apache.lucene.index.IndexWriter.mergeSegments(IndexWriter.java:686)
INFO | jvm 2 | 2007/07/24 10:58:43 | at org.apache.lucene.index.IndexWriter.flushRamSegments(IndexWriter.java:656)
INFO | jvm 2 | 2007/07/24 10:58:43 | at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:402)
INFO | jvm 2 | 2007/07/24 10:58:43 | at agiletrack.server.persistence.GenericFullTextIndexer.closeWriter(GenericFullTextIndexer.java:70)
INFO | jvm 2 | 2007/07/24 10:58:43 | at agiletrack.server.persistence.GenericFullTextIndexer.getReader(GenericFullTextIndexer.java:197)
INFO | jvm 2 | 2007/07/24 10:58:43 | at agiletrack.server.persistence.GenericFullTextIndexer.updateIndex(GenericFullTextIndexer.java:367)
INFO | jvm 2 | 2007/07/24 10:58:43 | at agiletrack.server.persistence.GenericFullTextIndexer.access$300(GenericFullTextIndexer.java:37)
INFO | jvm 2 | 2007/07/24 10:58:43 | at agiletrack.server.persistence.GenericFullTextIndexer$1.run(GenericFullTextIndexer.java:134)
INFO | jvm 2 | 2007/07/24 10:58:43 | at java.lang.Thread.run(Thread.java:595)
INFO | jvm 2 | 2007/07/24 10:58:44 | org.apache.lucene.store.jdbc.JdbcStoreException: Failed to execute sql [insert into lucene_index (name_, value_, size_, lf_, deleted_) values ( ?, ?, ?, current_timestamp, ? )]; nested exception is com.mysql.jdbc.exceptions.MySQLIntegrityConstraintViolationException: Duplicate entry '_ctf.fnm' for key 1
INFO | jvm 2 | 2007/07/24 10:58:44 | com.mysql.jdbc.exceptions.MySQLIntegrityConstraintViolationException: Duplicate entry '_ctf.fnm' for key 1
INFO | jvm 2 | 2007/07/24 10:58:44 | at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:931)
INFO | jvm 2 | 2007/07/24 10:58:44 | at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2870)
INFO | jvm 2 | 2007/07/24 10:58:44 | at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1573)
INFO | jvm 2 | 2007/07/24 10:58:44 | at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1665)
INFO | jvm 2 | 2007/07/24 10:58:44 | at com.mysql.jdbc.Connection.execSQL(Connection.java:3176)
INFO | jvm 2 | 2007/07/24 10:58:44 | at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1153)
INFO | jvm 2 | 2007/07/24 10:58:44 | at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1404)
INFO | jvm 2 | 2007/07/24 10:58:44 | at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1318)
INFO | jvm 2 | 2007/07/24 10:58:44 | at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1303)
INFO | jvm 2 | 2007/07/24 10:58:44 | at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:101)
INFO | jvm 2 | 2007/07/24 10:58:44 | at org.apache.lucene.store.jdbc.support.JdbcTemplate.executeUpdate(JdbcTemplate.java:159)
INFO | jvm 2 | 2007/07/24 10:58:44 | at org.apache.lucene.store.jdbc.index.AbstractJdbcIndexOutput.close(AbstractJdbcIndexOutput.java:47)
INFO | jvm 2 | 2007/07/24 10:58:44 | at org.apache.lucene.index.FieldInfos.write(FieldInfos.java:259)
INFO | jvm 2 | 2007/07/24 10:58:44 | at org.apache.lucene.index.SegmentMerger.mergeFields(SegmentMerger.java:176)
INFO | jvm 2 | 2007/07/24 10:58:44 | at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:88)
INFO | jvm 2 | 2007/07/24 10:58:44 | at org.apache.lucene.index.IndexWriter.mergeSegments(IndexWriter.java:709)
INFO | jvm 2 | 2007/07/24 10:58:44 | at org.apache.lucene.index.IndexWriter.mergeSegments(IndexWriter.java:686)
INFO | jvm 2 | 2007/07/24 10:58:44 | at org.apache.lucene.index.IndexWriter.flushRamSegments(IndexWriter.java:656)
INFO | jvm 2 | 2007/07/24 10:58:44 | at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:402)
INFO | jvm 2 | 2007/07/24 10:58:44 | at agiletrack.server.persistence.GenericFullTextIndexer.closeWriter(GenericFullTextIndexer.java:70)
INFO | jvm 2 | 2007/07/24 10:58:44 | at agiletrack.server.persistence.GenericFullTextIndexer.getReader(GenericFullTextIndexer.java:197)
INFO | jvm 2 | 2007/07/24 10:58:44 | at agiletrack.server.persistence.GenericFullTextIndexer.updateIndex(GenericFullTextIndexer.java:367)
INFO | jvm 2 | 2007/07/24 10:58:44 | at agiletrack.server.persistence.GenericFullTextIndexer.access$300(GenericFullTextIndexer.java:37)
INFO | jvm 2 | 2007/07/24 10:58:44 | at agiletrack.server.persistence.GenericFullTextIndexer$1.run(GenericFullTextIndexer.java:134)
INFO | jvm 2 | 2007/07/24 10:58:44 | at java.lang.Thread.run(Thread.java:595)
INFO | jvm 2 | 2007/07/24 10:58:45 | org.apache.lucene.store.jdbc.JdbcStoreException: Failed to execute sql [insert into lucene_index (name_, value_, size_, lf_, deleted_) values ( ?, ?, ?, current_timestamp, ? )]; nested exception is com.mysql.jdbc.exceptions.MySQLIntegrityConstraintViolationException: Duplicate entry '_cth.fnm' for key 1

—Posted by Software on Jul 24, 2007
Forum
AgileTrack Server
Reply

After a while I've seen these types of errors. I don't really know when it happens, but it's related to the Lucene JDBC directory being used for indexing. The solution to the problem is to delete the lucene_index table from the database and then restart AgileTrack. The index table will be automatically recreated and reinitialized. That should take care of the exceptions.

I really need to detect the broken table and reinitialize it automatically. The stack trace will help with detecting it. Thanks.

—Posted by Adam Lane on Jul 24, 2007 at 8:15:40 AM

All sorted! Cheers Adam for the swift response. The agiletrack.log had only managed to get itself to 53meg in 5 hours.

—Posted by Software on Jul 24, 2007 at 8:31:01 AM


You may post a reply to this topic, but you must be logged in. If you already have an account, you may login now. If you need to create an account, you may also register now.