Bug #3673: PTY.getpty with IO.pipe doesn't finish on FreeBSD

• Status: Closed
• Assignee: -
• Target version: 2.0.0
• ruby -v: ruby 1.9.3dev (2010-08-09 trunk 28938) [x86_64-freebsd8.1]

[naruse (Yui NARUSE)]

=begin
以下のプログラムが FreeBSD で終了しません。
(test/ruby/test_rubyoptions.rb の test_script_from_stdin より)
Ubuntu 8.04 や Mac OS X 10.6 では終わることを確認しています。

require 'pty'
#require 'timeout'
s, w = IO.pipe
PTY.getpty('./ruby', out: w) do |r, m|
w.close
#m.print("print 'abc'\n")
m.print("\C-d")
p s.read

result = Timeout.timeout(3) {s.read}

end
puts :fin
=end

[akr (Akira Tanaka)]

=begin
2010年8月10日10:53 Yui NARUSE [e-mail]:

以下のプログラムが FreeBSD で終了しません。
(test/ruby/test_rubyoptions.rb の test_script_from_stdin より)
Ubuntu 8.04 や Mac OS X 10.6 では終わることを確認しています。

単純化してみました。
パイプは関係ありません。

freebsd8(16:07:56)% cat z.rb
require 'pty'
PTY.getpty('sleep 1') do |r, w, pid|
p pid
w.print("a")
Process.wait pid
end
puts :fin

freebsd8(16:07:58)% ./ruby -v z.rb
ruby 1.9.3dev (2010-08-07 trunk 28906) [i386-freebsd8.1]
32576
(ここでハング)

他の端末から ps してみると、以下のようになります。

freebsd8(16:07:25)% ps u32576
USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
akr 32576 0.0 0.1 1536 504 7- SEs+ 4:07PM 0:00.00 sleep 1

STAT の意味は

S       Marks a process that is sleeping for less than about 20
   seconds.
E       The process is trying to exit.
s       The process is a session leader.
+       The process is in the foreground process group of its
   control terminal.

ということで、E のままで終わらないのがわかりません。

また、sleep 1 を ktrace sleep 1 にして kdump すると、

freebsd8(16:18:10)% kdump -E
...
33428 sleep 0.001572 RET sigprocmask 0
33428 sleep 0.001611 CALL nanosleep(0xbfbfeaac,0)
33428 sleep 1.001607 RET nanosleep 0
33428 sleep 1.001672 CALL sigprocmask(SIG_BLOCK,0x2807acc0,0xbfbfea10)
33428 sleep 1.001681 RET sigprocmask 0
33428 sleep 1.001688 CALL sigprocmask(SIG_SETMASK,0x2807acd0,0)
33428 sleep 1.001693 RET sigprocmask 0
33428 sleep 1.001712 CALL sigprocmask(SIG_BLOCK,0x2807acc0,0xbfbfe9d0)
33428 sleep 1.001718 RET sigprocmask 0
33428 sleep 1.001723 CALL sigprocmask(SIG_SETMASK,0x2807acd0,0)
33428 sleep 1.001742 RET sigprocmask 0
33428 sleep 1.001757 CALL exit(0)

というように nanosleep で 1秒待った後、exit(0) を呼んでいるようなのが
観察されます。

[田中 哲][たなか あきら][Tanaka Akira]

=end

[akr (Akira Tanaka)]

=begin
2010年8月10日16:21 Tanaka Akira [e-mail]:

freebsd8(16:07:56)% cat z.rb
require 'pty'
PTY.getpty('sleep 1') do |r, w, pid|
p pid
w.print("a")
Process.wait pid
end
puts :fin

C にしてさらに単純化するとこうですかね。

freebsd8(23:26:18)% cat t.c
#include <stdlib.h>
#include <stdio.h>
#include <fcntl.h>
#include <sys/types.h>
#include <unistd.h>
#include <sys/wait.h>

int main(int argc, char *argv[])
{
int m, s;
char *slavedev;
pid_t pid;
int status;

if ((m = posix_openpt(O_RDWR|O_NOCTTY)) == -1) {
perror("posix_openpt"); exit(1); }
if (grantpt(m) == -1) { perror("grantpt"); exit(1); }
if (unlockpt(m) == -1) { perror("unlockpt"); exit(1); }
if ((slavedev = ptsname(m)) == NULL) { perror("ptsname"); exit(1); }
if ((s = open(slavedev, O_RDWR|O_NOCTTY, 0)) == -1) {
perror("open(slavedev)"); exit(1); }

pid = fork();
if (pid == -1) { perror("fork"); exit(1); }
if (pid == 0) {
sleep(1);
exit(0);
}
if (close(s) == -1) { perror("close"); exit(1); }

if (write(m, "a", 1) == -1) { perror("write"); exit(1); }

fprintf(stderr, "pid=%d\n", (int)pid);
if (waitpid(pid, &status, 0) == -1) { perror("waitpid"); exit(1); }

return 0;
}
freebsd8(23:26:22)% gcc -Wall t.c
freebsd8(23:28:02)% time ./a.out
pid=68602
^C
./a.out 0.00s user 0.00s system 0% cpu 19.719 total

