FCO
Possible concurrency issue in query construction
I'm getting:
Unhandled exception in code scheduled on thread 18
Unknown Error!!!
Please, copy this backtrace and open an issue on https://github.com/FCO/Red/issues/new
Driver: Red::Driver::Pg
Original error: DB::Pg::Error::FatalError.new(message => "missing FROM-clause entry for table \"stats_view_refresh\"", message-detail => Str, message-hint => Str, context => Str, type => "ERROR", type-localized => "ERROR", state => "42P01", statement-position => "15", internal-position => Str, internal-query => Str, schema => Str, table => Str, column => Str, datatype => Str, constraint => Str, source-file => "parse_relation.c", source-line => "3460", source-function => "errorMissingRTE")
Original error:
missing FROM-clause entry for table "stats_view_refresh"
in method error-check at /usr/share/perl6/site/sources/9ECF9162BB652CECE7C4EFD616D11879DA0C14A1 (DB::Pg::Database) line 117
in method prepare at /usr/share/perl6/site/sources/9ECF9162BB652CECE7C4EFD616D11879DA0C14A1 (DB::Pg::Database) line 160
in method stt-exec at /usr/share/perl6/site/sources/D1E688B0A9E8CB821D8EF976E33BFCB0A991C8F6 (Red::Driver::Pg) line 180
in submethod TWEAK at /usr/share/perl6/site/sources/D50C5B6595B6222C75D4934116A1A4F844623D25 (Red::ResultSeq::Iterator) line 16
in method iterator at /usr/share/perl6/site/sources/14541EFEF63E0E567F36634F7459B1B64EF650D6 (Red::ResultSeq) line 95
in method Seq at /usr/share/perl6/site/sources/14541EFEF63E0E567F36634F7459B1B64EF650D6 (Red::ResultSeq) line 101
in method do-it at /usr/share/perl6/site/sources/14541EFEF63E0E567F36634F7459B1B64EF650D6 (Red::ResultSeq) line 106
in method head at /usr/share/perl6/site/sources/14541EFEF63E0E567F36634F7459B1B64EF650D6 (Red::ResultSeq) line 286
in method Bool at /usr/share/perl6/site/sources/14541EFEF63E0E567F36634F7459B1B64EF650D6 (Red::ResultSeq) line 310
in method upload-exists at /hesabu/lib/YNAP/Hesabu/Model/Upload.rakumod (YNAP::Hesabu::Model::Upload) line 17
in method insert-from-csv at /hesabu/lib/YNAP/Hesabu/Model/DailyMisalignment.rakumod (YNAP::Hesabu::Model::DailyMisalignment) line 35
in method insert-from-csv at /hesabu/lib/YNAP/Hesabu/Model/DailyMisalignment.rakumod (YNAP::Hesabu::Model::DailyMisalignment) line 31
in block at /hesabu/lib/YNAP/Hesabu/Route/Upload.rakumod (YNAP::Hesabu::Route::Upload) line 50
in block at /hesabu/lib/YNAP/Hesabu/Route/Upload.rakumod (YNAP::Hesabu::Route::Upload) line 39
This is very intermittent.
The thing is that the upload-exists method has nothing to do with the table stats_view_refresh, being defined as:
method upload-exists(Str() $filename, Str() $channel, Date(Str) $report-date --> Bool ) {
self.^all.grep( -> $r { $r.filename eq $filename && $r.channel-id eq $channel && $r.report-date eq $report-date }).so;
}
And usually would make SQL like:
SQL : SELECT
count('*') > 0 as "data_1"
FROM
"upload"
WHERE
"upload".channel = 'Bar' AND "upload".filename = 'Foo' AND "upload".report_date = '2022-08-05'
LIMIT 1
BIND: []
It looks like there is possibly some data that is shared between threads which results in the wrong query being generated.
I'll try and replicate with debugging on, but I might also do a PR such that the query gets passed to the map-exception so that e.g. the X::Red::Driver::Mapped::UnknownError can include it.
I think this is a symptom of the same problem but it doesn't get as far as making the query:
Unhandled exception in code scheduled on thread 12
No such method 'item' for invocant of type 'VMNull'. Found 'item' on
type 'Mu'
in method iterator at /home/jonathan/.raku/sources/14541EFEF63E0E567F36634F7459B1B64EF650D6 (Red::ResultSeq) line 102
in method Seq at /home/jonathan/.raku/sources/14541EFEF63E0E567F36634F7459B1B64EF650D6 (Red::ResultSeq) line 109
in method do-it at /home/jonathan/.raku/sources/14541EFEF63E0E567F36634F7459B1B64EF650D6 (Red::ResultSeq) line 115
in method head at /home/jonathan/.raku/sources/14541EFEF63E0E567F36634F7459B1B64EF650D6 (Red::ResultSeq) line 295
in method Bool at /home/jonathan/.raku/sources/14541EFEF63E0E567F36634F7459B1B64EF650D6 (Red::ResultSeq) line 319
in method upload-exists at /home/jonathan/working/NAP/hesabu/lib/YNAP/Hesabu/Model/Upload.rakumod (YNAP::Hesabu::Model::Upload) line 17
in method insert-from-csv at /home/jonathan/working/NAP/hesabu/lib/YNAP/Hesabu/Model/DailyMisalignment.rakumod (YNAP::Hesabu::Model::DailyMisalignment) line 35
in method insert-from-csv at /home/jonathan/working/NAP/hesabu/lib/YNAP/Hesabu/Model/DailyMisalignment.rakumod (YNAP::Hesabu::Model::DailyMisalignment) line 31
in block at /home/jonathan/working/NAP/hesabu/lib/YNAP/Hesabu/Route/Upload.rakumod (YNAP::Hesabu::Route::Upload) line 50
in block at /home/jonathan/working/NAP/hesabu/lib/YNAP/Hesabu/Route/Upload.rakumod (YNAP::Hesabu::Route::Upload) line 39
Will continue trying to provoke the same failure mode however. What I did notice is that immediately prior (or perhaps simultaneously,) to this is that it ran:
SQL : SELECT
"user_session".id , "user_session".user_id as "user-id", "user_session".logged_in as "logged-in", "user_session".created , "user_session_user".id as "user_session_user.id", "user_session_user".name as "user_session_user.name", "user_session_user".full_name as "user_session_user.full-name", "user_session_user".email as "user_session_user.email", "user_session_user".password as "user_session_user.password", "user_session_user".use_ldap as "user_session_user.use-ldap", "user_session_user".active as "user_session_user.active", "user_session_user".is_default as "user_session_user.is-default", "user_session_user".created as "user_session_user.created", "user_session_user".last_login as "user_session_user.last-login"
FROM
"user_session"
LEFT JOIN "login_user" as user_session_user ON "user_session".user_id = "user_session_user".id
WHERE
"user_session".id = 'LgUxDpBCF3KCvEpm7PtzFTYtwvfuuYa0Ri9qPwDj3EuBWxJGxYVwObR1GKlnfaP6'
LIMIT 1
BIND: []
SQL : DELETE FROM user_session
WHERE "user_session".created < '2022-08-04T15:28:24.654978+01:00'
BIND: []
in another thread (this is just the validating the session on refresh.)
Right, finally got the original error:
SQL : SELECT
max("stats_view_refresh".refresh_time) as "data_1"
FROM
"upload"
WHERE
"upload".channel = 'MRP' AND "upload".filename = 'XT_MRP_Stock_Misalignment_20220731.csv' AND "upload".report_date = '2022-07-31'
LIMIT 1
BIND: []
Unhandled exception in code scheduled on thread 7
Unknown Error!!!
Please, copy this backtrace and open an issue on https://github.com/FCO/Red/issues/new
Driver: Red::Driver::Pg
Original error: DB::Pg::Error::FatalError.new(message => "missing FROM-clause entry for table \"stats_view_refresh\"", message-detail => Str, message-hint => Str, context => Str, type => "ERROR", type-localized => "ERROR", state => "42P01", statement-position => "15", internal-position => Str, internal-query => Str, schema => Str, table => Str, column => Str, datatype => Str, constraint => Str, source-file => "parse_relation.c", source-line => "3236", source-function => "errorMissingRTE")
Original error:
missing FROM-clause entry for table "stats_view_refresh"
in method error-check at /home/jonathan/.raku/sources/9ECF9162BB652CECE7C4EFD616D11879DA0C14A1 (DB::Pg::Database) line 117
in method prepare at /home/jonathan/.raku/sources/9ECF9162BB652CECE7C4EFD616D11879DA0C14A1 (DB::Pg::Database) line 179
in method stt-exec at /home/jonathan/devel/raku/3rdparty-modules/Red/lib/Red/Driver/Pg.pm6 (Red::Driver::Pg) line 180
in submethod TWEAK at /home/jonathan/devel/raku/3rdparty-modules/Red/lib/Red/ResultSeq/Iterator.pm6 (Red::ResultSeq::Iterator) line 16
in method iterator at /home/jonathan/devel/raku/3rdparty-modules/Red/lib/Red/ResultSeq.pm6 (Red::ResultSeq) line 102
in method Seq at /home/jonathan/devel/raku/3rdparty-modules/Red/lib/Red/ResultSeq.pm6 (Red::ResultSeq) line 109
in method do-it at /home/jonathan/devel/raku/3rdparty-modules/Red/lib/Red/ResultSeq.pm6 (Red::ResultSeq) line 115
in method head at /home/jonathan/devel/raku/3rdparty-modules/Red/lib/Red/ResultSeq.pm6 (Red::ResultSeq) line 295
in method Bool at /home/jonathan/devel/raku/3rdparty-modules/Red/lib/Red/ResultSeq.pm6 (Red::ResultSeq) line 324
in method upload-exists at /home/jonathan/working/NAP/hesabu/lib/YNAP/Hesabu/Model/Upload.rakumod (YNAP::Hesabu::Model::Upload) line 17
in method insert-from-csv at /home/jonathan/working/NAP/hesabu/lib/YNAP/Hesabu/Model/DailyMisalignment.rakumod (YNAP::Hesabu::Model::DailyMisalignment) line 35
in method insert-from-csv at /home/jonathan/working/NAP/hesabu/lib/YNAP/Hesabu/Model/DailyMisalignment.rakumod (YNAP::Hesabu::Model::DailyMisalignment) line 31
in block at /home/jonathan/working/NAP/hesabu/lib/YNAP/Hesabu/Route/Upload.rakumod (YNAP::Hesabu::Route::Upload) line 50
in block at /home/jonathan/working/NAP/hesabu/lib/YNAP/Hesabu/Route/Upload.rakumod (YNAP::Hesabu::Route::Upload) line 39
It somehow has mashed up the "select list" from the query that was being run in another thread which is:
SQL : SELECT
count('*') as "data_1"
FROM
"upload"
WHERE
"upload".uploaded > ( SELECT
max("stats_view_refresh".refresh_time) as "data_1"
FROM
"stats_view_refresh" )
LIMIT 1
Which itself was made by :
method view-needs-refreshing( --> Bool ) {
my $svr = $.model('StatsViewRefresh').^rs.max(*.refresh-time );
?$.model('Upload').^all.grep( *.uploaded > $svr ).elems;
}
The only way I can see this happening is that somehow the ResultSeq is being shared, but I can't see how.
Yeah it's also tricky to reproduce because it is very sensitive to the timings.
The application accepts a multi-file upload and in the background (having returned a 204 response,) processes each in turn, calling the upload-exists to check whether each actually needs to be processed. If the file is successfully processed a notification is sent to the client (by EventSource,) which in turn will cause the client to refresh a chart based on the data that was uploaded, which in turn causes a request to the server for the current chart data. The chart data is derived from a materialised view (it's quite a heavyweight query whose results only change when there is a new upload,) so the request for the data first checks whether the view needs refreshing (i.e. the view-needs-refreshing,) and if so executes the REFRESH MATERIALIZED VIEW before returning the data (otherwise just returning the data.)
So I think what needs to happen to trigger this is that it moves on to processing the next uploaded file while the query of view-needs-refreshing is being built so the two queries are being built (in separate threads,) at the same time.
Having typed it out like that it does occur to me that the design could be improved (that the upload triggers a refresh of the view in the background and the client is notified to redraw the chart when the refresh completes,) but I'm not sure this would remedy the problem because it would still have the timing dependency.
I'm now also hitting this with the rakudo CI bot during boot up of the application.
