ファイルサーバーに対するクロール速度が一定時間経過後極端に遅くなる

andor · July 4, 2023, 1:55am

お世話になります
Fess 14.8/opensearch 2.7 のDocker版を使用させていただいています。
ファイルサーバーに対するクロールで、クロール開始直後は順調にインデックスが作成（200件超/分）されていくのですが、5分を過ぎたところから、クロール対象ファイルがまだ大量ににあるにもかかわらず、数分毎(※)に1ファイルしかインデックスが作成されない事象が発生しています。
※数分毎の間隔は、5分毎/10分毎/15分毎/20分毎/25分毎等さまざま

以下は、インデックス作成が低速に切り替わる直後のログの抜粋なのですが、10秒起きにqueueを見に行くが空振りという状況が延々と続き、たまにインデックス作成が成功、また空振りが続くように見えます。

T00:05:16.871Z","log.level": "INFO","message":"Processing 10/23 docs 
T00:05:16.959Z","log.level": "INFO","message":"Processing 9/13 docs 
T00:05:17.817Z","log.level": "INFO","message":"Sent 32 docs 
T00:05:17.910Z","log.level": "INFO","message":"Processing 4/4 docs 
T00:05:17.954Z","log.level": "INFO","message":"Processing no docs in indexing queue 
T00:05:18.315Z","log.level": "INFO","message":"Sent 10 docs 
T00:05:18.319Z","log.level": "INFO","message":"Processing no docs in indexing queue 
T00:05:28.320Z","log.level": "INFO","message":"Processing no docs in indexing queue 
T00:05:30.791Z","log.level": "INFO","message":"[SYSTEM MONITOR] {\"os\":{\"memory\":
T00:05:38.321Z","log.level": "INFO","message":"Processing no docs in indexing queue 
T00:05:48.321Z","log.level": "INFO","message":"Processing no docs in indexing queue 
T00:05:58.325Z","log.level": "INFO","message":"Processing no docs in indexing queue 
T00:06:08.323Z","log.level": "INFO","message":"Processing no docs in indexing queue 
T00:06:18.323Z","log.level": "INFO","message":"Processing no docs in indexing queue 
T00:06:28.324Z","log.level": "INFO","message":"Processing no docs in indexing queue 
T00:06:31.799Z","log.level": "INFO","message":"[SYSTEM MONITOR] {\"os\":{\"memory\":
T00:06:38.325Z","log.level": "INFO","message":"Processing no docs in indexing queue 
T00:06:48.325Z","log.level": "INFO","message":"Processing no docs in indexing queue 
T00:06:58.326Z","log.level": "INFO","message":"Processing no docs in indexing queue 
T00:07:08.326Z","log.level": "INFO","message":"Processing no docs in indexing queue 
T00:07:18.327Z","log.level": "INFO","message":"Processing no docs in indexing queue 
T00:07:28.328Z","log.level": "INFO","message":"Processing no docs in indexing queue 
～  （上記繰り返し）
T00:30:44.159Z","log.level": "INFO","message":"Crawling URL: smb://hostaddr/第一階層/第二階層/第三階層/第四階層/第四階層/ファイル名.xls", "ecs.version": "1.2.0","service.name":"fess","event.dataset":"crawler","process.thread.name":"Crawler-20230628235314-1-4","log.logger":"org.codelibs.fess.crawler.helper.impl.LogHelperImpl"}
T00:30:48.407Z","log.level": "INFO","message":"Processing 1/1 docs 
T00:30:48.424Z","log.level": "INFO","message":"Processing no docs in indexing queue 
T00:30:48.448Z","log.level": "INFO","message":"Sent 1 docs

後半のペースでは、対象ファイルのインデックス作成が何日かけても終了しない見込みです。
インデックス作成速度が低下する原因・回避策等、ご教示いただけないでしょうか？

他には、poi関係のWARNログは書かれているのですが、原因に結び付きそうなログは見当たりませんでした

shinsuke · July 4, 2023, 11:48am

adaptive.load.controlでCPU利用率が50%を超えると、クロールを止めますが、この状態になると、ログが出力されるので、これが原因でもないような気もします。
あとは、デバッグログにして、クロールが進まないログを見てみるとかが良いと思います。

andor · July 6, 2023, 8:18am

アドバイスありがとうございます。
adaptive.load.controlの値を0や100にしてみたのですが、結果は変わらないようです。

"debug"にして取得したログのうち、エラーが発生しているものは、以下の通りです。原因になりそうなものは含まれているでしょうか？

{"@timestamp":"2023-07-06T00:39:53.585Z",
"log.level":"DEBUG",
"message":"Exception on SID processing.",
 "ecs.version": "1.2.0",
"service.name":"fess",
"event.dataset":"crawler",
"process.thread.name":"Crawler-20230706003747-1-1",
"log.logger":"org.codelibs.fess.crawler.client.smb.SmbClient",
"error.type":"jcifs.CIFSException",
"error.message":"Failed to get group member SIDs",
"error.stack_trace":"jcifs.CIFSException: Failed to get group member SIDs\n\t
at jcifs.smb.SIDCacheImpl.getGroupMemberSids(SIDCacheImpl.java:253)\n\t
at jcifs.smb.SIDCacheImpl.getGroupMemberSids(SIDCacheImpl.java:53)\n\t
at org.codelibs.fess.crawler.client.smb.SmbClient.processAllowedSIDs(SmbClient.java:356)\n\t
at org.codelibs.fess.crawler.client.smb.SmbClient.processAccessControlEntries(SmbClient.java:337)\n\t
at org.codelibs.fess.crawler.client.smb.SmbClient.getResponseData(SmbClient.java:233)\n\t
at org.codelibs.fess.crawler.client.smb.SmbClient.processRequest(SmbClient.java:161)\n\t
at org.codelibs.fess.crawler.client.smb.SmbClient.doHead(SmbClient.java:391)\n\t
at org.codelibs.fess.crawler.client.AbstractCrawlerClient.execute(AbstractCrawlerClient.java:129)\n\t
at org.codelibs.fess.crawler.FessCrawlerThread.isContentUpdated(FessCrawlerThread.java:96)\n\t
at org.codelibs.fess.crawler.CrawlerThread.run(CrawlerThread.java:148)\n\t
at java.base/java.lang.Thread.run(Unknown Source)\nCaused by: jcifs.smb.SmbException: The specified domain did not exist.\n\t
at jcifs.dcerpc.msrpc.SamrDomainHandle.<init>(SamrDomainHandle.java:41)\n\t
at jcifs.smb.SIDCacheImpl.getGroupMemberSids(SIDCacheImpl.java:230)\n\t
... 10 more\n"}

{"@timestamp":"2023-07-06T00:41:31.740Z",
"log.level":"DEBUG",
"message":"Not retrying",
 "ecs.version": "1.2.0",
"service.name":"fess",
"event.dataset":"crawler",
"process.thread.name":"Crawler-20230706003747-1-1",
"log.logger":"jcifs.smb.SmbTreeConnection",
"error.type":"jcifs.smb.SmbException",
"error.message":"Failed to acquire credits in time",
"error.stack_trace":"jcifs.smb.SmbException: Failed to acquire credits in time\n\t
at jcifs.smb.SmbTransportImpl.sendrecv(SmbTransportImpl.java:967)\n\t
at jcifs.smb.SmbTransportImpl.send(SmbTransportImpl.java:1578)\n\t
at jcifs.smb.SmbSessionImpl.send(SmbSessionImpl.java:409)\n\t
at jcifs.smb.SmbTreeImpl.send(SmbTreeImpl.java:472)\n\t
at jcifs.smb.SmbTreeConnection.send0(SmbTreeConnection.java:404)\n\t
at jcifs.smb.SmbTreeConnection.send(SmbTreeConnection.java:318)\n\t
at jcifs.smb.SmbTreeConnection.send(SmbTreeConnection.java:298)\n\t
at jcifs.smb.SmbTreeHandleImpl.send(SmbTreeHandleImpl.java:130)\n\t
at jcifs.smb.SmbTreeHandleImpl.send(SmbTreeHandleImpl.java:117)\n\t
at jcifs.smb.SmbFileHandleImpl.closeInternal(SmbFileHandleImpl.java:207)\n\t
at jcifs.smb.SmbFileHandleImpl.release(SmbFileHandleImpl.java:247)\n\t
at jcifs.smb.SmbFileHandleImpl.close(SmbFileHandleImpl.java:232)\n\t
at jcifs.smb.SmbPipeHandleImpl.close(SmbPipeHandleImpl.java:332)\n\t
at jcifs.dcerpc.DcerpcPipeHandle.close(DcerpcPipeHandle.java:175)\n\t
at jcifs.smb.SIDCacheImpl.getGroupMemberSids(SIDCacheImpl.java:228)\n\t
at jcifs.smb.SIDCacheImpl.getGroupMemberSids(SIDCacheImpl.java:53)\n\t
at org.codelibs.fess.crawler.client.smb.SmbClient.processAllowedSIDs(SmbClient.java:356)\n\t
at org.codelibs.fess.crawler.client.smb.SmbClient.processAccessControlEntries(SmbClient.java:337)\n\t
at org.codelibs.fess.crawler.client.smb.SmbClient.getResponseData(SmbClient.java:233)\n\t
at org.codelibs.fess.crawler.client.smb.SmbClient.processRequest(SmbClient.java:161)\n\t
at org.codelibs.fess.crawler.client.smb.SmbClient.doHead(SmbClient.java:391)\n\t
at org.codelibs.fess.crawler.client.AbstractCrawlerClient.execute(AbstractCrawlerClient.java:129)\n\t
at org.codelibs.fess.crawler.FessCrawlerThread.isContentUpdated(FessCrawlerThread.java:96)\n\t
at org.codelibs.fess.crawler.CrawlerThread.run(CrawlerThread.java:148)\n\t
at java.base/java.lang.Thread.run(Unknown Source)\n"}

{"@timestamp":"2023-07-06T00:40:54.110Z",
"log.level":"DEBUG",
"message":"error reading control group stats",
 "ecs.version": "1.2.0",
"service.name":"fess",
"event.dataset":"crawler",
"process.thread.name":"pool-5-thread-5",
"log.logger":"org.opensearch.monitor.os.OsProbe",
"error.type":"java.nio.file.NoSuchFileException",
"error.message":"/sys/fs/cgroup/cpuacct/docker/6658c27d01bf57f13cac0a829f5d553300ec5371bf2b624453b0a1f1986f72a0/cpuacct.usage",
"error.stack_trace":"java.nio.file.NoSuchFileException: /sys/fs/cgroup/cpuacct/docker/6658c27d01bf57f13cac0a829f5d553300ec5371bf2b624453b0a1f1986f72a0/cpuacct.usage\n
\tat java.base/sun.nio.fs.UnixException.translateToIOException(Unknown Source)\n
\tat java.base/sun.nio.fs.UnixException.rethrowAsIOException(Unknown Source)\n
\tat java.base/sun.nio.fs.UnixException.rethrowAsIOException(Unknown Source)\n
\tat java.base/sun.nio.fs.UnixFileSystemProvider.newByteChannel(Unknown Source)\n
\tat java.base/java.nio.file.Files.newByteChannel(Unknown Source)\n
\tat java.base/java.nio.file.Files.newByteChannel(Unknown Source)\n
\tat java.base/java.nio.file.spi.FileSystemProvider.newInputStream(Unknown Source)\n
\tat java.base/java.nio.file.Files.newInputStream(Unknown Source)\n
\tat java.base/java.nio.file.Files.newBufferedReader(Unknown Source)\n
\tat java.base/java.nio.file.Files.readAllLines(Unknown Source)\n
\tat java.base/java.nio.file.Files.readAllLines(Unknown Source)\n
\tat org.opensearch.monitor.os.OsProbe.readSingleLine(OsProbe.java:251)\n
\tat org.opensearch.monitor.os.OsProbe.readSysFsCgroupCpuAcctCpuAcctUsage(OsProbe.java:340)\n
\tat org.opensearch.monitor.os.OsProbe.getCgroupCpuAcctUsageNanos(OsProbe.java:327)\n
\tat org.opensearch.monitor.os.OsProbe.getCgroup(OsProbe.java:558)\n
\tat org.opensearch.monitor.os.OsProbe.osStats(OsProbe.java:695)\n
\tat org.codelibs.fess.timer.SystemMonitorTarget.appendOsStats(SystemMonitorTarget.java:151)\n
\tat org.codelibs.fess.timer.SystemMonitorTarget.expired(SystemMonitorTarget.java:54)\n
\tat org.codelibs.core.timer.TimeoutTask.expired(TimeoutTask.java:113)\n
\tat org.codelibs.core.timer.TimeoutManager.lambda$processTask$0(TimeoutManager.java:198)\n
\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)\n
\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)\n
\tat java.base/java.lang.Thread.run(Unknown Source)\n
"}

それ以外で、原因になりそうなものは見当たらなかったのですが、こんなログに着目したらよい、というようなものがあれば教えていただけないでしょうか？

shinsuke · July 6, 2023, 8:49am

スレッド単位でみて、次の@timestampまで時間が空いているところなどを見ると良いと思います。

andor · July 7, 2023, 7:03am

アドバイスありがとうございます！

00:40:31 ごろ以降、スレッド単位に@timestanpの間隔が数秒となるケースが散見されることからその直前に発生しているログで、怪しいと思えるもの捜してみました。
クロールが始まってしばらく4分ぐらいたった 00:39:58 から 00:40:30までの約30秒の間に集中して、以下のログがペアで26回書かれていることが確認できました。(それ以前も、それ以降もこのエラーは発生していません)

0xC000011Fは、ここによると
STATUS_TOO_MANY_OPENED_FILES
らしいのですが、速度低下の原因である可能性はないでしょうか？
回避策あるいはヒントでもかまわないですが、ご教示いただけないでしょうか？

{"@timestamp":"2023-07-06T00:39:58.143Z",
"log.level":"DEBUG",
"message":"Error code: 0xC0000011 for Smb2ReadRequest",
 "ecs.version": "1.2.0",
"service.name":"fess",
"event.dataset":"crawler",
"process.thread.name":"Crawler-20230706003747-1-3",
"log.logger":"jcifs.smb.SmbTransportImpl"}

{"@timestamp":"2023-07-06T00:39:58.144Z",
"log.level":"DEBUG",
"message":"Not retrying",
 "ecs.version": "1.2.0",
"service.name":"fess",
"event.dataset":"crawler",
"process.thread.name":"Crawler-20230706003747-1-3",
"log.logger":"jcifs.smb.SmbTreeConnection",
"error.type":"jcifs.smb.SmbException",
"error.message":"End of file",
"error.stack_trace":"jcifs.smb.SmbException: End of file\n\t
at jcifs.smb.SmbTransportImpl.checkStatus2(SmbTransportImpl.java:1496)\n\t
at jcifs.smb.SmbTransportImpl.checkStatus(SmbTransportImpl.java:1607)\n\t
at jcifs.smb.SmbTransportImpl.sendrecv(SmbTransportImpl.java:1014)\n\t
at jcifs.smb.SmbTransportImpl.send(SmbTransportImpl.java:1578)\n\t
at jcifs.smb.SmbSessionImpl.send(SmbSessionImpl.java:409)\n\t
at jcifs.smb.SmbTreeImpl.send(SmbTreeImpl.java:472)\n\t
at jcifs.smb.SmbTreeConnection.send0(SmbTreeConnection.java:404)\n\t
at jcifs.smb.SmbTreeConnection.send(SmbTreeConnection.java:318)\n\t
at jcifs.smb.SmbTreeConnection.send(SmbTreeConnection.java:298)\n\t
at jcifs.smb.SmbTreeHandleImpl.send(SmbTreeHandleImpl.java:130)\n\t
at jcifs.smb.SmbTreeHandleImpl.send(SmbTreeHandleImpl.java:117)\n\t
at jcifs.smb.SmbFileInputStream.readDirect(SmbFileInputStream.java:335)\n\t
at jcifs.smb.SmbFileInputStream.read(SmbFileInputStream.java:278)\n\t
at java.base/java.io.BufferedInputStream.fill(Unknown Source)\n\t
at java.base/java.io.BufferedInputStream.read1(Unknown Source)\n\t
at java.base/java.io.BufferedInputStream.read(Unknown Source)\n\t
at java.base/java.io.FilterInputStream.read(Unknown Source)\n\t
at org.codelibs.core.io.CopyUtil.copyInternal(CopyUtil.java:1271)\n\t
at org.codelibs.core.io.CopyUtil.copy(CopyUtil.java:151)\n\t
at org.codelibs.core.io.InputStreamUtil.getBytes(InputStreamUtil.java:70)\n\t
at org.codelibs.fess.crawler.client.smb.SmbClient.getResponseData(SmbClient.java:249)\n\t
at org.codelibs.fess.crawler.client.smb.SmbClient.processRequest(SmbClient.java:161)\n\t
at org.codelibs.fess.crawler.client.smb.SmbClient.doGet(SmbClient.java:144)\n\t
at org.codelibs.fess.crawler.client.AbstractCrawlerClient.execute(AbstractCrawlerClient.java:128)\n\t
at org.codelibs.fess.crawler.CrawlerThread.run(CrawlerThread.java:154)\n\t
at java.base/java.lang.Thread.run(Unknown Source)\n"}

shinsuke · July 7, 2023, 11:57am

STATUS_TOO_MANY_OPENED_FILESだと、ファイルサーバー側のファイルディスクリプタが不足しているみたいな感じもするので、ファイルサーバー側の設定を確認して、対応してもらうのが良いと思います。Fess側で回避的に対応するのであれば、クロールのスレッド数を減らすなどすれば、開くファイル数は減るとは思います。

andor · July 14, 2023, 9:34am

お世話になります。
試行錯誤する過程で以下の事実がわかりました。
・Fess側のスレッド数を1にしても、STATUS_TOO_MANY_OPENED_FILESのエラーは発生する。
・問題なくindexを作りに行く時間帯①と、Processing no docs in indexing queue が多発してほとんどindexを作りにいかない時間帯②が交互に訪れることがある
・①は数分間、②は1～2時間
・STATUS_TOO_MANY_OPENED_FILESのエラーが発生せずに、②の時間帯が訪れるケースがある
（この時は、①②①②①の順になり、最後の①の時間帯でSTATUS_TOO_MANY_OPENED_FILESのエラーが発生しました）

②が起きる直前のログをから、手がかりとなるlogを探しているのですが、目ぼしいものは見つかっていません。
indexing queueへの書き出しが少なくなるような条件として考えられるものはないでしょうか？あるいは、DEBUGログのここに着目するとよいというようなものはないでしょうか？ご教示いただけると幸いです。

shinsuke · July 14, 2023, 12:48pm

STATUS_TOO_MANY_OPENED_FILESの問題であれば、Fessではなく、ファイルサーバー側の問題になるので、これ以上はFessで何かできることはないと思います。ファイルサーバー側のI/O周りを確認するのが良いと思います。

andor · July 15, 2023, 1:41am

すみません。説明がわかりづらかったようです。
STATUS_TOO_MANY_OPENED_FILESが出ていない状態でも、Processing no docs in indexing queue が多発することがわかりました。
この事実から、Processing no docs in indexing queue 多発の原因は、STATUS_TOO_MANY_OPENED_FILES以外にあると考えた次第です。

何らかのトリガーによって indexing queue にデータを入れる処理が動くと思うのですが、その処理が起動されなくなる可能性のある条件について、DEBUGログから判断できるものはないでしょうか？

shinsuke · July 15, 2023, 2:04am

ファイルサーバーは何でしょうか？Windows Serverでしょうか？まずは、ファイルサーバー側のログを確認する必要があると思います。

Processing no docs in indexing queue

はクロールが詰まって返ってこないだけだと思います。たぶん、ファイルサーバーがtoo many opened fileとかでレスポンスを返してこない状態になっている気がします。なので、これもファイルサーバー側のログを確認するのが良いと思います。

ファイルサーバーと言っても、いろいろなSMBプロトコルを話すものがあると思います。I/O以外の問題の可能性で、ファイルサーバーがWindows Serverでなければ、SMB1を話している気がするので、クロール設定で、smb://〜でなく、smb1://〜に変えるとつまらなくなる可能性もあるかもしれません。

andor · July 15, 2023, 4:03am

ありがとうございます。
ファイルサーバーは、Windows Serverです。
smb1://〜は、実施済で、別のエラーが出た記憶があります。

ファイルサーバーがレスポンスを返してこない状態になっている気がします。

ありがとうございます。お聞きしたかったのはこの種の条件です。

ファイルサーバー側のあるファイルがクローリングされた場合に書き出されるログ10種類のログについて、ログの種類ごとに本数を集計したところ、以下の通りでした。

①{"@timestamp":"2023-07-06T00:39:57.901Z","log.level": "INFO","message":"Crawling URL: smb://～                1583
②{"@timestamp":"2023-07-06T00:39:57.901Z","log.level":"DEBUG","message":"Creating SmbFile: smb://～            661
③{"@timestamp":"2023-07-06T00:39:57.901Z","log.level":"DEBUG","message":"Processing SmbFile: smb://～          661
④{"@timestamp":"2023-07-06T00:39:57.903Z","log.level":"DEBUG","message":"Checking SmbFile Size: smb://～       346
⑤{"@timestamp":"2023-07-06T00:39:57.903Z","log.level":"DEBUG","message":"Parsing SmbFile Owner: smb://～       346
⑥{"@timestamp":"2023-07-06T00:39:57.909Z","log.level":"DEBUG","message":"Parsing SmbFile ACL: smb://～         346
⑦{"@timestamp":"2023-07-06T00:39:57.999Z","log.level":"DEBUG","message":"Parsing SmbFile MIME Type: smb://～   341
⑧{"@timestamp":"2023-07-06T00:39:58.033Z","log.level": "INFO","message":"Not modified URL: smb://～            1009
⑨{"@timestamp":"2023-07-06T00:39:58.106Z","log.level":"DEBUG","message":"Finished smb://～                     315
⑩{"@timestamp":"2023-07-06T00:40:03.133Z","log.level":"DEBUG","message":"Indexing smb://～                     315

①のログは、Fessがファイルサーバーにリクエストを出す前に書くログ、②～⑩はファイルサーバーからのレスポンスが戻ってきた後に書くログ、と考えてよいですね。
⑧の数が他より多い理由が不明ですが、ファイルサーバーからのレスポンスが来ていないものが結構あるようです。

ファイルシステムクロールの間隔を調整してみます。
解決の糸口が見つかったようです。ありがとうございました。

andor · September 8, 2023, 1:52am

クロール速度が遅くなる原因が判明しました。

【状況説明】
原因はファイルサーバーからのレスポンス遅延・欠落ではなく、jcifs/smb/SmbTransportImpl.javaのsendrecvメソッド内で、セマフォのpermit取得不可によるtimeoutが連続的に発生したことでした。
以下、traceの設定にして取得した同一スレッドのログのうち、関係する箇所を抜粋したものです。

ログの先頭につけた①～④は、以下を表しています。
①fess/crawler/client/smb /SmbClient.javaのprocessAccessControlEntriesメソッド
で、file.getSecurity(resolveSids)で取得した各access control entryに対して書かれたログ
②jcifs/src/main/java/jcifs/smb/SmbTransportImpl.javaのsendrecvメソッド内whileループ先頭部分、
credits.tryAcquire(セマフォpermit取得)直前の「取得permit値」と「利用可能permit値」のログ
③ 〃メソッド内、credits.tryAcquireでFailed to acquire credits in timeのtimeoutが発生
した時のログ
④ 〃メソッド内、whileループ終盤でcredits.release(セマフォpermit解放)直前の解放permit値
のログ

①{00:12:28.713Z","DEBUG","ACE:Allow ファイルサーバーから応答された許可グループ名1        0x001301BF Inherited This folder only                  ",
②{00:12:28.714Z","TRACE","jcifs.internal.smb2.create.Smb2CreateRequest costs 1 avail 1 (Transport1)",
④{00:12:28.722Z","TRACE","Adding credits 1",
②{00:12:28.723Z","TRACE","jcifs.internal.smb2.ioctl.Smb2IoctlRequest costs 1 avail 1 (Transport1)",
④{00:12:28.731Z","TRACE","Adding credits 1",
②{00:12:28.732Z","TRACE","jcifs.internal.smb2.ioctl.Smb2IoctlRequest costs 1 avail 1 (Transport1)",
④{00:12:28.740Z","TRACE","Adding credits 1",
②{00:12:28.741Z","TRACE","jcifs.internal.smb2.ioctl.Smb2IoctlRequest costs 1 avail 1 (Transport1)",
④{00:12:28.749Z","TRACE","Adding credits 0",                                                              ※1
②{00:12:28.749Z","TRACE","jcifs.internal.smb2.create.Smb2CloseRequest costs 1 avail 0 (Transport1)",      ※2
③{00:12:58.750Z","TRACE","Send failed",:"Failed to acquire credits in time","error.stack_trace":"jcifs.smb.SmbException:
①{00:12:58.751Z","DEBUG","ACE:Allow ファイルサーバーから応答された許可グループ名2    0x001301BF Inherited This folder only 
②{00:12:58.754Z","TRACE","jcifs.internal.smb2.create.Smb2CreateRequest costs 1 avail 0 (Transport1)"
③{00:13:28.755Z","TRACE","Send failed",:"Failed to acquire credits in time","error.stack_trace":"jcifs.smb.SmbException:
.....

※1で、解放するpermit値が0となる。ここには、直前でファイルサーバーに送信したIoctlのRequestに対するresponseオブジェクト内のgrantedCreditsの集計値が設定される
※1の解放permit値0が※2のavail値に引き継がれ、次にpermit値が0の状態でcredits.tryAcquireが行われ、permitの取得はできずにtimeoutの30秒後に例外が発生し、③のtimeoutログが書かれる
※1までの間は、permit値が1以上の状態で、credits.tryAcquireが行われるので例外が発生せずに④のresponseからの集計処理が行われてきたが、これ以降は応答される許可グループの数分、30秒間隔で②と③を繰り返すのみ。timeoutが発生している時間帯は、このスレッドで新たなファイルはクロールされません。

一旦この状態になると、数十分～数時間この状態が続き、その後permit値は再び1以上になってクロールは復活するが、再度この状態になって、というようにクロール実行とクロール停止が繰り返されます。

※1で、突然responseオブジェクト内のgrantedCreditsが0になっているので、ファイルサーバー内で何等かの状況が発生していると思うのですが、ファイルサーバーのevent logを見ても関連しそうなものは見つかっていません。

【質問】
Timeout発生の回避につながる方策で心当たりのあるものがあれば、ご教示おねがいいたします。