Bug #8499 'tee' in command line client causes seg fault

Description:
Using the 'tee' command from the mysql command line client causes a segmentation fault and a output file that takes up all available space on the filesystem.

Endless loop somewhere perhaps?

I used tee in combination with the 'SHOW DATABASES' command, but it seems to fail with other commands also.

Transcript:
=======
# mysql -u root -p
Enter password: 
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 7 to server version: 4.1.9-standard-log

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> tee wank.txt
Logging to file 'wank.txt'
mysql> show databases;
+-------------+
| Database    |
+-------------+
| 0000_cms    |
Segmentation fault

How to repeat:
1. Download SUSE LINUX Enterprise Server 9 (x86_64) from the Novell web site.
2. Install MySQL-server-4.1.9-0.glibc23.x86_64.rpm and MySQL-client-4.1.9-0.glibc23.x86_64.rpm.
3. Connect to the server using the 'mysql' command.
4. Enter the following commands:
  tee wank.txt
  show databases;

I don't know whether the hardware configuration has any significance.

Couldn't verify this with SuSE 9.0 (kernel 2.4.21) and 4.1.9 built from source

Status "Can't repeat" after doing a test on a completely different OS?

Now that's just either plain dumb or pretty damn lazy.

Try your test again.
This time, for added fun, use the same configuration that I stated cause the problem.

That means (at the very least):
 - Same MySQL client version (MySQL-client-4.1.9-0.glibc23.x86_64)
 - Linux Kernel _2.6_
 - Use a SMP box

The easiest way to reproduce is probably to download the OS we're using (which, might I remind you, MySQL recommends in your manual as _the best_ for running MySQL), install it on a SMP box, add the MySQL server + client versions stated in the original report, and perform the test.

David, "can't repeat" doesn't mean "closed"

Okay.  I just assumed it meant that you declined the existence of the bug.
I'm sorry!

It may be a bit misleading that the bug doesn't show up in the "view your bugs" page anymore, that could sort of suggest that the bug is considered closed..

Hartmut, could you try to repeat this on melody ?

(it's x86_64, two CPU, 2.6.5-7.97-smp, SLES 9)

I've just reproduced this problem on Gentoo Linux 2004.3 (amd64). MySQL is 4.1.10 builded from source.
rathamahata@lights rathamahata $ uname -a
Linux lights.vh.com.ru 2.6.11 #1 SMP Thu Mar 3 10:56:12 MSK 2005 x86_64 AMD Opteron(tm) Processor 246 AuthenticAMD GNU/Linux
rathamahata@lights rathamahata $ mysql
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2256542 to server version: 4.1.10-log

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> tee logfile;
Logging to file 'logfile'
mysql> show status;
+--------------------------------+--------------+
Segmentation fault
rathamahata@lights rathamahata $

Program received signal SIGSEGV, Segmentation fault.
0x00002aaaab6de110 in strlen () from /lib/libc.so.6
(gdb) bt
#0  0x00002aaaab6de110 in strlen () from /lib/libc.so.6
#1  0x00002aaaab6b3238 in vfprintf () from /lib/libc.so.6
#2  0x000000000040ea56 in tee_fprintf(_IO_FILE*, char const*, ...) (
    file=0x2d2d2b2d2d2d2d2d, fmt=0x4236ad " %-*s|") at mysql.cc:3076
#3  0x000000000040c806 in print_table_data (result=0x54adf0) at mysql.cc:2026
#4  0x000000000040c253 in com_go (buffer=0x5339e0,
    line=0x5476a000 <Address 0x5476a000 out of bounds>) at mysql.cc:1869
#5  0x000000000040acfa in add_line (buffer=@0x5339e0, line=0x5483f0 "show status;",
    in_string=0x7ffffffff47e "", ml_comment=0x7ffffffff47f) at mysql.cc:1153
#6  0x000000000040a757 in read_lines (execute_commands=true) at mysql.cc:1003
#7  0x0000000000409bd0 in main (argc=2, argv=0x539100) at mysql.cc:455
(gdb)

Ooh!
A backtrace.
Good idea.

Here's a system call trace also, hope it's helpful.

==  Execute command:  TEE wak.txt  ==

