Wrong logging level in LuceneHelperImpl

• Type: Bug
• Status: Closed
• Resolution: Fixed
• Affects Version/s: 6.2.X EE
• Fix Version/s: 6.2.X EE
• Component/s: Search Infrastructure, Search Infrastructure > Lucene Impl
• Labels:
  • 6.2.x-only
  • INACTIVE
  • liferay-fixpack-portal-104-6210
• Branch Version/s:
  6.2.x
• Backported to Branch:
  Committed
• Fix Priority: 2
• Git Pull Request: https://github.com/brianchandotcom/liferay-portal-ee/pull/13175

[This issue happens in 6.2.x ]

In com.liferay.portal.search.lucene.LuceneHelperImpl.addTerm(BooleanQuery, String, String, boolean, BooleanClauseOccur)
there is a try-catch block for Exception. Its log level is "warn"

It can occur that org.apache.lucene.search.BooleanQuery$TooManyClauses exception is thrown when clauses are more than maxClauseCount Lucenes's property (this can be configured by lucene.boolean.query.clause.max.size portal's property).

As log level is "warn", it is complicated to detect this situation because no log message is written unless you change it (for example to "info").

And catching the exception causes that maxClauseCount items are added to the BooleanQuery, so the results can mislead to user (for example when he is using an AssetPublisher)

To diagnose what is happening could be improved changing the log level to "error", thus user can do it through log.

Steps to reproduce:

• Define in portal-ext.properties lucene.boolean.query.clause.max.size to 10
• Create thirteen tags (for example: '01', '02', ..., '13')
• Create a web content ('A') and set its categorization with tag '12'
• Create a second web ('B') content and set its categorization with tag '13'
• Add an Asset Publisher an configure with this settings:
  • Asset Selection -> Dynamic
  • Scope -> Current site
  • Asset type -> Any
  • Filter ->"Contains any of the following tags": '01', '02', '03', '04', '05', '06', '07', '08', '09', '10'.

Check point 1:
The Asset Publisher shows message "There are no results."

• Reconfigure the Asset Publisher changing
  • Filter ->"Contains any of the following tags": '01', '02', '03', '04', '05', '06', '07', '08', '09', '10', '11'

Observed behavior:
The Asset Publisher shows message "There are no results."
Portal log does not show any message

Expected behavior:
The Asset Publisher shows message "There are no results."
Portal log shows

08:37:53,876 WARN [RuntimePageImpl-2][LuceneHelperImpl:274] org.apache.lucene.search.BooleanQuery$TooManyClauses: maxClauseCount is set to 10 
org.apache.lucene.search.BooleanQuery$TooManyClauses: maxClauseCount is set to 10 
	at org.apache.lucene.search.BooleanQuery.add(BooleanQuery.java:136) 
	at org.apache.lucene.search.BooleanQuery.add(BooleanQuery.java:127) 
	at com.liferay.portal.search.lucene.LuceneHelperImpl._includeIfUnique(LuceneHelperImpl.java:1077) 
	at com.liferay.portal.search.lucene.LuceneHelperImpl.addTerm(LuceneHelperImpl.java:270) 
	at com.liferay.portal.search.lucene.LuceneHelperImpl.addTerm(LuceneHelperImpl.java:220) 
	at com.liferay.portal.search.lucene.LuceneHelperUtil.addTerm(LuceneHelperUtil.java:268) 
	at com.liferay.portal.search.lucene.LuceneHelperUtil.addTerm(LuceneHelperUtil.java:262) 
	at com.liferay.portal.search.lucene.LuceneHelperUtil.addTerm(LuceneHelperUtil.java:256) 
	at com.liferay.portal.search.lucene.BooleanQueryImpl.addTerm(BooleanQueryImpl.java:265) 
	at com.liferay.portlet.assetpublisher.util.AssetSearcher.addSearchAnyTags(AssetSearcher.java:280) 
	at com.liferay.portlet.assetpublisher.util.AssetSearcher.addSearchAssetTagNames(AssetSearcher.java:303) 
	at com.liferay.portal.kernel.search.BaseIndexer.getFullQuery(BaseIndexer.java:271) 
	at com.liferay.portal.kernel.search.BaseIndexer.doSearch(BaseIndexer.java:1418) 
	at com.liferay.portal.kernel.search.DefaultSearchResultPermissionFilter.getHits(DefaultSearchResultPermissionFilter.java:75) 
	at com.liferay.portal.kernel.search.BaseSearchResultPermissionFilter.search(BaseSearchResultPermissionFilter.java:54) 
	at com.liferay.portal.kernel.search.BaseIndexer.search(BaseIndexer.java:582) 
	at com.liferay.portlet.asset.util.AssetUtil.search(AssetUtil.java:716) 
	at com.liferay.portlet.asset.util.AssetUtil.search(AssetUtil.java:661) 
	at org.apache.jsp.html.portlet.asset_005fpublisher.view_jsp._jspService(Unknown Source) 
...

• Change log level for com.liferay.portal.search.lucene.LuceneHelperImpl to WARN
  Control Panel -> Configuration -> Server Administration -> Log Levels -> Add Category
• Go to page that contains the Asset Publisher

Check point 2:
The Asset Publisher shows message "There are no results."
Portal log shows

08:37:53,876 WARN [RuntimePageImpl-2][LuceneHelperImpl:274] org.apache.lucene.search.BooleanQuery$TooManyClauses: maxClauseCount is set to 10 
org.apache.lucene.search.BooleanQuery$TooManyClauses: maxClauseCount is set to 10 
	at org.apache.lucene.search.BooleanQuery.add(BooleanQuery.java:136) 
	at org.apache.lucene.search.BooleanQuery.add(BooleanQuery.java:127) 
	at com.liferay.portal.search.lucene.LuceneHelperImpl._includeIfUnique(LuceneHelperImpl.java:1077) 
	at com.liferay.portal.search.lucene.LuceneHelperImpl.addTerm(LuceneHelperImpl.java:270) 
	at com.liferay.portal.search.lucene.LuceneHelperImpl.addTerm(LuceneHelperImpl.java:220) 
	at com.liferay.portal.search.lucene.LuceneHelperUtil.addTerm(LuceneHelperUtil.java:268) 
	at com.liferay.portal.search.lucene.LuceneHelperUtil.addTerm(LuceneHelperUtil.java:262) 
	at com.liferay.portal.search.lucene.LuceneHelperUtil.addTerm(LuceneHelperUtil.java:256) 
	at com.liferay.portal.search.lucene.BooleanQueryImpl.addTerm(BooleanQueryImpl.java:265) 
	at com.liferay.portlet.assetpublisher.util.AssetSearcher.addSearchAnyTags(AssetSearcher.java:280) 
	at com.liferay.portlet.assetpublisher.util.AssetSearcher.addSearchAssetTagNames(AssetSearcher.java:303) 
	at com.liferay.portal.kernel.search.BaseIndexer.getFullQuery(BaseIndexer.java:271) 
	at com.liferay.portal.kernel.search.BaseIndexer.doSearch(BaseIndexer.java:1418) 
	at com.liferay.portal.kernel.search.DefaultSearchResultPermissionFilter.getHits(DefaultSearchResultPermissionFilter.java:75) 
	at com.liferay.portal.kernel.search.BaseSearchResultPermissionFilter.search(BaseSearchResultPermissionFilter.java:54) 
	at com.liferay.portal.kernel.search.BaseIndexer.search(BaseIndexer.java:582) 
	at com.liferay.portlet.asset.util.AssetUtil.search(AssetUtil.java:716) 
	at com.liferay.portlet.asset.util.AssetUtil.search(AssetUtil.java:661) 
	at org.apache.jsp.html.portlet.asset_005fpublisher.view_jsp._jspService(Unknown Source) 
...

That is, it has been necessary to make a log level change.

• Change log level for com.liferay.portal.search.lucene.LuceneHelperImpl to OFF
• Reconfigure the Asset Publisher changing
  • Filter ->"Contains any of the following tags": '01', '02', '03', '04', '05', '06', '07', '08', '09', '10', '11', '12'

Observed behavior:
The Asset Publisher shows message "There are no results." (because '12' tag is out of lucene query)
Portal log does not show any message

Expected behavior:
The Asset Publisher shows web content 'A' (because user knows that the Asset Publisher searches for '12' tag)
Portal log shows

08:37:53,876 WARN [RuntimePageImpl-2][LuceneHelperImpl:274] org.apache.lucene.search.BooleanQuery$TooManyClauses: maxClauseCount is set to 10 
org.apache.lucene.search.BooleanQuery$TooManyClauses: maxClauseCount is set to 10 
	at org.apache.lucene.search.BooleanQuery.add(BooleanQuery.java:136) 
