-
Notifications
You must be signed in to change notification settings - Fork 53
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Simple query execution fails: Index out of bounds #19
Comments
Hi, @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 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,
The code, class MaterializedConversationScore < Jennifer::Model::Base
mapping(
id: { type: Int32, primary: true }
)
belongs_to :user, User
end |
@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. |
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.
Crystal prints confusing information,
The thing with The messages I threw around point to this code,
It never reaches the "2". Same as in v0.3.2. |
@thomasnal thanks for such deep investigation 👍 Will go deeper at the evening |
@thomasnal please try fix in the |
I merged PR so now changes is in the master. Keep this open until you clarify that everything works on your side as well. |
Sure, will check it tomorrow evening. Was away... |
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)
^
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. |
@thomasnal finally I correctly reproduce your case. This one is because of this and is fixed under |
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
It is a one of table (materialized view) constructed to calculate a single value. The mapping contains the column class MaterializedVerificationScoreAverage < Jennifer::Model::Base
mapping(
total: { type: Float32, primary: true }
)
end New ErrorHappily, 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 Can you go ahead to check and fix it? |
@thomasnal About About given exception trace: it seems you passing |
|
|
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 |
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,
None of them is |
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? |
mapping({
id: { type: Int32, primary: true },
name: String
}, false)
|
Nice, this looks to be basically what I asked for. Commenting out many fields from I am on 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 ?? |
|
The code causing the above ids = rel.pluck(:id)
User.all
.includes(:default_profile_picture)
.includes(:profile)
.includes(:verification_score_assoc)
.where{ _id.in(ids) } |
@thomasnal checkout last changes - now all bugs with fields definition and building objects should be fixed. |
Now the error reporting is much more usable. You made a big service to anybody who wants to use Jennifer. Thanks for the update.
That made me to understand to declare type of |
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. |
Actually I came across a new 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: 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 |
@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) |
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. |
@thomasnal As I can see your This example may return not only one record - all conditions allow to exist result. |
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. |
@thomasnal pull from |
@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 Case 1u = User.all.where{ _id == 6293 }.to_a
Case 2User.all.includes(:connections_with_viewer).where{ _id == 6293 }.to_a
Case 3User.all.includes(:connections_with_viewer).to_a
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,
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. |
Hi @thomasnal. Check out latest ( |
@thomasnal what we should do here to be able to close it ? |
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. |
@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)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. |
@thomasnal please check master branch if it still produces same result |
Crystal version 0.23.1 and 0.22.
The text was updated successfully, but these errors were encountered: