Demonstration of I/O hang when using old-style Erlang VM console.

aaa-readme.txt

This gist contains 3 parts

1. The demo script, written with Expect.
2. Output when the bug is demonstrated: Erlang is started without a pseudo-tty.
3. Output when the bug is not demonstrated: Erlang is started *with* a pseudo-tty.

Please see the comments at the top of demo.expect for environment prerequisites.
For example, to disable the SSH authentication agent forwarding so that you are
always asked for a password, undefine the SSH_AUTH_SOCK environment variable.

demo.expect

#!/usr/bin/expect --

## Assumptions:
##
## 1. SSH has been used to log into "hostname" once before: we aren't
##    smart enough to deal with SSH host key verification stuff.
##
## 2. This script can successfully use SSH to log into hostname using
##    the specified user.
##
## 3. If SSH does not require a password for the specified user on
##    hostname, then please break that feature so that the SSH
##    password authentication method is required.
##
## 4. We assume that the account's shell prompt will include
##    a "$" in it.  If that is not a correct assumption, please fix
##    the login_prompt procedure below.
##
## 5. This script will kill any other beam.smp processes
##    that happen to be running on hostname.
##
## 6. We look at beam.smp processes only.
##
## 7. We assume that the machine has an IPv4 loopback address,
##    127.0.0.1.  If it is IPv6 only, this script won't work.

## Usage: this-script hostname username password run_erl_path erl_path [yes]
##        6th argument is optional.  If present, it should be "yes".
##
## For example:
##
## expect this-script 172.16.72.130 fritchie my-password-here /usr/lib64/riak/erts-5.9.1/bin 

## Reminder reminder reminder: never use single quotes
## Reminder reminder reminder: never use single quotes
## Reminder reminder reminder: never use single quotes

set timeout 10
set erl_prompt {@[^)]+\)\d+> }

set hostname [lindex $argv 0]
set username [lindex $argv 1]
set password [lindex $argv 2]
set erts_path [lindex $argv 3]
set use_ssh_minus_t [lindex $argv 4]

proc login_prompt {} {
    expect -re {\$}
    # If a dollar sign does not appear in the prompt, comment out
    # the line above, uncomment the line below, then edit the line
    # below to include the correct prompt string.
    # expect -re {some prompt regexp here}
}

proc erlang_prompt {} {
    global erl_prompt

    expect -re $erl_prompt
}

proc cmd {cmd} {
    send "$cmd\r"
    login_prompt
}

proc async_cmd {cmd} {
    send "$cmd\r"
}

proc erlang_cmd {cmd} {
    send "$cmd\r"
    erlang_prompt
}

proc announce {msg} {
    puts "\n\n*** [exec date]\n*** $msg"
}

proc switch_to {id} {
    global spawn_id

    announce "Switching to session $id"
    set spawn_id $id
}

# send_user "Password for host $hostname: "
# stty -echo
# expect_user -re "(.*)\n"
# stty echo
# set password $expect_out(1,string)
# puts ""

    spawn ssh -l $username $hostname
    set session1 $spawn_id
    expect {password}
    send "$password\r"
    login_prompt

announce "Killing all beam.smp processes"
switch_to $session1
cmd {ps axww | grep beam.smp | grep -v grep | awk '{print $1}' | xargs kill -9 ; sleep 1}
cmd {ps -ef | grep beam.smp | grep -v grep | awk '{print $2}' | xargs kill -9 ; sleep 1}
set tmp_dir /tmp/my-tmp-dir
cmd "rm -rf $tmp_dir ; mkdir -p $tmp_dir ; sleep 1"

if {$use_ssh_minus_t == "yes"} {
    set ssh_extra_arg "-t"
    set ssh_extra_msg "(ALLOCATING PTY via 'ssh -t')"
} else {
    set ssh_extra_arg "-a";     # Harmless
    set ssh_extra_msg ""
}

announce "Starting erl via run_erl $ssh_extra_msg"
    #spawn ssh $ssh_extra_arg -l $username $hostname "$erts_path/run_erl -daemon $tmp_dir $tmp_dir \"exec $erts_path/erl -sname foo\""
    spawn ssh $ssh_extra_arg -l $username $hostname "$erts_path/run_erl -daemon $tmp_dir $tmp_dir \"exec $erts_path/erl -name foo@127.0.0.1\""
    expect {password}
    send "$password\r"
    expect eof
    sleep 2

announce "Attach via to_erl, do sanity test"
switch_to $session1
async_cmd "$erts_path/to_erl $tmp_dir"
send "hello_world.\r"
expect {
    -re $erl_prompt { announce "Excellent, the sanity test passes" }
    timeout         { announce "to_erl FAILED.  Please try again.\n    This script is broken for you if it fails more than twice, sorry!\n    If this script runs to completion when 'yes' is *not* the final argument\n    but if fails at ths point when 'yes' *is* the final argument, then you\n    you are hitting a race condition with run_erl and to_erl that I\n    do not understand, sorry.  At any rate, you are able to run this script\n    to demonstrate the bug successfully when run_erl is started without\n    a pseudo-tty.\n" ; exit 4}
}
erlang_cmd "application:start(sasl)."
erlang_cmd "timer:sleep(2000)."

announce "2nd login session to $hostname, attach to erl via remsh"

    spawn ssh -l $username $hostname
    set session2 $spawn_id
    expect {password}
    send "$password\r"
    login_prompt

switch_to $session2
#async_cmd "$erts_path/erl -sname bar -remsh foo@`uname -n | sed 's/\..*//'`"
async_cmd "$erts_path/erl -name bar@127.0.0.1 -remsh foo@127.0.0.1"
erlang_prompt
erlang_cmd "node()."

announce "Log a message via lager, watch for it over on Riak console"
switch_to $session2
### erlang_cmd "error_logger:warning_msg(\"WARNING 1\", \[\])."
erlang_cmd "io:format(user, \"WARNING 1\", \[\])."

switch_to $session1
expect {
    "WARNING 1" { announce "Found our first warning, excellent!" }
    timeout     { puts "BUMMER 1!" ; exit 4 }
}

announce "Now, to hang the logger to demonstrate the bug.\n    Any incomplete term is fine, we'll use an unfinished tuple...."
switch_to $session1
async_cmd "{tuple_item_number_1,"
sleep 1

set bug_timeout 15
set timeout $bug_timeout
announce "Now that console is hung, call lager:log().\n    Set timeout time to $bug_timeout seconds.\n    This function should execute in only a few milliseconds."

switch_to $session2
send "\003" ; sleep 1
send "\003" ; sleep 1
login_prompt
cmd "echo do it again"
#async_cmd "$erts_path/erl -sname bar -remsh foo@localhost"
async_cmd "$erts_path/erl -name bar@127.0.0.1 -remsh foo@127.0.0.1"
erlang_prompt
erlang_cmd "{again, node(), nodes()}."

async_cmd "{time(), io:format(user, \"WARNING 2\", \[\]), time()}."
expect {
    -re $erl_prompt { announce "BUMMER, Found 2nd warning at wrong time, continuing with caution"; sleep 5}
    timeout     { announce "TIMEOUT! Excellent, the bug has been demonstrated (1)" }
}

switch_to $session1
expect {
    "WARNING 2" { announce "BUMMER, Found 2nd warning at wrong time\n    You used 'ssh -t' to allocate a pseudo-tty and therefore the bug\n    doesn't exist here, or there's a problem with this Expect script,\n    or you really don't have the problem that I'm trying to demonstrate.\n    Goodbye!"; exit 4}
    timeout     { announce "TIMEOUT! Excellent, the bug has been demonstrated (1b)" }
}

announce "When we finish the erlang term over on $session1 ('riak attach' session),\n    then the logger will become unblocked."
switch_to $session1
async_cmd "element_number_2}."
expect {
    -re $erl_prompt { announce "Excellent, we have 'riak attach' prompt" }
    timeout     { announce "BUMMER, timeout when not expected (2)"; exit 4}
}

announce "Now go to session $session2 and expect the -remsh's prompt."
switch_to $session2
# expect {
#     "WARNING 2" { announce "Excellent, I see the 'WARNING 2' log message" }
#     timeout     { announce "BUMMER, timeout when not expected @ 2nd w"; exit 4}
# }
expect {
    -re $erl_prompt { announce "Excellent, we have the 'riak -remsh' prompt" }
    timeout     { announce "BUMMER, timeout when not expected (3)"; exit 4}
}

announce "Time to clean up both sessions"

switch_to $session1
async_cmd "\004"
login_prompt
async_cmd "exit\r"
expect eof

switch_to $session2
async_cmd "\003" ; sleep 1
async_cmd "\003" ; sleep 1
login_prompt
async_cmd "exit\r"
expect eof

announce "Excellent, this successful test is finished."
exit 0

