Java error after 8.8.9 (Patch 3) (Zebra Tray Notifier)

[RuiSimoes]

After the last Zimbra update (Zimbra 8.8.9_GA_3019 (build 20180809160254)) i start to receave a error log in the "mailbox.log".

I use the ("Zebra tray notifier" http://zebra.ermoler.ru/ ) and i guess this is the origin of the error because now the software dont inform when we have new email.

--------
2018-08-20 08:57:13,153 WARN [qtp66233253-828:https:https://10.3.0.9/service/soap/] [name=fxxxxxxo@cxxxxxxxo.pt;mid=87;ip=10.3.51.18;port=57203;soapId=6551bc6d;] SoapEngine - handler exception
java.lang.NullPointerException
at com.zimbra.cs.index.SearchParams.isSortByReadFlag(SearchParams.java:644)
at com.zimbra.cs.index.SearchParams.parse(SearchParams.java:560)
at com.zimbra.cs.service.mail.Search.handle(Search.java:88)
at com.zimbra.soap.SoapEngine.dispatchRequest(SoapEngine.java:643)
at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:468)
at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:275)
at com.zimbra.soap.SoapServlet.doWork(SoapServlet.java:304)
at com.zimbra.soap.SoapServlet.doPost(SoapServlet.java:214)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at com.zimbra.cs.servlet.ZimbraServlet.service(ZimbraServlet.java:211)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:821)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1685)
at com.zimbra.cs.servlet.CsrfFilter.doFilter(CsrfFilter.java:169)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
at com.zimbra.cs.servlet.RequestStringFilter.doFilter(RequestStringFilter.java:54)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
at com.zimbra.cs.servlet.SetHeaderFilter.doFilter(SetHeaderFilter.java:59)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
at com.zimbra.cs.servlet.ETagHeaderFilter.doFilter(ETagHeaderFilter.java:47)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
at com.zimbra.cs.servlet.ContextPathBasedThreadPoolBalancerFilter.doFilter(ContextPathBasedThreadPoolBalancerFilter.java:107)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
at com.zimbra.cs.servlet.ZimbraQoSFilter.doFilter(ZimbraQoSFilter.java:116)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
at com.zimbra.cs.servlet.ZimbraInvalidLoginFilter.doFilter(ZimbraInvalidLoginFilter.java:117)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
at org.eclipse.jetty.servlets.DoSFilter.doFilterChain(DoSFilter.java:473)
at org.eclipse.jetty.servlets.DoSFilter.doFilter(DoSFilter.java:318)
at org.eclipse.jetty.servlets.DoSFilter.doFilter(DoSFilter.java:288)
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:524)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1158)
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:1090)
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:109)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:119)
at org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:318)
at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:437)
at org.eclipse.jetty.server.handler.DebugHandler.handle(DebugHandler.java:84)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:119)
at org.eclipse.jetty.server.Server.handle(Server.java:517)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:306)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:242)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:261)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:192)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:261)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:75)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceAndRun(ExecuteProduceConsume.java:213)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:147)
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)

[phoenix]

By any chance do you use Ubuntu and have you updated that recently? You should always provide the ZCS version by posting the full output of the full output of the following command:

Code: Select all

zmcontrol -v

[RuiSimoes]

Dear Phoenix this is the output of "zmcontol -v"

Release 8.8.9.GA.2055.UBUNTU14.64 UBUNTU14_64 FOSS edition, Patch 8.8.9_P3.


And yes, I made a system update before de Zimbra update to 8.8.9_P3

[phoenix]

This is possibly a problem with your updated kernel, please check this thread: viewtopic.php?f=15&t=64703

[RuiSimoes]

Maybe the problem is not only the kernel, i made a downgrade to Linux 3.19.0-8 and purge the 4.4 version but the stress continue

[andrey.ivanov]

I confirm, since passing from 8.8.9_P2 to 8.8.9_P3 (CentOS 7) i have approximately ~1000 java exceptions of this type per day (simple client acces by webmail), there were 0 of them for patch 8.8.9_P2:

Code: Select all

[zimbra@zimbra ~]$ zmcontrol -v
Release 8.8.9_GA_2055.RHEL6_64_20180703080917 RHEL6_64 NETWORK edition, Patch 8.8.9_P3.

