Unhelpful Error when inserting via Ecto Ch: "1st argument: not an iodata term"

[scottmessinger]

trafficstars

Hi! I really appreciate the work on this driver! It's been working great (I'm using it via ecto_ch). However, we're seeing an error occasionally pop up in production that we can't get to the bottom of. We're not sure if we're doing something wrong or if it's a bug in the driver. Here's the error.

** State machine #PID<0.17637.120> terminating
** Reason for termination ==
** (DBConnection.ConnectionError) client #PID<0.22047.124> stopped: ** (ArgumentError) errors were found at the given arguments:

  * 1st argument: not an iodata term

    :erlang.iolist_size([[["INSERT INTO ", 34, "card_stack_comparisons_to_parent_", 34] | " FORMAT RowBinaryWithNamesAndTypes"], 10, [55, [[17 | "empty_cards_count"], [15 | "standards_added"], [13 | "words_deleted"], [15 | "links_unchanged"], [24 | "cards_of_any_type_edited"], [7 | "version"], [32 | "google_classroom_cards_unchanged"], [16 | "text_cards_added"], [21 | "attachments_unchanged"], [21 | "standard_cards_edited"], [29 | "google_classroom_cards_edited"], [28 | "google_classroom_cards_added"], [15 | "day_cards_count"], [17 | "standards_deleted"], [17 | "attachments_added"], [23 | "date_plan_scheduled_for"], [30 | "google_classroom_cards_deleted"], [14 | "comments_added"], [20 | "words_in_title_count"], [11 | "words_count"], [13 | "card_stack_id"], [19 | "standards_unchanged"], [17 | "text_cards_edited"], [11 | "words_added"], [22 | "standard_cards_deleted"], [20 | "standard_cards_added"], [24 | "standard_cards_unchanged"], [21 | "date_action_performed"], [16 | "comments_deleted"], [18 | "comments_unchanged"], [18 | "text_cards_deleted"], [11 | "links_count"], [17 | "attachments_count"], [14 | "comments_count"], [34 | "standard_cards_with_comments_count"], [19 | "words_in_body_count"], [20 | "text_cards_unchanged"], [20 | "standard_cards_count"], [19 | "attachments_deleted"], [11 | "links_added"], [11 | "planbook_id"], [25 | "percentage_of_empty_cards"], [25 | "cards_of_any_type_deleted"], [23 | "cards_of_any_type_count"], [...], ...], [[5 | "UInt8"], [5 | "UInt8"], [6 | "UInt16"], [5 | "UInt8"], [5 | "UInt8"], [6 | "UInt32"], [5 | "UInt8"], [5 | "UInt8"], [5 | "UInt8"], [5 | "UInt8"], [5 | "UInt8"], [5 | "UInt8"], [5 | "UInt8"], [5 | "UInt8"], [5 | "UInt8"], [4 | "Date"], [5 | "UInt8"], [5 | "UInt8"], [6 | "UInt16"], [6 | "UInt16"], [15, "FixedString(", "24", 41], [5 | "UInt8"], [5 | "UInt8"], [6 | "UInt16"], [5 | "UInt8"], [5 | "UInt8"], [5 | "UInt8"], [4 | "Date"], [5 | "UInt8"], [5 | "UInt8"], [5 | "UInt8"], [5 | "UInt8"], [5 | "UInt8"], [5 | "UInt8"], [5 | "UInt8"], [6 | "UInt16"], [5 | "UInt8"], [5 | "UInt8"], [5 | "UInt8"], [5 | "UInt8"], [15, "FixedString(", "24", ...], [5 | "UInt8"], [5 | "UInt8"], [...], ...]], 5, 0, <<13, 0>>, 0, 6, <<12, 0, 0, 0>>, 0, 0, 0, 0, 0, 0, 0, 0, 0, "ZM", 0, 0, <<5, 0>>, <<44, 0>>, "65ef6b1c710c040fc2000010", 0, 1, <<42, 0>>, 0, 0, 0, "RM", 0, 0, 5, 1, 0, 0, 0, <<39, 0>>, 0, 0, 0, 1, "65982e230e6ea60001d8147e", 500, 5, 1, 0, "65982e280e6ea6000112cd33", 0, ...])
    (mint 1.5.2) lib/mint/http1.ex:1025: anonymous fn/1 in Mint.HTTP1.add_content_length_or_transfer_encoding/2
    (mint 1.5.2) lib/mint/core/util.ex:106: Mint.Core.Util.put_new_header_lazy/3
    (mint 1.5.2) lib/mint/http1.ex:1026: Mint.HTTP1.add_content_length_or_transfer_encoding/2
    (mint 1.5.2) lib/mint/http1.ex:268: Mint.HTTP1.request/5
    (ch 0.2.1) lib/ch/connection.ex:207: Ch.Connection.request/6
    (ch 0.2.1) lib/ch/connection.ex:140: Ch.Connection.handle_execute/4
    (db_connection 2.6.0) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4

Any idea what's going on here?

[ruslandoga]

👋 @scottmessinger

In this particular query the problem is 500 integer in the list which seems to correspond to some UInt8 field.

For better errors we can do type checks on the supplied values in Ch, right now it just "dumps" UInt8 as a byte for the sake of "performance" :)

[scottmessinger]

Woah! How'd you figure that out? To start figuring this out in the ecto_ch repo, should we be looking at an encode/decode error or a field issue? Happy to dig into this and help out getting it resolved!

[ruslandoga]

To start figuring this out in the ecto_ch repo, should we be looking at an encode/decode error or a field issue? Happy to dig into this and help out getting it resolved!

Sorry, it's not an ecto_ch issue, I was wrong. I've updated my comment above.

Woah! How'd you figure that out?

not an iodata term usually means an invalid integer somewhere in the list. Sometimes it's something like ["string" | 0], sometimes it's an integer > 255 like in this case. So I was looking for them in your query (thank you for providing it!)

[ruslandoga]

You'd need to check your insert and insert_all for UInt8 fields that are larger than 255.

Here's what seems to be inserted in your query:

[
  {"empty_cards_count", "UInt8", 5},
  {"standards_added", "UInt8", 0},
  {"words_deleted", "UInt16", <<13, 0>>},
  {"links_unchanged", "UInt8", 0},
  {"cards_of_any_type_edited", "UInt8", 6},
  {"version", "UInt32", <<12, 0, 0, 0>>},
  {"google_classroom_cards_unchanged", "UInt8", 0},
  {"text_cards_added", "UInt8", 0},
  {"attachments_unchanged", "UInt8", 0},
  {"standard_cards_edited", "UInt8", 0},
  {"google_classroom_cards_edited", "UInt8", 0},
  {"google_classroom_cards_added", "UInt8", 0},
  {"day_cards_count", "UInt8", 0},
  {"standards_deleted", "UInt8", 0},
  {"attachments_added", "UInt8", 0},
  {"date_plan_scheduled_for", "Date", <<90, 77>>},
  {"google_classroom_cards_deleted", "UInt8", 0},
  {"comments_added", "UInt8", 0},
  {"words_in_title_count", "UInt16", <<5, 0>>},
  {"words_count", "UInt16", <<44, 0>>},
  {"card_stack_id", "FixedString(24)", "65ef6b1c710c040fc2000010"},
  {"standards_unchanged", "UInt8", 0},
  {"text_cards_edited", "UInt8", 1},
  {"words_added", "UInt16", <<42, 0>>},
  {"standard_cards_deleted", "UInt8", 0},
  {"standard_cards_added", "UInt8", 0},
  {"standard_cards_unchanged", "UInt8", 0},
  {"date_action_performed", "Date", "RM"},
  {"comments_deleted", "UInt8", 0},
  {"comments_unchanged", "UInt8", 0},
  {"text_cards_deleted", "UInt8", 5},
  {"links_count", "UInt8", 1},
  {"attachments_count", "UInt8", 0},
  {"comments_count", "UInt8", 0},
  {"standard_cards_with_comments_count", "UInt8", 0},
  {"words_in_body_count", "UInt16", <<39, 0>>},
  {"text_cards_unchanged", "UInt8", 0},
  {"standard_cards_count", "UInt8", 0},
  {"attachments_deleted", "UInt8", 0},
  {"links_added", "UInt8", 1},
  {"planbook_id", "FixedString(24", "65982e230e6ea60001d8147e"},
  {"percentage_of_empty_cards", "UInt8", 500}, # <= problem
  {"cards_of_any_type_deleted", "UInt8", 5}
  # etc.
]

And I'd need to add some kind of check in https://github.com/plausible/ch/blob/419db4735934a99b9df6374324878604bb2de24d/lib/ch/row_binary.ex#L198

[scottmessinger]

@ruslandoga Thank you so, so much for doing this! It's small fixes like these which add up to make incredible, rock solid software. I'm really grateful and impressed that you took the time to change it.