BUG #14287: psql_history gets wiped out

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

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

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

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

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

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

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

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

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

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?

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, "\qn", 3) = 3
sendto(3,
"273335220x377`200210Z255251374X335206207r21212230271206246250v4375333n"...,
34, MSG_NOSIGNAL, NULL, 0) = 34
sendto(3, "253332220x377`200210Z256361U271I
330322J26732X?352u20026725210", 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, "\qn", 3) = -1 EIO (Input/output error)
sendto(3, "273335Z35364t26322026031627225f216314250234
357~niQ254S&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/ [1] 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

Links:
------
[1]: http://apt.postgresql.org/pub/repos/apt/

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

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

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:

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

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

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,
--
Daniel Vérité
PostgreSQL-powered mailer: http://www.manitou-mail.org
Twitter: @DanielVerite

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

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: