I created CALCITE-1565 for this issue.

On Thu, Jan 5, 2017 at 12:10 PM, Josh Elser <josh.elser@gmail.com> wrote:
Hrm, that's frustrating. No stack trace is a bug. I remember there being one of these I fixed in the past -- hopefully it's not a new issue. I guess the version of Phoenix you're using has a rather out-dated version of Avatica by now (1.6.0 vs 1.9.0).

Yes, the EXPLICIT is that the caller (PQS) made a call to remove the element from the cache. This lines up with what we'd expect since the closeStatement request was sent by the thin-client.

Taking a look at the original stack trace portion in ArrayList, it looks even more like a race condition:

        for (int index = 0; index < size; index++)
            if (o.equals(elementData[index])) {
                fastRemove(index);
                return true;
            }

The ArrayList found the element we asked it to remove and then tried to remove the element at that index. But, by the time it went to remove that element, the index was invalid. It doesn't look like Phoenix has any synchronization around closing the ResultSet.

So, that makes me think there are two potential causes:

1) You have multiple clients issuing a closeStatement() at the same time and trying to close the ResultSet.
2) One client issuing a closeStatement() is racing against PQS closing the statement, both trying to close the ResultSet.

This is sounding more and more like an Avatica bug to me. Any chance you can share more of the TRACE logging that you've turned on and maybe open up a JIRA issue under the CALCITE project (and ping me), please?

I really appreciate your help so far.

Tulasi Paradarami wrote:
Unfortunately, there's no error stack other than:
ArrayIndexOutOfBoundsException: (null exception message)

I've set org.apache.calcite.avatica=TRACE

jdbc.jdbcMeta has following messages:

17/01/05 18:47:49 TRACE server.AvaticaJsonHandler: request:
{"connectionId": "68b4686a-c51e-4e82-b9df-a55eeb6188d4", "request":
"closeStatement", "statementId": 15251}
17/01/05 18:47:49 TRACE jdbc.JdbcMeta: closing statement
68b4686a-c51e-4e82-b9df-a55eeb6188d4::15251
17/01/05 18:47:49 DEBUG jdbc.JdbcMeta: Expiring statement 15251 because
EXPLICIT

EXPLICIT implies statement has been closed and not evicted?

