Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1sTOSs-00FnFh-0b for pgsql-general@arkaria.postgresql.org; Mon, 15 Jul 2024 16:22:14 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.94.2) (envelope-from ) id 1sTOSq-00BHnt-5N for pgsql-general@arkaria.postgresql.org; Mon, 15 Jul 2024 16:22:12 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1sTOSp-00BHnk-P3 for pgsql-general@lists.postgresql.org; Mon, 15 Jul 2024 16:22:11 +0000 Received: from mail-oa1-x35.google.com ([2001:4860:4864:20::35]) by magus.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 (Exim 4.94.2) (envelope-from ) id 1sTOSi-002GNX-NT for pgsql-general@lists.postgresql.org; Mon, 15 Jul 2024 16:22:11 +0000 Received: by mail-oa1-x35.google.com with SMTP id 586e51a60fabf-25e3d388580so2197047fac.0 for ; Mon, 15 Jul 2024 09:22:04 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20230601; t=1721060522; x=1721665322; darn=lists.postgresql.org; h=to:subject:message-id:date:from:in-reply-to:references:mime-version :from:to:cc:subject:date:message-id:reply-to; bh=u6ffVgCtJnGpzXc4AANAcS9Sab2cehVLiYuz4tKynDY=; b=JzMIZVCK6gCECNYslZ0zY8n2EXe6FLNTVqVz7rhwibDoTT0ThQQ4umPxLeJ/N49y+y wP1HDb1DNRz9dJM/Rpd3aaJiTLok9vUcqIB6rnTYxtHXX36/xtxeNHSuzhJ2Yjv5sENA SKRGl1Fx3I6WfKIn5fWrRrg/NzoDCvYvR3KC3msIVjurOLRiy9Ujl/3WYG1OSCTq26og S6oK2TFpeARW19L8a4BKe3XFVRLQ+nvwsLSsNjHBSLMvvqJ2ikGsEjSKrdAOeW9uv7xi Ns2H9nndEobExDAIgjHVg7fB5DpQ4KX4VEQtWt6vMwevjeAlpVyo2nzfnF7NAEhwyNkp /frw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1721060522; x=1721665322; h=to:subject:message-id:date:from:in-reply-to:references:mime-version :x-gm-message-state:from:to:cc:subject:date:message-id:reply-to; bh=u6ffVgCtJnGpzXc4AANAcS9Sab2cehVLiYuz4tKynDY=; b=wwH98ZkFQPsKAV6v+TfcvW0bydbYMNaXU2qupVliA0Drj2fMI8b6DUY9ayXbYXpXP8 6N1yCl5h78NOm/oEOmDUuDtrto88zWstaoOiEadiwuxPEZZVTJfKGL9FEnDwGZFU9UGa drcIlCRh93fxcOWAZhvUr5lRpig96cXRzbeKUfnVHzgUY4CJ1eilw4wZ3M8kPcji8UCP MnLMd+HpCn+VHhLD8olNU7G+ykfi9LdaIQGVaOWbGMHW0J6nRY9BacsvXoYNKkqZ3xTi bb06yk8vtvtt6bFYueEehqQJOP7906twhhUTAbcQWMWIpcoQFKo2rLqpQYzeKlwVsx1K 7qoA== X-Gm-Message-State: AOJu0YwRBAp0mGaoEN0UNHPqYf7VWhf2VnXluOawbcOl7iKRvWwtLL+B szOa0WH4uM6BdiYPUCBsOCxEttknKBztkVyJ/HNwjqh8xw0gMJA1+Hw0icJWlvkmdtgE3QO/HSw dpfahEbCB2OHeqDIH3KX3sgvRBgN8gg== X-Google-Smtp-Source: AGHT+IFAqv6vdQta3l540WAY8qQfuakmvzgyozmdX7StX3OENUDfMDsCdtAB5K4S0b5CddfmJHBPvJ5jO87C0rfcBHM= X-Received: by 2002:a05:6870:6587:b0:25e:1ced:744 with SMTP id 586e51a60fabf-25eaebc7d95mr18115928fac.47.1721060522427; Mon, 15 Jul 2024 09:22:02 -0700 (PDT) MIME-Version: 1.0 References: <20240715143518.3v5xdfuj27ryzuzh@hjp.at> <4ff0dd59-9d7b-4a13-ad75-3627080458e1@aklaver.com> <28c88e41-36bc-4704-9c30-f81986f6cdc8@aklaver.com> In-Reply-To: <28c88e41-36bc-4704-9c30-f81986f6cdc8@aklaver.com> From: Ron Johnson Date: Mon, 15 Jul 2024 12:21:51 -0400 Message-ID: Subject: Re: How does this FK constraint error happen? To: "pgsql-generallists.postgresql.org" Content-Type: multipart/alternative; boundary="00000000000013919e061d4ba122" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --00000000000013919e061d4ba122 Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable On Mon, Jul 15, 2024 at 11:37=E2=80=AFAM Adrian Klaver wrote: > On 7/15/24 08:18, Ron Johnson wrote: > > On Mon, Jul 15, 2024 at 11:06=E2=80=AFAM Adrian Klaver > > > wrote: > > > > On 7/15/24 07:53, Ron Johnson wrote: > > > On Mon, Jul 15, 2024 at 10:35=E2=80=AFAM Peter J. Holzer > > > > > TAPd=3D# select * from rel_group_user > > > where user_id between 1100 and 1300 > > > order by user_id; > > > user_id | group_id | modified_by | modified_on > > > ---------+----------+-------------+------------------------- > > > 1133 | 2 | 1133 | 2024-07-15 08:43:35.669 > > > 1142 | 2 | 1142 | 2024-07-15 09:05:58.451 > > > 1147 | 2 | 1147 | 2024-07-15 09:30:37.169 > > > 1158 | 2 | 1158 | 2024-07-15 09:36:45.142 > > > 1197 | 2 | 1197 | 2024-07-15 09:52:58.477 > > > 1210 | 2 | 1210 | 2024-07-15 02:42:09.355 > > <<<<<<<<<<<<< > > > > Time travel? > > > > > > =F0=9F=98=9E > > > > > > 2024-07-15 02:41:15 Deleting from > > FISPTAPPGS401DA/TAPd.public.access_user > > DELETE FROM public.access_user; > > > > Or do the cron jobs take that long to execute? > > > > > > The deletes from 26*3 tables (the same 26 tables in three children) too= k > > from 02:40:02 to 02:41:47. > > Then a bunch of COPY statements run (pg_dump from the federation master= , > > then COPY to the federation children). Must be done in a specific orde= r. > > I don't think it is entirely coincidental that 1210 is the only shown > user_id with a modified_on value that is in proximity to the delete > error. I don't think so either. > My suspicion is that actions are not happening in the exact order > you think they are. modified_on is CURRENT_TIMESTAMP or NOW() or somesuch. I'm not sure, because I'm not privy to the code. But I'm printing the system time in bash before every statement. > I would think that combining DELETE FROM > rel_group_user; and DELETE FROM public.access_user; in a single > transaction would be a good start to fixing this. > That is in fact what I'm working on now. There are 26 tables, and they must be done in a specific order when deleting, and the reverse while inserting. postgres_fdw would make this easier... > > > > How is modified_on created? > > > > > > It's updated by the application. > > At what point in the process? > > > > > > 1229 | 2 | 1229 | 2024-07-15 08:33:48.443 > > > 1242 | 2 | 1242 | 2024-07-15 10:29:51.176 > > > 1260 | 2 | 1260 | 2024-07-15 07:36:21.182 > > > 1283 | 2 | 1283 | 2024-07-15 09:48:25.214 > > > 1288 | 2 | 1288 | 2024-07-15 08:10:33.609 > > > (11 rows) > > > > > > TAPd=3D# select user_id, login_id, created_on, modified_on > > > TAPd-# from public.access_user > > > TAPd-# where user_id =3D 1210; > > > user_id | login_id | created_on | > modified_on > > > > > > ---------+------------+-------------------------+-----------------------= -- > > > 1210 | JORIEUSER3 | 2023-10-20 11:54:24.562 | 2024-07-15 > > 02:42:09.355 > > > (1 row) > > > > -- > > Adrian Klaver > > adrian.klaver@aklaver.com > > > > -- > Adrian Klaver > adrian.klaver@aklaver.com > > --00000000000013919e061d4ba122 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
On Mon, Jul 15, 2024 at 11:37=E2=80=AFAM = Adrian Klaver <adrian.klave= r@aklaver.com> wrote:
On 7/15/24 08:18, Ron Johnson wrote= :
> On Mon, Jul 15, 2024 at 11:06=E2=80=AFAM Adrian Klaver
> <adr= ian.klaver@aklaver.com <mailto:adrian.klaver@aklaver.com>> wrote:
>
>=C2=A0 =C2=A0 =C2=A0On 7/15/24 07:53, Ron Johnson wrote:
>=C2=A0 =C2=A0 =C2=A0 > On Mon, Jul 15, 2024 at 10:35=E2=80=AFAM Pete= r J. Holzer


>=C2=A0 =C2=A0 =C2=A0 > TAPd=3D# select * from rel_group_user
>=C2=A0 =C2=A0 =C2=A0 > where user_id between 1100 and 1300
>=C2=A0 =C2=A0 =C2=A0 > order by user_id;
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0user_id | group_id | modified_by = | =C2=A0 =C2=A0 =C2=A0 modified_on
>=C2=A0 =C2=A0 =C2=A0 > ---------+----------+-------------+----------= ---------------
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 1133 | =C2=A0 =C2=A0 =C2= =A0 =C2=A02 | =C2=A0 =C2=A0 =C2=A0 =C2=A01133 | 2024-07-15 08:43:35.669
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 1142 | =C2=A0 =C2=A0 =C2= =A0 =C2=A02 | =C2=A0 =C2=A0 =C2=A0 =C2=A01142 | 2024-07-15 09:05:58.451
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 1147 | =C2=A0 =C2=A0 =C2= =A0 =C2=A02 | =C2=A0 =C2=A0 =C2=A0 =C2=A01147 | 2024-07-15 09:30:37.169
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 1158 | =C2=A0 =C2=A0 =C2= =A0 =C2=A02 | =C2=A0 =C2=A0 =C2=A0 =C2=A01158 | 2024-07-15 09:36:45.142
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 1197 | =C2=A0 =C2=A0 =C2= =A0 =C2=A02 | =C2=A0 =C2=A0 =C2=A0 =C2=A01197 | 2024-07-15 09:52:58.477
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 1210 | =C2=A0 =C2=A0 =C2= =A0 =C2=A02 | =C2=A0 =C2=A0 =C2=A0 =C2=A01210 | 2024-07-15 02:42:09.355 >=C2=A0 =C2=A0 =C2=A0<<<<<<<<<<<<<= ;
>
>=C2=A0 =C2=A0 =C2=A0Time travel?
>
>
> =F0=9F=98=9E
>
>
>=C2=A0 =C2=A0 =C2=A02024-07-15 02:41:15 Deleting from
>=C2=A0 =C2=A0 =C2=A0FISPTAPPGS401DA/TAPd.public.access_user
>=C2=A0 =C2=A0 =C2=A0DELETE FROM public.access_user;
>
>=C2=A0 =C2=A0 =C2=A0Or do the cron jobs take that long to execute?
>
>
> The deletes from 26*3 tables (the same 26 tables in three children) to= ok
> from 02:40:02 to 02:41:47.
> Then a bunch of COPY statements run (pg_dump from the federation maste= r,
> then COPY to the federation children).=C2=A0 Must be done in a specifi= c order.

