Thread: BUG #14287: psql_history gets wiped out

BUG #14287: psql_history gets wiped out

From
rotten@windfish.net
Date:
VGhlIGZvbGxvd2luZyBidWcgaGFzIGJlZW4gbG9nZ2VkIG9uIHRoZSB3ZWJz
aXRlOgoKQnVnIHJlZmVyZW5jZTogICAgICAxNDI4NwpMb2dnZWQgYnk6ICAg
ICAgICAgIFJpY2sgT3R0ZW4KRW1haWwgYWRkcmVzczogICAgICByb3R0ZW5A
d2luZGZpc2gubmV0ClBvc3RncmVTUUwgdmVyc2lvbjogOS41LjMKT3BlcmF0
aW5nIHN5c3RlbTogICBVYnVudHUgMTQuMDQKRGVzY3JpcHRpb246ICAgICAg
ICAKCkkgYmVsaWV2ZSB0aGlzIGJlaGF2aW9yIGlzIG5ldyB0byB0aGUgOS41
LjMgcHNxbCBjbGllbnQuICBJdCBoYXMgYmVlbgpidWdnaW5nIG1lIGV2ZXIg
c2luY2Ugd2UgcGF0Y2hlZCB0byB0aGF0IHJlbGVhc2UuDQoNClRoZSBwc3Fs
X2hpc3RvcnkgZmlsZSB3b3JrcyBmaW5lIHVubGVzcyB5b3UgY2xvc2UgeW91
ciB3aW5kb3cgd2l0aG91dApleGl0aW5nIHRoZSBwc3FsIHNoZWxsLiAgSWYg
eW91IGp1c3QgZHJvcCB5b3VyIHdpbmRvdyAoYW5kIGNvcnJlc3BvbmRpbmcg
c3NoCnNlc3Npb24pLCB0aGUgZW50aXJlIHBzcWxfaGlzdG9yeSBmaWxlIHdp
bGwgZ2V0IHdpcGVkIG91dC4gKGZpbGUgc2l6ZSAwKQ0KDQpUaGlzIHRvb2sg
bWUgcXVpdGUgYSB3aGlsZSB0byBmaWd1cmUgb3V0LiAgTXkgaGlzdG9yeSB3
b3VsZCBiZSB0aGVyZQpzb21ldGltZXMgd2hlbiBJIGNhbWUgYmFjaywgYW5k
IG90aGVyIHRpbWVzIGl0IHdvdWxkIGJlIHdpcGVkIG91dC4gIEF0IGZpcnN0
CkkgdGhvdWdodCBJIGhhZCBhIGhhY2tlciB0cnlpbmcgdG8gaGlkZSB0aGVp
ciB0cmFja3MuICBBZnRlciBzb21lIHJlc2VhcmNoIEkKY29uY2x1ZGVkIHRo
YXQgd2FzIG5vdCB0aGUgY2FzZS4NCg0KSXQgd2FzIGEgY29sbGVhZ3VlIHdo
b20gSSBvYnNlcnZlZCBjbG9zaW5nIHRoZWlyIHB1dHR5IHdpbmRvdyB3aXRo
b3V0IGZpcnN0CmV4aXRpbmcgdGhlIHBzcWwgc2hlbGwgdGhpcyBtb3JuaW5n
IHRoYXQgZmluYWxseSByZXZlYWxlZCBob3cgaXQgd2FzCmhhcHBlbmluZy4N
Cg0KSXQgaXMgcmVwcm9kdWNpYmxlIGluIG91ciBlbnZpcm9ubWVudC4NCg0K
DQoKCg==

Re: BUG #14287: psql_history gets wiped out

From
Alvaro Herrera
Date:
rotten@windfish.net wrote:
> The following bug has been logged on the website:
>
> Bug reference:      14287
> Logged by:          Rick Otten
> Email address:      rotten@windfish.net
> PostgreSQL version: 9.5.3
> Operating system:   Ubuntu 14.04
> Description:
>
> I believe this behavior is new to the 9.5.3 psql client.  It has been
> bugging me ever since we patched to that release.

