after history for directory fails, individual files are history indexed

[vladak]

A colleague of mine has a big Mercurial repo (12 GB) where hg log on the top-level directory takes many hours to complete. When such repo is indexed for the first time, the hg log command times out and the indexer proceeds to adding every single file in the repository and generates xrefs for them. Unfortunately, as a side effect it also tries to generate history for each file (as there is none in the history cache) sequentially.

In the log it looks like this:

2014-01-27 09:19:08.175-0800 WARNING t31 Executor.exec: Non-zero exit status -1 from command [/usr/bin/hg, log, --template, changeset: {rev}:{node|short}\n{branches}{tags}{parents}\nuser: {author}\ndate: {date|isodate}\nfiles: {files}\ndescription: {desc|strip|obfuscate}\nfile_copies: {file_copies}\n] in directory /builds1/psumbera2
2014-01-27 09:19:08.175-0800 WARNING t31 HistoryGuru.createCache: An error occured while creating cache for /builds1/psumbera2/userland-src (MercurialRepository)
org.opensolaris.opengrok.history.HistoryException: Failed to get history for: "/builds1/psumbera2/userland-src" Exit code: -1
        at org.opensolaris.opengrok.history.MercurialHistoryParser.parse(MercurialHistoryParser.java:79)
        at org.opensolaris.opengrok.history.MercurialRepository.getHistory(MercurialRepository.java:509)
        at org.opensolaris.opengrok.history.Repository.createCache(Repository.java:296)
        at org.opensolaris.opengrok.history.HistoryGuru.createCache(HistoryGuru.java:475)
        at org.opensolaris.opengrok.history.HistoryGuru.access$000(HistoryGuru.java:51)
        at org.opensolaris.opengrok.history.HistoryGuru$1.run(HistoryGuru.java:519)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:744)
2014-01-27 09:19:08.176-0800 INFO t1 Indexer.prepareIndexer: Done...
2014-01-27 09:19:08.177-0800 INFO t1 Indexer.doIndexerExecution: Starting indexing

...

2014-01-27 11:19:08.516-0800 WARNING t39 HistoryGuru.createCache: An error occured while creating cache for /builds1/psumbera2/userland-src (MercurialRepository)
org.opensolaris.opengrok.history.HistoryException: Failed to get history for: "/builds1/psumbera2/userland-src" Exit code: -1
        at org.opensolaris.opengrok.history.MercurialHistoryParser.parse(MercurialHistoryParser.java:79)
        at org.opensolaris.opengrok.history.MercurialRepository.getHistory(MercurialRepository.java:509)
        at org.opensolaris.opengrok.history.Repository.createCache(Repository.java:296)
        at org.opensolaris.opengrok.history.HistoryGuru.createCache(HistoryGuru.java:475)
        at org.opensolaris.opengrok.history.HistoryGuru.ensureHistoryCacheExists(HistoryGuru.java:636)
        at org.opensolaris.opengrok.index.IndexDatabase.update(IndexDatabase.java:350)
        at org.opensolaris.opengrok.index.IndexDatabase$1.run(IndexDatabase.java:168)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:744)
2014-01-27 11:19:08.583-0800 INFO t39 DefaultIndexChangedListener.fileAdd: Add: /components/a2ps/a2ps/.a2ps.prcs_aux (PlainAnalyzer)
2014-01-27 11:19:08.630-0800 FINE t39 Executor.exec: Executing command [/usr/bin/hg, log, -f, --template, changeset: {rev}:{node|short}\n{branches}{tags}{parents}\nuser: {author}\ndate: {date|isodate}\nfiles: {files}\ndescription: {desc|strip|obfuscate}\n, components/a2ps/a2ps/.a2ps.prcs_aux] in directory /builds1/psumbera2/userland-src
2014-01-27 11:19:20.977-0800 FINE t39 Ctags.initialize: Executing ctags command [/builds1/psumbera2/ctags-5.8/ctags --c-kinds=+l --sql-kinds=+l --Fortran-kinds=+L --C++-kinds=+l --file-scope=yes -u --filter=yes --filter-terminator=__ctags_done_with_file__
 --fields=-anf+iKnS --excmd=pattern --langmap=sh:+.kshlib --langmap=sql:+.plb --langmap=sql:+.pls --langmap=sql:+.pld --langmap=sql:+.pks --langdef=scala --langmap=scala:.scala --regex-scala=/^[      ]*((abstract|final|sealed|implicit|lazy)[       ]*)*(private|protected)?[       ]*class[        ]+([a-zA-Z0-9_]+)/^D/c,classes/ --regex-scala=/^[       ]*((abstract|final|sealed|implicit|lazy)[       ]*)*(private|protected)?[       ]*object[       ]+([a-zA-Z0-9_]+)/^D/c,objects/ --regex-scala=/^[       ]*((abstract|final|sealed|implicit|lazy)[       ]*)*(private|protected)?[       ]*case class[   ]+([a-zA-Z0-9_]+)/^D/c,case classes/ --regex-scala=/^[  ]*((abstract|final|sealed|implicit|lazy)[       ]*)*(private|protected)?[       ]*case object[  ]+([a-zA-Z0-9_]+)/^D/c,case objects/ --regex-scala=/^[  ]*((abstract|final|sealed|implicit|lazy)[       ]*)*(private|protected)?[       ]*trait[        ]+([a-zA-Z0-9_]+)/^D/t,traits/ --regex-scala=/^[        ]*type[         ]+([a-zA-Z0-9_]+)/^A/T,types/ --regex-scala=/^[         ]*((abstract|final|sealed|implicit|lazy)[       ]*)*def[        ]+([a-zA-Z0-9_]+)/^C/m,methods/ --regex-scala=/^[       ]*((abstract|final|sealed|implicit|lazy)[       ]*)*val[        ]+([a-zA-Z0-9_]+)/^C/l,constants/ --regex-scala=/^[     ]*((abstract|final|sealed|implicit|lazy)[       ]*)*var[        ]+([a-zA-Z0-9_]+)/^C/l,variables/ --regex-scala=/^[     ]*package[      ]+([a-zA-Z0-9_.]+)/^A/p,packages/ ]
2014-01-27 11:19:21.444-0800 FINER t39 DefaultIndexChangedListener.fileAdded: Added: /components/a2ps/a2ps/.a2ps.prcs_aux (PlainAnalyzer)
2014-01-27 11:19:21.445-0800 INFO t39 DefaultIndexChangedListener.fileAdd: Add: /components/a2ps/a2ps/.patched (FileAnalyzer)
2014-01-27 11:19:21.445-0800 FINE t39 Executor.exec: Executing command [/usr/bin/hg, log, -f, --template, changeset: {rev}:{node|short}\n{branches}{tags}{parents}\nuser: {author}\ndate: {date|isodate}\nfiles: {files}\ndescription: {desc|strip|obfuscate}\n, components/a2ps/a2ps/.patched] in directory /builds1/psumbera2/userland-src
2014-01-27 11:19:25.329-0800 FINER t39 DefaultIndexChangedListener.fileAdded: Added: /components/a2ps/a2ps/.patched (FileAnalyzer)
2014-01-27 11:19:25.330-0800 INFO t39 DefaultIndexChangedListener.fileAdd: Add: /components/a2ps/a2ps/.prep (FileAnalyzer)
2014-01-27 11:19:25.331-0800 FINE t39 Executor.exec: Executing command [/usr/bin/hg, log, -f, --template, changeset: {rev}:{node|short}\n{branches}{tags}{parents}\nuser: {author}\ndate: {date|isodate}\nfiles: {files}\ndescription: {desc|strip|obfuscate}\n, components/a2ps/a2ps/.prep] in directory /builds1/psumbera2/userland-src
2014-01-27 11:19:29.365-0800 FINER t39 DefaultIndexChangedListener.fileAdded: Added: /components/a2ps/a2ps/.prep (FileAnalyzer)
2014-01-27 11:19:29.381-0800 INFO t39 DefaultIndexChangedListener.fileAdd: Add: /components/a2ps/a2ps/.prev-version (PlainAnalyzer)
2014-01-27 11:19:29.383-0800 FINE t39 Executor.exec: Executing command [/usr/bin/hg, log, -f, --template, changeset: {rev}:{node|short}\n{branches}{tags}{parents}\nuser: {author}\ndate: {date|isodate}\nfiles: {files}\ndescription: {desc|strip|obfuscate}\n, components/a2ps/a2ps/.prev-version] in directory /builds1/psumbera2/userland-src
2014-01-27 11:19:33.423-0800 FINER t39 DefaultIndexChangedListener.fileAdded: Added: /components/a2ps/a2ps/.prev-version (PlainAnalyzer)