^C する前に ps した結果:
freebsd8(23:28:08)% ps u68602
USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
akr 68602 0.0 0.1 1536 664 3 SE+ 11:28PM 0:00.00 ./a.out

やっぱ E ですが、E って具体的にはどういう状況なのかなぁ。

しかし、setsid しなくても再現するなら

% ./ruby -rpty -e '
m, s = PTY.open
pid = spawn("sleep 1")
s.close
m.write "a"
Process.wait pid
'

で発症してもおかしくないと思うんですが再現しない...

[田中 哲][たなか あきら][Tanaka Akira]

=end

[naruse (Yui NARUSE)]

=begin
成瀬です。

(2010/08/10 23:32), Tanaka Akira wrote:

C にしてさらに単純化するとこうですかね。

どうもです。

^C する前に ps した結果:
freebsd8(23:28:08)% ps u68602
USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
akr 68602 0.0 0.1 1536 664 3 SE+ 11:28PM 0:00.00 ./a.out

やっぱ E ですが、E って具体的にはどういう状況なのかなぁ。

とりあえず ps(3) のソースをみると、exit しているがゾンビではない、と。
if (flag & P_WEXIT && k->ki_p->ki_stat != SZOMB)
*cp++ = 'E';
http://svn.freebsd.org/viewvc/base/head/bin/ps/print.c?revision=205271&view=markup

あと、ps で wchan を見てみると、以下のようになりますね
% pgrep a.out|xargs procstat
PID PPID PGID SID TSID THR LOGIN WCHAN EMUL COMM
35305 35304 35304 47112 47112 1 naruse ttyout FreeBSD ELF64 a.out
35304 47112 35304 47112 47112 1 naruse wait FreeBSD ELF64 a.out

--
NARUSE, Yui [e-mail]

=end

[akr (Akira Tanaka)]

=begin
2010年8月11日8:05 NARUSE, Yui [e-mail]:

あと、ps で wchan を見てみると、以下のようになりますね
% pgrep a.out|xargs procstat
PID PPID PGID SID TSID THR LOGIN WCHAN EMUL COMM
35305 35304 35304 47112 47112 1 naruse ttyout FreeBSD ELF64 a.out
35304 47112 35304 47112 47112 1 naruse wait FreeBSD ELF64 a.out

これは良い情報です。
ttyout ってことはなにか出力を待っているんですね。

子プロセスも取り除けました。

freebsd8% cat tst.c
#include <stdlib.h>
#include <stdio.h>
#include <fcntl.h>
#include <sys/types.h>
#include <unistd.h>

int main(int argc, char *argv[])
{
int m, s;
char *slavedev;

if ((m = posix_openpt(O_RDWR|O_NOCTTY)) == -1) {
perror("posix_openpt"); exit(1); }
if (grantpt(m) == -1) { perror("grantpt"); exit(1); }
if (unlockpt(m) == -1) { perror("unlockpt"); exit(1); }
if ((slavedev = ptsname(m)) == NULL) { perror("ptsname"); exit(1); }
if ((s = open(slavedev, O_RDWR|O_NOCTTY, 0)) == -1) {
perror("open"); exit(1); }

if (write(m, "a", 1) == -1) { perror("write"); exit(1); }

fprintf(stderr, "before close(s)\n");
if (close(s) == -1) { perror("close"); exit(1); }
fprintf(stderr, "after close(s)\n");

return 0;
}
freebsd8% gcc -Wall tst.c
freebsd8% ./a.out
before close(s)
(ここでハング)

どうやら、close がブロックしているようですね。
exit も内部的には close 相当のことをするでしょうから、
そこでブロックしているのでしょう。

以下のようにしてもハングします。

% ./ruby -rpty -e '
m, s = PTY.open
m.write "a"
s.close
'

なんで出力があるかというと、おそらく tty のエコーだろうということで、
エコーを抑制するとハングしません。

#include <stdlib.h>
#include <stdio.h>
#include <fcntl.h>
#include <sys/types.h>
#include <unistd.h>
#include <sys/wait.h>
#include <termios.h>