Do you mean that it worked fine in 9.5.2?  Or do you mean that it worked
fine in 9.4.x?  Or do you mean something different?

--
Álvaro Herrera                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Re: BUG #14287: psql_history gets wiped out

From
Tom Lane
Date:
Alvaro Herrera <alvherre@2ndquadrant.com> writes:
> rotten@windfish.net wrote:
>> I believe this behavior is new to the 9.5.3 psql client.  It has been
>> bugging me ever since we patched to that release.

> Do you mean that it worked fine in 9.5.2?  Or do you mean that it worked
> fine in 9.4.x?  Or do you mean something different?

Some digging in our git history says that we haven't changed anything
about how we write the history file since 2009.  If Rick has seen a
recent behavioral change, I'd wonder more about whether libreadline
changed, or maybe he switched his build between libreadline and libedit.

            regards, tom lane

Re: BUG #14287: psql_history gets wiped out

From
Rick Otten
Date:

I usually patch Ubuntu at the same time I'm patching PostgreSQL, so as far as I can tell at this time, either is possible - the repo could have switched which library it was using, or ubuntu could have bumped a libedit release.

I'm sure I've had sessions die due to network problems or laptop problems in the past and not had my psql_history file wiped out, so even if my colleague's usage pattern was a new thing, I'm pretty sure I would have noticed this before.

 

I'm using the repo:

     deb http://apt.postgresql.org/pub/repos/apt/ trusty-pgdg main 9.5

 

That repo version is using libedit, not libreadline:

postgresql/9.5/bin $ ldd psql
linux-vdso.so.1 => (0x00007ffe933af000)
libpq.so.5 => /usr/lib/x86_64-linux-gnu/libpq.so.5 (0x00007f1fed6d6000)
libedit.so.2 => /usr/lib/x86_64-linux-gnu/libedit.so.2 (0x00007f1fed4a6000)
libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007f1fed1a0000)
libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007f1fecddb000)
libssl.so.1.0.0 => /lib/x86_64-linux-gnu/libssl.so.1.0.0 (0x00007f1fecb7c000)
libcrypto.so.1.0.0 => /lib/x86_64-linux-gnu/libcrypto.so.1.0.0 (0x00007f1fec7a0000)
libgssapi_krb5.so.2 => /usr/lib/x86_64-linux-gnu/libgssapi_krb5.so.2 (0x00007f1fec559000)
libldap_r-2.4.so.2 => /usr/lib/x86_64-linux-gnu/libldap_r-2.4.so.2 (0x00007f1fec308000)
libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007f1fec0ea000)
libtinfo.so.5 => /lib/x86_64-linux-gnu/libtinfo.so.5 (0x00007f1febec1000)
/lib64/ld-linux-x86-64.so.2 (0x00007f1fedb90000)
libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007f1febcbd000)
libkrb5.so.3 => /usr/lib/x86_64-linux-gnu/libkrb5.so.3 (0x00007f1feb9f2000)
libk5crypto.so.3 => /usr/lib/x86_64-linux-gnu/libk5crypto.so.3 (0x00007f1feb7c3000)
libcom_err.so.2 => /lib/x86_64-linux-gnu/libcom_err.so.2 (0x00007f1feb5bf000)
libkrb5support.so.0 => /usr/lib/x86_64-linux-gnu/libkrb5support.so.0 (0x00007f1feb3b4000)
liblber-2.4.so.2 => /usr/lib/x86_64-linux-gnu/liblber-2.4.so.2 (0x00007f1feb1a5000)
libresolv.so.2 => /lib/x86_64-linux-gnu/libresolv.so.2 (0x00007f1feaf8a000)
libsasl2.so.2 => /usr/lib/x86_64-linux-gnu/libsasl2.so.2 (0x00007f1fead6f000)
libgssapi.so.3 => /usr/lib/x86_64-linux-gnu/libgssapi.so.3 (0x00007f1feab31000)
libgnutls.so.26 => /usr/lib/x86_64-linux-gnu/libgnutls.so.26 (0x00007f1fea873000)
libgcrypt.so.11 => /lib/x86_64-linux-gnu/libgcrypt.so.11 (0x00007f1fea5f3000)
libkeyutils.so.1 => /lib/x86_64-linux-gnu/libkeyutils.so.1 (0x00007f1fea3ef000)
libheimntlm.so.0 => /usr/lib/x86_64-linux-gnu/libheimntlm.so.0 (0x00007f1fea1e6000)
libkrb5.so.26 => /usr/lib/x86_64-linux-gnu/libkrb5.so.26 (0x00007f1fe9f5e000)
libasn1.so.8 => /usr/lib/x86_64-linux-gnu/libasn1.so.8 (0x00007f1fe9cbd000)
libhcrypto.so.4 => /usr/lib/x86_64-linux-gnu/libhcrypto.so.4 (0x00007f1fe9a8a000)
libroken.so.18 => /usr/lib/x86_64-linux-gnu/libroken.so.18 (0x00007f1fe9875000)
libz.so.1 => /lib/x86_64-linux-gnu/libz.so.1 (0x00007f1fe965c000)
libtasn1.so.6 => /usr/lib/x86_64-linux-gnu/libtasn1.so.6 (0x00007f1fe9448000)
libp11-kit.so.0 => /usr/lib/x86_64-linux-gnu/libp11-kit.so.0 (0x00007f1fe9206000)
libgpg-error.so.0 => /lib/x86_64-linux-gnu/libgpg-error.so.0 (0x00007f1fe9001000)
libwind.so.0 => /usr/lib/x86_64-linux-gnu/libwind.so.0 (0x00007f1fe8dd8000)
libheimbase.so.1 => /usr/lib/x86_64-linux-gnu/libheimbase.so.1 (0x00007f1fe8bca000)
libhx509.so.5 => /usr/lib/x86_64-linux-gnu/libhx509.so.5 (0x00007f1fe8981000)
libsqlite3.so.0 => /usr/lib/x86_64-linux-gnu/libsqlite3.so.0 (0x00007f1fe86c8000)
libcrypt.so.1 => /lib/x86_64-linux-gnu/libcrypt.so.1 (0x00007f1fe848f000)
libffi.so.6 => /usr/lib/x86_64-linux-gnu/libffi.so.6 (0x00007f1fe8287000)

