Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1i0R3v-0007BH-NZ for pgsql-bugs@arkaria.postgresql.org; Wed, 21 Aug 2019 13:54:08 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1i0R3u-0005Fu-Fu for pgsql-bugs@arkaria.postgresql.org; Wed, 21 Aug 2019 13:54:06 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1i0QeB-0000TW-UD for pgsql-bugs@lists.postgresql.org; Wed, 21 Aug 2019 13:27:32 +0000 Received: from mout.web.de ([212.227.15.14]) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1i0Qe9-0002XY-1c for pgsql-bugs@lists.postgresql.org; Wed, 21 Aug 2019 13:27:31 +0000 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=web.de; s=dbaedf251592; t=1566394039; bh=wZtzjmbxT9QSU9ISfXRfQt0+oNNaLqATQe1SMsP0W54=; h=X-UI-Sender-Class:Date:In-Reply-To:References:Subject:To:CC:From; b=Cw0BsL27Vsp2wpd83FCEJJcK844G9+ce40SwV/Tv+Yu5T8w97VnAOIQJaktcsUT3i +me3PwKhUUpvlPUGIeDTSpFOB+I5PRfSgz2vWxvohSutr7zvl/iCyveKKHfYWM9bn0 Sm4hHxMkTFwN9C5yY5DRjNxZ4mzqOTEuor6w6rjU= X-UI-Sender-Class: c548c8c5-30a9-4db5-a2e7-cb6cb037b8f9 Received: from [192.168.100.225] ([195.243.192.178]) by smtp.web.de (mrweb001 [213.165.67.108]) with ESMTPSA (Nemesis) id 0Lk8Ow-1iY7VF0qJW-00c6Fc; Wed, 21 Aug 2019 15:27:19 +0200 Date: Wed, 21 Aug 2019 15:27:15 +0200 User-Agent: K-9 Mail for Android In-Reply-To: <1591F404-9363-4333-AC6C-0C85795DEC2F@web.de> References: <15967-ae7fd939200f4547@postgresql.org> <6F9C0D52-A45B-4D2E-A558-F15170301C0A@web.de> <1591F404-9363-4333-AC6C-0C85795DEC2F@web.de> MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="----3YQS3M8W4FBJ8FYGDAIVFTSOQEQLJG" Content-Transfer-Encoding: 7bit Subject: Re: BUG #15967: Sequence generation using NEXTVAL() fails on 64bit systems To: Christoph Ziegenberg ,Merlin Moncure CC: Jeff Janes ,pgsql-bugs From: Christoph Ziegenberg Message-ID: X-Provags-ID: V03:K1:o1pemUg8wOXDJJ0XOvnXSY4k4BKraxe3TAccBzH1IQXHq0kpNwa gxfurHtp7ypOqLXDrGtLgniW52EYXC60om1BVrX2fcCD2tBbbWDK5S0rMdh/gaeSbtG3WgW fxyVSgYzSPgvTDIQg9pTh+2PztNZ6liUurnOsAur6ASG7cENjss1BcE+hFW/7t0y7ugWmh2 7sg7Yhcopr6AqCz/f+CWw== X-Spam-Flag: NO X-UI-Out-Filterresults: notjunk:1;V03:K0:W33qTTKpzfA=:Z2ATFNET8fXTmlKlkhaaEe 400VH+kLIvq/8qxirWoI0zW3oCa5m+UaZJbcGWbZ0dd1wcqFhgTF3gsvXHXVMfEBoPxudnICn CzvmQFRZa6Ka7fvCda6wYwqD/BIG9HaGDUW0k+JWiac8jI07sBms1kKJ2dUkwyJ+4tExx5Afu uoT48JylsfbQf7Cu6GmaLKImCEQxrZcFWWRpKnrGtv1kNnTLQulk7owdN5xGHNJ+M6ornrD5w uV4dCk5HNct8K/vbL1GCDWxdsmstVhMhY0kT+SDpQOm+JX8oNsGJbkYfA7/t37GNYAaKfxxuq lr6GeLylJVBf+3iQ4w7pm5pzUMTtjB96HuGSFrzSbGSJf8rEOuNgiN2jMJA2vvbEYJ/wkgXDr QyMQed8iVN7eZty6Zzm45I3SdGgFtk0j9dfQoPr5iAyKRIr/vM8sKz7uZVEQKzf2/CRsqiq/A eAg9agKmJuDFuMn3ClIkOX47TZEjuwdjWZBpRb7cf+AeMKjhrw3fjEsCOCCYJrZD+dRdIlkD9 6LhZidhzlTTBeErYmHfTefi1KsHFpeRKuRconeMAb4PZegBwV4T/4mn1RORwAlaC/GvIhuJvt NBthCg+v35ONYlDHrrRsJy6sxf9hykklFrkpcGXj3OG6vHSBAolmoO70P6nx6PeOyuFuCnP6Z LuLlve1RhgCKXfqXiDSrFh4h0HacBrG7Y2E4zN2JFd9bIEOh3WB72kl7hs3tWTstARoQibEiz UZkt5y6CZw0l50hSWGbXjqNYK8JiLDXIBwohQ07DffOYjMUyjXk7SX/JHCBaaegpDQpdnFByV v/+dR54MBGcoorz8YMGMKW/+ZuF8x98Bvc+F0S3i4n7mqXnwHZGlW7Iuh3jE2u15K//lmR/kN UP1hQog9GlZMrCrVV+LcE3VO1LYnV+VkIgHY7DSsdctvH8Ai5pss9QHhE/1rsqzg/xmbNq4hp 6xw2aJdxi6bEZM9H/lBS7eLrdMo5hhtlmlv+qJYMGxBCSj32zmHBgSam8Uw93WqvbvCe7rUqD AnDkLhNi2D7UxjD0byPv1tFZaAgjgnk3r4N4ming8efW/pCPGfcHhpf1GyUf4KLyvr+zQAk65 4XPmxmANhHQU4yN3V54iYCTObVny1973vT9JNKyHFx8ZjrleUi+0puOWSmgE3TC5zrBVLLi8z tNXJk= List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk ------3YQS3M8W4FBJ8FYGDAIVFTSOQEQLJG Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable Good news: We finally found the error=2E It was a trigger on one table that updated the sequence using setval()=2E= =2E=2E Of course this cannot work and I don't know why this was added (perh= aps for a migration script?)=2E This use of setval() via the trigger was missing in the Postgres statement= log (perhaps because it was a PERFORM statement?), so we didn't find it ea= rlier=2E Sorry and thanks for your help to all=2E Christoph Am 21=2E August 2019 07:11:16 MESZ schrieb Christoph Ziegenberg : >Good idea with the replacement of the nextval function=2E This confirms, >that the problem is not an application or PHP problem=2E > >Here an extract from the logs, showing the error: > >--- > >2019-08-21 06:57:38=2E812 CEST [5824] WARNUNG:=C2=A0 Got value 2799 from >public=2Ee2_ws_log_login_seq >2019-08-21 06:57:38=2E812 CEST [5824] ZUSAMMENHANG:=C2=A0 PL/pgSQL-Funkti= on >log_nextval(text) Zeile 6 bei RAISE >2019-08-21 06:57:38=2E872 CEST [16236] WARNUNG:=C2=A0 Got value 2800 from >public=2Ee2_ws_log_login_seq >2019-08-21 06:57:38=2E872 CEST [16236] ZUSAMMENHANG:=C2=A0 PL/pgSQL-Funkt= ion >log_nextval(text) Zeile 6 bei RAISE >2019-08-21 06:57:38=2E873 CEST [1436] WARNUNG:=C2=A0 Got value 2801 from >public=2Ee2_ws_log_login_seq >2019-08-21 06:57:38=2E873 CEST [1436] ZUSAMMENHANG:=C2=A0 PL/pgSQL-Funkti= on >log_nextval(text) Zeile 6 bei RAISE >2019-08-21 06:57:38=2E910 CEST [12480] WARNUNG:=C2=A0 Got value 2801 from >public=2Ee2_ws_log_login_seq >2019-08-21 06:57:38=2E910 CEST [12480] ZUSAMMENHANG:=C2=A0 PL/pgSQL-Funkt= ion >log_nextval(text) Zeile 6 bei RAISE >2019-08-21 06:57:38=2E915 CEST [12480] FEHLER:=C2=A0 doppelter Schl=C3=83= =C2=BCsselwert >verletzt Unique-Constraint =C3=82=C2=BBp_e2_ws_log_login=C3=82=C2=AB >2019-08-21 06:57:38=2E915 CEST [12480] DETAIL:=C2=A0 Schl=C3=83=C2=BCssel >=C3=82=C2=BB(log_login_id)=3D(2801)=C3=82=C2=AB existiert bereits=2E >2019-08-21 06:57:38=2E915 CEST [12480] ANWEISUNG:=C2=A0 INSERT INTO >e2_ws_log_login (log_login_id, client_id, log_action, log_datetime, >log_ip_address, log_data) VALUES ($1, $2, $3, $4, $5, $6) >2019-08-21 06:57:39=2E031 CEST [10672] WARNUNG:=C2=A0 Got value 2802 from >public=2Ee2_ws_log_login_seq >2019-08-21 06:57:39=2E031 CEST [10672] ZUSAMMENHANG:=C2=A0 PL/pgSQL-Funkt= ion >log_nextval(text) Zeile 6 bei RAISE > >--- > >BTW: I had to change the function a little bit: > >CREATE OR REPLACE FUNCTION log_nextval(_Sequence TEXT) RETURNS BIGINT >AS >$$ >DECLARE >=C2=A0=C2=A0=C2=A0 s BIGINT; >BEGIN >=C2=A0 s :=3D nextval(_Sequence); >=C2=A0 RAISE WARNING 'Got value % from %', s, _Sequence; >=C2=A0 RETURN s; >END; >$$ LANGUAGE 'plpgsql'; > > >Christoph > > >Am 20=2E August 2019 18:06:42 MESZ schrieb Merlin Moncure >: >>On Tue, Aug 20, 2019 at 9:56 AM Christoph Ziegenberg >> wrote: >>> New info: >>> We could also reproduce it with Postgres 10=2E10 32bit on Windows >>Server 2016 and 9=2E6=2E8 64bit on Ubuntu (18=2Ex)=2E So also the 32bit >version >>is affected, as well as 9=2Ex versions=2E >> >>Ok, that makes sense; if we don't have arch specific reproduction I'd >>say that lowers the likelihood of having a serious problem within >>postgres itself (just a hunch)=2E >> >>> Current test state: >>> We (2 of my colleagues and me) are currently trying to create an >>independent test, but at the moment it only occurrs within the >specific >>application=2E >> >>This of course is key=2E Most people reading this list are going to be >>suspicious of your application rather than postgres internals causing >>the issue=2E Having said that, let's see if we can isolate the problem= =2E >> >>> Of course we search for an error in the application first, checked >>the connection settings, tracked all statements=2E=2E=2E there is nothin= g >>special, only a handful of SELECTS and UPDATES, then the sequence >>generation and the (sometimes failing) INSERT, and another INSERT (no >>sequence generate here) and UPDATE following=2E In all cases we tested >>with the Postgres default configuration=2E >> >>> We could see that wrapping the selection of NEXTVAL() in a >>transaction (which shouldn't have any effect?) reduced the problem in >>one case, but it was still possible to reproduce the error with an >>increased number of requests=2E >> >>Being in a transaction makes shouldn't make any difference with >>regards to behavior=2E >> >>> At the moment we don't have a real idea how to proceed=2E Next step >>planned is to simulate all of the aforementioned requests done by the >>application, because they seem to influence the behavior=2E >> >>Isolating in a separate test would be proof=2E Sans that, we need to be >>suspicious of your test environment=2E Hm, how about this: perhaps we >>can tease the problem out with logging=2E One possible trick is to do >>this: >>CREATE OR REPLACE FUNCTION log_nextval(_Sequence TEXT, s OUT) RETURNS >>BIGINT AS >>$$ >>BEGIN >> s :=3D nextval(_Sequence); >> RAISE WARNING 'Got value % from %', s, _Sequence; >> RETURN s; >>END; >>$$ LANGUAGE PLGSQL; >> >>Then, as an experiment, you can move all your nextval() generation to >>this function (note: there will be significant performance hit) and >>attempt to reproduce the problem in your application=2E If when you >>did, we could then interrogate the database log to see if the same >>value >1 times, this would be a smoking gun=2E If you did not see the >>value returned >1 times, maybe turn on full statement logging (also a >>big performance hit) and see where your application might be jacking >>things up=2E >> >>> Background: >>> The application is written in PHP (different versions used in the >>tests, 7=2E2 - 7=2E4 I guess), runs on Apache/IIS (FastCGI) and uses the >>PDO extension for the communication with Postgres=2E >> >>merlin ------3YQS3M8W4FBJ8FYGDAIVFTSOQEQLJG Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: quoted-printable Good news: We finally found the error=2E

