Cockroach: Regression starting from 19.2 with Elixir / binary protocol when loading arrays

[tlvenn]

Describe the problem

Arrays use to work just fine in 19.1 but from 19.2, it seems a regression has been introduced and now Elixir / Postgrex is crashing when trying to decode an array from the DB:

[error] GenServer #PID<0.795.0> terminating
** (DBConnection.ConnectionError) client #PID<0.1054.0> stopped: ** (MatchError) no match of right hand side value: <<0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 4, 19, 0, 0, 0, 2, 0, 0, 0, 1, 0, 0, 0, 22, 117, 112, 115, 101, 114, 116, 95, 105, 100, 101, 109, 112, 111, 116, 101, 110, 99, 121, 95, 107, 101, 121, 0, 0, 0, 12, ...>>
    (postgrex 0.15.5) lib/postgrex/type_module.ex:897: Postgrex.DefaultTypes."Elixir.Postgrex.Extensions.Array"/8
    (postgrex 0.15.5) lib/postgrex/protocol.ex:2870: Postgrex.Protocol.rows_recv/4
    (postgrex 0.15.5) lib/postgrex/protocol.ex:1899: Postgrex.Protocol.recv_execute/5
    (postgrex 0.15.5) lib/postgrex/protocol.ex:1773: Postgrex.Protocol.bind_execute/4
    (db_connection 2.2.2) lib/db_connection/holder.ex:316: DBConnection.Holder.holder_apply/4
    (db_connection 2.2.2) lib/db_connection.ex:1255: DBConnection.run_execute/5
    (db_connection 2.2.2) lib/db_connection.ex:1342: DBConnection.run/6
    (db_connection 2.2.2) lib/db_connection.ex:539: DBConnection.parsed_prepare_execute/5
    (db_connection 2.2.2) lib/db_connection.ex:532: DBConnection.prepare_execute/4
    (ecto_sql 3.4.5) lib/ecto/adapters/sql.ex:534: Ecto.Adapters.SQL.execute!/4
    (ecto_sql 3.4.5) lib/ecto/adapters/sql.ex:526: Ecto.Adapters.SQL.execute/5
    (ecto 3.4.5) lib/ecto/repo/queryable.ex:192: Ecto.Repo.Queryable.execute/4
    (ecto 3.4.5) lib/ecto/repo/queryable.ex:17: Ecto.Repo.Queryable.all/3
    (stdlib 3.13) erl_eval.erl:680: :erl_eval.do_apply/6
    (elixir 1.10.4) src/elixir.erl:278: :elixir.recur_eval/3
    (elixir 1.10.4) src/elixir.erl:263: :elixir.eval_forms/3
    (iex 1.10.4) lib/iex/evaluator.ex:258: IEx.Evaluator.handle_eval/5
    (iex 1.10.4) lib/iex/evaluator.ex:239: IEx.Evaluator.do_eval/3
    (iex 1.10.4) lib/iex/evaluator.ex:217: IEx.Evaluator.eval/3
    (iex 1.10.4) lib/iex/evaluator.ex:103: IEx.Evaluator.loop/1

This was first reported to me by @damboscolo in https://github.com/jumpn/ecto_cockroachdb/issues/3 and I was kinda hoping it would go away with the 20.X release but unfortunately we are not so lucky ;)

To Reproduce
Create a table with a array column, in my case it is a VARCHAR(255)[] NOT NULL, insert one row in the database and query it

Expected behavior
The rows should load just fine.

Environment:

• CockroachDB version: 20.1
• Server OS: OSX 11
• Client app: Postgrex / Elixir

[blathers-crl[bot]]

Hello, I am Blathers. I am here to help you get the issue triaged.

Hoot - a bug! Though bugs are the bane of my existence, rest assured the wretched thing will get the best of care here.

I have CC'd a few people who may be able to assist you:

• @rafiss (found keywords: ecto)

If we have not gotten back to your issue within a few business days, you can try the following:

• Join our community slack channel and ask on #cockroachdb.
• Try find someone from here if you know they worked closely on the area and CC them.

_{:owl: Hoot! I am a Blathers, a bot for CockroachDB. My owner is otan.}

[rafiss]

Thanks for the issue.

I haven't been able to reproduce it yet. I wrote the following test using our DSL for testing wire protocol, and it passes.

send
Query {"String": "CREATE TABLE t9 (a INT8 PRIMARY KEY, b VARCHAR(256)[] NOT NULL)"}
----

until
ReadyForQuery
----
{"Type":"CommandComplete","CommandTag":"CREATE TABLE"}
{"Type":"ReadyForQuery","TxStatus":"I"}

send
Query {"String": "INSERT INTO t9 VALUES(4, ARRAY['hello', 'goodbye'])"}
----