open("wak.txt", O_RDWR|O_APPEND|O_CREAT, 0666) = 4
write(1, "Logging to file \'wak.txt\'\n", 26) = 26
fstat(4, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2a955a6000
rt_sigprocmask(SIG_BLOCK, [INT], [], 8) = 0
ioctl(0, TIOCGWINSZ, {ws_row=67, ws_col=132, ws_xpixel=0, ws_ypixel=0}) = 0
ioctl(0, TIOCSWINSZ, {ws_row=67, ws_col=132, ws_xpixel=0, ws_ypixel=0}) = 0
ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig -icanon -echo ...}) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigaction(SIGINT, {0x425ac0, [], 0x4000000}, {0x4128e0, [INT], SA_RESTART|0x4000000}, 8) = 0
rt_sigaction(SIGTERM, {0x425ac0, [], 0x4000000}, {SIG_DFL}, 8) = 0
rt_sigaction(SIGQUIT, {0x425ac0, [], 0x4000000}, {0x4128e0, [QUIT], SA_RESTART|0x4000000}, 8) = 0
rt_sigaction(SIGALRM, {0x425ac0, [], 0x4000000}, {SIG_DFL}, 8) = 0
rt_sigaction(SIGTSTP, {0x425ac0, [], 0x4000000}, {SIG_DFL}, 8) = 0
rt_sigaction(SIGTTOU, {0x425ac0, [], 0x4000000}, {SIG_DFL}, 8) = 0
rt_sigaction(SIGTTIN, {0x425ac0, [], 0x4000000}, {SIG_DFL}, 8) = 0
rt_sigaction(SIGWINCH, {0x425b70, [], 0x4000000}, {SIG_DFL}, 8) = 0
write(1, "mysql> ", 7)                  = 7
# read/write("select * from mysql.test;\r\n") snipped!
rt_sigprocmask(SIG_BLOCK, [INT], [], 8) = 0
ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon echo ...}) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigaction(SIGINT, {0x4128e0, [INT], SA_RESTART|0x4000000}, {0x425ac0, [], 0x4000000}, 8) = 0
rt_sigaction(SIGTERM, {SIG_DFL}, {0x425ac0, [], 0x4000000}, 8) = 0
rt_sigaction(SIGQUIT, {0x4128e0, [QUIT], SA_RESTART|0x4000000}, {0x425ac0, [], 0x4000000}, 8) = 0
rt_sigaction(SIGALRM, {SIG_DFL}, {0x425ac0, [], 0x4000000}, 8) = 0
rt_sigaction(SIGTSTP, {SIG_DFL}, {0x425ac0, [], 0x4000000}, 8) = 0
rt_sigaction(SIGTTOU, {SIG_DFL}, {0x425ac0, [], 0x4000000}, 8) = 0
rt_sigaction(SIGTTIN, {SIG_DFL}, {0x425ac0, [], 0x4000000}, 8) = 0
rt_sigaction(SIGWINCH, {SIG_DFL}, {0x425b70, [], 0x4000000}, 8) = 0

==  Execute command:  SELECT * FROM mysql.test;  ==

times({tms_utime=0, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 250172062
fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
read(3, 0x638b20, 16384)                = -1 EAGAIN (Resource temporarily unavailable)
fcntl(3, F_SETFL, O_RDWR)               = 0
write(3, "\31\0\0\0\3select * from mysql.test", 29) = 29
read(3, "\1\0\0\1", 4)                  = 4
read(3, "\1", 1)                        = 1
read(3, "\'\0\0\2", 4)                  = 4
read(3, "\3def\5mysql\4test\4test\2Id\2Id\f?\0\4\0\0"..., 39) = 39
read(3, "\1\0\0\3", 4)                  = 4
read(3, "\376", 1)                      = 1
read(3, "\4\0\0\4", 4)                  = 4
read(3, "\003123", 4)                   = 4
brk(0)                                  = 0x679000
brk(0x69b000)                           = 0x69b000
read(3, "\5\0\0\5", 4)                  = 4
read(3, "\376\0\0\2\0", 5)              = 5
times({tms_utime=0, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 250172062
write(1, "+------+\n", 9)               = 9
mmap(NULL, 1779785728, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2a95fb5000
write(4, "mysql> select * from mysql.test;"..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096
write(4, "                                "..., 4096) = 4096

==  Yes, well, the above line repeats forever :-)  ==

Verified with 4.1.10 client on SLES 9 (x86_64), client only shows the first ascii table header 
row for a SHOW STATUS, hangs for a while and crashes. The TEE file created is about
1.7GB in size although only the first two lines are valid, followed by some magled characters
and billion of spaces ...

I believe this is due to collision between va_* internals and second vfprintf() сall in tee_fprintf()

void tee_fprintf(FILE *file, const char *fmt, ...)
{
  va_list args;

  NETWARE_YIELD;
  va_start(args, fmt);
  (void) vfprintf(file, fmt, args);
#ifdef OS2
  fflush( file);
#endif
  if (opt_outfile)
    (void) vfprintf(OUTFILE, fmt, args);
^^^^^^^^^^^^^^^^^^^^^^^^^
  va_end(args);
}

According to: http://www.opengroup.org/onlinepubs/009695399/basedefs/stdarg.h.html
<cite>
The object ap may be passed as an argument to another function; if that function invokes the va_arg() macro with parameter ap, the value of ap in the calling function is unspecified and shall be passed to the va_end() macro prior to any further reference to ap.
<cite>

So the following patch is needed (it has fixed segfault for me). Patch is against current bk.

===== client/mysql.cc 1.199 vs edited =====
--- 1.199/client/mysql.cc       2005-03-07 11:47:18 +03:00
+++ edited/client/mysql.cc      2005-03-11 20:37:07 +03:00
@@ -3074,6 +3074,8 @@
   fflush( file);
 #endif
   if (opt_outfile)
+    va_end(args);
+    va_start(args, fmt);
     (void) vfprintf(OUTFILE, fmt, args);
   va_end(args);
 }

Oops, that was a wrong patch (stupid typo). The correct one is:
===== client/mysql.cc 1.199 vs edited =====
--- 1.199/client/mysql.cc       2005-03-07 11:47:18 +03:00
+++ edited/client/mysql.cc      2005-03-11 21:51:24 +03:00
@@ -3073,8 +3073,11 @@
 #ifdef OS2
   fflush( file);
 #endif
-  if (opt_outfile)
+  if (opt_outfile) {
+    va_end(args);
+    va_start(args, fmt);
     (void) vfprintf(OUTFILE, fmt, args);
+  }
   va_end(args);
 }

Awesome.

If you want to make sure it scratches the original itch, I'd be happy to give it a whirl.

Don't have the time to set up a development environment though, so you'd have to email me a binary that matches MySQL-client-4.1.9-0.glibc23.x86_64....

If you're sure it's fixed, no need to bother though :-).

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/internals/23067

Pushed, will be fixed in 4.1.11 and 5.0.4.

Noted in 4.1.11, 5.0.4 changelogs.