Simple query execution fails: Index out of bounds

[imdrasil]

Simple query execution fails: Index out of bounds

[thomasnal]

@imdrasil Hello again. It took me a while to verify the improvement. Amber, I have the service served by, has suddenly had something broken. It is fixed now.

I have updated to Jennifer v0.3.4 today. I see it has received really useful logging information. 👍 I have a slight amendment request to it. Check this out,

Case 1

u = User.all.where{ _id == 6293 }.to_a

Unhandled exception on HTTP::Handler
Column User.current_sign_in_at is expected to be a Time but got Nil. (Jennifer::DataTypeMismatch)

Case 2

User.all.includes(:connections_with_viewer).where{ _id == 6293 }.to_a

Unhandled exception on HTTP::Handler
Column User.current_sign_in_at is expected to be a Time but got Nil. (Jennifer::DataTypeMismatch)

Case 3

User.all.includes(:connections_with_viewer).to_a

Unhandled exception on HTTP::Handler
Column User.current_sign_in_at is expected to be a Time but got Nil. (Jennifer::DataTypeMismatch)

That's the great part, Jennifer informs us what has caused the error. Saves lots of time not only of any adopter but down in any project too.

Compare it what we had before,

SELECT users.*
FROM users
WHERE users.id = $1
 | [6293]
Unhandled exception on HTTP::Handler
Column current_sign_in_at is expected to be a Time but got Nil. (Jennifer::DataTypeMismatch)

You can see that the query itself has been swallowed. It is definitely useful and wanted to see the whole information including the query printed too. Most likely the output change is due the query gets logged only after execution. Although I believe that the exception handler have access to the query. Let's print it.

With that I will be fully satisfied with the improvement. I would recommend to keep/add tests for this output information to prevent accidental change during any future refactoring.

[imdrasil]

Hi, @thomasnal
Given exception stacktrace looks little bit strange. Would you mind to update Jennifer to latest version (0.3.3) and paste exception again.

[thomasnal]

It was confusing because when I was debugging it then the crash was somewhere in the adapter. I was not able to locate it. However, I have got around the error by replacing Jennifer's table << ".*" by explicit fields' names, i.e. MyModel.field_names.map{ |f| table + "." + f }.join(", "). So actually the code was crashing somewhere in adapter where the former table << ".*" was processed.

I used master branch and v0.3.2.

Back to your request, I upgraded to v0.3.3. Many strange compile errors have appeared, such as one below,

Error in src/matcher.cr:9: while requiring "../config/*"

require "../config/*"
^

in config/routes.cr:1: instantiating 'Amber::Server#config()'

Amber::Server.instance.config do
                       ^~~~~~

in config/routes.cr:1: instantiating 'Amber::Server#config()'

Amber::Server.instance.config do
                       ^~~~~~

in config/routes.cr:35: expanding macro

  routes :web do
  ^

in macro 'routes' /app/lib/amber/src/amber.cr:125, line 1:

>  1.       router.draw :web, "" do
   2.          #<loc:push>begin #<loc:"/app/config/routes.cr",38,5>#<loc:"/app/config/routes.cr",38,5>get(#<loc:"/app/config/routes.cr",38,9>"/", #<loc:"/app/config/routes.cr",38,14>MatchesController, #<loc:"/app/config/routes.cr",38,33>:index)
   3. #<loc:"/app/config/routes.cr",39,5>get(#<loc:"/app/config/routes.cr",39,9>"/recommendations/:id", #<loc:"/app/config/routes.cr",39,33>MatchesController, #<loc:"/app/config/routes.cr",39,52>:index)
   4.  end#<loc:pop>
   5.       end
   6.

instantiating 'Amber::Router::Router#draw(Symbol, String)'
in config/routes.cr:35: expanding macro

  routes :web do
  ^

in macro 'routes' /app/lib/amber/src/amber.cr:125, line 1:

>  1.       router.draw :web, "" do
   2.          #<loc:push>begin #<loc:"/app/config/routes.cr",38,5>#<loc:"/app/config/routes.cr",38,5>get(#<loc:"/app/config/routes.cr",38,9>"/", #<loc:"/app/config/routes.cr",38,14>MatchesController, #<loc:"/app/config/routes.cr",38,33>:index)
   3. #<loc:"/app/config/routes.cr",39,5>get(#<loc:"/app/config/routes.cr",39,9>"/recommendations/:id", #<loc:"/app/config/routes.cr",39,33>MatchesController, #<loc:"/app/config/routes.cr",39,52>:index)
   4.  end#<loc:pop>
   5.       end
   6.

instantiating 'Amber::Router::Router#draw(Symbol, String)'
in macro 'get' expanded macro: macro_116785712:2, line 1:

>  1.         route :get, "/", MatchesController, :index
   2.

expanding macro
in macro 'route' /app/lib/amber/src/amber/dsl/router.cr:11, line 5:

   1.       __temp_1329 = ->(context : HTTP::Server::Context){
   2.         controller = MatchesController.new(context)
   3.         controller.run_before_filter(:index) unless context.content
   4.         unless context.content
>  5.           context.content = controller.index.to_s
   6.           controller.run_after_filter(:index)
   7.         end
   8.       }
   9.       __temp_1330 = "GET"
  10.       __temp_1331 = Amber::Route.new(
  11.         __temp_1330, "/", __temp_1329, :index, valve, scope, "MatchesController"
  12.       )
  13.
  14.       router.add(__temp_1331)
  15.

instantiating 'MatchesController#index()'
in src/controllers/matches_controller.cr:7: instantiating 'User#matches_feed()'

    users = current_user.matches_feed page: page, per_page: per_page
                         ^~~~~~~~~~~~

in src/models/user.cr:262: instantiating 'User#my_preference!()'

    distance = self.my_preference!.distance.to_i32
                    ^~~~~~~~~~~~~~

in src/models/user.cr:50: expanding macro

  has_one :my_preference, MyPreference
  ^

in macro 'has_one' expanded macro: included:179, line 23:

   1.           @@relations["my_preference"] =
   2.             ::Jennifer::Relation::HasOne(MyPreference, User).new("my_preference", nil, nil, nil, nil,
   3.               MyPreference.all)
   4.
   5.
   6.
   7.           @my_preference : MyPreference?
   8.
   9.           def self.my_preference_relation
  10.             @@my_preference_relation ||= ::Jennifer::Relation::HasOne(MyPreference, User).new("my_preference", nil, nil, nil, nil,
  11.               MyPreference.all)
  12.           end
  13.
  14.           def my_preference
  15.             if @my_preference
  16.               @my_preference
  17.             else
  18.               my_preference_reload
  19.             end
  20.           end
  21.
  22.           def my_preference!
> 23.             my_preference.not_nil!
  24.           end
  25.
  26.           def my_preference_query
  27.             primary_field =
  28.
  29.                 primary
  30.
  31.
  32.             @@relations["my_preference"].query(primary_field)
  33.           end
  34.
  35.           def my_preference_reload
  36.             @my_preference = my_preference_query.first.as(MyPreference?)
  37.           end
  38.
  39.           def append_my_preference(rel : Hash)
  40.             @my_preference = MyPreference.build(rel, false)
  41.           end
  42.
  43.           def remove_my_preference
  44.             User.my_preference_relation.remove(self)
  45.             @my_preference = nil
  46.           end
  47.
  48.           def add_my_preference(rel : Hash)
  49.             @my_preference = User.my_preference_relation.insert(self, rel)
  50.           end
  51.
  52.           def add_my_preference(rel : MyPreference)
  53.             @my_preference = User.my_preference_relation.insert(self, rel)
  54.           end
  55.

instantiating 'my_preference()'
in src/models/user.cr:50: expanding macro

  has_one :my_preference, MyPreference
  ^

in macro 'has_one' expanded macro: included:179, line 18:

   1.           @@relations["my_preference"] =
   2.             ::Jennifer::Relation::HasOne(MyPreference, User).new("my_preference", nil, nil, nil, nil,
   3.               MyPreference.all)
   4.
   5.
   6.
   7.           @my_preference : MyPreference?
   8.
   9.           def self.my_preference_relation
  10.             @@my_preference_relation ||= ::Jennifer::Relation::HasOne(MyPreference, User).new("my_preference", nil, nil, nil, nil,
  11.               MyPreference.all)
  12.           end
  13.
  14.           def my_preference
  15.             if @my_preference
  16.               @my_preference
  17.             else
> 18.               my_preference_reload
  19.             end
  20.           end
  21.
  22.           def my_preference!
  23.             my_preference.not_nil!
  24.           end
  25.
  26.           def my_preference_query
  27.             primary_field =
  28.
  29.                 primary
  30.
  31.
  32.             @@relations["my_preference"].query(primary_field)
  33.           end
  34.
  35.           def my_preference_reload
  36.             @my_preference = my_preference_query.first.as(MyPreference?)
  37.           end
  38.
  39.           def append_my_preference(rel : Hash)
  40.             @my_preference = MyPreference.build(rel, false)
  41.           end
  42.
  43.           def remove_my_preference
  44.             User.my_preference_relation.remove(self)
  45.             @my_preference = nil
  46.           end
  47.
  48.           def add_my_preference(rel : Hash)
  49.             @my_preference = User.my_preference_relation.insert(self, rel)
  50.           end
  51.
  52.           def add_my_preference(rel : MyPreference)
  53.             @my_preference = User.my_preference_relation.insert(self, rel)
  54.           end
  55.

instantiating 'my_preference_reload()'
in src/models/user.cr:50: expanding macro

  has_one :my_preference, MyPreference
  ^

in macro 'has_one' expanded macro: included:179, line 36:

   1.           @@relations["my_preference"] =
   2.             ::Jennifer::Relation::HasOne(MyPreference, User).new("my_preference", nil, nil, nil, nil,
   3.               MyPreference.all)
   4.
   5.
   6.
   7.           @my_preference : MyPreference?
   8.
   9.           def self.my_preference_relation
  10.             @@my_preference_relation ||= ::Jennifer::Relation::HasOne(MyPreference, User).new("my_preference", nil, nil, nil, nil,
  11.               MyPreference.all)
  12.           end
  13.
  14.           def my_preference
  15.             if @my_preference
  16.               @my_preference
  17.             else
  18.               my_preference_reload
  19.             end
  20.           end
  21.
  22.           def my_preference!
  23.             my_preference.not_nil!
  24.           end
  25.
  26.           def my_preference_query
  27.             primary_field =
  28.
  29.                 primary
  30.
  31.
  32.             @@relations["my_preference"].query(primary_field)
  33.           end
  34.
  35.           def my_preference_reload
> 36.             @my_preference = my_preference_query.first.as(MyPreference?)
  37.           end
  38.
  39.           def append_my_preference(rel : Hash)
  40.             @my_preference = MyPreference.build(rel, false)
  41.           end
  42.
  43.           def remove_my_preference
  44.             User.my_preference_relation.remove(self)
  45.             @my_preference = nil
  46.           end
  47.
  48.           def add_my_preference(rel : Hash)
  49.             @my_preference = User.my_preference_relation.insert(self, rel)
  50.           end
  51.
  52.           def add_my_preference(rel : MyPreference)
  53.             @my_preference = User.my_preference_relation.insert(self, rel)
  54.           end
  55.

instantiating 'Jennifer::QueryBuilder::Query+#first()'
in lib/jennifer/src/jennifer/query_builder/query.cr:190: instantiating 'to_a()'

        r = to_a[0]?
            ^~~~

in lib/jennifer/src/jennifer/query_builder/model_query.cr:59: instantiating 'Jennifer::Adapter::Base+#select(Jennifer::QueryBuilder::ModelQuery(MaterializedConversationScore))'

        ::Jennifer::Adapter.adapter.select(self) do |rs|
                                    ^~~~~~

in lib/jennifer/src/jennifer/adapter/request_methods.cr:77: instantiating 'query(String, Array(Bool | Float32 | Float64 | Int32 | Int64 | Slice(UInt8) | String | Time | Nil))'

        query(parse_query(body, args), args) { |rs| yield rs }
        ^~~~~