I don't think it is entirely coincidental that 1210 is the only shown <= br> user_id with a modified_on value that is in proximity to the delete
error.

I don't think so either.
=C2=A0
My suspic= ion is that actions are not happening in the exact order
you think they are.

modified_on is CURRENT_= TIMESTAMP or NOW() or somesuch.=C2=A0 I'm not sure, because I'm not= privy to the code.

But I'm printing the syste= m time in bash before=C2=A0every statement.
=C2=A0
I would think that combining DELE= TE FROM
rel_group_user; and DELETE FROM public.access_user; in a single
transaction would be a good start to fixing this.

=
That is in fact what I'm working on now.=C2=A0 There are 26 = tables, and they must be done in a specific order when deleting, and the re= verse while inserting.

postgres_fdw would make thi= s easier...
=C2=A0
>
>=C2=A0 =C2=A0 =C2=A0How is modified_on created?
>
>
> It's updated by the application.

At what point in the process?

>
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 1229 | =C2=A0 =C2=A0 =C2= =A0 =C2=A02 | =C2=A0 =C2=A0 =C2=A0 =C2=A01229 | 2024-07-15 08:33:48.443
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 1242 | =C2=A0 =C2=A0 =C2= =A0 =C2=A02 | =C2=A0 =C2=A0 =C2=A0 =C2=A01242 | 2024-07-15 10:29:51.176
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 1260 | =C2=A0 =C2=A0 =C2= =A0 =C2=A02 | =C2=A0 =C2=A0 =C2=A0 =C2=A01260 | 2024-07-15 07:36:21.182
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 1283 | =C2=A0 =C2=A0 =C2= =A0 =C2=A02 | =C2=A0 =C2=A0 =C2=A0 =C2=A01283 | 2024-07-15 09:48:25.214
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 1288 | =C2=A0 =C2=A0 =C2= =A0 =C2=A02 | =C2=A0 =C2=A0 =C2=A0 =C2=A01288 | 2024-07-15 08:10:33.609
>=C2=A0 =C2=A0 =C2=A0 > (11 rows)
>=C2=A0 =C2=A0 =C2=A0 >
>=C2=A0 =C2=A0 =C2=A0 > TAPd=3D# select user_id, login_id, created_on= , modified_on
>=C2=A0 =C2=A0 =C2=A0 > TAPd-# from public.access_user
>=C2=A0 =C2=A0 =C2=A0 > TAPd-# where user_id =3D 1210;
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0user_id | =C2=A0login_id =C2=A0| = =C2=A0 =C2=A0 =C2=A0 created_on =C2=A0 =C2=A0 =C2=A0 =C2=A0| =C2=A0 =C2=A0 = =C2=A0 modified_on
>=C2=A0 =C2=A0 =C2=A0 >
>=C2=A0 =C2=A0 =C2=A0---------+------------+-------------------------+--= -----------------------
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 1210 | JORIEUSER3 | 2023-= 10-20 11:54:24.562 | 2024-07-15
>=C2=A0 =C2=A0 =C2=A002:42:09.355
>=C2=A0 =C2=A0 =C2=A0 > (1 row)
>
>=C2=A0 =C2=A0 =C2=A0--
>=C2=A0 =C2=A0 =C2=A0Adrian Klaver
>=C2=A0 =C2=A0 =C2=A0adrian.klaver@aklaver.com <mailto:adrian.klaver@aklaver.com><= br> >

--
Adrian Klaver
adrian.klave= r@aklaver.com

--00000000000013919e061d4ba122--