For a fresh glimpse at the lengths to which I'm going to ensure smooth sailing in the Gales of MySQL, get a load of this mud pie, straight from the official mysql-test suite:
main.mysql [ fail ]
Test ended at 2026-01-14 22:30:23
CURRENT_TEST: main.mysql
ERROR 1050 (42S01) at line 1: Table 't2' already exists
ERROR: Can't initialize batch_readline - may be the input source is a directory or a block device.
--- /home/user/gales-linux/gports/mysql/build/pk/mysql-test/r/mysql.result 2026-01-14 08:29:01 +0300
+++ /home/user/gales-linux/gports/mysql/build/pk/mysql-test/var/log/mysql.reject 2026-01-15 01:30:23 +0300
@@ -1,8 +1,8 @@
drop table if exists t1;
create table t1(a int);
insert into t1 values(1);
-ERROR at line 9: DELIMITER must be followed by a 'delimiter' character or string
+ERROR at line 9: DELIMITER must be followed by a 'delimiter' character or string
Test default delimiter ;
a
1
mysqltest: Result content mismatch
- the logfile can be found in '/home/user/gales-linux/gports/mysql/build/pk/mysql-test/var/log/main.mysql/mysql.log'
Nine times out of ten with these tests, the referenced logfile won't contain anything but further noise on top of whatever the broken code spews directly on the terminal output. Looking past the irrelevant errors, the symptom here is that the error message that the test case expects is showing up, but after a blank line rather than before it.
If you're wondering what bearing this could possibly have on a real database application, I'm right there with you... but then, this is computer stuff, and any little thing amiss is liable to eventually break something in totally unexpected ways. Besides, it's just weird, and in that unsettling way where if I don't track it down, I won't be sure that it's not a sign of something more seriously broken.
I already took care of the more serious looking test failures, meaning we're down to this irritating list of largely spurious and sometimes mysterious ones. In fact, through the mere passage of time the list grew from 16 to 25 failures, and I'm sure that won't be the end of the magic number time bombs, either.
MySQL of course is a database system with client-server networking model, and there's an orchestration of distinct programs involved in running the tests, which we'll need to grasp if we're to know what's coming from where in the output. At the top level is a Perl script, mysql-test-runner; it locates the individual test cases, starts up one or more mysqld server instances running from temporary directories as necessary, then invokes the mysqltest binary to run each selected test. That last is a full fledged client program, akin to the mysql shell but implementing its own language for writing test cases; test code can execute SQL queries, Perl snippets, system commands and other sundries, with its output ultimately compared against the expected results provided in a separate file.
This main.mysql (in the tree at mysql-test/t/mysql.test) is an amalgamation that covers a bunch of things in the mysql client, and in the case of this DELIMITER error, rather than making the erroneous query directly it's running the external mysql binary so as to check that it reports the error as expected.
Thus enlightened, we can examine the source of the different output sections:
drop table if exists t1; create table t1(a int); insert into t1 values(1);
are setup queries run directly from mysqltest, which echoes them to its output as it runs them.
ERROR at line 9: DELIMITER must be followed by a 'delimiter' character or string Test default delimiter ; a 1
or else
ERROR at line 9: DELIMITER must be followed by a 'delimiter' character or string Test default delimiter ; a 1
Those are query results displayed by the mysql subprocess, so that's where the trouble is to be found.
A first frustration was that I was unable to reproduce either ordering of the output when running mysql in isolation on the delimiter test code (mysql-test/t/mysql_delimiter.sql). Those "Test default delimiter ;", "a", "1" and following lines result from valid queries listed before the erroneous one. Running it outside the whole test-runner orchestra, the output is exactly as the naive user would expect: the successful lines followed by the error, matching the order in the code. But with the extra players in the mix, the error jumps all the way to the top and the dispute is whether it lands on the first or second line.
This, then, brings us to some C programming basics along with the murky details that accompany them.
A C program running in a hosted environment (i.e. operating system) is born with access to three input/output data streams for user and/or system interfacing purposes, known as standard input, standard output, and standard error. On Unix, all three typically start out connected to the terminal, but can be individually redirected elsewhere. The idea is that stdout is for normal program output while stderr provides a separate channel for indicating exceptional conditions, for instance so that they can be visible to the operator right away and won't interfere with the intended output which may be captured to a file.
Where it gets trickier is that the programming interfaces to these streams implemented in the standard I/O library (stdio) may involve buffering. Generally this is done to economize the overhead of frequent context switching into the protected kernel mode to deliver the data on to its next destination. This means it may vary when exactly a program's writes become visible to the outside world, and even in what order they appear relative to its reads and writes to the other streams. If a particular ordering or deadline is required, the user code must call fflush to drain the buffer.(i)
In practice, having to explicitly flush all the time is a bother and so there's also a "line buffering" compromise mode, where the buffer flushes automatically when the program writes a newline character. Traditionally, stdout is line buffered when connected to a terminal and otherwise fully buffered; stderr, in light of its purpose, is unbuffered.
Given our discerning use of musl libc on Gales in place of the commoner's GNU libc, this all might seem sufficient to explain the difference in error vs. output ordering. But how do we verify this?
A difference that's come up before is that glibc will also flush stdout when the program reads from stdin, on the idea that it's a common pattern to display a prompt and then wait for user input. There's no requirement for this behavior in the standards, and musl doesn't do it, presumably for simplicity and performance reasons, but the assumption crept in to various places (the sftp prompt for instance). That doesn't account for the case at hand though; as far as I'd seen, musl implements the usual line or block buffered stdout, so shouldn't it give the same output results, at least below the minimum buffer size?
By looking for the mysql client's error printing mechanism, I found a suspicious spot, where an extra flush of stdout might resolve things to always show in the sensible, unbuffered style. But to get to the bottom of the discrepancy, I wanted a way to reproduce the unexpected behavior under a debugger, and this required finding the relevant difference between the orchestrated and direct invocations. Was it the exact invocation flags? Was I missing a --batch or --quick mode? Maybe an environment variable set somewhere in that halfway-documented pile of perl? It appears I looked first in all the wrong places.
It turns out that mysqltest runs all its exec commands through popen i.e. as piped subprocesses so as to collect the output; thus, its mysql was running with block buffering on stdout while mine was line buffered. So piping the output or even just redirecting it to a file did the trick, showing the error before the output of the earlier queries but after that peculiar blank line. I wasn't sure how such output redirection would mix with an interactive gdb session; handily, gdb itself implements some usual shell redirection operators when starting the target program ("run" command).
I found where that initial newline was coming from at the mysql level, and more interestingly how it was bypassing the usual block buffering at the musl level. The FILE object for stdout is initially line buffered (musl/src/stdio/stdout.c); the first time the buffer is filled or a newline is written (fwrite.c), a special case first-time write routine for stdout (__stdout_write.c) checks whether the output is to a terminal, sets the mode accordingly, switches a pointer to the real write routine (__stdio_write.c), and finishes by calling that to flush the data as requested. It makes perfect sense from an implementation standpoint: simple and efficient, unobtrusive, functionally invisible in the line buffered case, and in the block buffered case just flushing earlier than strictly necessary the first time around. It's hard to find any fault with it, since correctly written programs (ahem) won't depend on such minutiae of buffering behavior.
Which brings us finally to the real culprit: a bizarre mysql.cc change which the git history dates to 2003, purporting to fix an unspecified bug in error message printing. The prior code sensibly flushed stdout before writing to stderr; the change hides all destinations for the put_info function behind a "file" misdirection variable, lumping them all into the same thing so that stderr gets an extra fflush or two and stdout gets none. Then a 2005 update to the mysql.test case, rather than noticing the strange, locked it in with the glibc flavor.
And the moral of the story is... I dunno, birds of a feather get stupid together? I'll revert the antifix, update the expected result, then perhaps I'd better take a closer look at what if anything the original flaw might have been. Then MySQL on Gales will always show the sensible, in-order interleaving of error and output lines.
- Alternatively, for explicit programmer control, the whole stdio mess can be bypassed in favor of more direct system calls; these are relatively standardized at the level of POSIX, which includes most operating systems of interest these days but not DOS/Windows. [^]