BZ 6701 - Improve error messages (patch)

BZ 6701 - Improve error messages (patch)

[Rajan Arora]

[-- Attachment #1: Type: text/plain, Size: 1504 bytes --]

Hi:

 This is a proposed patch for the Bugzilla bug 6701 
(http://sources.redhat.com/bugzilla/show_bug.cgi?id=6701) to improve 
error/warning messages with source context. After application of the 
patch, error/warning messages should be followed by a handy ``source: " 
line and an ascii `^' character in the following line pointing at the 
exact column. Hence, displaying the line and column where the error was 
encountered and in case of some parse errors, the last source line 
visited. Improvements have been made by adding a ``print_error_source'' 
method to the systemtap_session struct which does the actual work of 
displaying the error causing line and col once it has been encountered. 
New error messages look something like this:

# stap -ve 'probe begin { log("hello world") exit () }'
Pass 1: parsed user script and 45 library script(s) in 150usr/10sys/172real ms.
semantic error: unresolved arity-0 function: identifier 'exxit' at <input>:1:34
        source: probe begin { log("hello world") exxit () }
                                                 ^


Changes have been made to testsuite/systemtap.base/warnings.exp so it 
recognizes the ``source: " lines and those with the `^' character. A 
test script has also been added to the testuite/parseko directory. The 
following patch file may be applied to have a feel of how it looks and 
any suggestions/comments are welcome. Since, this is my first patch, I 
hope I can improve this with some feedback from the group.

best,
-Rajan

[-- Attachment #2: 6701-e.patch --]
[-- Type: text/x-patch, Size: 7145 bytes --]

diff --git a/ChangeLog b/ChangeLog
index ea1d51d..e84aac6 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,3 +1,16 @@
+2008-09-30  Rajan Arora   <rarora@redhat.com>
+
+	* elaborate.cxx (systemtap_session::print_error_source): New.
+	(systemtap_session::print_error): Call it.
+	(systemtap_session::print_warning): Likewise.
+	* parse.cxx (parser::print_error): Likewise.
+	* session.h (struct systemtap_session::print_error_source):
+	Declare it.
+	* parse.cxx (lexer::get_input_contents): New.
+	(parser::parser): Call it.
+	* parse.h (class lexer::get_input_contents): Declare it.
+	* staptree.h (struct stapfile): New member file_contents.
+
 2008-09-30  Mark Wielaard  <mjw@redhat.com>
 
 	* tapsets.cxx (literal_stmt_for_local): Check if alternatives can be
diff --git a/elaborate.cxx b/elaborate.cxx
index 94bfd1c..9ead814 100644
--- a/elaborate.cxx
+++ b/elaborate.cxx
@@ -1425,6 +1425,7 @@ void
 systemtap_session::print_error (const semantic_error& e)
 {
   string message_str[2];
+  stringstream errormsg;
 
   // NB: we don't print error messages during listing mode.
   if (listing_mode) return;
@@ -1461,6 +1462,20 @@ systemtap_session::print_error (const semantic_error& e)
     {
       seen_errors.insert (message_str[1]);
       cerr << message_str[0];
+
+      //Do file_contents exist? If not, error is in tapset!
+      if (e.tok1 && user_file->file_contents.size() != 0)
+        {
+          errormsg.str ("");
+          print_error_source (errormsg, user_file->file_contents, e.tok1);
+          cerr << errormsg.str();
+        }
+      if (e.tok2 && user_file->file_contents.size() != 0)
+        {
+          errormsg.str ("");
+          print_error_source (errormsg, user_file->file_contents, e.tok2);
+          cerr << errormsg.str();
+        }
     }
 
   if (e.chain)
@@ -1468,15 +1483,41 @@ systemtap_session::print_error (const semantic_error& e)
 }
 
 void
+systemtap_session::print_error_source (std::stringstream& message,
+                                       std::string& file_contents, const token* tok)
+{
+  unsigned i = 0;
+  unsigned line = tok->location.line;
+  unsigned col = tok->location.column;
+  size_t start_pos = 0, end_pos = 0;
+  //Navigate to the appropriate line
+  while (i != line && end_pos != std::string::npos)
+    {
+      start_pos = end_pos;
+      end_pos = file_contents.find ('\n', start_pos) + 1;
+      i++;
+    }
+  message << "\tsource: " << file_contents.substr (start_pos, end_pos-start_pos-1) << endl;
+  message << "\t        ";
+  message.fill (' ');
+  message.width (col);
+  message << "^" << endl;
+}
+
+void
 systemtap_session::print_warning (const string& message_str, const token* tok)
 {
   // Duplicate elimination
+  stringstream message;
   if (seen_warnings.find (message_str) == seen_warnings.end())
     {
       seen_warnings.insert (message_str);
       clog << "WARNING: " << message_str;
       if (tok) { clog << ": "; print_token (clog, tok); }
       clog << endl;
+      message.str ("");
+      print_error_source (message, user_file->file_contents, tok);
+      clog << message.str();
     }
 }
 
diff --git a/parse.cxx b/parse.cxx
index 1c1772f..7848250 100644
--- a/parse.cxx
+++ b/parse.cxx
@@ -124,17 +124,28 @@ operator << (ostream& o, const token& t)
 void
 parser::print_error  (const parse_error &pe)
 {
+  stringstream error_source;
+  string input_contents;
+  input.get_input_contents (input_contents);
   cerr << "parse error: " << pe.what () << endl;
 
   if (pe.tok)
     {
       cerr << "\tat: " << *pe.tok << endl;
+      error_source.str ("");
+      session.print_error_source (error_source, input_contents, pe.tok);
+      cerr << "     " << error_source.str ();
     }
   else
     {
       const token* t = last_t;
       if (t)
-        cerr << "\tsaw: " << *t << endl;
+	{
+	  cerr << "\tsaw: " << *t << endl;
+	  error_source.str ("");
+	  session.print_error_source (error_source, input_contents, t);
+	  cerr << error_source.str ();
+	}
       else
         cerr << "\tsaw: " << input_name << " EOF" << endl;
     }
@@ -588,6 +599,13 @@ lexer::lexer (istream& i, const string& in, systemtap_session& s):
     input_contents.push_back(c);
 }
 
+void
+lexer::get_input_contents (std::string& file_contents)
+{
+  unsigned i;
+  for (i=0; i<input_contents.size(); i++)
+    file_contents += input_contents[i];
+}
 
 int
 lexer::input_peek (unsigned n)
@@ -1021,6 +1039,9 @@ parser::parse ()
       delete f;
       return 0;
     }
+  //Assuming tapsets are error-free, only user's script contents are fetched
+  if (!strstr (input_name.c_str(),"tapset/"))
+    input.get_input_contents (f->file_contents);
 
   return f;
 }
diff --git a/parse.h b/parse.h
index cf31f4f..84ba572 100644
--- a/parse.h
+++ b/parse.h
@@ -71,6 +71,7 @@ class lexer
 public:
   token* scan (bool wildcard=false);
   lexer (std::istream&, const std::string&, systemtap_session&);
+  void get_input_contents (std::string&);
 
 private:
   int input_get ();
diff --git a/session.h b/session.h
index b8bd971..9f272b3 100644
--- a/session.h
+++ b/session.h
@@ -179,6 +179,7 @@ struct systemtap_session
   const token* last_token;
   void print_token (std::ostream& o, const token* tok);
   void print_error (const semantic_error& e);
+  void print_error_source (std::stringstream&, std::string&, const token* tok);
   void print_warning (const std::string& w, const token* tok = 0);
 
   // reNB: new POD members likely need to be explicitly cleared in the ctor.
diff --git a/staptree.h b/staptree.h
index 770a731..ac229c7 100644
--- a/staptree.h
+++ b/staptree.h
@@ -574,6 +574,7 @@ struct stapfile
   std::vector<functiondecl*> functions;
   std::vector<vardecl*> globals;
   std::vector<embeddedcode*> embeds;
+  std::string file_contents;
   bool privileged;
   stapfile (): privileged (false) {}
   void print (std::ostream& o) const;
diff --git a/testsuite/ChangeLog b/testsuite/ChangeLog
index f3fad07..f3b8ca4 100644
--- a/testsuite/ChangeLog
+++ b/testsuite/ChangeLog
@@ -1,3 +1,8 @@
+2008-09-26  Rajan Arora   <rarora@redhat.com>
+
+	* systemtap.base/warnings.exp: Allow for source: lines.
+	* parseko/source_context.stp: New file.
+
 2008-09-26  Frank Ch. Eigler  <fche@elastic.org>
 
 	PR 6916.
diff --git a/testsuite/parseko/source_context.stp b/testsuite/parseko/source_context.stp
new file mode 100755
index 0000000..e718d9e
--- /dev/null
+++ b/testsuite/parseko/source_context.stp
@@ -0,0 +1,11 @@
+global count_test
+probe timer.ms(123)
+{
+printf("%d loops have executed\n",count_test)
+count_test ++
+iffff(count_test == 5)
+{
+priiintf("Done execution 5 times and about to exit. . .\n")
+   eeexit ()
+}
+}
diff --git a/testsuite/systemtap.base/warnings.exp b/testsuite/systemtap.base/warnings.exp
index a90860d..f6bfa34 100644
--- a/testsuite/systemtap.base/warnings.exp
+++ b/testsuite/systemtap.base/warnings.exp
@@ -6,6 +6,8 @@ expect {
     -timeout 30
     -re {^WARNING:[^\r\n]*\r\n} { incr ok; exp_continue }
     -re {^[^\r\n]*.ko\r\n} { incr ok; exp_continue }
+    -re {^source:[^\r\n]*\r\n} {exp_continue}
+    -re {^[^\r\n]*\^[^\r\n]*\r\n} {exp_continue}
     timeout { fail "$test (timeout)" }
     eof { }
 }

Re: BZ 6701 - Improve error messages (patch)

[Frank Ch. Eigler]

Hi, Rajan -


> This is a proposed patch for the Bugzilla bug 6701 [...]

Thanks, nice work!


> # stap -ve 'probe begin { log("hello world") exit () }'
> Pass 1: parsed user script and 45 library script(s) in 150usr/10sys/172real ms.
> semantic error: unresolved arity-0 function: identifier 'exxit' at <input>:1:34
>        source: probe begin { log("hello world") exxit () }
>                                                 ^

Please check the rendering heuristics for the case of the inputs
containing tabs and for lines perhaps too long to draw in their
entirety.


> +      //Do file_contents exist? If not, error is in tapset!
> +      if (e.tok1 && user_file->file_contents.size() != 0)
> +        {
> +          errormsg.str ("");
> +          print_error_source (errormsg, user_file->file_contents, e.tok1);
> +          cerr << errormsg.str();
> +        }

For this and similar cases, is there some reason for the errormsg
object?  Would this not work just as well?

             print_error_source (cerr, user_file->file_contents, e.tok1);



> +systemtap_session::print_error_source (std::stringstream& message,
> +                                       std::string& file_contents, const token* tok)
> +{
> [...]
> +  message << "\tsource: " << file_contents.substr (start_pos, end_pos-start_pos-1) << endl;
> +  message << "\t        ";
> +  message.fill (' ');
> +  message.width (col);
> +  message << "^" << endl;

Yeah, this won't work right if the input contains tabs.  Instead of
the .fill()/.width() way of lining up with the input, you could try
looping over the contents of file_contents[start_pos .. end_pos].  You
could copy each isspace(char) and emit a ' ' otherwise.


> +void
> +lexer::get_input_contents (std::string& file_contents)
> +{
> +  unsigned i;
> +  for (i=0; i<input_contents.size(); i++)
> +    file_contents += input_contents[i];
> +}

Could you look into making that input_contents[] widget into a plain
std::string?  That should turn this into a simple assignment ...
or rather a "return input_contents;" - the function might as well
return a std::string instead of a value by reference.


>  int
>  lexer::input_peek (unsigned n)
> [...]
> +  //Assuming tapsets are error-free, only user's script contents are fetched
> +  if (!strstr (input_name.c_str(),"tapset/"))
> +    input.get_input_contents (f->file_contents);

Nothing's error free :-) ... except my wife's mother.  Drop this
assumption - we can have semantic errors that occur with e.g. $context
variables or probe points that exist only on a ragtag collection of
kernel versions.


> +++ b/testsuite/parseko/source_context.stp
> @@ -0,0 +1,11 @@
> +global count_test
> +probe timer.ms(123)
> +{
> +printf("%d loops have executed\n",count_test)
> +count_test ++
> +iffff(count_test == 5)
> +{
> +priiintf("Done execution 5 times and about to exit. . .\n")
> +   eeexit ()
> +}
> +}

OK (though one error per file might be more assertive).


- FChE

Re: BZ 6701 - Improve error messages (patch)

[Frank Ch. Eigler]

Hi, Rajan -


> This is a proposed patch for the Bugzilla bug 6701 [...]

Thanks, nice work!


> # stap -ve 'probe begin { log("hello world") exit () }'
> Pass 1: parsed user script and 45 library script(s) in 150usr/10sys/172real ms.
> semantic error: unresolved arity-0 function: identifier 'exxit' at <input>:1:34
>        source: probe begin { log("hello world") exxit () }
>                                                 ^

Please check the rendering heuristics for the case of the inputs
containing tabs and for lines perhaps too long to draw in their
entirety.


> +      //Do file_contents exist? If not, error is in tapset!
> +      if (e.tok1 && user_file->file_contents.size() != 0)
> +        {
> +          errormsg.str ("");
> +          print_error_source (errormsg, user_file->file_contents, e.tok1);
> +          cerr << errormsg.str();
> +        }

For this and similar cases, is there some reason for the errormsg
object?  Would this not work just as well?

             print_error_source (cerr, user_file->file_contents, e.tok1);



> +systemtap_session::print_error_source (std::stringstream& message,
> +                                       std::string& file_contents, const token* tok)
> +{
> [...]
> +  message << "\tsource: " << file_contents.substr (start_pos, end_pos-start_pos-1) << endl;
> +  message << "\t        ";
> +  message.fill (' ');
> +  message.width (col);
> +  message << "^" << endl;

Yeah, this won't work right if the input contains tabs.  Instead of
the .fill()/.width() way of lining up with the input, you could try
looping over the contents of file_contents[start_pos .. end_pos].  You
could copy each isspace(char) and emit a ' ' otherwise.


> +void
> +lexer::get_input_contents (std::string& file_contents)
> +{
> +  unsigned i;
> +  for (i=0; i<input_contents.size(); i++)
> +    file_contents += input_contents[i];
> +}

Could you look into making that input_contents[] widget into a plain
std::string?  That should turn this into a simple assignment ...
or rather a "return input_contents;" - the function might as well
return a std::string instead of a value by reference.


>  int
>  lexer::input_peek (unsigned n)
> [...]
> +  //Assuming tapsets are error-free, only user's script contents are fetched
> +  if (!strstr (input_name.c_str(),"tapset/"))
> +    input.get_input_contents (f->file_contents);

Nothing's error free :-) ... except my wife's mother.  Drop this
assumption - we can have semantic errors that occur with e.g. $context
variables or probe points that exist only on a ragtag collection of
kernel versions.


> +++ b/testsuite/parseko/source_context.stp
> @@ -0,0 +1,11 @@
> +global count_test
> +probe timer.ms(123)
> +{
> +printf("%d loops have executed\n",count_test)
> +count_test ++
> +iffff(count_test == 5)
> +{
> +priiintf("Done execution 5 times and about to exit. . .\n")
> +   eeexit ()
> +}
> +}

OK (though one error per file might be more assertive).


- FChE

Re: BZ 6701 - Improve error messages (updated-patch)

[Rajan Arora]

[-- Attachment #1: Type: text/plain, Size: 506 bytes --]

Hello everyone:

  First of, thanks Frank for all your detailed comments - all 
incorporated, except for taking care of the exceptionally long lines. In 
that case too, the `^' wraps up correctly along with the desired column, 
but the wrapped up source line may cause some issues. Anyhow, the 
alignment works correctly now for tabs in the source line and for that 
matter, spaces mixed with tabs. Please have a look at the updated patch, 
and any further suggestions are more than welcome.

best
-Rajan


[-- Attachment #2: 6701-f.patch --]
[-- Type: text/x-patch, Size: 6494 bytes --]

diff --git a/ChangeLog b/ChangeLog
index 434a2e9..95544c3 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,3 +1,16 @@
+2008-10-02  Rajan Arora   <rarora@redhat.com>
+
+	* elaborate.cxx (systemtap_session::print_error_source): New.
+	(systemtap_session::print_error): Call it.
+	(systemtap_session::print_warning): Likewise.
+	* parse.cxx (parser::print_error): Likewise.
+	* session.h (struct systemtap_session::print_error_source):
+	Declare it.
+	* parse.cxx (lexer::get_input_contents): New.
+	(parser::parser): Call it.
+	* parse.h (class lexer::get_input_contents): Declare it.
+	* staptree.h (struct stapfile): New member file_contents.
+
 2008-09-30  Mark Wielaard  <mjw@redhat.com>
 
 	* tapsets.cxx (literal_stmt_for_local): Check if alternatives can be
diff --git a/elaborate.cxx b/elaborate.cxx
index afdc796..54892fc 100644
--- a/elaborate.cxx
+++ b/elaborate.cxx
@@ -1462,6 +1462,12 @@ systemtap_session::print_error (const semantic_error& e)
     {
       seen_errors.insert (message_str[1]);
       cerr << message_str[0];
+
+      if (e.tok1 && user_file->file_contents.size() != 0)
+        print_error_source (cerr, user_file->file_contents, e.tok1);
+
+      if (e.tok2 && user_file->file_contents.size() != 0)
+        print_error_source (cerr, user_file->file_contents, e.tok2);
     }
 
   if (e.chain)
@@ -1469,6 +1475,34 @@ systemtap_session::print_error (const semantic_error& e)
 }
 
 void
+systemtap_session::print_error_source (std::ostream& message,
+                                       std::string& file_contents, const token* tok)
+{
+  unsigned i = 0;
+  unsigned line = tok->location.line;
+  unsigned col = tok->location.column;
+  size_t start_pos = 0, end_pos = 0;
+  //Navigate to the appropriate line
+  while (i != line && end_pos != std::string::npos)
+    {
+      start_pos = end_pos;
+      end_pos = file_contents.find ('\n', start_pos) + 1;
+      i++;
+    }
+  message << "\tsource: " << file_contents.substr (start_pos, end_pos-start_pos-1) << endl;
+  message << "\t        ";
+  //Navigate to the appropriate column
+  for (i=start_pos; i<start_pos+col-1; i++)
+    {
+      if(isspace(file_contents[i]))
+	message << file_contents[i];
+      else
+	message << ' ';
+    }
+  message << "^" << endl;
+}
+
+void
 systemtap_session::print_warning (const string& message_str, const token* tok)
 {
   // Duplicate elimination
@@ -1478,6 +1512,7 @@ systemtap_session::print_warning (const string& message_str, const token* tok)
       clog << "WARNING: " << message_str;
       if (tok) { clog << ": "; print_token (clog, tok); }
       clog << endl;
+      print_error_source (clog, user_file->file_contents, tok);
     }
 }
 
diff --git a/parse.cxx b/parse.cxx
index 1c1772f..5fd871e 100644
--- a/parse.cxx
+++ b/parse.cxx
@@ -124,17 +124,22 @@ operator << (ostream& o, const token& t)
 void
 parser::print_error  (const parse_error &pe)
 {
+  string input_contents = input.get_input_contents ();
   cerr << "parse error: " << pe.what () << endl;
 
   if (pe.tok)
     {
       cerr << "\tat: " << *pe.tok << endl;
+      session.print_error_source (cerr, input_contents, pe.tok);
     }
   else
     {
       const token* t = last_t;
       if (t)
-        cerr << "\tsaw: " << *t << endl;
+	{
+	  cerr << "\tsaw: " << *t << endl;
+	  session.print_error_source (cerr, input_contents, t);
+	}
       else
         cerr << "\tsaw: " << input_name << " EOF" << endl;
     }
@@ -588,6 +593,11 @@ lexer::lexer (istream& i, const string& in, systemtap_session& s):
     input_contents.push_back(c);
 }
 
+std::string
+lexer::get_input_contents ()
+{
+  return input_contents;
+}
 
 int
 lexer::input_peek (unsigned n)
@@ -1021,6 +1031,7 @@ parser::parse ()
       delete f;
       return 0;
     }
+  f->file_contents = input.get_input_contents ();
 
   return f;
 }
diff --git a/parse.h b/parse.h
index cf31f4f..1f87dcd 100644
--- a/parse.h
+++ b/parse.h
@@ -71,6 +71,7 @@ class lexer
 public:
   token* scan (bool wildcard=false);
   lexer (std::istream&, const std::string&, systemtap_session&);
+  std::string get_input_contents ();
 
 private:
   int input_get ();
@@ -79,7 +80,7 @@ private:
   int input_peek (unsigned n=0);
   std::istream& input;
   std::string input_name;
-  std::vector<char> input_contents;
+  std::string input_contents;
   int input_pointer; // index into input_contents
   unsigned cursor_suspend_count;
   unsigned cursor_line;
diff --git a/session.h b/session.h
index b8bd971..4746422 100644
--- a/session.h
+++ b/session.h
@@ -179,6 +179,7 @@ struct systemtap_session
   const token* last_token;
   void print_token (std::ostream& o, const token* tok);
   void print_error (const semantic_error& e);
+  void print_error_source (std::ostream&, std::string&, const token* tok);
   void print_warning (const std::string& w, const token* tok = 0);
 
   // reNB: new POD members likely need to be explicitly cleared in the ctor.
diff --git a/staptree.h b/staptree.h
index 770a731..ac229c7 100644
--- a/staptree.h
+++ b/staptree.h
@@ -574,6 +574,7 @@ struct stapfile
   std::vector<functiondecl*> functions;
   std::vector<vardecl*> globals;
   std::vector<embeddedcode*> embeds;
+  std::string file_contents;
   bool privileged;
   stapfile (): privileged (false) {}
   void print (std::ostream& o) const;
diff --git a/testsuite/ChangeLog b/testsuite/ChangeLog
index 4825cd2..ec6c451 100644
--- a/testsuite/ChangeLog
+++ b/testsuite/ChangeLog
@@ -1,3 +1,8 @@
+2008-10-02  Rajan Arora   <rarora@redhat.com>
+
+	* systemtap.base/warnings.exp: Allow for source: lines.
+	* parseko/source_context.stp: New file.
+
 2008-10-01  Mark Wielaard  <mjw@redhat.com>
 
 	* semok/thirtythree.stp: Use page->mapping instead of page->inuse
diff --git a/testsuite/parseko/source_context.stp b/testsuite/parseko/source_context.stp
new file mode 100755
index 0000000..403b203
--- /dev/null
+++ b/testsuite/parseko/source_context.stp
@@ -0,0 +1,5 @@
+probe timer.ms(123)
+{
+printf("Probe successful\n")
+				   eeexit ()
+}
diff --git a/testsuite/systemtap.base/warnings.exp b/testsuite/systemtap.base/warnings.exp
index a90860d..f6bfa34 100644
--- a/testsuite/systemtap.base/warnings.exp
+++ b/testsuite/systemtap.base/warnings.exp
@@ -6,6 +6,8 @@ expect {
     -timeout 30
     -re {^WARNING:[^\r\n]*\r\n} { incr ok; exp_continue }
     -re {^[^\r\n]*.ko\r\n} { incr ok; exp_continue }
+    -re {^source:[^\r\n]*\r\n} {exp_continue}
+    -re {^[^\r\n]*\^[^\r\n]*\r\n} {exp_continue}
     timeout { fail "$test (timeout)" }
     eof { }
 }

Re: BZ 6701 - Improve error messages (updated-patch)

[Frank Ch. Eigler]

Hi -

> [...] Please have a look at the updated patch, and any further
> suggestions are more than welcome.

Thanks for going once more around.  I am afraid I noticed one other
largish issue.  That is the multiple-instance hard-coded use of of
session.user_file->input_contents to feed the source printer.  That's
not right, since errors may occur associated with any stapfile.  All
you would have to go on in general is what was given in the
semantic_error object (token pointers).

So what's probably needed here is an additional field in the token
object that points to the stapfile (or perhaps even to the file
contents directly, if identical std::string sharing works properly).

- FChE