Yugabyte-db: [YCQL][JSONB] T-Server crashes with prepared and variable bound query

[allesklarbeidir]

Hi,

I'm working on a library named "Cadoose" which is an ORM library and implements most of the features from the popular "Mongoose" library for MongoDB. The goal is to have Mongoose for YugaByte YCQL and Cassandra CQL. Cassandra CQL is mostly done but now I want to implement the YugaByte-specific functionalities.

During development I came across the following issue:

Inserting and retrieving data as JSONB data type works fine (using a modified "cassandra-driver"). But when I want to query the database with a SELECT condition on a jsonb attribute the whole t-server crashes without an error message.

What works, what doesn't:

Works

INSERT INTO ybdemo.employee (id, name, age, language, info) 
VALUES (1, 'John', 35, 'NodeJS', '{"years_experience": 5}');

Works

SELECT name, age, language FROM ybdemo.employee WHERE id = 1 
AND info->>'years_experience' = '5';

Works (prepared query, but variable only bound for 'id' column)

SELECT name, age, language FROM ybdemo.employee WHERE id = ?
AND info->>'years_experience' = '5';

queryParams = [1]
queryOptions = {prepared: true}

CRASH (prepared query, both variables bound for column 'id' and JSONB-column 'info')

SELECT name, age, language FROM ybdemo.employee WHERE id = ?
AND info->>'years_experience' = ?;

queryParams = [1, "5"]
queryOptions = {prepared: true}

I have created a repo with a minimal example to reproduce the above scenarios.
I've used the example code from the YugaByte documentation for building NodeJS apps (https://docs.yugabyte.com/latest/quick-start/build-apps/nodejs/ycql/).

The minimal example repo: https://github.com/allesklarbeidir/ybdemo-jsonb-crash

The output after running the above mentioned repo is the following:

Creating keyspace ybdemo
Creating table employee
Inserting row with: INSERT INTO ybdemo.employee (id, name, age, language, info) VALUES (1, 'John', 35, 'NodeJS', '{"years_experience": 5}');
Unprepared query without bound variables works.
Query for id=1 returned: name=John, age=35, language=NodeJS
Prepared query with bound variable (NOT FOR JSONB) works.
Query for id=1 returned: name=John, age=35, language=NodeJS
Prepared query with bound variable (FOR JSONB) crashes the server.
There was an error All host(s) tried for query failed. First host tried, 127.0.0.1:9042: DriverError: Socket was closed. See innerErrors. NoHostAvailableError: All host(s) tried for query failed. First host tried, 127.0.0.1:9042: DriverError: Socket was closed. See innerErrors.
    at Function.borrowNextConnection (/private/tmp/ybdemo/node_modules/cassandra-driver/lib/request-handler.js:52:23)
    at PrepareHandler._prepareWithQueryPlan (/private/tmp/ybdemo/node_modules/cassandra-driver/lib/prepare-handler.js:116:20)
    at PrepareHandler._onPrepareError (/private/tmp/ybdemo/node_modules/cassandra-driver/lib/prepare-handler.js:145:19)
    at EventEmitter.prepareOnceCallback (/private/tmp/ybdemo/node_modules/cassandra-driver/lib/prepare-handler.js:123:25)
    at Object.onceWrapper (events.js:317:30)
    at emitTwo (events.js:126:13)
    at EventEmitter.emit (events.js:214:7)
    at /private/tmp/ybdemo/node_modules/cassandra-driver/lib/connection.js:455:10
    at OperationState (/private/tmp/ybdemo/node_modules/cassandra-driver/lib/connection.js:478:5)
    at OperationState._swapCallbackAndInvoke (/private/tmp/ybdemo/node_modules/cassandra-driver/lib/operation-state.js:145:5)
Shutting down

My setup:

macOS 10.14
YugaByte is running in docker, setup using this guide: https://docs.yugabyte.com/latest/deploy/docker/docker-compose/

When I run

tail -f /mnt/disk0/yb-data/tserver/logs/yb-tserver.ERROR

Inside the docker container and then run the code which crashes the tserver, the whole docker container shuts down, my "tail -f" process is gone and there are no new errors in the yb-tserver.ERROR file after I restart the container.

Hope this helps finding the bug.
If you need more information let me know.

[UPDATE]

I could extract an error message from the docker container log.
This is what is being logged in the yb-tserver-n1 docker container after starting it and then running the minimal example repo to reproduce the crash:

2019-07-15 09:21:06.391 UTC [7] LOG:  YugaByte is ENABLED in PostgreSQL. Transactions are enabled.
2019-07-15 09:21:06.394 UTC [7] LOG:  listening on IPv4 address "0.0.0.0", port 5433
2019-07-15 09:21:06.412 UTC [7] LOG:  redirecting log output to logging collector process
2019-07-15 09:21:06.412 UTC [7] HINT:  Future log output will appear in directory "/mnt/disk0/yb-data/tserver/logs".
*** Aborted at 1563182544 (unix time) try "date -d @1563182544" if you are using GNU date ***
PC: @     0x7fb3a5da031d yb::ql::PreparedResult::PreparedResult()
*** SIGSEGV (@0x8) received by PID 1 (TID 0x7fb38269c700) from PID 8; stack trace: ***
    @     0x7fb399a88ba0 (unknown)
    @     0x7fb3a5da031c  yb::ql::PreparedResult::PreparedResult()
    @     0x7fb3a6bd865c  yb::ql::Statement::Prepare()
    @     0x7fb3a77e5f9a  yb::cqlserver::CQLProcessor::ProcessRequest()
    @     0x7fb3a77e7bc4  yb::cqlserver::CQLProcessor::ProcessRequest()
    @     0x7fb3a77e7f24  yb::cqlserver::CQLProcessor::ProcessCall()
    @     0x7fb3a780169d  yb::cqlserver::CQLServiceImpl::Handle()
    @     0x7fb3a0062e47  yb::rpc::ServicePoolImpl::Handle()
    @     0x7fb3a0010583  yb::rpc::InboundCall::InboundCallTask::Run()
    @     0x7fb3a006e537  yb::rpc::(anonymous namespace)::Worker::Execute()
    @     0x7fb39e044ac8  yb::Thread::SuperviseThread()
    @     0x7fb399a80694 start_thread
    @     0x7fb3991bd41d __clone
    @                0x0 (unknown)

[kmuthukk]

Thx @allesklarbeidir for detailed information. We will take a look into this right away.

[m-iancu]

@allesklarbeidir We were been able to replicate this crash and are working on a fix.

In the meantime, as a workaround, could you try using named variables for the places where the left-hand-side is not a column (i.e. it is a jsonb operator call).
Concretely that means using :somename instead of ? (note the : at the beginning).

For instance, in your case, you can use something like:

    const select = 'SELECT name, age, language FROM ybdemo.employee 
       WHERE  id = ? AND info->>\'years_experience\' = :info;';

Note: The named parameter also allows you to bind by name instead of by position (when actually binding the values) but binding by position should still work, so the client.execute(select, [1, "5"],... part does not need to change.

[OlegLoginov]

Smallest reproducer:

create table e (id int primary key, j jsonb);
select * from e where j->>'y'=?;

The crash call-stack:

yb::ql::Executor::PTExprToPB(std::__1::shared_ptr<yb::ql::PTExpr> const&, yb::QLExpressionPB*) eval_expr.cc:52
yb::ql::Executor::WhereJsonColOpToPB(yb::QLConditionPB*, yb::ql::JsonColumnOp const&) eval_where.cc:334
yb::ql::Executor::WhereClauseToPB(yb::QLReadRequestPB*, std::__1::vector<yb::ql::ColumnOp, yb::internal::ArenaAllocatorBase<yb::ql::ColumnOp, yb::internal::ArenaTraits> > const&, std::__1::list<yb::ql::ColumnOp, yb::internal::ArenaAllocatorBase<yb::ql::ColumnOp, yb::internal::ArenaTraits> > const&, std::__1::list<yb::ql::SubscriptedColumnOp, yb::internal::ArenaAllocatorBase<yb::ql::SubscriptedColumnOp, yb::internal::ArenaTraits> > const&, std::__1::list<yb::ql::JsonColumnOp, yb::internal::ArenaAllocatorBase<yb::ql::JsonColumnOp, yb::internal::ArenaTraits> > const&, std::__1::list<yb::ql::PartitionKeyOp, yb::internal::ArenaAllocatorBase<yb::ql::PartitionKeyOp, yb::internal::ArenaTraits> > const&, std::__1::list<yb::ql::FuncOp, yb::internal::ArenaAllocatorBase<yb::ql::FuncOp, yb::internal::ArenaTraits> > const&, yb::ql::TnodeContext*) eval_where.cc:245
yb::ql::Executor::ExecPTNode(yb::ql::PTSelectStmt const*, yb::ql::TnodeContext*) executor.cc:715
yb::ql::Executor::ExecTreeNode(yb::ql::TreeNode const*) executor.cc:243
yb::ql::Executor::Execute(yb::ql::ParseTree const&, yb::ql::StatementParameters const&) executor.cc:176
yb::ql::Executor::ExecuteAsync(yb::ql::ParseTree const&, yb::ql::StatementParameters const&, yb::Callback<void (yb::Status const&, std::__1::shared_ptr<yb::ql::ExecutedResult> const&)>) executor.cc:90
yb::ql::QLProcessor::ExecuteAsync(yb::ql::ParseTree const&, yb::ql::StatementParameters const&, yb::Callback<void (yb::Status const&, std::__1::shared_ptr<yb::ql::ExecutedResult> const&)>) ql_processor.cc:354
yb::ql::QLProcessor::RunAsync(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, yb::ql::StatementParameters const&, yb::Callback<void (yb::Status const&, std::__1::shared_ptr<yb::ql::ExecutedResult> const&)>, bool) ql_processor.cc:372
yb::cqlserver::CQLProcessor::ProcessRequest(yb::cqlserver::QueryRequest const&) cql_processor.cc:313
yb::cqlserver::CQLProcessor::ProcessRequest(yb::cqlserver::CQLRequest const&) cql_processor.cc:221
yb::cqlserver::CQLProcessor::ProcessCall(std::__1::shared_ptr<yb::rpc::InboundCall>) cql_processor.cc:175
yb::cqlserver::CQLServiceImpl::Handle(std::__1::shared_ptr<yb::rpc::InboundCall>) cql_service.cc:142

Crash point:

CHECKED_STATUS Executor::PTExprToPB(const PTBindVar *bind_pt, QLExpressionPB *expr_pb) {
  QLValue ql_bind;
  RETURN_NOT_OK(exec_context_->params().GetBindVariable(bind_pt->name()->c_str(),  <<<<<<<<<<<<<
                                                        bind_pt->pos(),
                                                        bind_pt->ql_type(),
                                                        &ql_bind));
  *expr_pb->mutable_value() = std::move(*ql_bind.mutable_value());
  return Status::OK();
}

Reason: _name is NULL in bind_pt.

[allesklarbeidir]

Wow! Great to see you moving so fast and working on fix already. Thanks!

@m-iancu, thanks for the workaround. It works for me and I'm totally fine with using named parameters. I could update my library this way and move on. Thank you!

[OlegLoginov]

The fix is quite simple here - replace (line 93 in src/yb/yql/cql/ql/exec/eval_expr.cc):
RETURN_NOT_OK(exec_context_->params().GetBindVariable(bind_pt->name()->c_str(),
by the line:
RETURN_NOT_OK(exec_context_->params().GetBindVariable(bind_pt->name() ? bind_pt->name()->c_str() : string(),

I've tested the fix locally. It will be landed after review & a set of automated tests.

[frozenspider]

This helped uncover a deeper issue: https://github.com/YugaByte/yugabyte-db/issues/1821