m-bug-demonstrated-output.txt

NOTE: This output was generated by:
  csh users:
      expect ~/b/notes/2013-04-22.hanging-log-plain.expect 172.16.72.130 fritchie foofoo /usr/lib64/riak/erts-5.9.1/bin | & tee ~/foo2
  sh/bash users:
      expect ~/b/notes/2013-04-22.hanging-log-plain.expect 172.16.72.130 fritchie foofoo /usr/lib64/riak/erts-5.9.1/bin 2>&1 | tee ~/foo2

spawn ssh -l fritchie 172.16.72.130
fritchie@172.16.72.130's password: 
Last login: Tue Apr 23 10:07:45 2013 from 172.16.72.1

]0;fritchie@localhost:~[fritchie@localhost ~]$ 

*** Tue Apr 23 12:07:59 CDT 2013
*** Killing all beam.smp processes


*** Tue Apr 23 12:07:59 CDT 2013
*** Switching to session exp7
ps axww | grep beam.smp | grep -v grep | awk '{print $1} 
' | xargs kill -9 ; sleep 1
]0;fritchie@localhost:~[fritchie@localhost ~]$ ps -ef | grep beam.smp | grep -v grep | awk '{print $2}' 
 | xargs kill -9 ; sleep 1


*** Tue Apr 23 12:08:00 CDT 2013
*** Starting erl via run_erl 
spawn ssh -a -l fritchie 172.16.72.130 /usr/local/erlang/R15B03.64-bit/bin/run_erl -daemon /tmp/my-tmp-dir /tmp/my-tmp-dir "exec /usr/local/erlang/R15B03.64-bit/bin/erl -name foo@127.0.0.1"
fritchie@172.16.72.130's password: 


*** Tue Apr 23 12:08:02 CDT 2013
*** Attach via to_erl, do sanity test


*** Tue Apr 23 12:08:02 CDT 2013
*** Switching to session exp7
rm -rf /tmp/my-tmp-dir ; mkdir -p /tmp/my-tmp-dir ; sleep 1
usage: kill [ -s signal | -p ] [ -a ] pid ...
       kill -l [ signal ]
]0;fritchie@localhost:~[fritchie@localhost ~]$ rm -rf /tmp/my-tmp-dir ; mkdir -p /tmp/my-tmp-dir ; slee 
p 1
]0;fritchie@localhost:~[fritchie@localhost ~]$ /usr/local/erlang/R15B03.64-bit/bin/to_erl /tmp/my-tmp-d 
ir
Attaching to /tmp/my-tmp-dir (^D to exit)

^R

hello_world.

hello_world

(foo@127.0.0.1)2> 

*** Tue Apr 23 12:08:02 CDT 2013
*** Excellent, the sanity test passes
application:start(sasl).

ok

(foo@127.0.0.1)3> 

=PROGRESS REPORT==== 23-Apr-2013::10:08:02 ===

          supervisor: {local,sasl_safe_sup}

             started: [{pid,<0.44.0>},

                       {name,alarm_handler},

                       {mfargs,{alarm_handler,start_link,[]}},

                       {restart_type,permanent},

                       {shutdown,2000},

                       {child_type,worker}]

(foo@127.0.0.1)3> 

=PROGRESS REPORT==== 23-Apr-2013::10:08:02 ===

          supervisor: {local,sasl_safe_sup}

             started: [{pid,<0.45.0>},

                       {name,overload},

                       {mfargs,{overload,start_link,[]}},

                       {restart_type,permanent},

                       {shutdown,2000},

                       {child_type,worker}]

(foo@127.0.0.1)3> 

=PROGRESS REPORT==== 23-Apr-2013::10:08:02 ===

          supervisor: {local,sasl_sup}

             started: [{pid,<0.43.0>},

                       {name,sasl_safe_sup},

              

*** Tue Apr 23 12:08:02 CDT 2013
*** 2nd login session to 172.16.72.130, attach to erl via remsh
spawn ssh -l fritchie 172.16.72.130
fritchie@172.16.72.130's password: 
Last login: Tue Apr 23 10:07:59 2013 from 172.16.72.1

]0;fritchie@localhost:~[fritchie@localhost ~]$ 

*** Tue Apr 23 12:08:02 CDT 2013
*** Switching to session exp9
/usr/local/erlang/R15B03.64-bit/bin/erl -name bar@127.0. 
0.1 -remsh foo@127.0.0.1
Erlang R15B03 (erts-5.9.3.1) [source] [64-bit] [smp:2:2] [async-threads:0] [hipe] [kernel-poll:false]

