Skip to content
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.

Sign up for GitHub

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

Jump to bottom

Possible concurrency issue in query construction #554

Open
jonathanstowe opened this issue Aug 5, 2022 · 6 comments
Open

Possible concurrency issue in query construction #554

jonathanstowe opened this issue Aug 5, 2022 · 6 comments

Comments

@jonathanstowe
Copy link
Contributor

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.
@jonathanstowe
Copy link
Contributor Author

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.)

@jonathanstowe
Copy link
Contributor Author

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.

@FCO
Copy link
Owner

FCO commented Aug 5, 2022

Thanks... I'll also try to find that out... but it will be hard...

@jonathanstowe
Copy link
Contributor Author

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.

@patrickbkr
Copy link
Contributor

I'm now also hitting this with the rakudo CI bot during boot up of the application.

@FCO
Copy link
Owner

FCO commented Jun 23, 2023

Could you share a snippet where we could see that happening?

Thanks

FCO added a commit that referenced this issue Oct 15, 2023
@FCO
Make as-sub-select and as-select return a new select, maybe related to …
fbe7d5a 
…#554?
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@FCO @jonathanstowe @patrickbkr