in lib/jennifer/src/jennifer/adapter/base.cr:75: instantiating 'with_connection()'

        with_connection { |conn| conn.query(_query, args) { |rs| yield rs } }
        ^~~~~~~~~~~~~~~

in lib/jennifer/src/jennifer/adapter/base.cr:75: instantiating 'with_connection()'

        with_connection { |conn| conn.query(_query, args) { |rs| yield rs } }
        ^~~~~~~~~~~~~~~

in lib/jennifer/src/jennifer/adapter/base.cr:75: instantiating 'DB::Connection+#query(String, Array(Bool | Float32 | Float64 | Int32 | Int64 | Slice(UInt8) | String | Time | Nil))'

        with_connection { |conn| conn.query(_query, args) { |rs| yield rs } }
                                      ^~~~~

in lib/jennifer/src/jennifer/adapter/base.cr:75: instantiating 'DB::Connection+#query(String, Array(Bool | Float32 | Float64 | Int32 | Int64 | Slice(UInt8) | String | Time | Nil))'

        with_connection { |conn| conn.query(_query, args) { |rs| yield rs } }
                                      ^~~~~

in lib/jennifer/src/jennifer/adapter/request_methods.cr:77: instantiating 'query(String, Array(Bool | Float32 | Float64 | Int32 | Int64 | Slice(UInt8) | String | Time | Nil))'

        query(parse_query(body, args), args) { |rs| yield rs }
        ^~~~~

in lib/jennifer/src/jennifer/query_builder/model_query.cr:59: instantiating 'Jennifer::Adapter::Base+#select(Jennifer::QueryBuilder::ModelQuery(MaterializedConversationScore))'

        ::Jennifer::Adapter.adapter.select(self) do |rs|
                                    ^~~~~~

in lib/jennifer/src/jennifer/query_builder/model_query.cr:60: instantiating 'PG::ResultSet#each()'

          rs.each do
             ^~~~

in lib/jennifer/src/jennifer/query_builder/model_query.cr:60: instantiating 'PG::ResultSet#each()'

          rs.each do
             ^~~~

in lib/jennifer/src/jennifer/query_builder/model_query.cr:61: instantiating 'MaterializedConversationScore:Class#build(PG::ResultSet)'

            result << T.build(rs)
                        ^~~~~

in lib/jennifer/src/jennifer/model/base.cr:37: instantiating 'new(PG::ResultSet)'

        o = new(pull)
            ^~~

in macro 'mapping' /app/lib/jennifer/src/jennifer/model/mapping.cr:435, line 1:

>  1.         mapping({id: {type: Int32, primary: true}})
   2.

expanding macro
in macro 'mapping' /app/lib/jennifer/src/jennifer/model/mapping.cr:89, line 56:

   1.         macro def self.children_classes
   2.
   3.
   4.               [] of Model::Base
   5.
   6.
   7.         end
   8.
   9.         FIELD_NAMES = [
  10.
  11.             "id",
  12.
  13.         ]
  14.
  15.         # Returns field count
  16.         def self.field_count
  17.           1
  18.         end
  19.
  20.         # Returns array of field names
  21.         def self.field_names
  22.           FIELD_NAMES
  23.         end
  24.
  25.         # generates hash with options
  26.
  27.
  28.
  29.
  30.
  31.
  32.
  33.
  34.
  35.
  36.
  37.
  38.
  39.         __field_declaration({id: {type: Int32, primary: true, parsed_type: "Int32?"}}, true)
  40.
  41.         # Returns if primary field is autoincrementable
  42.         def self.primary_auto_incrementable?
  43.           true
  44.         end
  45.
  46.         @new_record = true
  47.         @destroyed = false
  48.
  49.         # Creates object from `DB::ResultSet`
  50.         def initialize(__temp_116 : DB::ResultSet)
  51.           @new_record = false
  52.
  53.
  54.
  55.