On Thu, Jan 5, 2017 at 11:03 AM, Josh Elser <josh.elser@gmail.com
<mailto:josh.elser@gmail.com>> wrote:

    No, PQS itself is not instrumented with the HTrace library, only
    (parts of?) the thick Phoenix JDBC inside of PQS.

    There is some support for metrics that I built into Avatica, but,
    sadly, I've not had the time to spend to focus on how we expose
    those downstream in Phoenix. That would be the "easiest" way to
    monitor it, but I think it'd require modifying Phoenix and
    re-building it (which is likely not something you want to do).

    You can try setting org.apache.calcite.avatica.jdbc.JdbcMeta=DEBUG
    in the $PHOENIX_HOME/bin/log4j.properties file. That will print some
    messages when a statement or connection is automatically evicted
    from the respective cache.

    Finally, no stack trace on the ErrorResponse you showed for fetch()?

    Tulasi Paradarami wrote:

        Another question: does enabling tracing
        (https://phoenix.apache.org/tracing.html
        <https://phoenix.apache.org/tracing.html>) on phoenix help monitor
        following properties used by PQS?

        avatica.connectioncache.concurrency
        avatica.connectioncache.initialcapacity
        avatica.connectioncache.maxcapacity
        avatica.connectioncache.expiryduration
        avatica.connectioncache.expiryunit

        avatica.statementcache.concurrency
        avatica.statementcache.initialcapacity
        avatica.statementcache.maxcapacity
        avatica.statementcache.expiryduration
        avatica.statementcache.expiryunit

        On Thu, Jan 5, 2017 at 10:04 AM, Tulasi Paradarami
        <tulasi.krishna.p@gmail.com <mailto:tulasi.krishna.p@gmail.com>
        <mailto:tulasi.krishna.p@gmail.com

        <mailto:tulasi.krishna.p@gmail.com>>> wrote:

             Yes, I mean 4.7.0.
             Since PQS restart, we are seeing the error raised during fetch
             instead of closeStatement.

             Here is the latest trace:

             TRACE server.AvaticaJsonHandler: request: {"connectionId":
        "0359595b-509a-41e2-9348-d3f8fcec65df", "request": "fetch",
        "fetchMaxRowCount": 2000, "offset": 100, "statementId": 181894}
             TRACE jdbc.JdbcMeta: fetching
             0359595b-509a-41e2-9348-d3f8fcec65df::181894 offset:100
             fetchMaxRowCount:2000
             TRACE server.AvaticaJsonHandler: response: Response:

        {"response":"error","exceptions":["java.lang.ArrayIndexOutOfBoundsException\n"],"errorMessage":"ArrayIndexOutOfBoundsException:
             (null exception

        message)","errorCode":-1,"sqlState":"00000","severity":"UNKNOWN","rpcMetadata":{"response":"rpcMetadata","serverAddress":"pqs_hostname:8765"}},
             Status:500
             DEBUG server.Server: RESPONSE /  500 handled=true


             I also noticed that as the number concurrent connections on the
             server increases, we are hitting this exception more
        frequently.
             Note that, we are using default values for following
        parameters.

             *Configurations relating to the server statement cache.*
             *Property*  *Description*   *Default*
             avatica.statementcache.concurrency  Statement cache concurrency
             level. Default is 100.      100
             avatica.statementcache.initialcapacity      Statement cache
        initial
             capacity. Default is 1000.  1000
             avatica.statementcache.maxcapacity  Statement cache maximum
        capacity.
             Approaching this point, the cache will start to evict least
        recently
             used statement objects. Default is 10000.   10000
             avatica.statementcache.expiryduration       Statement cache
        expiration
             duration. Any statements older than this value will be
        discarded.
             Default is 5 minutes.       5
             avatica.statementcache.expiryunit   Statement cache
        expiration unit.
             Unit modifier applied to the value provided in
             avatica.statementcache.expiryunit. Default is minutes.
        MINUTES



             On Thu, Jan 5, 2017 at 9:44 AM, Josh Elser
        <josh.elser@gmail.com <mailto:josh.elser@gmail.com>
        <mailto:josh.elser@gmail.com <mailto:josh.elser@gmail.com>>> wrote:

                 Interesting! I haven't come across this one myself.

                 By Phoenix 4.7, am I to assume you mean 4.7.0? Phoenix
        version
                 strings are 3 "digits", not 2.

                 My first guess would be that it might be a race
        condition around
                 the closeStatement call (either from multiple callers)
        or the
                 automatic-closing logic inside of PQS itself (by
        default, PQS
                 will close statements that haven't been used for
        10mins, IIRC).

                 Any more information on the context in which you see
        this would
                 be very helpful.

                 Tulasi Paradarami wrote:

                     We noticed that PQS started raising
                     ArrayIndexOutOfBoundsException in
                     our production cluster. This exception is raised
                     sporadically and goes
                     away when PQS is restarted. Does anyone know what
        might be
                     causing this
                     exception? Are there any configuration (PQS and/or
        Avatica)
                     parameters
                     that we can modify to prevent it from recurring?

                     CDH 5.7.2
                     HBase: 1.2.0
                     Phoenix: 4.7

                     Here is an error stack for "closeStatement" request:

                     {"level":"TRACE","message":" server.AvaticaJsonHandler:
                     response:
                     Response:

        {"response":"error","exceptions":["java.lang.ArrayIndexOutOfBoundsException:
                     -1
                     at java.util.ArrayList.fastRemove(ArrayList.java:528)
                     at java.util.ArrayList.remove(ArrayList.java:511)
                     at

        org.apache.phoenix.jdbc.PhoenixResultSet.close(PhoenixResultSet.java:165)
                     at

        org.apache.calcite.avatica.jdbc.JdbcMeta.closeStatement(JdbcMeta.java:559)
                     at

        org.apache.calcite.avatica.remote.LocalService.apply(LocalService.java:256)
                     at

        org.apache.calcite.avatica.remote.Service$CloseStatementRequest.accept(Service.java:1529)
                     at

        org.apache.calcite.avatica.remote.Service$CloseStatementRequest.accept(Service.java:1511)
                     at

        org.apache.calcite.avatica.remote.AbstractHandler.apply(AbstractHandler.java:102)
                     at

        org.apache.calcite.avatica.remote.JsonHandler.apply(JsonHandler.java:43)
                     at

        org.apache.calcite.avatica.server.AvaticaJsonHandler.handle(AvaticaJsonHandler.java:73)
                     at

        org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52)
                     at

        org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
                     at
        org.eclipse.jetty.server.Server.handle(Server.java:497)
                     at

        org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310)
                     at

        org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:245)
                     at org.eclipse.jetty.io
        <http://org.eclipse.jetty.io> <http://org.eclipse.jetty.io>
        <http://org.eclipse.jetty.io>.AbstractConnection$2.run(AbstractConnection.java:540)
                     at

        org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
                     at

        org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
                     at java.lang.Thread.run(Thread.java:745)
        "],"errorMessage":"ArrayIndexOutOfBoundsException:

        -1","errorCode":-1,"sqlState":"00000","severity":"UNKNOWN","rpcMetadata":{"response":"rpcMetadata","serverAddress":"pqs_hostname:8765"}},
                     Status:500"}