Protocol Error

[mmmries]

I found an error in my app logs and I'm not sure what the error means. Any chance someone can help me interpret?

OS: Alpine Linux 3.6
Erlang/OTP: 19.3.0-r3
Elixir: 1.4.5
Hex: 0.16.0
Postgrex: 0.13.2
DB Connection: 1.1.2

mix.lock file

%{"atlas": {:git, "https://gitlab.mx.com/dev/atlas", "6932e767280c473b49fe15e70029f902a52745ee", [branch: "master"]},
  "benchee": {:hex, :benchee, "0.6.0", "c2565506c621ee010e71d05f555e39a1b937e00810e284bc85463a4d4efc4b00", [:mix], [{:deep_merge, "~> 0.1", [hex: :deep_merge, repo: "hexpm", optional: false]}], "hexpm"},
  "bunt": {:hex, :bunt, "0.2.0", "951c6e801e8b1d2cbe58ebbd3e616a869061ddadcc4863d0a2182541acae9a38", [:mix], [], "hexpm"},
  "certifi": {:hex, :certifi, "1.2.1", "c3904f192bd5284e5b13f20db3ceac9626e14eeacfbb492e19583cf0e37b22be", [:rebar3], [], "hexpm"},
  "connection": {:hex, :connection, "1.0.4", "a1cae72211f0eef17705aaededacac3eb30e6625b04a6117c1b2db6ace7d5976", [:mix], [], "hexpm"},
  "credo": {:hex, :credo, "0.8.4", "4e50acac058cf6292d6066e5b0d03da5e1483702e1ccde39abba385c9f03ead4", [:mix], [{:bunt, "~> 0.2.0", [hex: :bunt, repo: "hexpm", optional: false]}], "hexpm"},
  "db_connection": {:hex, :db_connection, "1.1.2", "2865c2a4bae0714e2213a0ce60a1b12d76a6efba0c51fbda59c9ab8d1accc7a8", [:mix], [{:connection, "~> 1.0.2", [hex: :connection, repo: "hexpm", optional: false]}, {:poolboy, "~> 1.5", [hex: :poolboy, repo: "hexpm", optional: true]}, {:sbroker, "~> 1.0", [hex: :sbroker, repo: "hexpm", optional: true]}], "hexpm"},
  "decimal": {:hex, :decimal, "1.3.1", "157b3cedb2bfcb5359372a7766dd7a41091ad34578296e951f58a946fcab49c6", [:mix], [], "hexpm"},
  "deep_merge": {:hex, :deep_merge, "0.1.1", "c27866a7524a337b6a039eeb8dd4f17d458fd40fbbcb8c54661b71a22fffe846", [:mix], [], "hexpm"},
  "ecto": {:hex, :ecto, "2.1.4", "d1ba932813ec0e0d9db481ef2c17777f1cefb11fc90fa7c142ff354972dfba7e", [:mix], [{:db_connection, "~> 1.1", [hex: :db_connection, repo: "hexpm", optional: true]}, {:decimal, "~> 1.2", [hex: :decimal, repo: "hexpm", optional: false]}, {:mariaex, "~> 0.8.0", [hex: :mariaex, repo: "hexpm", optional: true]}, {:poison, "~> 2.2 or ~> 3.0", [hex: :poison, repo: "hexpm", optional: true]}, {:poolboy, "~> 1.5", [hex: :poolboy, repo: "hexpm", optional: false]}, {:postgrex, "~> 0.13.0", [hex: :postgrex, repo: "hexpm", optional: true]}, {:sbroker, "~> 1.0", [hex: :sbroker, repo: "hexpm", optional: true]}], "hexpm"},
  "ecto_enum": {:hex, :ecto_enum, "1.0.2", "866f717cffbf33561ccacdb55d68e444dd76a54cd76f313620d1a516da304e49", [:mix], [{:ecto, "~> 2.1.0", [hex: :ecto, repo: "hexpm", optional: false]}, {:mariaex, "~> 0.8.0", [hex: :mariaex, repo: "hexpm", optional: true]}, {:postgrex, "~> 0.13.0", [hex: :postgrex, repo: "hexpm", optional: true]}], "hexpm"},
  "excoveralls": {:hex, :excoveralls, "0.7.1", "3dd659db19c290692b5e2c4a2365ae6d4488091a1ba58f62dcbdaa0c03da5491", [:mix], [{:exjsx, ">= 3.0.0", [hex: :exjsx, repo: "hexpm", optional: false]}, {:hackney, ">= 0.12.0", [hex: :hackney, repo: "hexpm", optional: false]}], "hexpm"},
  "exjsx": {:hex, :exjsx, "4.0.0", "60548841e0212df401e38e63c0078ec57b33e7ea49b032c796ccad8cde794b5c", [:mix], [{:jsx, "~> 2.8.0", [hex: :jsx, repo: "hexpm", optional: false]}], "hexpm"},
  "exmx": {:git, "https://gitlab.mx.com/dev/exmx", "bb6a1b1f39d2e273db9acdf49348190fbf8b8729", [branch: "master"]},
  "gnat": {:hex, :gnat, "0.3.4", "1bbd150aff020a796b233181b33f1dbabee79b1655d8829491c3242013277b5d", [:mix], [{:poison, "~> 3.0", [hex: :poison, repo: "hexpm", optional: false]}], "hexpm"},
  "gpb": {:hex, :gpb, "3.26.8", "9051411bb8b992ae9c681a64aeb598a36a4e55f613551d5461128573447155e2", [:make, :rebar], [], "hexpm"},
  "hackney": {:hex, :hackney, "1.8.6", "21a725db3569b3fb11a6af17d5c5f654052ce9624219f1317e8639183de4a423", [:rebar3], [{:certifi, "1.2.1", [hex: :certifi, repo: "hexpm", optional: false]}, {:idna, "5.0.2", [hex: :idna, repo: "hexpm", optional: false]}, {:metrics, "1.0.1", [hex: :metrics, repo: "hexpm", optional: false]}, {:mimerl, "1.0.2", [hex: :mimerl, repo: "hexpm", optional: false]}, {:ssl_verify_fun, "1.1.1", [hex: :ssl_verify_fun, repo: "hexpm", optional: false]}], "hexpm"},
  "honeybadger": {:hex, :honeybadger, "0.6.3", "6fd1aafb29b79aa70cc56ca735e99fed90795b5768045684ddca0ee7eb01db2f", [:mix], [{:httpoison, "~> 0.9 or ~> 0.11", [hex: :httpoison, repo: "hexpm", optional: false]}, {:plug, ">= 0.13.0 and < 2.0.0", [hex: :plug, repo: "hexpm", optional: false]}, {:poison, "~> 2.0 or ~> 3.0", [hex: :poison, repo: "hexpm", optional: false]}], "hexpm"},
  "httpoison": {:hex, :httpoison, "0.12.0", "8fc3d791c5afe6beb0093680c667dd4ce712a49d89c38c3fe1a43100dd76cf90", [:mix], [{:hackney, "~> 1.8.0", [hex: :hackney, repo: "hexpm", optional: false]}], "hexpm"},
  "idna": {:hex, :idna, "5.0.2", "ac203208ada855d95dc591a764b6e87259cb0e2a364218f215ad662daa8cd6b4", [:rebar3], [{:unicode_util_compat, "0.2.0", [hex: :unicode_util_compat, repo: "hexpm", optional: false]}], "hexpm"},
  "jsx": {:hex, :jsx, "2.8.2", "7acc7d785b5abe8a6e9adbde926a24e481f29956dd8b4df49e3e4e7bcc92a018", [:mix, :rebar3], [], "hexpm"},
  "metrics": {:hex, :metrics, "1.0.1", "25f094dea2cda98213cecc3aeff09e940299d950904393b2a29d191c346a8486", [:rebar3], [], "hexpm"},
  "mime": {:hex, :mime, "1.1.0", "01c1d6f4083d8aa5c7b8c246ade95139620ef8effb009edde934e0ec3b28090a", [:mix], [], "hexpm"},
  "mimerl": {:hex, :mimerl, "1.0.2", "993f9b0e084083405ed8252b99460c4f0563e41729ab42d9074fd5e52439be88", [:rebar3], [], "hexpm"},
  "plug": {:hex, :plug, "1.3.5", "7503bfcd7091df2a9761ef8cecea666d1f2cc454cbbaf0afa0b6e259203b7031", [:mix], [{:cowboy, "~> 1.0.1 or ~> 1.1", [hex: :cowboy, repo: "hexpm", optional: true]}, {:mime, "~> 1.0", [hex: :mime, repo: "hexpm", optional: false]}], "hexpm"},
  "poison": {:hex, :poison, "3.1.0", "d9eb636610e096f86f25d9a46f35a9facac35609a7591b3be3326e99a0484665", [:mix], [], "hexpm"},
  "poolboy": {:hex, :poolboy, "1.5.1", "6b46163901cfd0a1b43d692657ed9d7e599853b3b21b95ae5ae0a777cf9b6ca8", [:rebar], [], "hexpm"},
  "postgrex": {:hex, :postgrex, "0.13.2", "2b88168fc6a5456a27bfb54ccf0ba4025d274841a7a3af5e5deb1b755d95154e", [:mix], [{:connection, "~> 1.0", [hex: :connection, repo: "hexpm", optional: false]}, {:db_connection, "~> 1.1", [hex: :db_connection, repo: "hexpm", optional: false]}, {:decimal, "~> 1.0", [hex: :decimal, repo: "hexpm", optional: false]}], "hexpm"},
  "sobelow": {:hex, :sobelow, "0.3.12", "ce864fbd05e5d57e71f8f2d843d4f7c462653d0c2764f6da91bc16b0829a4a21", [:mix], [], "hexpm"},
  "ssl_verify_fun": {:hex, :ssl_verify_fun, "1.1.1", "28a4d65b7f59893bc2c7de786dec1e1555bd742d336043fe644ae956c3497fbe", [:make, :rebar], [], "hexpm"},
  "unicode_util_compat": {:hex, :unicode_util_compat, "0.2.0", "dbbccf6781821b1c0701845eaf966c9b6d83d7c3bfc65ca2b78b88b8678bfa35", [:rebar3], [], "hexpm"},
  "uuid": {:hex, :uuid, "1.1.7", "007afd58273bc0bc7f849c3bdc763e2f8124e83b957e515368c498b641f7ab69", [:mix], [], "hexpm"}}

