bug#25740: Error reporting with confess mangles messages

classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

bug#25740: Error reporting with confess mangles messages

Christophe de Dinechin
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.


Reply | Threaded
Open this post in threaded view
|

bug#25740: [PATCH] Swallow m4traces that have no file/line number

Christophe de Dinechin
The symptoms are something like:

  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

The root cause is m4 traces without a file/line number shown.

So instead of something like:

   m4trace:configure.ac:48: -1- ...

you have something like:

  m4trace: -1- ...

In the scenarios I ran into, this is due to some error that throws m4 out.
Eliminating these messages from the temporary m4 file being generated
(which will not complete anyway) is sufficient for the rest of autoconf
to complete, until it prints errors.

In my case, the final error looks like:

  common/Makefile.am:20: error: Libtool library used but 'LIBTOOL' is undefined
  common/Makefile.am:20:   The usual way to define 'LIBTOOL' is to add 'LT_INIT'
  common/Makefile.am:20:   to 'configure.ac' and run 'aclocal' and 'autoconf' again.
  common/Makefile.am:20:   If 'LT_INIT' is in 'configure.ac', make sure
  common/Makefile.am:20:   its definition is in aclocal's search path.
  autoreconf: automake failed with exit status: 1

But I've seen various reports for other root causes that ran into the same
problem (see bug report)

Signed-off-by: Christophe de Dinechin <[hidden email]>
---
 bin/autom4te.in | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/bin/autom4te.in b/bin/autom4te.in
index 964ac1a..b3f3831 100644
--- a/bin/autom4te.in
+++ b/bin/autom4te.in
@@ -821,6 +821,8 @@ EOF
   my $traces = new Autom4te::XFile ($tcache . $req->id, "<");
   while ($_ = $traces->getline)
     {
+      # Traces without file/line
+      next if (m{^m4trace: -(\d+)- ([^(]+)\((.*)$});
       # Trace with arguments, as the example above.  We don't try
       # to match the trailing parenthesis as it might be on a
       # separate line.
--
2.10.1 (Apple Git-78)




Reply | Threaded
Open this post in threaded view
|

bug#25740: [PATCH] Swallow m4traces that have no file/line number

Eric Blake-3
autom4te is maintained by autoconf, not automake; redirecting your patch
there.

On 03/07/2017 04:00 PM, Christophe de Dinechin wrote:

> The symptoms are something like:
>
>   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
>
> The root cause is m4 traces without a file/line number shown.
>
> So instead of something like:
>
>    m4trace:configure.ac:48: -1- ...
>
> you have something like:
>
>   m4trace: -1- ...
>
> In the scenarios I ran into, this is due to some error that throws m4 out.
> Eliminating these messages from the temporary m4 file being generated
> (which will not complete anyway) is sufficient for the rest of autoconf
> to complete, until it prints errors.
>
> In my case, the final error looks like:
>
>   common/Makefile.am:20: error: Libtool library used but 'LIBTOOL' is undefined
>   common/Makefile.am:20:   The usual way to define 'LIBTOOL' is to add 'LT_INIT'
>   common/Makefile.am:20:   to 'configure.ac' and run 'aclocal' and 'autoconf' again.
>   common/Makefile.am:20:   If 'LT_INIT' is in 'configure.ac', make sure
>   common/Makefile.am:20:   its definition is in aclocal's search path.
>   autoreconf: automake failed with exit status: 1
>
> But I've seen various reports for other root causes that ran into the same
> problem (see bug report)
>
> Signed-off-by: Christophe de Dinechin <[hidden email]>
> ---
>  bin/autom4te.in | 2 ++
>  1 file changed, 2 insertions(+)
>
> diff --git a/bin/autom4te.in b/bin/autom4te.in
> index 964ac1a..b3f3831 100644
> --- a/bin/autom4te.in
> +++ b/bin/autom4te.in
> @@ -821,6 +821,8 @@ EOF
>    my $traces = new Autom4te::XFile ($tcache . $req->id, "<");
>    while ($_ = $traces->getline)
>      {
> +      # Traces without file/line
> +      next if (m{^m4trace: -(\d+)- ([^(]+)\((.*)$});
Would it be better to keep the error message, but set the file and line
to placeholders, instead of completely discarding the message?

>        # Trace with arguments, as the example above.  We don't try
>        # to match the trailing parenthesis as it might be on a
>        # separate line.
>

--
Eric Blake   eblake redhat com    +1-919-301-3266
Libvirt virtualization library http://libvirt.org


signature.asc (617 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

bug#25740: [PATCH] Swallow m4traces that have no file/line number

Christophe de Dinechin

On 7 Mar 2017, at 23:51, Eric Blake <[hidden email]> wrote:

autom4te is maintained by autoconf, not automake; redirecting your patch
there.

On 03/07/2017 04:00 PM, Christophe de Dinechin wrote:
The symptoms are something like:

 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

The root cause is m4 traces without a file/line number shown.

So instead of something like:

  m4trace:configure.ac:48: -1- ...

you have something like:

 m4trace: -1- ...

In the scenarios I ran into, this is due to some error that throws m4 out.
Eliminating these messages from the temporary m4 file being generated
(which will not complete anyway) is sufficient for the rest of autoconf
to complete, until it prints errors.

In my case, the final error looks like:

 common/Makefile.am:20: error: Libtool library used but 'LIBTOOL' is undefined
 common/Makefile.am:20:   The usual way to define 'LIBTOOL' is to add 'LT_INIT'
 common/Makefile.am:20:   to 'configure.ac' and run 'aclocal' and 'autoconf' again.
 common/Makefile.am:20:   If 'LT_INIT' is in 'configure.ac', make sure
 common/Makefile.am:20:   its definition is in aclocal's search path.
 autoreconf: automake failed with exit status: 1

But I've seen various reports for other root causes that ran into the same
problem (see bug report)

Signed-off-by: Christophe de Dinechin <[hidden email]>
---
bin/autom4te.in | 2 ++
1 file changed, 2 insertions(+)

diff --git a/bin/autom4te.in b/bin/autom4te.in
index 964ac1a..b3f3831 100644
--- a/bin/autom4te.in
+++ b/bin/autom4te.in
@@ -821,6 +821,8 @@ EOF
  my $traces = new Autom4te::XFile ($tcache . $req->id, "<");
  while ($_ = $traces->getline)
    {
+      # Traces without file/line
+      next if (m{^m4trace: -(\d+)- ([^(]+)\((.*)$});

Would it be better to keep the error message, but set the file and line
to placeholders, instead of completely discarding the message?

I had tried, and that works too in my case. I.e. you can use if this seems to be better:

Subject: [PATCH 2/2] Alternate fix for #25740 (error reporting mangles
 messages)

The symptoms are something like:

  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

The root cause is m4 traces without a file/line number shown.

So instead of something like:

   m4trace:configure.ac:48: -1- ...

you have something like:

  m4trace: -1- ...

In the scenarios I ran into, this is due to some error that throws m4 out.
Eliminating these messages from the temporary m4 file being generated
(which will not complete anyway) is sufficient for the rest of autoconf
to complete, until it prints errors.

In my case, the final error looks like:

  common/Makefile.am:20: error: Libtool library used but 'LIBTOOL' is undefined
  common/Makefile.am:20:   The usual way to define 'LIBTOOL' is to add 'LT_INIT'
  common/Makefile.am:20:   to 'configure.ac' and run 'aclocal' and 'autoconf' again.
  common/Makefile.am:20:   If 'LT_INIT' is in 'configure.ac', make sure
  common/Makefile.am:20:   its definition is in aclocal's search path.
  autoreconf: automake failed with exit status: 1

But I've seen various reports for other root causes that ran into the same
problem (see bug report)

Signed-off-by: Christophe de Dinechin <[hidden email]>
---
 bin/autom4te.in | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/bin/autom4te.in b/bin/autom4te.in
index b3f3831..406ebfe 100644
--- a/bin/autom4te.in
+++ b/bin/autom4te.in
@@ -821,8 +821,6 @@ EOF
   my $traces = new Autom4te::XFile ($tcache . $req->id, "<");
   while ($_ = $traces->getline)
     {
-      # Traces without file/line
-      next if (m{^m4trace: -(\d+)- ([^(]+)\((.*)$});
       # Trace with arguments, as the example above.  We don't try
       # to match the trailing parenthesis as it might be on a
       # separate line.
@@ -831,6 +829,8 @@ EOF
       # Traces without arguments, always on a single line.
       s{^m4trace:(.+):(\d+): -(\d+)- ([^)]*)\n$}
        {AT_$4([$1], [$2], [$3], [$4])\n};
+      s{^m4trace: -(\d+)- ([^(]+)\((.*)$}
+       {AT_$2([nowhere], [0], [$1], [$2], $3};
       print $trace_m4 "$_";
     }
   $trace_m4->close;
-- 
2.10.1 (Apple Git-78)


I thought discarding lines that did not seem to correspond to any known file was more efficient and less risky.


      # Trace with arguments, as the example above.  We don't try
      # to match the trailing parenthesis as it might be on a
      # separate line.


-- 
Eric Blake   eblake redhat com    +1-919-301-3266
Libvirt virtualization library http://libvirt.org