...

With this log message user could know that there is not any result in the Asset Publisher because '12' tag is out of lucene query.

• Reconfigure the Asset Publisher changing
  • Filter ->"Contains any of the following tags": '01', '02', '03', '04', '05', '06', '07', '08', '12', '13'

Observed and Expected behavior:
The Asset Publisher shows web content 'A'
The Asset Publisher shows web content 'B'

• Reconfigure the Asset Publisher changing
  • Filter ->"Contains any of the following tags": '01', '02', '03', '04', '05', '06', '07', '08', '12', '09', '13'

Observed behavior:
The Asset Publisher shows web content 'A'
The Asset Publisher does not show web content 'B' (because '13' tag is out of lucene query)
Portal log does not show any message

Expected behavior:
The Asset Publisher shows web content 'A' (because user knows that the Asset Publisher searches for '12' tag)
The Asset Publisher shows web content 'B' (because user knows that the Asset Publisher searches for '13' tag)
Portal log shows

08:37:53,876 WARN [RuntimePageImpl-2][LuceneHelperImpl:274] org.apache.lucene.search.BooleanQuery$TooManyClauses: maxClauseCount is set to 10 
org.apache.lucene.search.BooleanQuery$TooManyClauses: maxClauseCount is set to 10 
	at org.apache.lucene.search.BooleanQuery.add(BooleanQuery.java:136) 
...

With this log message user could know that results in the Asset Publisher are wrong because '13' tag is out of lucene query.

Check point 3:
The Asset Publisher results can confuse to user but there is not any clue about that.

---

With the proposed solution.

• Define in portal-ext.properties lucene.boolean.query.clause.max.size to 10
• Create thirteen tags (for example: '01', '02', ..., '13')
• Create a web content ('A') and set its categorization with tag '12'
• Create a second web ('B') content and set its categorization with tag '13'
• Add an Asset Publisher an configure with this settings:
  • Asset Selection -> Dynamic
  • Scope -> Current site
  • Asset type -> Any
  • Filter ->"Contains any of the following tags": '01', '02', '03', '04', '05', '06', '07', '08', '09', '10'.

Observed and Expected behavior:
The Asset Publisher shows message "There are no results."

• Reconfigure the Asset Publisher changing
  • Filter ->"Contains any of the following tags": '01', '02', '03', '04', '05', '06', '07', '08', '09', '10', '11'

Observed and Expected behavior:
The Asset Publisher shows message "There are no results."
Portal log shows