until
ReadyForQuery
----
{"Type":"CommandComplete","CommandTag":"INSERT 0 1"}
{"Type":"ReadyForQuery","TxStatus":"I"}

# 80 = ASCII 'P' for Portal
send
Parse {"Name": "s", "Query": "SELECT b FROM t9"}
Bind {"DestinationPortal": "p", "PreparedStatement": "s"}
Describe {"ObjectType": 80, "Name": "p"}
Execute {"Portal": "p"}
Sync
----

until
ReadyForQuery
----
{"Type":"ParseComplete"}
{"Type":"BindComplete"}
{"Type":"RowDescription","Fields":[{"Name":"b","TableOID":0,"TableAttributeNumber":0,"DataTypeOID":1015,"DataTypeSize":-1,"TypeModifier":-1,"Format":0}]}
{"Type":"DataRow","Values":[{"text":"{hello,goodbye}"}]}
{"Type":"CommandComplete","CommandTag":"SELECT 1"}
{"Type":"ReadyForQuery","TxStatus":"I"}

Would you be able to provide an exact sequence of commands and queries that fails? I believe the report is saying that this only happens when using prepared statements. Is that correct?

If you could point me to how to run the code (and if I can get an Elixir environment set up on my computer), I might be able to try capturing the wire protocol commands that are being sent. Or if you are able to capture this yourself with Wireshark, that would be really helpful!

[tlvenn]

Hi @rafiss, I can definitely capture the sequence for you. I will get back to you on this asap.

[tlvenn]

Hi @rafiss ,

Please find the captured packets

binary_protocol_arrays.pcapng.gz

View of the table and the data:

with completed_phases being defined as completed_phases VARCHAR(255)[] NOT NULL

The exact error:

iex(5)> from(k in Jumpn.Idempotency.Key, select: k.completed_phases) |> Jumpn.Repo.all
[error] GenServer #PID<0.774.0> terminating
** (DBConnection.ConnectionError) client #PID<0.987.0> stopped: ** (MatchError) no match of right hand side value: <<0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 4, 19, 0, 0, 0, 2, 0, 0, 0, 1, 0, 0, 0, 22, 117, 112, 115, 101, 114, 116, 95, 105, 100, 101, 109, 112, 111, 116, 101, 110, 99, 121, 95, 107, 101, 121, 0, 0, 0, 12, ...>>
    (postgrex 0.15.5) lib/postgrex/type_module.ex:897: Postgrex.DefaultTypes."Elixir.Postgrex.Extensions.Array"/8
    (postgrex 0.15.5) lib/postgrex/protocol.ex:2870: Postgrex.Protocol.rows_recv/4
    (postgrex 0.15.5) lib/postgrex/protocol.ex:1899: Postgrex.Protocol.recv_execute/5
    (postgrex 0.15.5) lib/postgrex/protocol.ex:1773: Postgrex.Protocol.bind_execute/4
    (db_connection 2.2.2) lib/db_connection/holder.ex:316: DBConnection.Holder.holder_apply/4
    (db_connection 2.2.2) lib/db_connection.ex:1255: DBConnection.run_execute/5
    (db_connection 2.2.2) lib/db_connection.ex:1342: DBConnection.run/6
    (db_connection 2.2.2) lib/db_connection.ex:539: DBConnection.parsed_prepare_execute/5
    (db_connection 2.2.2) lib/db_connection.ex:532: DBConnection.prepare_execute/4
    (ecto_sql 3.4.5) lib/ecto/adapters/sql.ex:534: Ecto.Adapters.SQL.execute!/4
    (ecto_sql 3.4.5) lib/ecto/adapters/sql.ex:526: Ecto.Adapters.SQL.execute/5
    (ecto 3.4.5) lib/ecto/repo/queryable.ex:192: Ecto.Repo.Queryable.execute/4
    (ecto 3.4.5) lib/ecto/repo/queryable.ex:17: Ecto.Repo.Queryable.all/3
    (stdlib 3.13) erl_eval.erl:680: :erl_eval.do_apply/6
    (elixir 1.10.4) src/elixir.erl:278: :elixir.recur_eval/3
    (elixir 1.10.4) src/elixir.erl:263: :elixir.eval_forms/3
    (iex 1.10.4) lib/iex/evaluator.ex:258: IEx.Evaluator.handle_eval/5
    (iex 1.10.4) lib/iex/evaluator.ex:239: IEx.Evaluator.do_eval/3
    (iex 1.10.4) lib/iex/evaluator.ex:217: IEx.Evaluator.eval/3
    (iex 1.10.4) lib/iex/evaluator.ex:103: IEx.Evaluator.loop/1

    (db_connection 2.2.2) lib/db_connection/connection.ex:168: DBConnection.Connection.handle_cast/2
    (connection 1.0.4) lib/connection.ex:810: Connection.handle_async/3
    (stdlib 3.13) gen_server.erl:680: :gen_server.try_dispatch/4
    (stdlib 3.13) gen_server.erl:756: :gen_server.handle_msg/6
    (stdlib 3.13) proc_lib.erl:236: :proc_lib.wake_up/3