Eshell V5.9.3.1  (abort with ^G)
(foo@127.0.0.1)1> node().
'foo@127.0.0.1'
(foo@127.0.0.1)2> 

*** Tue Apr 23 12:08:02 CDT 2013
*** Log a message via lager, watch for it over on Riak console


*** Tue Apr 23 12:08:02 CDT 2013
*** Switching to session exp9
io:format(user, "WARNING 1", []).
ok
(foo@127.0.0.1)3> 

*** Tue Apr 23 12:08:02 CDT 2013
*** Switching to session exp7
         {mfargs,

                           {supervisor,start_link,

                               [{local,sasl_safe_sup},sasl,safe]}},

                       {restart_type,permanent},

                       {shutdown,infinity},

                       {child_type,supervisor}]

(foo@127.0.0.1)3> 

=PROGRESS REPORT==== 23-Apr-2013::10:08:02 ===

          supervisor: {local,sasl_sup}

             started: [{pid,<0.46.0>},

                       {name,release_handler},

                       {mfargs,{release_handler,start_link,[]}},

                       {restart_type,permanent},

                       {shutdown,2000},

                       {child_type,worker}]

(foo@127.0.0.1)3> 

=PROGRESS REPORT==== 23-Apr-2013::10:08:02 ===

         application: sasl

          started_at: 'foo@127.0.0.1'

(foo@127.0.0.1)3> timer:sleep(2000).

WARNING 1

*** Tue Apr 23 12:08:02 CDT 2013
*** Found our first warning, excellent!


*** Tue Apr 23 12:08:02 CDT 2013
*** Now, to hang the logger to demonstrate the bug.
    Any incomplete term is fine, we'll use an unfinished tuple....


*** Tue Apr 23 12:08:02 CDT 2013
*** Switching to session exp7


*** Tue Apr 23 12:08:03 CDT 2013
*** Now that console is hung, call lager:log().
    Set timeout time to 15 seconds.
    This function should execute in only a few milliseconds.


*** Tue Apr 23 12:08:03 CDT 2013
*** Switching to session exp9


BREAK: (a)bort (c)ontinue (p)roc info (i)nfo (l)oaded

       (v)ersion (k)ill (D)b-tables (d)istribution

]0;fritchie@localhost:~[fritchie@localhost ~]$ echo do it again
do it again
]0;fritchie@localhost:~[fritchie@localhost ~]$ /usr/local/erlang/R15B03.64-bit/bin/erl -name bar@127.0. 
0.1 -remsh foo@127.0.0.1
Erlang R15B03 (erts-5.9.3.1) [source] [64-bit] [smp:2:2] [async-threads:0] [hipe] [kernel-poll:false]

Eshell V5.9.3.1  (abort with ^G)
(foo@127.0.0.1)1> {again, node(), nodes()}.
{again,'foo@127.0.0.1',['bar@127.0.0.1']}
(foo@127.0.0.1)2> {time(), io:format(user, "WARNING 2", []), time()}.


*** Tue Apr 23 12:08:20 CDT 2013
*** TIMEOUT! Excellent, the bug has been demonstrated (1)


*** Tue Apr 23 12:08:20 CDT 2013
*** Switching to session exp7
{tuple_item_number_1,

ok

(foo@127.0.0.1)4> 

*** Tue Apr 23 12:08:35 CDT 2013
*** TIMEOUT! Excellent, the bug has been demonstrated (1b)


*** Tue Apr 23 12:08:35 CDT 2013
*** When we finish the erlang term over on exp7 ('riak attach' session),
    then the logger will become unblocked.


*** Tue Apr 23 12:08:35 CDT 2013
*** Switching to session exp7


*** Tue Apr 23 12:08:35 CDT 2013
*** Excellent, we have 'riak attach' prompt


*** Tue Apr 23 12:08:35 CDT 2013
*** Now go to session exp9 and expect the -remsh's prompt.


*** Tue Apr 23 12:08:35 CDT 2013
*** Switching to session exp9
{{10,8,5},ok,{10,8,35}}
(foo@127.0.0.1)3> 

*** Tue Apr 23 12:08:35 CDT 2013
*** Excellent, we have the 'riak -remsh' prompt


*** Tue Apr 23 12:08:35 CDT 2013
*** Time to clean up both sessions


*** Tue Apr 23 12:08:35 CDT 2013
*** Switching to session exp7
element_number_2}.

