Subject: bug#4975: 23.1; comint.el: command line is sometimes echoed in the command output

From: Johan Euphrosine <[email-masked]>
Date: Thu, 19 Nov 2009 17:40:05 +0100

Hi,

I managed to reproduce
http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=284727 with
comint-mode, and emacs23:

After running php -r 'fwrite(STDOUT, "stdout\n");' in a bash comint
buffer: every command is echoed twice.

emacs
M-x comint-run
/bin/bash
proppy@pasokon:~$ echo 'command is echoed once'
command is echoed once
proppy@pasokon:~$ php -r 'fwrite(STDOUT, "stdout\n");'
stdout
proppy@pasokon:~$ php -r 'fwrite(STDOUT, "stdout\n");'
php -r 'fwrite(STDOUT, "stdout\n");'
stdout
proppy@pasokon:~$ echo 'command is echoed twice'
echo 'command is echoed twice'
command is echoed twice

I found out that setting 'comint-process-echoes to 't' workaround
this issue:

emacs
(setq comint-process-echoes t)
M-x comint-run
/bin/bash
proppy@pasokon:~$ echo 'command is echoed once'
command is echoed once
proppy@pasokon:~$ php -r 'fwrite(STDOUT, "stdout\n");'
stdout
proppy@pasokon:~$ php -r 'fwrite(STDOUT, "stdout\n");'
stdout
proppy@pasokon:~$ echo 'command is *not* echoed twice'
command is *not* echoed twice

I ran strace on php -r 'fwrite(STDOUT, "stdout\n");' to find out if
there is something strange done with the file descriptors, that might
bother comint-mode:

fstat64(0, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
fstat64(0, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
fstat64(0, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb7720000
_llseek(0, 0, 0xbffad494, SEEK_CUR)     = -1 ESPIPE (Illegal seek)
fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb771f000
_llseek(1, 0, 0xbffad494, SEEK_CUR)     = -1 ESPIPE (Illegal seek)
fstat64(2, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
fstat64(2, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
_llseek(2, 0, 0xbffad494, SEEK_CUR)     = -1 ESPIPE (Illegal seek)
write(1, "stdout\n", 7stdout
)                 = 7
close(2)                                = 0
close(1)                                = 0
munmap(0xb771f000, 4096)                = 0
close(0)                                = 0
munmap(0xb7720000, 4096)                = 0
open("/dev/urandom", O_RDONLY)          = 0
read(0, "\362\233\264#", 4)             = 4
close(0)                                = 0
open("/dev/urandom", O_RDONLY)          = 0
read(0, "\314R}\32", 4)                 = 4
close(0)                                = 0
open("/dev/urandom", O_RDONLY)          = 0
read(0, "=\247\332f", 4)                = 4
close(0)                                = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
munmap(0x3c4000, 29352)                 = 0
munmap(0xea9000, 89020)                 = 0
gettimeofday({1258647750, 866613}, NULL) = 0
munmap(0x3aa000, 105232)                = 0
munmap(0x39e000, 47616)                 = 0
munmap(0xfd9000, 2054564)               = 0
exit_group(0)                           = ?

but when trying to mimic this behaviour with a simple c program:

#include <stdio.h>
#include <fcntl.h>

int main() {
  int a;
  llseek(0, 0, 0, SEEK_CUR);
  llseek(1, 0, 0, SEEK_CUR);
  llseek(2, 0, 0, SEEK_CUR);
  write(1, "stdout\n", 7);
  close(2);
  close(1);
  close(0);
  open("/dev/urandom", O_RDONLY);
  read(0, "\34\256\nY", 4);
  close(0);
  open("/dev/urandom", O_RDONLY);
  read(0, "\34\256\nY", 4);
  close(0);
  open("/dev/urandom", O_RDONLY);
  read(0, "\34\256\nY", 4);
  close(0);
  return 0;
}

_llseek(0, 0, 0xbfd27570, SEEK_CUR)     = -1 ESPIPE (Illegal seek)
_llseek(1, 0, 0xbfd27570, SEEK_CUR)     = -1 ESPIPE (Illegal seek)
_llseek(2, 0, 0xbfd27570, SEEK_CUR)     = -1 ESPIPE (Illegal seek)
write(1, "stdout\n", 7stdout
)                 = 7
close(2)                                = 0
close(1)                                = 0
close(0)                                = 0
open("/dev/urandom", O_RDONLY)          = 0
read(0, 0x8048705, 4)                   = -1 EFAULT (Bad address)
close(0)                                = 0
open("/dev/urandom", O_RDONLY)          = 0
read(0, 0x8048705, 4)                   = -1 EFAULT (Bad address)
close(0)                                = 0
open("/dev/urandom", O_RDONLY)          = 0
read(0, 0x8048705, 4)                   = -1 EFAULT (Bad address)
close(0)                                = 0
exit_group(0)                           = ?

It do not trigger the issue in comint:
emacs
M-x comint-run
/bin/bash
proppy@pasokon:~$ echo 'command is echoed once'
command is echoed once
proppy@pasokon:~$ /tmp/a
stdout
proppy@pasokon:~$ echo 'command is *not* echoed twice'
command is *not* echoed twice
proppy@pasokon:~$ php -r 'fwrite(STDOUT, "stdout\n");'
stdout
proppy@pasokon:~$ echo 'command is echoed twice'
echo 'command is echoed twice'
command is echoed twice
proppy@pasokon:~$ 

Do you have suggestion on how to debug this issue further ?

Let me know if you need more information.

Thanks in advance.

If Emacs crashed, and you have the Emacs process in the gdb debugger,
please include the output from the following gdb commands:
    `bt full' and `xbacktrace'.
If you would like to further debug the crash, please read the file
/usr/share/emacs/23.1/etc/DEBUG for instructions.

In GNU Emacs 23.1.1 (i486-pc-linux-gnu, GTK+ Version 2.18.3)
 of 2009-11-10 on vernadsky, modified by Debian
Windowing system distributor `The X.Org Foundation', version
11.0.10604000
configured using `configure  '--build=i486-linux-gnu'
'--host=i486-linux-gnu' '--prefix=/usr' '--sharedstatedir=/var/lib'
'--libexecdir=/usr/lib' '--localstatedir=/var/lib'
'--infodir=/usr/share/info' '--mandir=/usr/share/man' '--with-pop=yes'
'--enable-locallisppath=/etc/emacs23:/etc/emacs:/usr/local/share/emacs/23.1/site-lisp:/usr/local/share/emacs/site-lisp:/usr/share/emacs/23.1/site-lisp:/usr/share/emacs/site-lisp:/usr/share/emacs/23.1/leim' '--with-x=yes' '--with-x-toolkit=gtk' '--with-toolkit-scroll-bars' 'build_alias=i486-linux-gnu' 'host_alias=i486-linux-gnu' 'CFLAGS=-DDEBIAN -g -O2' 'LDFLAGS=-g' 'CPPFLAGS=''

Important settings:
  value of $LC_ALL: nil
  value of $LC_COLLATE: nil
  value of $LC_CTYPE: nil
  value of $LC_MESSAGES: nil
  value of $LC_MONETARY: nil
  value of $LC_NUMERIC: nil
  value of $LC_TIME: nil
  value of $LANG: en_US.UTF-8
  value of $XMODIFIERS: nil
  locale-coding-system: utf-8-unix
  default-enable-multibyte-characters: t

Major mode: Emacs-Lisp

Minor modes in effect:
  rcirc-track-minor-mode: t
  tooltip-mode: t
  tool-bar-mode: t
  mouse-wheel-mode: t
  menu-bar-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  blink-cursor-mode: t
  global-auto-composition-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  line-number-mode: t
  transient-mark-mode: t

Recent input:
M-p M-p M-p M-p M-p M-p M-n M-n <return> <prior> <next> 
<prior> <down> <down> <down> C-x b <return> <up> <down> 
0 , SPC <down> <left> <left> <left> 0 , SPC <down> 
<left> <left> <left> 0 , SPC C-x C-s M-x c o m p i 
l e <return> <return> C-x b <return> M-> M-p M-p <return> 
C-x 1 <prior> <up> <up> <up> <up> C-x b <return> <up> 
<up> <left> <left> <left> M-d M-d 0 <down> <left> M-d 
M-d 0 <down> <left> M-d M-d 0 C-x C-s M-x c o m p i 
l e <return> <return> C-x b <return> M-> M-p <return> 
C-x 1 <prior> <down> <down> <down> M-> l s <return> 
C-x k <return> M-x M-p M-p C-a C-g C-g M-x s h e l 
l <return> <return> <return> <return> <return> M-p 
M-p <return> l s <return> l s <return> l s SPC - a 
l <return> C-x 1 <prior> <down> <down> <return> <return> 
C-x b <return> C-x b c o <tab> <return> M-< <next> 
<prior> <prior> <down-mouse-1> <mouse-movement> <mouse-movement> 
<drag-mouse-1> <help-echo> <help-echo> <tool-bar> <copy> 
<help-echo> M-x r e p o <tab> t <tab> <backspace> r 
t <tab> <return> c o m i n t SPC C-x o C-s p r o c 
e s C-x o C-x b C-g C-x b b u <tab> <return> M-< <next> 
<prior> <down> <down> <up> <up> <up> <up> <up> <up> 
<up> <up> <up> <up> <up> <up> <up> <up> <up> <up> <up> 
<up> <up> <up> <up> <up> <down> <down> <down> <up> 
<up> M-f M-f C-x b <return> M-x M-p M-p C-g C-g C-x 
b <return> <down> <up> M-f <right> <right> C-SPC C-e 
M-w M-w C-x b <return> M-x c o m <tab> i <tab> C-g 
M-x r e p o <tab> <tab> t <tab> - <backspace> <backspace> 
r t - e <tab> <return>

Recent messages:
call-interactively: Beginning of buffer
Making completion list...
read-buffer-to-switch: Command attempted to use minibuffer while in
minibuffer
Quit [2 times]
Mark set
Quit [2 times]
Mark set
Making completion list...
Quit
Making completion list...

-- 
Johan Euphrosine <[email-masked]>
Development and services around Free Software
http://aminche.com/