$ dpkg -l | grep libedit
ii libedit2:amd64 3.1-20130712-2 amd64 BSD editline and history libraries

$ dpkg -s libedit2
Package: libedit2
Status: install ok installed
Priority: standard
Section: libs
Installed-Size: 236
Maintainer: Ubuntu Developers <ubuntu-devel-discuss@lists.ubuntu.com>
Architecture: amd64
Multi-Arch: same
Source: libedit
Version: 3.1-20130712-2
Depends: libc6 (>= 2.17), libtinfo5
Pre-Depends: multiarch-support
Description: BSD editline and history libraries
Command line editor library provides generic line editing,
history, and tokenization functions.
.
It slightly resembles GNU readline
Original-Maintainer: LLVM Packaging Team <pkg-llvm-team@lists.alioth.debian.org>
Homepage: http://www.thrysoee.dk/editline/

 

 

 

On 2016-08-11 14:55, Tom Lane wrote:

Alvaro Herrera <alvherre@2ndquadrant.com> writes:
rotten@windfish.net wrote:
I believe this behavior is new to the 9.5.3 psql client. It has been bugging me ever since we patched to that release.
Do you mean that it worked fine in 9.5.2? Or do you mean that it worked fine in 9.4.x? Or do you mean something different?
Some digging in our git history says that we haven't changed anything
about how we write the history file since 2009.  If Rick has seen a
recent behavioral change, I'd wonder more about whether libreadline
changed, or maybe he switched his build between libreadline and libedit.
		regards, tom lane

 

Re: BUG #14287: psql_history gets wiped out

From
Tom Lane
Date:
Rick Otten <rotten@windfish.net> writes:
> I'm using the repo:
>  deb http://apt.postgresql.org/pub/repos/apt/ trusty-pgdg main 9.5
> That repo version is using _libedit_, not _libreadline_:

Hmm.  Our general experience is that libedit is buggier than libreadline,
but I've not heard of this particular symptom before.  It might be
entertaining to see if you can strace psql while it's doing this.
Something like

    strace -o some.file psql ... usual parameters ...
    ... issue a command or two just to be sure there's history to write
    ... close window

and then look at the last few dozen lines of some.file.

            regards, tom lane



Re: BUG #14287: psql_history gets wiped out

From
Peter Eisentraut
Date:
On 8/11/16 4:52 PM, Rick Otten wrote:
> That repo version is using /libedit/, not /libreadline/:

But if you have readline installed, it will load it at run time.  Do you
have readline installed?  Did you accidentally uninstall it when
upgrading the OS?

--
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Re: BUG #14287: psql_history gets wiped out

From
Rick Otten
Date:

I think I have readline installed on the system:

$ dpkg -l | grep readline
ii libreadline5:amd64 5.2+dfsg-2 amd64 GNU readline and history libraries, run-time libraries
ii libreadline6:amd64 6.3-4ubuntu2 amd64 GNU readline and history libraries, run-time libraries
ii readline-common

 

On 2016-08-12 08:37, Peter Eisentraut wrote:

On 8/11/16 4:52 PM, Rick Otten wrote:

That repo version is using /libedit/, not /libreadline/:

But if you have readline installed, it will load it at run time.  Do you
have readline installed?  Did you accidentally uninstall it when
upgrading the OS?

 

 

Re: BUG #14287: psql_history gets wiped out

From
Rick Otten
Date:

Here is what the last few lines of the strace look like during a normal exit:

rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
write(1, "\\q\n", 3) = 3
sendto(3, "\27\3\3\0\35\220x\377`\200\210Z\255\251\374X\335\206\207\r\21\212\230\271\206\246\250\v\4\375\333\n"..., 34, MSG_NOSIGNAL, NULL, 0) = 34
sendto(3, "\25\3\3\0\32\220x\377`\200\210Z\256\361U\271I \330\322J\267\32X?\352u\200\267\252\10", 31, MSG_NOSIGNAL, NULL, 0) = 31
close(3) = 0
rt_sigaction(SIGPIPE, {SIG_DFL, [], SA_RESTORER|SA_RESTART, 0x7f263ea4ccb0}, {SIG_DFL, [], SA_RESTORER|SA_RESTART, 0x7f263ea4ccb0}, 8) = 0
open("/postgresql/.psql_history", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
fchmod(3, 0600) = 0
fstat(3, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f263f9e4000
open("/usr/lib/x86_64-linux-gnu/gconv/gconv-modules.cache", O_RDONLY) = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=26258, ...}) = 0
mmap(NULL, 26258, PROT_READ, MAP_SHARED, 4, 0) = 0x7f263f9dd000
close(4) = 0
futex(0x7f263edd5a70, FUTEX_WAKE_PRIVATE, 2147483647) = 0
write(3, "_HiStOrY_V2_\nselect\\040*\\040from"..., 663) = 663
close(3) = 0
munmap(0x7f263f9e4000, 4096) = 0
exit_group(0) = ?
+++ exited with 0 +++

 

And here is what the last few lines of the strace look like when I close the (ssh terminal) window:

 

