Thread: BUG #14287: psql_history gets wiped out
VGhlIGZvbGxvd2luZyBidWcgaGFzIGJlZW4gbG9nZ2VkIG9uIHRoZSB3ZWJz aXRlOgoKQnVnIHJlZmVyZW5jZTogICAgICAxNDI4NwpMb2dnZWQgYnk6ICAg ICAgICAgIFJpY2sgT3R0ZW4KRW1haWwgYWRkcmVzczogICAgICByb3R0ZW5A d2luZGZpc2gubmV0ClBvc3RncmVTUUwgdmVyc2lvbjogOS41LjMKT3BlcmF0 aW5nIHN5c3RlbTogICBVYnVudHUgMTQuMDQKRGVzY3JpcHRpb246ICAgICAg ICAKCkkgYmVsaWV2ZSB0aGlzIGJlaGF2aW9yIGlzIG5ldyB0byB0aGUgOS41 LjMgcHNxbCBjbGllbnQuICBJdCBoYXMgYmVlbgpidWdnaW5nIG1lIGV2ZXIg c2luY2Ugd2UgcGF0Y2hlZCB0byB0aGF0IHJlbGVhc2UuDQoNClRoZSBwc3Fs X2hpc3RvcnkgZmlsZSB3b3JrcyBmaW5lIHVubGVzcyB5b3UgY2xvc2UgeW91 ciB3aW5kb3cgd2l0aG91dApleGl0aW5nIHRoZSBwc3FsIHNoZWxsLiAgSWYg eW91IGp1c3QgZHJvcCB5b3VyIHdpbmRvdyAoYW5kIGNvcnJlc3BvbmRpbmcg c3NoCnNlc3Npb24pLCB0aGUgZW50aXJlIHBzcWxfaGlzdG9yeSBmaWxlIHdp bGwgZ2V0IHdpcGVkIG91dC4gKGZpbGUgc2l6ZSAwKQ0KDQpUaGlzIHRvb2sg bWUgcXVpdGUgYSB3aGlsZSB0byBmaWd1cmUgb3V0LiAgTXkgaGlzdG9yeSB3 b3VsZCBiZSB0aGVyZQpzb21ldGltZXMgd2hlbiBJIGNhbWUgYmFjaywgYW5k IG90aGVyIHRpbWVzIGl0IHdvdWxkIGJlIHdpcGVkIG91dC4gIEF0IGZpcnN0 CkkgdGhvdWdodCBJIGhhZCBhIGhhY2tlciB0cnlpbmcgdG8gaGlkZSB0aGVp ciB0cmFja3MuICBBZnRlciBzb21lIHJlc2VhcmNoIEkKY29uY2x1ZGVkIHRo YXQgd2FzIG5vdCB0aGUgY2FzZS4NCg0KSXQgd2FzIGEgY29sbGVhZ3VlIHdo b20gSSBvYnNlcnZlZCBjbG9zaW5nIHRoZWlyIHB1dHR5IHdpbmRvdyB3aXRo b3V0IGZpcnN0CmV4aXRpbmcgdGhlIHBzcWwgc2hlbGwgdGhpcyBtb3JuaW5n IHRoYXQgZmluYWxseSByZXZlYWxlZCBob3cgaXQgd2FzCmhhcHBlbmluZy4N Cg0KSXQgaXMgcmVwcm9kdWNpYmxlIGluIG91ciBlbnZpcm9ubWVudC4NCg0K DQoKCg==
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
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
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
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
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, "\\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
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
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
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
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
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-commonAccording 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,