> 56.           @id = _extract_attributes(__temp_116)
  57.         end
  58.
  59.         # Extracts arguments due to mapping from *pull* and returns tuple for
  60.         # fields assignment
  61.         # TODO: think about moving it to class scope
  62.         def _extract_attributes(pull : DB::ResultSet)
  63.
  64.             __temp_117 = nil
  65.             __temp_118 = false
  66.
  67.
  68.           1.times do |i|
  69.             column = pull.column_name(pull.column_index)
  70.             case column
  71.
  72.               when "id"
  73.                 __temp_118 = true
  74.                 __temp_117 = pull.read(Int32?)
  75.                 # if value[:type].is_a?(Path) || value[:type].is_a?(Generic)
  76.
  77.             else
  78.
  79.                 raise ::Jennifer::BaseException.new("Undefined column #{column}")
  80.
  81.             end
  82.           end
  83.           {
  84.
  85.             __temp_117.as(Int32?),
  86.
  87.           }
  88.         end
  89.
  90.         # Accepts symbol hash or named tuple, stringify it and calls
  91.         # TODO: check how converting affects performance
  92.         def initialize(values : Hash(Symbol, ::Jennifer::DBAny) | NamedTuple)
  93.           initialize(stringify_hash(values, Jennifer::DBAny))
  94.         end
  95.
  96.         def initialize(values : Hash(String, ::Jennifer::DBAny))
  97.
  98.             __temp_117 = nil
  99.             __temp_118 = true
 100.
 101.
 102.
 103.             if !values["id"]?.nil?
 104.               __temp_117 = values["id"]
 105.             else
 106.               __temp_118 = false
 107.             end
 108.
 109.
 110.
 111.
 112.
 113.               @id = __bool_convert(__temp_117, Int32?)
 114.
 115.
 116.         end
 117.
 118.         def initialize(values : Hash | NamedTuple, @new_record)
 119.           initialize(values)
 120.         end
 121.
 122.         #def attributes=(values : Hash)
 123.         #
 124.         #    if !values[:id]?.nil?
 125.         #      %var{key.id} = values[:id]
 126.         #    elsif !values["id"]?.nil?
 127.         #      %var{key.id} = values["id"]
 128.         #    else
 129.         #      %found{key.id} = false
 130.         #    end
 131.         #
 132.         #end
 133.
 134.         # Accepts splatted named tuple.
 135.         def initialize(**values)
 136.           initialize(values)
 137.         end
 138.
 139.         # Default constructor without any fields
 140.         def initialize
 141.           initialize({} of Symbol => DBAny)
 142.         end
 143.
 144.         # Saves all changes to db; if validation not passed - returns `false`
 145.         def save(skip_validation = false)
 146.           unless skip_validation
 147.             return false unless __before_validation_callback
 148.             validate!
 149.             __after_validation_callback
 150.             return false unless valid?
 151.           end
 152.           return false unless __before_save_callback
 153.           response =
 154.             if new_record?
 155.               return false unless __before_create_callback
 156.               res = ::Jennifer::Adapter.adapter.insert(self)
 157.
 158.                 if primary.nil? && res.last_insert_id > -1
 159.                   init_primary_field(res.last_insert_id.to_i)
 160.                 end
 161.
 162.               @new_record = false if res.rows_affected != 0
 163.               __after_create_callback
 164.               res
 165.             else
 166.               ::Jennifer::Adapter.adapter.update(self)
 167.             end
 168.           __after_save_callback
 169.           response.rows_affected == 1
 170.         end
 171.
 172.         # Reloads all fields from db
 173.         def reload
 174.           raise ::Jennifer::RecordNotFound.new("It is not persisted yet") if new_record?
 175.           this = self
 176.           self.class.where { this.class.primary == this.primary }.each_result_set do |rs|
 177.
 178.
 179.
 180.
 181.             @id = _extract_attributes(rs)
 182.           end
 183.           self
 184.         end
 185.
 186.         # Returns if any field was changed. If field again got first value - `true` anyway
 187.         # will be returned
 188.         def changed?
 189.
 190.             @id_changed ||
 191.
 192.           false
 193.         end
 194.
 195.         # Returns hash with all attributes and symbol keys
 196.         def to_h
 197.           {
 198.
 199.               :id => @id,
 200.
 201.           }
 202.         end
 203.
 204.         # Returns hash with all attributes and string keys
 205.         def to_str_h
 206.           {
 207.
 208.               "id" => @id,
 209.
 210.           }
 211.         end
 212.
 213.         # Sets *value* to field with name *name* and stores them directly to db without
 214.         # any validation or callback
 215.         def update_column(name, value : Jennifer::DBAny)
 216.           update_columns({name => value})
 217.         end
 218.
 219.         # Sets given *values* to proper fields and stores them directly to db without
 220.         # any validation or callback
 221.         def update_columns(values : Hash(String | Symbol, Jennifer::DBAny))
 222.           values.each do |name, value|
 223.             case name.to_s
 224.
 225.             when "id"
 226.               if value.is_a?(Int32?)
 227.                 local = value.as(Int32?)
 228.                 @id = local
 229.               else
 230.                 raise ::Jennifer::BaseException.new("Wrong type for #{name} : #{value.class}")
 231.               end
 232.
 233.             else
 234.               raise ::Jennifer::BaseException.new("Unknown model attribute - #{name}")
 235.             end
 236.           end
 237.
 238.           _primary = self.class.primary
 239.           _primary_value = primary
 240.           ::Jennifer::Adapter.adapter.update(self.class.all.where { _primary == _primary_value }, values)
 241.         end
 242.
 243.         # Sets *name* field with *value*
 244.         def set_attribute(name, value : Jennifer::DBAny)
 245.           case name.to_s
 246.
 247.
 248.               when "id"
 249.                 if value.is_a?(Int32?)
 250.                   self.id = value.as(Int32?)
 251.                 else
 252.                   raise ::Jennifer::BaseException.new("wrong type for #{name} : #{value.class}")
 253.                 end
 254.
 255.
 256.           else
 257.             raise ::Jennifer::BaseException.new("Unknown model attribute - #{name}")
 258.           end
 259.         end
 260.
 261.         # Returns field by given name. If object has no such field - will raise `BaseException`.
 262.         # To avoid raising exception set `raise_exception` to `false`.
 263.         def attribute(name : String | Symbol, raise_exception = true)
 264.           case name.to_s
 265.
 266.           when "id"
 267.             @id
 268.
 269.           else
 270.             raise ::Jennifer::BaseException.new("Unknown model attribute - #{name}") if raise_exception
 271.           end
 272.         end
 273.
 274.         def attributes_hash
 275.           hash = to_h
 276.
 277.
 278.               hash.delete(:id) if hash[:id]?.nil?
 279.
 280.
 281.           hash
 282.         end
 283.
 284.         def arguments_to_save
 285.           args = [] of ::Jennifer::DBAny
 286.           fields = [] of String
 287.
 288.
 289.
 290.           {args: args, fields: fields}
 291.         end
 292.
 293.         def arguments_to_insert
 294.           {
 295.             args: [
 296.
 297.
 298.
 299.             ],
 300.             fields: [
 301.
 302.
 303.
 304.             ]
 305.           }
 306.         end
 307.
 308.         private def __refresh_changes
 309.
 310.             @id_changed = false
 311.
 312.         end
 313.

instance variable '@id' of MaterializedConversationScore must be (Int32 | Nil), not Tuple(Int32 | Nil)

The code,

class MaterializedConversationScore < Jennifer::Model::Base
  mapping(
    id: { type: Int32, primary: true }
  )

  belongs_to :user, User
end

[imdrasil]

@thomasnal last exception is caused that you have only one field (id) and that is why Tuple wan't splat. Will add fix for this case. Will also try to deep into this.

[thomasnal]

Thanks. The single field situation needs to be fixed.

I have added another field and the app compiles successfully. The error is back to its original form I posted above.

I, [2017-08-15 16:12:59 +0000 #96]  INFO -- : [Amber 0.1.8] serving application "Crystal Matcher" at http://0.0.0.0:8080
I, [2017-08-15 16:12:59 +0000 #96]  INFO -- : Server started in development.
I, [2017-08-15 16:12:59 +0000 #96]  INFO -- : Startup Time 00:00:00.0001800


2017-08-15 16:13:18 +0000:
  SELECT e.enumtypid
  FROM pg_type t, pg_enum e
  WHERE t.oid = e.enumtypid
2017-08-15 16:13:18 +0000:
SELECT users.*
FROM users
WHERE users.id = $1
 | ["5846"]
Unhandled exception on HTTP::Handler
Index out of bounds.
Original query was:
SELECT users.*
FROM users
WHERE users.id = $1
 | ["5846"] (Jennifer::BadQuery)
0x5b0187: *CallStack::unwind:Array(Pointer(Void)) at ??
0x71e796: to_a at /app/lib/jennifer/src/jennifer/query_builder/model_query.cr 77:9
0x71e036: first! at /app/lib/jennifer/src/jennifer/query_builder/query.cr 197:9
0x7104da: find! at /app/lib/jennifer/src/jennifer/model/base.cr 257:9
0x7d7a59: index at /app/src/controllers/matches_controller.cr 6:5
0x7d276c: call at /app/lib/amber/src/amber/router/route.cr 255:3
0x7cf366: process_request at /app/lib/amber/src/amber/router/context.cr 59:5
0x5a8c56: ~procProc(HTTP::Server::Context, Nil) at /opt/crystal/src/concurrent.cr 29:3
0x7c93ee: call_next at /opt/crystal/src/http/server/handler.cr 255:3
0x7c892d: call at /app/lib/amber/src/amber/router/pipe/csrf.cr 15:11
0x7c841f: call_next at /opt/crystal/src/http/server/handler.cr 24:7
0x7c7fd0: call at /app/lib/amber/src/amber/router/pipe/session.cr 10:12
0x7c79be: call_next at /opt/crystal/src/http/server/handler.cr 24:7
0x7c7640: call at /app/lib/amber/src/amber/router/pipe/flash.cr 11:9
0x7c6dd1: call_next at /opt/crystal/src/http/server/handler.cr 24:7
0x7c6325: call at /app/lib/amber/src/amber/router/pipe/logger.cr 12:9
0x7c4126: call at /app/lib/amber/src/amber/router/pipe/pipeline.cr 21:11
0x8eff0d: process at /opt/crystal/src/http/server/request_processor.cr 39:11
0x8efbc9: process at /opt/crystal/src/http/server/request_processor.cr 16:3
0x8efad0: handle_client at /opt/crystal/src/http/server.cr 191:5
0x5a91e3: ~procProc(Nil) at /opt/crystal/src/kernel.cr 167:1
0x5cb74e: run at /opt/crystal/src/fiber.cr 255:3
0x590c56: ~proc2Proc(Fiber, (IO::FileDescriptor | Nil)) at /opt/crystal/src/concurrent.cr 61:3
0x0: ??? at ??

Crystal prints confusing information,

0x71e796: to_a at /app/lib/jennifer/src/jennifer/query_builder/model_query.cr 77:9

The thing with to_a is that if you replace the table.* with naming each column then Jennifer to_a can deal with it. Hope this clue gets you on the path.

The messages I threw around point to this code,

      # TODO: debug case when exception was rised under #each
      def to_a
        add_aliases if @relation_used
        return to_a_with_relations if @relations.size > 0
        result = [] of T
        ::Jennifer::Adapter.adapter.select(self) do |rs|
          rs.each do
puts "1"
            result << T.build(rs)
puts "2"
          end
        end
        result
      end

It never reaches the "2". Same as in v0.3.2.

[imdrasil]

@thomasnal thanks for such deep investigation 👍 Will go deeper at the evening

[imdrasil]

@thomasnal please try fix in the fix_one_field_issue. It looks like it should fix this one. If so - I'll close this issue.

[imdrasil]

I merged PR so now changes is in the master. Keep this open until you clarify that everything works on your side as well.

[thomasnal]

Sure, will check it tomorrow evening. Was away...

[thomasnal]

This is what happens to me regarding one field issue:

class MaterializedVerificationScoreAverage < Jennifer::Model::Base
  mapping(
    total: { type: Float32, primary: true }
  )
end

in src/models/user.cr:458: instantiating 'MaterializedVerificationScoreAverage:Class#all()'

    total = MaterializedVerificationScoreAverage.all.first
                                                 ^~~

in lib/jennifer/src/jennifer/model/base.cr:260: instantiating 'to_a()'

        QueryBuilder::ModelQuery(self).build(table_name)
        ^

shard.yml:

dependencies:
  jennifer:
    github: imdrasil/jennifer.cr
    branch: master

Note: the one field issue is side issue of the original report at the top. To keep communication simple, one threaded, let's resolve one field issue before we focus on the original issue.

[imdrasil]

@thomasnal finally I correctly reproduce your case. This one is because of this and is fixed under v_0.3.4 branch. I gonna to merge it after all my planned features to be finished but if it is blocker for your project - will cut it and make a release.

[thomasnal]

Brilliant, according to the compilation using v_0.3.4 the error is gone. It is not clear however in my case how the issue causes it. The issue suggests that the error happens if f2 is not listed in the mapping. In my case however this is the table,

development=# \dS materialized_verification_score_averages
Materialized view "public.materialized_verification_score_averages"
 Column |  Type   | Modifiers
--------+---------+-----------
 total  | numeric |

development=#

It is a one of table (materialized view) constructed to calculate a single value. The mapping contains the column total. There is no other column in the table, all columns are mentioned.

class MaterializedVerificationScoreAverage < Jennifer::Model::Base
  mapping(
    total: { type: Float32, primary: true }
  )
end

New Error

Happily, the previous error is gone 🎉 I hoped to move to the original error from the top of this issue, however, the following appeared - I have seen it before and haven't been able to resolve it.

instantiating 'JSON::Builder#field(String, (MaterializedVerificationScoreAverage | Nil))'
in /opt/crystal/src/json/builder.cr:226: no overload matches 'JSON::Builder#scalar' with type (MaterializedVerificationScoreAverage | Nil)
Overloads are:
 - JSON::Builder#scalar(value : Nil)
 - JSON::Builder#scalar(value : Bool)
 - JSON::Builder#scalar(value : Int | Float)
 - JSON::Builder#scalar(value : String)
 - JSON::Builder#scalar(string = false, &block)
Couldn't find overloads for these types:
 - JSON::Builder#scalar(MaterializedVerificationScoreAverage)

    scalar(value)
    ^~~~~~

As you can see, some columns in the Postgres database are defined as NUMERIC. I have not seen a guide in Jennifer source how to cope with it.

Can you go ahead to check and fix it?

[imdrasil]

@thomasnal About NUMERIC fields: due to postgres documentation and current official postgres adapter you should use PG::Numeric for such field (will add this to wiki and to supported datatypes).

About given exception trace: it seems you passing MaterializedVerificationScoreAverage instance to json serializer instead of #total value.

[thomasnal]

MaterializedVerificationScoreAverage true, I left the code total = MaterializedVerificationScoreAverage.all.first in place didn't actually extracted the total attribute after the fixes we have done.

[thomasnal]

NUMERIC is specified as NUMERIC in Postgres as other types INTEGER, STRING, etc.. Should be definitely supported by Jennifer. See the Postgres datatypes.

PG::Numeric looks like a type reported by crystal postgres adapter or an explicitly typed datatype, never encountered it in practical use. Definitely shouldn't be a requirement.

[thomasnal]

I am making my progress, however, has bumped my head to walls on the way many times. I see that the original report from the top of this issue has been address. Great work, thank you and I have further suggestions that would be much appreciated by users.

As a user, I would like to see name of the column that has caused the error.

2017-08-27 09:51:47 +0000:
  SELECT e.enumtypid
  FROM pg_type t, pg_enum e
  WHERE t.oid = e.enumtypid
2017-08-27 09:51:47 +0000:
SELECT users.*
FROM users
WHERE users.id = $1
 | ["5846"]
Unhandled exception on HTTP::Handler
PG::ResultSet#read returned a Nil. A String was expected..
Original query was:
SELECT users.*
FROM users
WHERE users.id = $1
 | ["5846"] (Jennifer::BadQuery)
0x5caa47: *CallStack::unwind:Array(Pointer(Void)) at ??
0x76301b: to_a at /app/lib/jennifer/src/jennifer/query_builder/model_query.cr 77:9
0x762776: first! at /app/lib/jennifer/src/jennifer/query_builder/query.cr 197:9
0x72d25a: find! at /app/lib/jennifer/src/jennifer/model/base.cr 249:9
0x85fc09: index at /app/src/controllers/matches_controller.cr 6:5
0x85a91c: call at /app/lib/amber/src/amber/router/route.cr 255:3
0x857516: process_request at /app/lib/amber/src/amber/router/context.cr 59:5
0x5c3466: ~procProc(HTTP::Server::Context, Nil) at /opt/crystal/src/concurrent.cr 29:3
0x85159e: call_next at /opt/crystal/src/http/server/handler.cr 255:3
0x850add: call at /app/lib/amber/src/amber/router/pipe/csrf.cr 15:11
0x8505cf: call_next at /opt/crystal/src/http/server/handler.cr 24:7
0x850180: call at /app/lib/amber/src/amber/router/pipe/session.cr 10:12
0x84fb6e: call_next at /opt/crystal/src/http/server/handler.cr 24:7
0x84f7f0: call at /app/lib/amber/src/amber/router/pipe/flash.cr 11:9
0x84ef81: call_next at /opt/crystal/src/http/server/handler.cr 24:7
0x84e4d5: call at /app/lib/amber/src/amber/router/pipe/logger.cr 12:9
0x84c2d6: call at /app/lib/amber/src/amber/router/pipe/pipeline.cr 21:11
0x9ba51d: process at /opt/crystal/src/http/server/request_processor.cr 39:11
0x9ba1d9: process at /opt/crystal/src/http/server/request_processor.cr 16:3
0x9ba0e0: handle_client at /opt/crystal/src/http/server.cr 191:5
0x5c39f3: ~procProc(Nil) at /opt/crystal/src/kernel.cr 167:1
0x5e6abe: run at /opt/crystal/src/fiber.cr 255:3
0x5aae86: ~proc2Proc(Fiber, (IO::FileDescriptor | Nil)) at /opt/crystal/src/concurrent.cr 61:3
0x0: ??? at ??

Can Jennifer catch the error and output PG::ResultSet#read returned a Nil for column "xyz". A String was expected.

[thomasnal]

It solves the situations as below,

PG::ResultSet#read returned a Slice(UInt8). A (String | Nil) was expected..

All columns in the table have a type of one of,

integer
character varying(255)
character varying
timestamp without time zone
boolean
hstore

None of them is UInt8 or Slice(UInt8). Therefore I can't infer what is causing the error.

[thomasnal]

However, I have a suggestion to the solution you made. Jennifer is now forcing definition of all table columns even if our model is not interested in them. The much more appreciated approach would be to ignore read of those columns that are not specified in mapping section. That was my interim solution while waited for yours.

In my situation, I have 35 columns in one of the many tables. In this table my application is interested in 8 columns only.

Can you improve your solution in this suggested way?

[imdrasil]

1. By default Jennifer expecting from you defining all columns or raise exception when faces some undefined (master branch has a bug with this case; v_0.3.4 got a fix). If u want to ignore any other field just add false as second argument, e.g.:

mapping({
  id: { type: Int32, primary: true },
  name: String
}, false)

2. About NUMERIC - numeric and decimal are the same types in postgres (as far as I can understand from documentation). Official driver allows to parse such fields using PG::Numeric or BigRational. Now Jennifer doesn't allow converters in mapping definition and I don't know if this is a nice idea to add it. If u think this will not feat real project requirements - feel free to create separate issue.

3. About more readable exceptions from column parsing - will take a look.

[thomasnal]

If u want to ignore any other field just add false as second argument

Nice, this looks to be basically what I asked for. Commenting out many fields from User mappings helped me to get through the Slice(UInt8) exception. (I will keep testing Slice(UInt8) though once you improve the exception reporting that helps me to understand which column is causing it.)

I am on v0.3.4 got through the Slice(UInt8), fixed Profiles and VerificationScore with the false parameter. I have reached to about the same exception as originally Index out of bounds. Jennifer is mishandling the parameters going to the query. There is only one parameter, an array of 10 user ids, however the query generated is looking for 10 parameters. That looks like a cause of the index out of bounds exception.

2017-08-27 14:44:51 +0000:
SELECT users.*, profile_pictures.*, profiles.*, verification_scores.*
FROM users
LEFT JOIN profile_pictures ON profile_pictures.user_id = users.id
 LEFT JOIN profiles ON profiles.user_id = users.id
 LEFT JOIN verification_scores ON verification_scores.user_id = users.id
WHERE users.id IN($1, $2, $3, $4, $5, $6, $7, $8, $9, $10)
 | [5166, 6742, 6059, 6604, 5873, 6701, 6704, 6871, 6620, 6561]
Unhandled exception on HTTP::Handler
Index out of bounds.
Original query was:
SELECT users.*, profile_pictures.*, profiles.*, verification_scores.*
FROM users
LEFT JOIN profile_pictures ON profile_pictures.user_id = users.id
 LEFT JOIN profiles ON profiles.user_id = users.id
 LEFT JOIN verification_scores ON verification_scores.user_id = users.id
WHERE users.id IN($1, $2, $3, $4, $5, $6, $7, $8, $9, $10)
 | [5166, 6742, 6059, 6604, 5873, 6701, 6704, 6871, 6620, 6561] (Jennifer::BadQuery)
0x5cab67: *CallStack::unwind:Array(Pointer(Void)) at ??
0x74ad8d: to_a_with_relations at /app/lib/jennifer/src/jennifer/query_builder/model_query.cr 77:9
0x744c64: to_a at /app/lib/jennifer/src/jennifer/query_builder/model_query.cr 81:16
0x84494e: index at /app/src/controllers/matches_controller.cr 9:46
0x83f5ec: call at /app/lib/amber/src/amber/router/route.cr 255:3
0x83c1e6: process_request at /app/lib/amber/src/amber/router/context.cr 59:5
0x5c3586: ~procProc(HTTP::Server::Context, Nil) at /opt/crystal/src/concurrent.cr 29:3
0x83626e: call_next at /opt/crystal/src/http/server/handler.cr 255:3
0x8357ad: call at /app/lib/amber/src/amber/router/pipe/csrf.cr 15:11
0x83529f: call_next at /opt/crystal/src/http/server/handler.cr 24:7
0x834e50: call at /app/lib/amber/src/amber/router/pipe/session.cr 10:12
0x83483e: call_next at /opt/crystal/src/http/server/handler.cr 24:7
0x8344c0: call at /app/lib/amber/src/amber/router/pipe/flash.cr 11:9
0x833c51: call_next at /opt/crystal/src/http/server/handler.cr 24:7
0x8331a5: call at /app/lib/amber/src/amber/router/pipe/logger.cr 12:9
0x830fa6: call at /app/lib/amber/src/amber/router/pipe/pipeline.cr 21:11
0x99f27d: process at /opt/crystal/src/http/server/request_processor.cr 39:11
0x99ef39: process at /opt/crystal/src/http/server/request_processor.cr 16:3
0x99ee40: handle_client at /opt/crystal/src/http/server.cr 191:5
0x5c3b13: ~procProc(Nil) at /opt/crystal/src/kernel.cr 167:1
0x5e6bde: run at /opt/crystal/src/fiber.cr 255:3
0x5aafa6: ~proc2Proc(Fiber, (IO::FileDescriptor | Nil)) at /opt/crystal/src/concurrent.cr 61:3
0x0: ??? at ??

[thomasnal]

NUMERIC is fine as long as it will allow to process the value. Previously, I though there is an exception because Jennifer can't fit this value to Float for example. Once I get through the above errors and get the query output and the NUMERIC will work, e.g. with Float, it is definitely alright for any project.

[thomasnal]

The code causing the above Index out of bounds is,

    ids = rel.pluck(:id)
    User.all
      .includes(:default_profile_picture)
      .includes(:profile)
      .includes(:verification_score_assoc)
      .where{ _id.in(ids) }

[imdrasil]

@thomasnal checkout last changes - now all bugs with fields definition and building objects should be fixed.

[thomasnal]

Now the error reporting is much more usable. You made a big service to anybody who wants to use Jennifer. Thanks for the update.

Column total is expected to be a (Float32 | Nil) but got PG::Numeric. (Jennifer::DataTypeMismatch)

That made me to understand to declare type of total in mapping as PG::Numeric and then use #to_f to cast it to float. 🥇

[thomasnal]

I am happy to close this issue and follow with other issues I have on hand to remove hurdles in adoption and iron out Jennifer usage further.

[thomasnal]

Actually I came across a new Index out of bounds.

SELECT users.*, connections.*
FROM users
LEFT JOIN connections ON (connections.user_id = users.id AND connections.friend_id = $1)
 | [5262]
Unhandled exception on HTTP::Handler
Index out of bounds.
Original query was:
SELECT users.*, connections.*
FROM users
LEFT JOIN connections ON (connections.user_id = users.id AND connections.friend_id = $1)
 | [5262] (Jennifer::BadQuery)
0x5c5917: *CallStack::unwind:Array(Pointer(Void)) at ??
0x745952: to_a_with_relations at /app/lib/jennifer/src/jennifer/query_builder/model_query.cr 84:9
0x73fac1: to_a at /app/lib/jennifer/src/jennifer/query_builder/model_query.cr 81:16
0x825bb6: connections at /app/src/controllers/matches_controller.cr 15:5
0x82071c: call at /app/lib/amber/src/amber/core/router/route.cr 255:3
0x81d316: process_request at /app/lib/amber/src/amber/core/router/context.cr 124:5
0x5be2d6: ~procProc(HTTP::Server::Context, Nil) at /opt/crystal/src/concurrent.cr 29:3
0x8173ce: call_next at /opt/crystal/src/http/server/handler.cr 255:3
0x81690d: call at /app/lib/amber/src/amber/core/router/pipe/csrf.cr 15:11
0x8163ff: call_next at /opt/crystal/src/http/server/handler.cr 24:7
0x815fb0: call at /app/lib/amber/src/amber/core/router/pipe/session.cr 10:12
0x81599e: call_next at /opt/crystal/src/http/server/handler.cr 24:7
0x815620: call at /app/lib/amber/src/amber/core/router/pipe/flash.cr 11:9
0x814db1: call_next at /opt/crystal/src/http/server/handler.cr 24:7
0x814305: call at /app/lib/amber/src/amber/core/router/pipe/logger.cr 12:9
0x812106: call at /app/lib/amber/src/amber/core/router/pipe/pipeline.cr 21:11
0x95266d: process at /opt/crystal/src/http/server/request_processor.cr 39:11
0x952329: process at /opt/crystal/src/http/server/request_processor.cr 16:3
0x952230: handle_client at /opt/crystal/src/http/server.cr 191:5
0x5be853: ~procProc(Nil) at /opt/crystal/src/kernel.cr 167:1
0x5e198e: run at /opt/crystal/src/fiber.cr 255:3
0x5a59c6: ~proc2Proc(Fiber, (IO::FileDescriptor | Nil)) at /opt/crystal/src/concurrent.cr 61:3
0x0: ??? at ??

Line that causes the error:
(0x825bb6: connections at /app/src/controllers/matches_controller.cr 15:5)

User.all.includes(:connections_with_viewer).to_a

class User < Jennifer::Model::Base
  ...
  has_one :connections_with_viewer, Connection, request: {
    where{ _friend_id == 5262 }
  }
end

[imdrasil]

@thomasnal I can't reproduce it for now. Please investigate could be there some preconditions (e.g. you have no users but connections_with_viewer or smth like this)

[thomasnal]

Roman, I have got more data. Our simplified situation from above,

The relation:

class User < Jennifer::Model::Base
  has_one :connections_with_viewer, Connection, request: {
    where{ _friend_id == 5262 }
  }
end

The code being executed:

User.all.includes(:connections_with_viewer).to_a

Leading to,

SELECT users.*, connections.*
FROM users
LEFT JOIN connections ON (connections.user_id = users.id AND connections.friend_id = $1)
 | [5262]
Unhandled exception on HTTP::Handler
Index out of bounds.

Let's explore,

User.all.includes(:connections_with_viewer).where{ _id == 3 }.to_a

SELECT users.*, connections.*
FROM users
LEFT JOIN connections ON (connections.user_id = users.id AND connections.friend_id = $1)
WHERE users.id = $2
 | [5262, 3]

=> works

Let's see further,

User.all.includes(:connections_with_viewer).where{ _id == 6293 }.to_a

SELECT users.*, connections.*
FROM users
LEFT JOIN connections ON (connections.user_id = users.id AND connections.friend_id = $1)
WHERE users.id = $2
 | [5262, 6293]
Unhandled exception on HTTP::Handler
cast from Nil to Time failed, at /app/src/models/user.cr:8:3:2.

db_development# select * from connections where friend_id = 5262 and user_id = 6293;
=> (0 rows) # abbreviation, can't share the header with all columns

Is this record the culprit? Surely it contributes. This query is expected to end with empty results successfully. A useful candidate to be added to tests.

[imdrasil]

@thomasnal As I can see your User or Connection model has some Time field without allowing nil and last request returns at least one record with nil time. Last commit in v_0.3.4 has handling of this case with describing column name and expected type.

This example may return not only one record - all conditions allow to exist result.

[thomasnal]

See below,

SELECT users.*
FROM users
WHERE users.id = $1
 | [6293]
Unhandled exception on HTTP::Handler
Column current_sign_in_at is expected to be a Time but got Nil. (Jennifer::DataTypeMismatch)

So I found a record that is culprit. Seeing it, it would be helpful if this error propagates through those other two query executions. Can you implement it? I see that debugging without it is tricky and time consuming.

[imdrasil]

@thomasnal pull from v_0.3.4 - now Jennifer::DataTypeCasting exception is raised with descriptive message

[imdrasil]

Hi @thomasnal. Check out latest (0.4.0) release - it inclues all needed error message improvements

[imdrasil]

@thomasnal what we should do here to be able to close it ?

[imdrasil]

it seems everything now works as you described so I'm closing this one. Feel free to reopen it if u will found any problem with it.

[thomasnal]

@imdrasil There is something fishy going on and it relates to the swallowed debug output I mentioned above. See this code below,

def connections
  current_user = User.find! params["id"]
end

Now compare debug output for the following two calls that execute it,

1) http://localhost/connections/5262
2) http://localhost/connections/6293

1)

2017-11-14 12:16:23 +0000:
5554 µs SELECT users.*
FROM users
WHERE users.id = $1
 | ["5262"]
Unhandled exception on HTTP::Handler
Column User.current_sign_in_at can't be casted from Nil to it's type - Time (Jennifer::DataTypeCasting)
0x74042e: _extract_attributes at /app/src/models/user.cr 8:3
...

2)

Unhandled exception on HTTP::Handler
Column User.current_sign_in_at is expected to be a Time but got Nil. (Jennifer::DataTypeMismatch)
0x74042e: _extract_attributes at /app/src/models/user.cr 8:3
...

These two calls, executing the same code, produce two different debug outputs. The second call is swallowing the timestamp and the query. It is the same behavior I reported/requested above (point 3). I can keep calling these endpoints in any order and the first always produces output with the timestamp/query while the second never.

The expected behavior is that every command produces consistent debug output starting with the timestamp and containing the query that caused the error. Please have a look if you can find and fix it.

[imdrasil]

@thomasnal please check master branch if it still produces same result