[zimbra@zimbra ~]$ zgrep isSortByReadFlag /opt/zimbra/log/mailbox.log.2018-08-20.gz | wc 
      0       0       0
[zimbra@zimbra ~]$ zgrep isSortByReadFlag /opt/zimbra/log/mailbox.log.2018-08-21.gz | wc
      0       0       0
[zimbra@zimbra ~]$ zgrep isSortByReadFlag /opt/zimbra/log/mailbox.log.2018-08-22.gz | wc
      0       0       0
[zimbra@zimbra ~]$ zgrep isSortByReadFlag /opt/zimbra/log/mailbox.log.2018-08-23.gz | wc
    997    1994   76769

According to the source code, this exception happens in the next new code added in 8.8.9_P3 in the file /zm-mailbox/store/src/java/com/zimbra/cs/index/SearchParams.java (line 644) :

Code: Select all

    public static boolean isSortByReadFlag(SortBy sortBy) {
        return (sortBy.getKey() == SortBy.READ_ASC.getKey()
            || sortBy.getKey() == SortBy.READ_DESC.getKey());
    }

All the changes in the file between 8.8.9_P2 and 8.8.9_P3 :

Code: Select all

--- /home/toto/Zimbra/Source/git/8.8.9.p1/zm-mailbox/store/src/java/com/zimbra/cs/index/SearchParams.java 2018-06-21 11:28:29.283210110 +0200
+++ /home/toto/Zimbra/Source/git/8.8.9.p3/zm-mailbox/store/src/java/com/zimbra/cs/index/SearchParams.java 2018-08-24 14:56:33.608486848 +0200
@@ -557,7 +557,11 @@
             params.setTypes(types);
         }
         params.setSortBy(soapParams.getSortBy());
-
+        if (query.toLowerCase().contains("is:unread") && isSortByReadFlag(SortBy.of(soapParams.getSortBy()))) {
+            params.setSortBy(SortBy.DATE_DESC);
+        } else {
+            params.setSortBy(soapParams.getSortBy());
+        }
         params.setIncludeTagDeleted(MoreObjects.firstNonNull(soapParams.getIncludeTagDeleted(), false));
         params.setIncludeTagMuted(MoreObjects.firstNonNull(soapParams.getIncludeTagMuted(), true));
         String allowableTasks = soapParams.getAllowableTaskStatus();
@@ -616,8 +620,9 @@
         params.setOffset(MoreObjects.firstNonNull(soapParams.getOffset(), 0));
 
         CursorInfo cursor = soapParams.getCursor();