[rafiss]

Thank you @tlvenn. I looked at the captured packets, and it looks like the completed_phases column has this type metadata:

Column name: completed_phases
    Table OID: 0
    Column index: 0
    Type OID: 1009
    Column length: -1
    Type modifier: -1
    Format: Text (0)

The type OID is 1099, which is the OID for a TEXT[]. A VARCHAR(n)[] would have an OID of 1015 as seen in the example in my previous comment.

Would you mind sharing the output of the following commands:

SHOW CREATE TABLE idempotency_keys;

SELECT pg_typeof(completed_phases), pg_typeof(completed_phases)::regtype from idempotency_keys

I wonder if some part of the Ecto CockroachDB adapter is turning VARCHAR(n)[] into TEXT[] at table creation time. This could cause issues when reading from the table later and trying to interpret as a VARCHAR(n)[]. As for why this started with 19.2, a good guess is this PR: https://github.com/cockroachdb/cockroach/pull/36598. This PR made our type system align with the Postgres type system more closely. Maybe before this PR, the Ecto CockroachDB adapter had a workaround for some of the differences in the type system.

[tlvenn]

SHOW CREATE TABLE idempotency_keys:
CREATE TABLE idempotency_keys ( id INT8 NOT NULL DEFAULT unique_rowid(), key VARCHAR(255) NOT NULL, last_executed_at TIMESTAMP NOT NULL, locked_at TIMESTAMP NULL, mutation_query STRING NOT NULL, mutation_variables JSONB NOT NULL, mutation_result JSONB NULL, completed_phases VARCHAR(255)[] NOT NULL, user_id INT8 NULL, inserted_at TIMESTAMP NOT NULL, CONSTRAINT "primary" PRIMARY KEY (id ASC), CONSTRAINT idempotency_keys_user_id_fkey FOREIGN KEY (user_id) REFERENCES users(id), INDEX idempotency_keys_auto_index_idempotency_keys_user_id_fkey (user_id ASC), UNIQUE INDEX idempotency_keys_user_id_key_index (user_id ASC, key ASC), FAMILY "primary" (id, key, last_executed_at, locked_at, mutation_query, mutation_variables, mutation_result, completed_phases, user_id, inserted_at) )

SELECT pg_typeof(completed_phases), pg_typeof(completed_phases)::regtype from idempotency_keys

|pg_typeof | pg_typeof |
|-----------|----------------------|
|varchar[] | 'character varying[]' |

It seems the column has the good type (varchar[]) and the issue is elsewhere.

[tlvenn]

@rafiss is there any thing else I could help you with ?

[rafiss]

Thanks for the info so far. It does look like the schema is correct.

I've tried a few other ideas and still cannot reproduce it. Can you provide me with Elixir code that runs into the issue and instructions to run it?

[tlvenn]

Sure thing

[tlvenn]

I created a repo to reproduce the issue at: https://github.com/tlvenn/cdb_test
Please follow the steps as explained in the readme and you should see the following error:

[rafiss]

Thank you very much for creating this sample. It was really helpful to finally track this down. My previous attempts to reproduce this failed because of a combo of this being fixed in our 20.2 alphas (unintentionally) and my own issues with getting our pgwire testing DSL working on older branches.

The reason this is not working with 19.2 and 20.1 is this code: https://github.com/cockroachdb/cockroach/blob/20ea783887c1f33ab925cc8233041c54b58da1c5/pkg/sql/pgwire/types.go#L67-L88

PR #44471 removed that bit of code, and indeed this issue doesn't happen in the 20.2 release.

Since we broke functionality here, we could consider backporting the PR that repairs the functionality to the 19.2 and 20.1 branches. Thoughts @jordanlewis / @RaduBerinde? (tagging you two since the idea of backporting this same PR already came up in #49353)

@tlvenn: even if we aren't able to backport, the good news is that this will be fixed in the 20.2 release that will come later this year.

[tlvenn]

Given how trivial the PR seems to be, it would make sense to backport it to at the very least the 20.1.X branch so it's available within the next release. It seems we missed the 20.1.4 already, hoping to see this fixed with the 20.1.5.

@jordanlewis 🙏

[rafiss]

I created the backport #52351 and will advocate for it to be approved.

[rafiss]

Closing this out since it will be in the next 20.1 release.