read(0, 0x7ffd1140ff30, 1) = -1 EIO (Input/output error)
ioctl(0, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7ffd1140ff00) = -1 EIO (Input/output error)
ioctl(0, SNDCTL_TMR_STOP or SNDRV_TIMER_IOCTL_GINFO or TCSETSW, {B38400 opost isig icanon echo ...}) = -1 EIO (Input/output error)
rt_sigprocmask(SIG_BLOCK, [HUP INT QUIT TERM CONT TSTP WINCH], [], 8) = 0
rt_sigaction(SIGINT, {0x7fb2dbc68920, [], SA_RESTORER|SA_RESTART, 0x7fb2daf38cb0}, NULL, 8) = 0
rt_sigaction(SIGTSTP, {SIG_DFL, [], SA_RESTORER, 0x7fb2daf38cb0}, NULL, 8) = 0
rt_sigaction(SIGQUIT, {SIG_DFL, [], SA_RESTORER, 0x7fb2daf38cb0}, NULL, 8) = 0
rt_sigaction(SIGHUP, {SIG_DFL, [], SA_RESTORER, 0x7fb2daf38cb0}, NULL, 8) = 0
rt_sigaction(SIGTERM, {SIG_DFL, [], SA_RESTORER, 0x7fb2daf38cb0}, NULL, 8) = 0
rt_sigaction(SIGCONT, {SIG_DFL, [], SA_RESTORER, 0x7fb2daf38cb0}, NULL, 8) = 0
rt_sigaction(SIGWINCH, {SIG_DFL, [], SA_RESTORER, 0x7fb2daf38cb0}, NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
write(1, "\\q\n", 3) = -1 EIO (Input/output error)
sendto(3, "\27\3\3\0\35Z\35\364\t\263\220\260\316\272\25f\216\314\250\234 \357~niQ\254S&\255gl"..., 34, MSG_NOSIGNAL, NULL, 0) = 34
--- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=95075, si_uid=5432} ---
+++ killed by SIGHUP +++

 

I can send the full strace outputs if someone really wants them.

 

 

On 2016-08-11 17:15, Tom Lane wrote:

Rick Otten <rotten@windfish.net> writes:
I'm using the repo: deb http://apt.postgresql.org/pub/repos/apt/ trusty-pgdg main 9.5 That repo version is using _libedit_, not _libreadline_:
Hmm.  Our general experience is that libedit is buggier than libreadline,
but I've not heard of this particular symptom before.  It might be
entertaining to see if you can strace psql while it's doing this.
Something like
   strace -o some.file psql ... usual parameters ...   ... issue a command or two just to be sure there's history to write   ... close window

and then look at the last few dozen lines of some.file.
		regards, tom lane

 

Re: BUG #14287: psql_history gets wiped out

From
Tom Lane
Date:
Rick Otten <rotten@windfish.net> writes:
> And here is what the last few lines of the strace look like when I close
> the (ssh terminal) window:

> --- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=95075, si_uid=5432}
> ---
> +++ killed by SIGHUP +++

So the issue seems to be that psql is getting killed by SIGHUP before
it can write the history file (in this example), or in the midst of
writing the history file (in your problem cases), depending on timing.

The weird thing here is that psql is able to see EOF on stdin and
begin taking actions in response to that before SIGHUP arrives.
I'm not sure if that's expected or not.  That seems like a deliberately
created race condition, which is seldom a good idea.

Anyway it seems like your behavioral change must boil down to a timing
change in either the kernel or sshd.  There's nothing in psql that changed
in this area, and probably not in libedit either.

We could maybe try to prevent this by blocking signals while writing the
history file, but I'm not exactly convinced that would be a good idea.
It's probably be better to pester kernel & sshd people about whether
they changed anything here.

            regards, tom lane



Re: BUG #14287: psql_history gets wiped out

From
Rick Otten
Date:

Wouldn't it be better to write the commands to the history file as you go instead of at the end of the session?

At most you would only need to close the file pointer when you tear down instead of having to flush the command history (which may be hundreds of queries).

 

On 2016-08-12 10:50, Tom Lane wrote:

Rick Otten <rotten@windfish.net> writes:
And here is what the last few lines of the strace look like when I close the (ssh terminal) window:
--- SIGHUP {si_signo=SIGHUP, si_code=SI_USER, si_pid=95075, si_uid=5432} --- +++ killed by SIGHUP +++
So the issue seems to be that psql is getting killed by SIGHUP before
it can write the history file (in this example), or in the midst of
writing the history file (in your problem cases), depending on timing.

The weird thing here is that psql is able to see EOF on stdin and
begin taking actions in response to that before SIGHUP arrives.
I'm not sure if that's expected or not.  That seems like a deliberately
created race condition, which is seldom a good idea.