WARNING 2{tuple_item_number_1,element_number_2}

(foo@127.0.0.1)5> [Quit]

]0;fritchie@localhost:~[fritchie@localhost ~]$ exit
logout
Connection to 172.16.72.130 closed.



*** Tue Apr 23 12:08:35 CDT 2013
*** Switching to session exp9

(foo@127.0.0.1)3> 

BREAK: (a)bort (c)ontinue (p)roc info (i)nfo (l)oaded

       (v)ersion (k)ill (D)b-tables (d)istribution


]0;fritchie@localhost:~[fritchie@localhost ~]$ exit
logout
Connection to 172.16.72.130 closed.



*** Tue Apr 23 12:08:37 CDT 2013
*** Excellent, this successful test is finished.

n-no-bug-output.txt

NOTE: This output was generated by:
  csh users:
      expect ~/b/notes/2013-04-22.hanging-log-plain.expect 172.16.72.130 fritchie foofoo /usr/lib64/riak/erts-5.9.1/bin yes | & tee ~/foo2b
  sh/bash users:
      expect ~/b/notes/2013-04-22.hanging-log-plain.expect 172.16.72.130 fritchie foofoo /usr/lib64/riak/erts-5.9.1/bin yes 2>&1 | tee ~/foo2b

spawn ssh -l fritchie 172.16.72.130
fritchie@172.16.72.130's password: 
Last login: Tue Apr 23 10:06:37 2013 from 172.16.72.1

]0;fritchie@localhost:~[fritchie@localhost ~]$ 

*** Tue Apr 23 12:07:40 CDT 2013
*** Killing all beam.smp processes


*** Tue Apr 23 12:07:40 CDT 2013
*** Switching to session exp7
ps axww | grep beam.smp | grep -v grep | awk '{print $1} 
' | xargs kill -9 ; sleep 1
]0;fritchie@localhost:~[fritchie@localhost ~]$ ps -ef | grep beam.smp | grep -v grep | awk '{print $

*** Tue Apr 23 12:07:41 CDT 2013
*** Starting erl via run_erl (ALLOCATING PTY via 'ssh -t')
spawn ssh -t -l fritchie 172.16.72.130 /usr/local/erlang/R15B03.64-bit/bin/run_erl -daemon /tmp/my-tmp-dir /tmp/my-tmp-dir "exec /usr/local/erlang/R15B03.64-bit/bin/erl -name foo@127.0.0.1"
fritchie@172.16.72.130's password: 
Connection to 172.16.72.130 closed.



*** Tue Apr 23 12:07:43 CDT 2013
*** Attach via to_erl, do sanity test


*** Tue Apr 23 12:07:43 CDT 2013
*** Switching to session exp7
2}' 
 | xargs kill -9 ; sleep 1
usage: kill [ -s signal | -p ] [ -a ] pid ...
       kill -l [ signal ]
]0;fritchie@localhost:~[fritchie@localhost ~]$ rm -rf /tmp/my-tmp-dir ; mkdir -p /tmp/my-tmp-dir ; slee 
p 1
]0;fritchie@localhost:~[fritchie@localhost ~]$ /usr/local/erlang/R15B03.64-bit/bin/to_erl /tmp/my-tmp-d 
ir
Attaching to /tmp/my-tmp-dir (^D to exit)

hello_world.

hello_world

(foo@127.0.0.1)2> 

*** Tue Apr 23 12:07:43 CDT 2013
*** Excellent, the sanity test passes
application:start(sasl).

ok

(foo@127.0.0.1)3> 

=PROGRESS REPORT==== 23-Apr-2013::10:07:43 ===

          supervisor: {local,sasl_safe_sup}

             started: [{pid,<0.45.0>},

                       {name,alarm_handler},

                       {mfargs,{alarm_handler,start_link,[]}},

                       {restart_type,permanent},

                       {shutdown,2000},

                       {child_type,worker}]



=PROGRESS REPORT==== 23-Apr-2013::10:07:43 ===

          supervisor: {local,sasl_safe_sup}

             started: [{pid,<0.46.0>},

                       {name,overload},

                       {mfargs,{overload,start_link,[]}},

                       {restart_type,permanent},

                       {shutdown,2000},

                       {child_type,worker}]