It= was a trigger on one table that updated the sequence using setval()=2E=2E= =2E Of course this cannot work and I don't know why this was added (perhaps= for a migration script?)=2E

This use of setval() via the trigger wa= s missing in the Postgres statement log (perhaps because it was a PERFORM s= tatement?), so we didn't find it earlier=2E

Sorry and thanks for you= r help to all=2E

Christoph


Am = 21=2E August 2019 07:11:16 MESZ schrieb Christoph Ziegenberg <ziegenberg= @web=2Ede>:
Good idea with the replacement of the nextval function=2E This confirms, t= hat the problem is not an application or PHP problem=2E

Here an extr= act from the logs, showing the error:
2019-08-21 06:57:38=2E812 CEST [58= 24] WARNUNG:  Got value 2799 from public=2Ee2_ws_log_login_seq
2019= -08-21 06:57:38=2E812 CEST [5824] ZUSAMMENHANG:  PL/pgSQL-Funktion log= _nextval(text) Zeile 6 bei RAISE
2019-08-21 06:57:38=2E872 CEST [16236] = WARNUNG:  Got value 2800 from public=2Ee2_ws_log_login_seq
2019-08-= 21 06:57:38=2E872 CEST [16236] ZUSAMMENHANG:  PL/pgSQL-Funktion log_ne= xtval(text) Zeile 6 bei RAISE
2019-08-21 06:57:38=2E873 CEST [1436] WARN= UNG:  Got value 2801 from public=2Ee2_ws_log_login_seq
2019-08-21 0= 6:57:38=2E873 CEST [1436] ZUSAMMENHANG:  PL/pgSQL-Funktion log_nextval= (text) Zeile 6 bei RAISE
2019-08-21 06:57:38=2E910 CEST [12480] WARNUNG:=   Got value 2801 from public=2Ee2_ws_log_login_seq
2019-08-21 06:57= :38=2E910 CEST [12480] ZUSAMMENHANG:  PL/pgSQL-Funktion log_nextval(te= xt) Zeile 6 bei RAISE
2019-08-21 06:57:38=2E915 CEST [12480] FEHLER:&nbs= p; doppelter Schl=C3=83=C2=BCsselwert verletzt Unique-Constraint =C3=82=C2= =BBp_e2_ws_log_login=C3=82=C2=AB
2019-08-21 06:57:38=2E915 CEST [12480] = DETAIL:  Schl=C3=83=C2=BCssel =C3=82=C2=BB(log_login_id)=3D(2801)=C3= =82=C2=AB existiert bereits=2E
2019-08-21 06:57:38=2E915 CEST [12480] AN= WEISUNG:  INSERT INTO e2_ws_log_login (log_login_id, client_id, log_ac= tion, log_datetime, log_ip_address, log_data) VALUES ($1, $2, $3, $4, $5, $= 6)
2019-08-21 06:57:39=2E031 CEST [10672] WARNUNG:  Got value 2802 = from public=2Ee2_ws_log_login_seq
2019-08-21 06:57:39=2E031 CEST [10672]= ZUSAMMENHANG:  PL/pgSQL-Funktion log_nextval(text) Zeile 6 bei RAISE<= hr>BTW: I had to change the function a little bit:

CREATE OR REPLACE= FUNCTION log_nextval(_Sequence TEXT) RETURNS BIGINT AS
$$
DECLARE    s BIGINT;
BEGIN
  s :=3D nextval(_Sequence);=
  RAISE WARNING 'Got value % from %', s, _Sequence;
  RETU= RN s;
END;
$$ LANGUAGE 'plpgsql';


Christoph


Am 20=2E August 2019 18:06:42 MESZ schrieb Merlin M= oncure <mmoncure@gmail=2Ecom>:
On Tue, Aug 20, 2019 at 9:56 AM Christoph Ziegenberg=
 <ziegenberg@web=2Ede> wrote:
New info:
We could also reproduce it with Postgres 10=2E10 =
32bit on Windows Server 2016 and 9=2E6=2E8 64bit on Ubuntu (18=2Ex)=2E So a=
lso the 32bit version is affected, as well as 9=2Ex versions=2E

Ok, that makes sense; if we don't have arch specific reproduction =
I'd
say that lowers the likelihood of having a serious problem withinpostgres itself (just a hunch)=2E

Current test state:
We (2 of my colleagues and me) are c=
urrently trying to create an independent test, but at the moment it only oc=
currs within the specific application=2E

This of course=
 is key=2E  Most people reading this list are going to be
