Subject: bug#25740: Error reporting with confess mangles messages

From: Christophe de Dinechin <[email-masked]>
Date: Wed, 15 Feb 2017 10:02:03 +0100

I had the following output from running autogen.sh in the spice project on macOS:

Use of uninitialized value $msg in concatenation (.) or string at /usr/local/Cellar/autoconf/2.69/bin/autom4te line 1032.
Use of uninitialized value $stacktrace in pattern match (m//) at /usr/local/Cellar/autoconf/2.69/bin/autom4te line 1032.
unknown channel m4trace: -1- AS_VAR_APPEND(ac_configure_args, " '$ac_arg'")
 at /usr/local/Cellar/autoconf/2.69/share/autoconf/Autom4te/Channels.pm line 638.
    Autom4te::Channels::msg('m4trace: -1- AS_VAR_APPEND(ac_configure_args, " \'$ac_arg\'")\x{a}', undef, 'warning: ', 'partial', 0) called at /usr/local/Cellar/autoconf/2.69/bin/autom4te line 1032

This is with automake 1.15 and autoconf 2.69, installed using Homebrew.

Google search showed that this kind of error pops up rather frequently, here are a few examples:
	https://github.com/jedisct1/libsodium/issues/217
	https://lists.samba.org/archive/samba/2009-November/152184.html
	https://lists.gnu.org/archive/html/autoconf/2016-12/msg00003.html
	http://lists-archives.com/samba/49430-autogen-sh-failing-over-samba-share.html
	http://dangerousprototypes.com/forum/viewtopic.php?f=37&t=3957
	http://samba.2283325.n4.nabble.com/autogen-sh-failing-over-samba-share-td2456468.html

Notice how in at least two cases, there is no follow up, because the message gives no clue at what is actually happening.

I added the following instrumentation in autom4te around line 1015:

  open (my $fh, '>', '/tmp/perldebug');
  print $fh "-- Begin warnings --\n";
  print $fh contents ("$tmp/warnings”);
  print $fh "-- End warnings --\n";
  print $fh "Separator '$separator'\n";
  close($fh);

  # Swallow excessive newlines.
  for (split (/\n*$separator\n*/o, contents ("$tmp/warnings")))

What this showed is that, at that stage, the message was apparently perfectly legitimate, but nowhere to be found on the console output:

 -- Begin warnings —
obsolete::configure.ac:34::'AM_CONFIG_HEADER': this macro is obsolete.
You should use the 'AC_CONFIG_HEADERS' macro instead.::/usr/local/Cellar/automake/1.15/share/aclocal-1.15/obsolete.m4:15: AM_CONFIG_HEADER is expanded from...
configure.ac:34: the top level
------------------------- END OF WARNING -------------------------

obsolete::configure.ac:189::The macro `AC_TRY_CPP' is obsolete.
You should run autoupdate.::../../lib/autoconf/general.m4:2530: AC_TRY_CPP is expanded from...
configure.ac:189: the top level
------------------------- END OF WARNING -------------------------

obsolete::configure.ac:286::AC_OUTPUT should be used without arguments.
You should run autoupdate.::
------------------------- END OF WARNING -------------------------

m4trace: -1- AS_VAR_APPEND(ac_configure_args, " '$ac_arg'")
-- End warnings —

The original message seems to be coming from Channels.pm around line 642, a line that reads:

  confess "unknown channel $channel" unless exists $channels{$channel};

The same kind of instrumentation added there

	open (my $fh, '>', '/tmp/perldebug');
	print $fh "Unknown channel $channel - We are going to die horribly\n";
 	close($fh);

This instrumentation showed that the channel name at that level is legit (it’s “fatal”), nothing like the mangled ‘m4trace: -1…’ mangled stuff that is later sent to the console:

	Unknown channel fatal - We are going to die horribly

I also checked that the Perl installation is not the problem with the following test:

	use Carp qw/croak confess/;
	sub zoo ()
	{
	    confess "Boo, I'm dead";
	}
	sub bar () { zoo(); }
	sub foo () { bar(); }
	foo();

This results in the expected output:

	Boo, I'm dead at /tmp/truc.pl line 4.
	    main::zoo() called at /tmp/truc.pl line 6
	    main::bar() called at /tmp/truc.pl line 7
	    main::foo() called at /tmp/truc.pl line 8

I’ll keep investigating, but I thought this was worth a bug report as is.