=PROGRESS REPORT==== 23-Apr-2013::10:07:43 ===

          supervisor: {local,sasl_sup}

             started: [{pid,<0.44.0>},

                       {name,sasl_safe_sup},

                       {mfargs,

                           {supervisor,start_link,

                               [{local,sasl_safe_sup},sasl,safe]}},

                       {restart_type,permanent},

                       {shutdown,infinity},

                       {child_type,supervisor}]



=PROGRESS REPORT==== 23-Apr-2013::10:07:43 ===

          supervisor: {local,sasl_sup}

             started: [{pid,<0.47.0>},

                       {name,release_handler},

                       {mfargs,{release_handler,start_link,[]}},

                       {restart_type,permanent},

                       {shutdown,2000},

                       {child_type,worker}]



=PROGRESS REPORT==== 23-Apr-2013::10:07:43 ===

         application: sasl

          started_at: 'foo@127.0.0.1'

timer:sleep(2000).

ok

(foo@127.0.0.1)4> 

*** Tue Apr 23 12:07:45 CDT 2013
*** 2nd login session to 172.16.72.130, attach to erl via remsh
spawn ssh -l fritchie 172.16.72.130
fritchie@172.16.72.130's password: 
Last login: Tue Apr 23 10:07:41 2013 from 172.16.72.1

]0;fritchie@localhost:~[fritchie@localhost ~]$ 

*** Tue Apr 23 12:07:45 CDT 2013
*** Switching to session exp9
/usr/local/erlang/R15B03.64-bit/bin/erl -name bar@127.0. 
0.1 -remsh foo@127.0.0.1
Erlang R15B03 (erts-5.9.3.1) [source] [64-bit] [smp:2:2] [async-threads:0] [hipe] [kernel-poll:false]

Eshell V5.9.3.1  (abort with ^G)
(foo@127.0.0.1)1> node().
'foo@127.0.0.1'
(foo@127.0.0.1)2> 

*** Tue Apr 23 12:07:45 CDT 2013
*** Log a message via lager, watch for it over on Riak console


*** Tue Apr 23 12:07:45 CDT 2013
*** Switching to session exp9
io:format(user, "WARNING 1", []).
ok
(foo@127.0.0.1)3> 

*** Tue Apr 23 12:07:45 CDT 2013
*** Switching to session exp7
WARNING 1

*** Tue Apr 23 12:07:45 CDT 2013
*** Found our first warning, excellent!


*** Tue Apr 23 12:07:45 CDT 2013
*** Now, to hang the logger to demonstrate the bug.
    Any incomplete term is fine, we'll use an unfinished tuple....


*** Tue Apr 23 12:07:45 CDT 2013
*** Switching to session exp7


*** Tue Apr 23 12:07:46 CDT 2013
*** Now that console is hung, call lager:log().
    Set timeout time to 15 seconds.
    This function should execute in only a few milliseconds.


*** Tue Apr 23 12:07:46 CDT 2013
*** Switching to session exp9


BREAK: (a)bort (c)ontinue (p)roc info (i)nfo (l)oaded

       (v)ersion (k)ill (D)b-tables (d)istribution

]0;fritchie@localhost:~[fritchie@localhost ~]$ echo do it again
do it again
]0;fritchie@localhost:~[fritchie@localhost ~]$ /usr/local/erlang/R15B03.64-bit/bin/erl -name bar@127.0. 
0.1 -remsh foo@127.0.0.1
Erlang R15B03 (erts-5.9.3.1) [source] [64-bit] [smp:2:2] [async-threads:0] [hipe] [kernel-poll:false]

Eshell V5.9.3.1  (abort with ^G)
(foo@127.0.0.1)1> {again, node(), nodes()}.
{again,'foo@127.0.0.1',['bar@127.0.0.1']}
(foo@127.0.0.1)2> {time(), io:format(user, "WARNING 2", []), time()}.
{{10,7,48},ok,{10,7,48}}
(foo@127.0.0.1)3> 

*** Tue Apr 23 12:07:48 CDT 2013
*** BUMMER, Found 2nd warning at wrong time, continuing with caution


*** Tue Apr 23 12:07:53 CDT 2013
*** Switching to session exp7
{tuple_item_number_1,

(foo@127.0.0.1)4> WARNING 2

*** Tue Apr 23 12:07:53 CDT 2013
*** BUMMER, Found 2nd warning at wrong time
    You used 'ssh -t' to allocate a pseudo-tty and therefore the bug
    doesn't exist here, or there's a problem with this Expect script,
    or you really don't have the problem that I'm trying to demonstrate.
    Goodbye!