suspicious of =
your application rather than postgres internals causing
the issue=2E  Ha=
ving said that, let's see if we can isolate the problem=2E

Of course we search for an error in=
 the application first, checked the connection settings, tracked all statem=
ents=2E=2E=2E there is nothing special, only a handful of SELECTS and UPDAT=
ES, then the sequence generation and the (sometimes failing) INSERT, and an=
other INSERT (no sequence generate here) and UPDATE following=2E In all cas=
es we tested with the Postgres default configuration=2E
We could see that wrappin=
g the selection of NEXTVAL() in a transaction (which shouldn't have any eff=
ect?) reduced the problem in one case, but it was still possible to reprodu=
ce the error with an increased number of requests=2E

Be=
ing in a transaction makes shouldn't make any difference with
regards to=
 behavior=2E

At the=
 moment we don't have a real idea how to proceed=2E Next step planned is to=
 simulate all of the aforementioned requests done by the application, becau=
se they seem to influence the behavior=2E

Isolating in =
a separate test would be proof=2E  Sans that, we need to be
suspicious o=
f your test environment=2E  Hm, how about this: perhaps we
can tease the=
 problem out with logging=2E One possible trick is to do
this:
CREATE=
 OR REPLACE FUNCTION log_nextval(_Sequence TEXT, s OUT) RETURNS BIGINT AS$$
BEGIN
  s :=3D nextval(_Sequence);
  RAISE WARNING 'Got value=
 % from %', s, _Sequence;
  RETURN s;
END;
$$ LANGUAGE PLGSQL;
=

Then, as an experiment, you can move all your nextval() generation tothis function (note: there will be significant performance  hit) and
a=
ttempt to reproduce the problem in your application=2E  If when you
did,=
 we could then interrogate the database log to see if the same
value >=
;1 times, this would be a smoking gun=2E  If you did not see the
value r=
eturned >1 times, maybe turn on full statement logging (also a
big pe=
rformance hit) and see where your application might be  jacking
things u=
p=2E

Background:The application is written in PHP (different versions used in the tests, 7=
=2E2 - 7=2E4 I guess), runs on Apache/IIS (FastCGI) and uses the PDO extens=
ion for the communication with Postgres=2E

merlin
------3YQS3M8W4FBJ8FYGDAIVFTSOQEQLJG--