【Solrエラー対応】LukeRequestHandler Error getting file length for [segments_N]の警告について

事象

題名の通りSolr6系統で以下の警告が出る場合があります。

LukeRequestHandler Error getting file length for [segments_N]

StackTraceの例:

java.nio.file.NoSuchFileException: /var/solr_node_8983/data/mycore/data/index/segments_3
    at sun.nio.fs.UnixException.translateToIOException(UnixException.java:86)
    at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:102)
    at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:107)
    at sun.nio.fs.UnixFileAttributeViews$Basic.readAttributes(UnixFileAttributeViews.java:55)
    at sun.nio.fs.UnixFileSystemProvider.readAttributes(UnixFileSystemProvider.java:144)
    at sun.nio.fs.LinuxFileSystemProvider.readAttributes(LinuxFileSystemProvider.java:99)
    at java.nio.file.Files.readAttributes(Files.java:1737)
    at java.nio.file.Files.size(Files.java:2332)
    at org.apache.lucene.store.FSDirectory.fileLength(FSDirectory.java:243)
    at org.apache.lucene.store.NRTCachingDirectory.fileLength(NRTCachingDirectory.java:128)
    at org.apache.solr.handler.admin.LukeRequestHandler.getFileLength(LukeRequestHandler.java:597)
    at org.apache.solr.handler.admin.LukeRequestHandler.getIndexInfo(LukeRequestHandler.java:585)
    at org.apache.solr.handler.admin.CoreAdminOperation.getCoreStatus(CoreAdminOperation.java:907)
    at org.apache.solr.handler.admin.CoreAdminOperation$4.call(CoreAdminOperation.java:193)
    at org.apache.solr.handler.admin.CoreAdminHandler$CallInfo.call(CoreAdminHandler.java:351)
    at org.apache.solr.handler.admin.CoreAdminHandler.handleRequestBody(CoreAdminHandler.java:153)
    at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:155)
    at org.apache.solr.servlet.HttpSolrCall.handleAdminRequest(HttpSolrCall.java:658)
    at org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:441)
    at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:229)
    at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:184)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:581)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1160)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:511)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1092)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
    at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:213)
    at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:119)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
    at org.eclipse.jetty.server.Server.handle(Server.java:518)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:308)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:244)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
    at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceAndRun(ExecuteProduceConsume.java:246)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:156)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:654)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:572)
    at java.lang.Thread.run(Thread.java:748)

事象に伴う問題

普段の検索の動きには実害無いと思うのですが、問題が出るのはCoreAdminHandlerを使っている時です。

CoreAdminHandler
http://solr_host:sore_port/solr/admin/cores?action=STATUS&core=mycore

segmentsFilesegmentsFileSizeInBytesindexversioncurrent などの項目が最新化されなくなります。

この情報を使って動く処理を作っている場合は問題が顕在化します。バックアップの処理などもこの情報を参照しているので影響があります。

原因

原因は既にJIRAに挙がっています。

[SOLR-8587] Add segments file information to core admin status - ASF JIRA

[SOLR-9120] o.a.s.h.a.LukeRequestHandler Error getting file length for [segments_NNN] -- NoSuchFileException - ASF JIRA

Luceneは最新コミットで参照されなくなったファイルを削除するようですが、Unix上のinodeが参照されている限り削除されることはありません。Lucene上は削除されている古い情報をLukeRequestHandlerの該当の処理で使われているインスタンスが保持しているため不整合が出ているようです。

再現方法

古いセグメントが使われなくなるようにドキュメントを更新すると発生します。例えば以下の3つの更新を上から順番に流して、その後 CoreAdminHandler を使ってステータス確認すると発生します。(CoreAdminHandlerの情報も更新されてない状態になる)

以下の順序で更新処理
id,text
1,a
2,b
3,c
id,text
4,d
5,e
6,f
id,text
1,g
2,h
3,i
CoreAdminHandlerを実行
http://solr_host:sore_port/solr/admin/cores?action=STATUS&core=mycore

回避策

SOLR-9120で対応策が練られていますが、現時点の最新版の6.6.0ではまだ対策がされていません。

とりあえずワークアラウンドとして、①segmentsFileSizeInBytes-1 になっていることをチェックする。②空commitすると最新情報取れるようになる。③ solrconfig.xmlmaxCommitsToKeep の値を調整するなど。

③が一番自然な気はしますが、インデックスサイズが増えるので、諸々ケアが必要です。