int main(int argc, char *argv[])
{
int m, s;
char *slavedev;
struct termios t;

if ((m = posix_openpt(O_RDWR|O_NOCTTY)) == -1) {
perror("posix_openpt"); exit(1); }
if (grantpt(m) == -1) { perror("grantpt"); exit(1); }
if (unlockpt(m) == -1) { perror("unlockpt"); exit(1); }
if ((slavedev = ptsname(m)) == NULL) { perror("ptsname"); exit(1); }
if ((s = open(slavedev, O_RDWR|O_NOCTTY, 0)) == -1) {
perror("open(slavedev)"); exit(1); }

if (tcgetattr(s, &t) == -1) { perror("tcgetattr"); }
t.c_lflag &= ~(tcflag_t)(ECHO|ECHOE|ECHOK|ECHONL);
if (tcsetattr(s, TCSANOW, &t) == -1) { perror("tcsetattr"); }

if (write(m, "a", 1) == -1) { perror("write"); exit(1); }

if (close(s) == -1) { perror("close"); exit(1); }

return 0;
}

ruby ならこうです。

% ./ruby -rio/console -rpty -e '
m, s = PTY.open
s.echo = false
m.write "a"
s.close
'

では、test_script_from_stdin でも、というと、そこが微妙です。
PTY.spawn は slave tty を教えてくれないので、
slave tty に tcsetattr ができません。
FreeBSD だと以下のように master 側に tcsetattr を発行しても動くんですが、
これはポータブルではありません。[ruby-list:28382]

% svn diff --diff-cmd diff -x -u test/ruby/test_rubyoptions.rb
Index: test/ruby/test_rubyoptions.rb

--- test/ruby/test_rubyoptions.rb (revision 28906)
+++ test/ruby/test_rubyoptions.rb (working copy)
@@ -436,6 +436,7 @@
result = nil
s, w = IO.pipe
PTY.spawn(EnvUtil.rubybin, out: w) do |r, m|

•  m.echo = false
   w.close
   m.print("\C-d")
   assert_nothing_raised('[ruby-dev:37798]') do
  

@@ -446,6 +447,7 @@
assert_equal("", result, '[ruby-dev:37798]')
s, w = IO.pipe
PTY.spawn(EnvUtil.rubybin, out: w) do |r, m|

•  m.echo = false
   w.close
   m.print("$stdin.read; p $stdin.gets\n\C-d")
   m.print("abc\n\C-d")
  

このテストでは制御端末を変える必要はないと思うので、
PTY.open を使って書き直すのがいいかなぁ。

[田中 哲][たなか あきら][Tanaka Akira]

=end

[akr (Akira Tanaka)]

• Status changed from Open to Closed
• % Done changed from 0 to 100

=begin
This issue was solved with changeset r28965.
Yui, thank you for reporting this issue.
Your contribution to Ruby is greatly appreciated.
May Ruby be with you.

=end

[naruse (Yui NARUSE)]

=begin
まずはテストの修正ありがとうございます。

確かに以下の通り close(2) の前にエコーによって出力された文字列を読んであげるとちゃんと閉じられますね。
うーん、前の Bug #3515 と関係あるのかなぁ。

#include <stdlib.h>
#include <stdio.h>
#include <fcntl.h>
#include <sys/types.h>
#include <unistd.h>
#include <sys/wait.h>
#include <termios.h>

int main(int argc, char *argv[])
{
int m, s;
char *slavedev;
struct termios t;

   if ((m = posix_openpt(O_RDWR|O_NOCTTY)) == -1) {
       perror("posix_openpt"); exit(1); }
   if (grantpt(m) == -1) { perror("grantpt"); exit(1); }
   if (unlockpt(m) == -1) { perror("unlockpt"); exit(1); }
   if ((slavedev = ptsname(m)) == NULL) { perror("ptsname"); exit(1); }
   if ((s = open(slavedev, O_RDWR|O_NOCTTY, 0)) == -1) {
       perror("open(slavedev)"); exit(1); }

   if (tcgetattr(s, &t) == -1) { perror("tcgetattr"); }
   t.c_lflag &= ~(tcflag_t)(ECHO|ECHOE|ECHOK|ECHONL);
   //if (tcsetattr(s, TCSANOW, &t) == -1) { perror("tcsetattr"); }

   if (write(m, "a", 1) == -1) { perror("write"); exit(1); }

   {
       char buf[100];
       if (read(m, buf, 1) == -1) { perror("write"); exit(1); }
       printf("echo: %c\n", buf[0]);
   }

   if (close(s) == -1) { perror("close"); exit(1); }

   return 0;

}

=end

[akr (Akira Tanaka)]

=begin
2010年8月14日19:55 Yui NARUSE [e-mail]:

うーん、前の Bug #3515 と関係あるのかなぁ。

NetBSD や OpenBSD でも再現するので関係ないと思います。

[田中 哲][たなか あきら][Tanaka Akira]

=end