07:58:39.342 [error]     (postgrex) lib/postgrex/protocol.ex:1900: Postgrex.Protocol.handle_msg(%Postgrex.Protocol{buffer: nil, connection_id: 283848846, connection_key: -465462317, null: nil, parameters: #Reference<0.0.1.924>, peer: {{127, 0, 0, 1}, 6432}, postgres: :transaction, queries: nil, sock: {:gen_tcp, #Port<0.5842>}, timeout: 15000, transactions: :naive, types: {Ecto.Adapters.Postgres.TypeModule, 159795}}, %{mode: :transaction, notify: #Function<31.104721290/2 in Postgrex.Protocol.notify/1>, sync: :flushed_sync}, {:msg_ready, :failed})
    (postgrex) lib/postgrex/protocol.ex:1213: Postgrex.Protocol.execute_recv/5
    (db_connection) lib/db_connection.ex:958: DBConnection.handle/4
    (db_connection) lib/db_connection.ex:1078: DBConnection.describe_run/5
    (db_connection) lib/db_connection.ex:1142: anonymous fn/4 in DBConnection.run_meter/5
    (db_connection) lib/db_connection.ex:584: DBConnection.prepare_execute/4
    (ecto) lib/ecto/adapters/postgres/connection.ex:93: Ecto.Adapters.Postgres.Connection.execute/4
    (ecto) lib/ecto/adapters/sql.ex:243: Ecto.Adapters.SQL.sql_call/6
    (ecto) lib/ecto/adapters/sql.ex:562: Ecto.Adapters.SQL.struct/7
    (ecto) lib/ecto/repo/schema.ex:467: Ecto.Repo.Schema.apply/4
    (ecto) lib/ecto/repo/schema.ex:205: anonymous fn/13 in Ecto.Repo.Schema.do_insert/4
    (ecto) lib/ecto/repo/schema.ex:684: anonymous fn/3 in Ecto.Repo.Schema.wrap_in_transaction/6
    (ecto) lib/ecto/adapters/sql.ex:620: anonymous fn/3 in Ecto.Adapters.SQL.do_transaction/3
    (db_connection) lib/db_connection.ex:1275: DBConnection.transaction_run/4
    (db_connection) lib/db_connection.ex:1199: DBConnection.run_begin/3
    (db_connection) lib/db_connection.ex:790: DBConnection.transaction/3
    (dispatch_ex) lib/dispatch/user_shard_service.ex:8: Dispatch.UserShardService.create/1
    (dispatch_ex) lib/dispatch/rpc_server.ex:30: Dispatch.RpcServer.generate_response/1
    (stdlib) timer.erl:166: :timer.tc/1
    (dispatch_ex) lib/dispatch/rpc_server.ex:19: Dispatch.RpcServer.handle_request/1
    (dispatch_ex) lib/dispatch/rpc_server.ex:10: Dispatch.RpcServer.handle_message/1
    (elixir) lib/task/supervised.ex:85: Task.Supervised.do_apply/2
    (elixir) lib/task/supervised.ex:36: Task.Supervised.reply/5
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3

Also it might help to know that I'm using prepare: :unnamed and my actual network connections look like:

postgrex -> haproxy(localhost) -> pgbouncer -> postgres

[fishcakez]

It certainly looks like a bug in Postgrex.Protocol, a sync response is received when Postgrex expects an execute response. Given the failed status in the ready message (sync response) it seems like it only occurs where we run into a particularly error case which I can't work out...we successfully bind but don't get an execute result, go straight to sync result....

[mmmries]

I would be happy to provide more details on exactly what postgres commands I'm sending or more details about my ecto configuration. I'm just not sure what information is useful at this point since I've never worked on the protocol layer of postgres before. Just let me know if I can help in any way. Happy to share code, logs, data, examples, etc

[fishcakez]

@mmmries I think just the query being run at lib/dispatch/user_shard_service.ex:8 and whether you are using any options or pooling (e.g. sandboxing)

[mmmries]

Here is what the changeset looks like:

#Ecto.Changeset<action: nil,
 changes: %{application: :ABACUS,
   guid: "USH-8cf72e9e-723a-11e7-a55a-a0999b1ab4a9",
   shard_guid: "SHR-ff9d670e-7075-11e7-a1c9-a0999b1ab4a9", shard_id: 27,
   user_guid: "USR-6789"}, errors: [], data: #Dispatch.UserShard<>,
 valid?: true>

The :ABACUS value is part of an ecto_enum definition which gets mapped to 1 before it goes to postgres. Here's what the postgres query looks like:

[debug] QUERY OK db=2.3ms
begin []
[debug] QUERY OK db=10.4ms
INSERT INTO "user_shards" ("application","guid","shard_guid","shard_id","user_guid","created_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6,$7) RETURNING "id" [1, "USH-8cf72e9e-723a-11e7-a55a-a0999b1ab4a9", "SHR-ff9d670e-7075-11e7-a1c9-a0999b1ab4a9", 27, "USR-6789", {{2017, 7, 26}, {19, 44, 42, 753688}}, {{2017, 7, 26}, {19, 44, 42, 756467}}]
[debug] QUERY OK db=0.5ms
commit []

And here's my ecto config from prod (with a few values masked)

Application.get_env(:dispatch_ex, Dispatch.Repo)
[
  adapter: Ecto.Adapters.Postgres,
  migration_source: "migration_versions",
  prepare: :unnamed,
  database: "dispatch_production",
  hostname: "**MASKED**",
  username: "**MASKED**",
  password: "**MASKED**",
  port: 6432
]

[fishcakez]

I have a local branch off of #321 that uses the same code path for named and unnamed that should resolve this. I will open a new PR once that one is merged.