-        if (cursor != null) {
-            params.parseCursor(cursor, zsc.getRequestedAccountId());
+       
+        if (cursor != null ) {
+            params.parseCursor(cursor, zsc.getRequestedAccountId(), params);
         }
 
         if (soapParams instanceof MailSearchParams) {
@@ -632,6 +637,15 @@
 
 
     /**
+     * @param params
+     * @return
+     */
+    public static boolean isSortByReadFlag(SortBy sortBy) {
+        return (sortBy.getKey() == SortBy.READ_ASC.getKey() 
+            || sortBy.getKey() == SortBy.READ_DESC.getKey());
+    }
+
+    /**
      * Parse the search parameters from a {@code <SearchRequest>} or similar element.
      *
      * @param request {@code <SearchRequest>} itself, or similar element ({@code <SearchConvRequest>}, etc)
@@ -719,7 +733,7 @@
 
         Element cursor = request.getOptionalElement(MailConstants.E_CURSOR);
         if (cursor != null) {
-            params.parseCursor(cursor, zsc.getRequestedAccountId());
+            params.parseCursor(cursor, zsc.getRequestedAccountId(), params);
         }
 
         params.setWantContent(MoreObjects.firstNonNull(
@@ -735,11 +749,13 @@
      * @param cursor cursor element taken from a {@code <SearchRequest>}
      * @param acctId requested account id
      */
-    public void parseCursor(Element el, String acctId) throws ServiceException {
+    public void parseCursor(Element el, String acctId, SearchParams params) throws ServiceException {
         cursor = new Cursor();
         cursor.itemId = new ItemId(el.getAttribute(MailConstants.A_ID), acctId);
+        if (!isSortByReadFlag(params.getSortBy())) {
         cursor.sortValue = el.getAttribute(MailConstants.A_SORTVAL, null); // optional
         cursor.endSortValue = el.getAttribute(MailConstants.A_ENDSORTVAL, null); // optional
+        }
         cursor.includeOffset = el.getAttributeBool(MailConstants.A_INCLUDE_OFFSET, false); // optional
     }
 
@@ -749,14 +765,17 @@
      * @param cursorInfo cursor element taken from a {@code <SearchRequest>}
      * @param acctId requested account id
      */
-    public void parseCursor(CursorInfo cursorInfo, String acctId) throws ServiceException {
+    public void parseCursor(CursorInfo cursorInfo, String acctId,  SearchParams params) throws ServiceException {
         cursor = new Cursor();
         if (null == cursorInfo.getId()) {
                 throw ServiceException.INVALID_REQUEST("Invalid ID for " + MailConstants.E_CURSOR, null);
         }
         cursor.itemId = new ItemId(cursorInfo.getId(), acctId);
-        cursor.sortValue = cursorInfo.getSortVal(); // optional
-        cursor.endSortValue = cursorInfo.getEndSortVal(); // optional
+        if (!isSortByReadFlag(params.getSortBy())) {
+            cursor.sortValue = cursorInfo.getSortVal(); // optional
+            cursor.endSortValue = cursorInfo.getEndSortVal(); // optional
+        }
+       
         cursor.includeOffset = MoreObjects.firstNonNull(cursorInfo.getIncludeOffset(), false); // optional
     }

[DavidMerrill]

Nice sleuthing!

[Lindworm]

I can confirm the problem.

On a server with 8.8.9_P3 it's not possible to use "Zimbra Mail Notifier"-Add-on for Firefox (https://addons.mozilla.org/de/firefox/a ... -notifier/).

Code: Select all

root@mail:~# grep isSortByReadFlag /opt/zimbra/log/mailbox.log | wc -l
30619

No Problem with 8.8.9_P1.

Is there already a case opened?
Is a workaround known?

[andrey.ivanov]

Yes, I have created a Support Case (00757169) for both this issue and the other issue of upgrading 8.8.9_P2 -> 8.8.9_P3 (viewtopic.php?f=13&t=64746). You can check if you are concerned by these issues quite easily:

Code: Select all

grep isSortByReadFlag /opt/zimbra/log/mailbox.log | wc -l

grep 'index - Caught ServiceException trying to compare ZimbraHit' /opt/zimbra/log/mailbox.log | wc -l

The support suggested reindexing the affected mailboxes (zmprov rim) but it did not help. So the current status of the ticket is "information is passed to DEV team".

[andrey.ivanov]

I have an answer on the ticket:

Yes this will happen only if your query contains "is:unread" and no sortBy is provided.

{"Header":{"context":{"_jsns":"urn:zimbra","userAgent":
{"name":"ZimbraWebClient - FF61 (Mac)","version":"8.8.9_GA_3019"}

,"session":{"_content":12,"id":12},"notify":{"seq":5},"account":
{"_content":"user1@rdesai.zdev.local","by":"name"}

,"csrfToken":"0_929cad6b74aeee7ae347709540b5ec762ae3cadf"}},"Body":{"SearchRequest":{"_jsns":"urn:zimbraMail","header":[
{"n":"List-ID"}

,{"n":"X-Zimbra-DL"},{"n":"IN-REPLY-TO"}],"tz":{"id":"Asia/Kolkata"},"locale":{"_content":"en_US"},"offset":0,"limit":100,"query":"in:inbox is:unread","types":"conversation","recip":"0","fullConversation":1,"needExp":1}}}

This is not reproducible from webclient, as we always sent a sortBy flag. The problem seems to the custom add-on which is sending SearchRequest without sortBy attribute.

So it means that either the SOAP request in "Zimbra Mail Notifier" add-on should be a bit rewritten by adding sortBy attribute (contact add-on editor) or Zimbra devs could have a "default" sortBy if it is not indicated in the request, it would avoid NullPointerException (i asked in the ticket if they would make it).