Anyway it seems like your behavioral change must boil down to a timing
change in either the kernel or sshd.  There's nothing in psql that changed
in this area, and probably not in libedit either.

We could maybe try to prevent this by blocking signals while writing the
history file, but I'm not exactly convinced that would be a good idea.
It's probably be better to pester kernel & sshd people about whether
they changed anything here.
		regards, tom lane

 

Re: BUG #14287: psql_history gets wiped out

From
Tom Lane
Date:
Rick Otten <rotten@windfish.net> writes:
> Wouldn't it be better to write the commands to the history file as you
> go instead of at the end of the session?

No, I wouldn't think so.  That just means you have windows for failure all
the time rather than only at session end.  Keep in mind that the write is
seldom just an append, since the history length is supposed to be bounded.

> At most you would only need to close the file pointer when you tear down
> instead of having to flush the command history (which may be hundreds of
> queries).

The APIs that libreadline and libedit provide for this do not look
anything like what you're assuming here.

            regards, tom lane



Re: BUG #14287: psql_history gets wiped out

From
"Daniel Verite"
Date:
Rick Otten wrote:

>  think I have readline installed on the system:=20
>=20
> $ dpkg -l | grep readline
> ii libreadline5:amd64 5.2+dfsg-2 amd64 GNU readline and history
> libraries, run-time libraries
> ii libreadline6:amd64 6.3-4ubuntu2 amd64 GNU readline and history
> libraries, run-time libraries
> ii readline-common=20

According to the strace output, the replacement of libedit
by libreadline at runtime does not happen in your case
(the "_HiStOrY_V2_" string is from libedit).

This replacement is done by pg_wrapper, a Perl script to which
/usr/bin/psql is normally linked:
$ ls -l /usr/bin/psql
/usr/bin/psql -> ../share/postgresql-common/pg_wrapper
The script pushes libreadline over libedit through LD_PRELOAD, and
launches the actual binary located in=20
/usr/lib/postgresql/X.Y/bin/psql (where X.Y is the current cluster's
PG version).

You may want to check if that script is not entirely sidestepped in
your setup, as that would explain why libedit gets used. For instance,
a modified PATH or psql being a shell alias could lead to that.

Aside from the bug resulting in an empty file, libedit
will ignore readline's history and remove it from the file
when saving, which is annoying by itself if using it by accident.

Best regards,
--=20
Daniel V=E9rit=E9
PostgreSQL-powered mailer: http://www.manitou-mail.org
Twitter: @DanielVerite

Re: BUG #14287: psql_history gets wiped out

From
Rick Otten
Date:

Aha.  Indeed my path was going straight to the psql binary without passing through the /usr/bin/psql perl wrapper.

Even when I use the wrapper, I was still able to reproduce wiping out my .psql_history file by closing the window before exiting psql.

 

On 2016-08-12 12:21, Daniel Verite wrote:

	Rick Otten wrote:
think I have readline installed on the system: $ dpkg -l | grep readline ii libreadline5:amd64 5.2+dfsg-2 amd64 GNU readline and history libraries, run-time libraries ii libreadline6:amd64 6.3-4ubuntu2 amd64 GNU readline and history libraries, run-time libraries ii readline-common
According to the strace output, the replacement of libedit
by libreadline at runtime does not happen in your case
(the "_HiStOrY_V2_" string is from libedit).

This replacement is done by pg_wrapper, a Perl script to which
/usr/bin/psql is normally linked:
$ ls -l /usr/bin/psql
/usr/bin/psql -> ../share/postgresql-common/pg_wrapper
The script pushes libreadline over libedit through LD_PRELOAD, and
launches the actual binary located in 
/usr/lib/postgresql/X.Y/bin/psql (where X.Y is the current cluster's
PG version).

You may want to check if that script is not entirely sidestepped in
your setup, as that would explain why libedit gets used. For instance,
a modified PATH or psql being a shell alias could lead to that.

Aside from the bug resulting in an empty file, libedit
will ignore readline's history and remove it from the file
when saving, which is annoying by itself if using it by accident.

Best regards,