09:32:54,757 ERROR [RuntimePageImpl-2][LuceneHelperImpl:274] org.apache.lucene.search.BooleanQuery$TooManyClauses: maxClauseCount is set to 10 
org.apache.lucene.search.BooleanQuery$TooManyClauses: maxClauseCount is set to 10 
	at org.apache.lucene.search.BooleanQuery.add(BooleanQuery.java:136) 
	at org.apache.lucene.search.BooleanQuery.add(BooleanQuery.java:127) 
	at com.liferay.portal.search.lucene.LuceneHelperImpl._includeIfUnique(LuceneHelperImpl.java:1077) 
	at com.liferay.portal.search.lucene.LuceneHelperImpl.addTerm(LuceneHelperImpl.java:270) 
	at com.liferay.portal.search.lucene.LuceneHelperImpl.addTerm(LuceneHelperImpl.java:220) 
	at com.liferay.portal.search.lucene.LuceneHelperUtil.addTerm(LuceneHelperUtil.java:268) 
	at com.liferay.portal.search.lucene.LuceneHelperUtil.addTerm(LuceneHelperUtil.java:262) 
	at com.liferay.portal.search.lucene.LuceneHelperUtil.addTerm(LuceneHelperUtil.java:256) 
	at com.liferay.portal.search.lucene.BooleanQueryImpl.addTerm(BooleanQueryImpl.java:265) 
	at com.liferay.portlet.assetpublisher.util.AssetSearcher.addSearchAnyTags(AssetSearcher.java:280) 
	at com.liferay.portlet.assetpublisher.util.AssetSearcher.addSearchAssetTagNames(AssetSearcher.java:303) 
	at com.liferay.portal.kernel.search.BaseIndexer.getFullQuery(BaseIndexer.java:271) 
	at com.liferay.portal.kernel.search.BaseIndexer.doSearch(BaseIndexer.java:1418) 
	at com.liferay.portal.kernel.search.DefaultSearchResultPermissionFilter.getHits(DefaultSearchResultPermissionFilter.java:75) 
	at com.liferay.portal.kernel.search.BaseSearchResultPermissionFilter.search(BaseSearchResultPermissionFilter.java:54) 
	at com.liferay.portal.kernel.search.BaseIndexer.search(BaseIndexer.java:582) 
	at com.liferay.portlet.asset.util.AssetUtil.search(AssetUtil.java:716) 
	at com.liferay.portlet.asset.util.AssetUtil.search(AssetUtil.java:661) 
	at org.apache.jsp.html.portlet.asset_005fpublisher.view_jsp._jspService(Unknown Source) 
	at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70) 
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:731) 
	at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:439) 
	at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:395) 
	at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:339) 
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:731) 
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) 
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) 
	at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.doFilter(InvokerFilterChain.java:119) 
	at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilter.doFilter(InvokerFilter.java:119) 
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) 
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) 
	at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:748) 
	at org.apache.catalina.core.ApplicationDispatcher.doInclude(ApplicationDispatcher.java:604) 
	at org.apache.catalina.core.ApplicationDispatcher.include(ApplicationDispatcher.java:543) 
	at com.liferay.portal.servlet.DirectServletPathRegisterDispatcher.include(DirectServletPathRegisterDispatcher.java:55) 
	at com.liferay.portal.servlet.ClassLoaderRequestDispatcherWrapper.doDispatch(ClassLoaderRequestDispatcherWrapper.java:78) 
	at com.liferay.portal.servlet.ClassLoaderRequestDispatcherWrapper.include(ClassLoaderRequestDispatcherWrapper.java:53) 
	at com.liferay.taglib.util.IncludeTag.include(IncludeTag.java:290) 
	at com.liferay.taglib.util.IncludeTag.doInclude(IncludeTag.java:184) 
	at com.liferay.taglib.util.IncludeTag.doEndTag(IncludeTag.java:75) 
	at org.apache.jsp.html.common.themes.portlet_jsp._jspService(Unknown Source) 

...

• Reconfigure the Asset Publisher changing
  • Filter ->"Contains any of the following tags": '01', '02', '03', '04', '05', '06', '07', '08', '09', '10', '11', '12'

Observed and Expected behavior:
The Asset Publisher shows message "There are no results." (because '12' tag is out of lucene query)
Portal log shows

09:32:54,757 ERROR [RuntimePageImpl-2][LuceneHelperImpl:274] org.apache.lucene.search.BooleanQuery$TooManyClauses: maxClauseCount is set to 10 
org.apache.lucene.search.BooleanQuery$TooManyClauses: maxClauseCount is set to 10 
	at org.apache.lucene.search.BooleanQuery.add(BooleanQuery.java:136) 
...

With this log message user could know that there is not any result in the Asset Publisher because '12' tag is out of lucene query.

• Reconfigure the Asset Publisher changing
  • Filter ->"Contains any of the following tags": '01', '02', '03', '04', '05', '06', '07', '08', '12', '13'

Observed and Expected behavior:
The Asset Publisher shows web content 'A'
The Asset Publisher shows web content 'B'

• Reconfigure the Asset Publisher changing
  • Filter ->"Contains any of the following tags": '01', '02', '03', '04', '05', '06', '07', '08', '12', '09', '13'

Observed and Expected behavior:
The Asset Publisher shows web content 'A'
The Asset Publisher does not show web content 'B' (because '13' tag is out of lucene query)
Portal log shows

09:32:54,757 ERROR [RuntimePageImpl-2][LuceneHelperImpl:274] org.apache.lucene.search.BooleanQuery$TooManyClauses: maxClauseCount is set to 10 
org.apache.lucene.search.BooleanQuery$TooManyClauses: maxClauseCount is set to 10 
	at org.apache.lucene.search.BooleanQuery.add(BooleanQuery.java:136) 
...

With this log message user could know that results in the Asset Publisher are wrong because '13' tag is out of lucene query.

Conclusion:
The Asset Publisher results can confuse to user but now there is a clue about that and there is no need to set up any log level.