[vladak]

The workaround is of course to set the timeout to some insanely high value however this does not solve the case when hg fails by itself for some other reason (within the timeout).

[vladak]

I don't think this is a stopper.

[vladak]

Not sure what is the exact mechanism of triggering the history index for each file but maybe the solution would be to propagate the top-level directory hg log failure and suppress the history indexing of individual files.

[vladak]

Thinking of this, the mechanism is most probably similar to that of SCM types which do not support per-directory history such as CVS.

[vladak]

The stack looks like this:

org.opensolaris.opengrok.history.MercurialRepository.getHistoryLogExecutor(MercurialRepository.java:112)
org.opensolaris.opengrok.history.MercurialHistoryParser.parse(MercurialHistoryParser.java:75)
org.opensolaris.opengrok.history.MercurialRepository.getHistory(MercurialRepository.java:515)
org.opensolaris.opengrok.history.MercurialRepository.getHistory(MercurialRepository.java:508)
org.opensolaris.opengrok.history.FileHistoryCache.get(FileHistoryCache.java:378)
org.opensolaris.opengrok.history.HistoryGuru.getHistory(HistoryGuru.java:209)
org.opensolaris.opengrok.history.HistoryGuru.getHistoryReader(HistoryGuru.java:172)
org.opensolaris.opengrok.analysis.AnalyzerGuru.populateDocument(AnalyzerGuru.java:284)
org.opensolaris.opengrok.index.IndexDatabase.addFile(IndexDatabase.java:590)
org.opensolaris.opengrok.index.IndexDatabase.indexDown(IndexDatabase.java:841)
org.opensolaris.opengrok.index.IndexDatabase.indexDown(IndexDatabase.java:811)
org.opensolaris.opengrok.index.IndexDatabase.indexDown(IndexDatabase.java:811)
org.opensolaris.opengrok.index.IndexDatabase.update(IndexDatabase.java:378)
org.opensolaris.opengrok.index.IndexDatabase$1.run(IndexDatabase.java:168)
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
java.util.concurrent.FutureTask.run(FutureTask.java:262)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
java.lang.Thread.run(Thread.java:744)

In populateDocument() the history generation is done by this piece:

283        try {
284            HistoryReader hr = HistoryGuru.getInstance().getHistoryReader(file);
285            if (hr != null) {
286                doc.add(new TextField(QueryBuilder.HIST, hr));
287                // date = hr.getLastCommentDate() //RFE
288            }
289        } catch (HistoryException e) {
290            OpenGrokLogger.getLogger().log(Level.WARNING, "An error occurred while reading history: ", e);
291        }

which bubbles down to the actual getHistory() in MercurialRepository object instance. The failed history for the whole repo should tick a flag that it failed and subsequent requests for history should be suppressed (by getHistoryReader(file) returning null in the above code).

[vladak]

Thinking of this further the approach of suppressing would lead to data loss - the Lucene index needs to be generated completely with the history - so that the history queries can be made. That's why history index for given repo is done first and only once it is done the Lucene indexing is done. Strictly, we might want to actually terminate the whole index of a repo (one that supports history for directory) if the history index fails.

[vladak]

For SCMs that are capable of fetching history per directory this can be workarounded by using the fetchHistoryWhenNotInCache tunable (see https://github.com/oracle/opengrok/wiki/Indexer-configuration). Still, this might be unwanted if one rather likes not to generate the index at all if history for the top-level directory cannot be retrieved.

[vladak]

Also, this error propagation needs to work for any repository for given project. If indexing without projects, this should result in the whole reindex to be terminated.

[vladak]

As a pre-requisite, this needs per-project tunable to ignore failures for certain repositories. E.g. the OpenGrok git repository has some sub-repositories for which it might not be possible to generate the history for (RCS, SCCS) and yet it is desired to ignore these failures and generate the history for the top-level repository.