Re: Dubugging an intermittent foreign key insert error with csvlog - Mailing list pgsql-general

On 9/16/19 1:46 PM, Jeff Ross wrote:
> Hi all,
> 
> I've been debugging an intermittent foreign key insert error on our 
> single database / multi-tenant server.  To help isolate traffic by 
> tenant, I've switched to using csvlog and for the duration and have set 
> log_min_duration_statement to 0 to get *everything*.  Fortunately, daily 
> 80G csvlogs compress nicely.
> 
> For lack of a readable way to paste in the 12 lines of relevant csvlog 
> into an e-mail, I've uploaded a very small 3K csv file to my web server at
> 
>      https://openvistas.net/hansens_error.csv
> 
> The bare bones of the issue involve inserting a row into a table named 
> load_det, then getting the serial sequence of that table, getting the 
> last_value of that sequence and then inserting into another table named 
> cargo_det using that retrieved last_value as the foreign key that ties 
> this row to the load_det table.  The vast majority of these succeed 
> without issue but not all.
> 
> The csvlog snip shows what I believe are 2 simultaneous but separate 
> sessions and the session that attempts to insert into the cargo_det 
> table is not the same session that inserted into the load_det table. 
> That's what my hunch is but what is unclear to me is if those separate 
> sessions are also in separate transactions.

To me it looks like the INSERT into load_det and into cargo_det are 
occurring in the same transaction(934281062). The part that would 
concern me is that:

select last_value from load_det_id_seq

occurs in different transactions and sessions. From here:

https://www.postgresql.org/docs/11/sql-createsequence.html

"Also, last_value will reflect the latest value reserved by any session, 
whether or not it has yet been returned by nextval."

Especially as the error is coming from a different 
transaction(934281063) and session then the INSERTs. I'm guessing that 
there is cross talk on the sequence number fetch and application to 
cargo_det.

> 
> csvlog has a couple of columns that I'm unclear about: 
> session_start_time, virtual_transaction_id.  Is session_start_time the 
> time inside a transaction block, as in beginning with a begin but before 
> a commit or rollback?  Or is it maybe just how long this pgbouncer 
> session has been connected?  virtual_transaction_id is defined in the 
> docs as backendID/localXID--do separate backendIDs also represent 
> separate transactions?  Is there a better way to determine separate 
> transactions within csvlog?
> 
> Also, the app code that does this is legacy perl using DBD::Pg but the 
> original code was written for Informix.  We've been in the process of 
> moving off informix for a while now and should be done within the month. 
>   I intend to re-work this to use returning id (available in postgres 
> since 8.2!) instead of the serial sequence / last_value hack but not 
> quite there yet.
> 
> Thanks,
> 
> Jeff Ross
> 
> 


-- 
Adrian Klaver
adrian.klaver@aklaver.com