Re: [Boost-build] module_action test broken by Boost.Jam changes.

From: Jurko Gospodnetiæ (jurko.gospodnetic_at_[hidden])
Date: 2007-12-23 19:04:31

   Hi.

   It seems that after latest 'record_time' interface fixes by Rene the 
timedata test is broken for the same reason as module_action. Boost.Jam 
when run by these tests no longer pipes any action output to stdout.

   A bit of playing around showed me that the difference is in how the 
-d0 Boost.Jam flag is handled. Before that meant no messages except 
those explicitly displayed by the build scripts - using either rules or 
actions. Now it no longer displays action output. I guess this new 
behavior is more in line with its description under 'bjam 
--help-options' but not having the old behavior available causes 
problems for automated output testing.

   BoostBuild.py specifies the '-d0' flag for all tests it runs and when 
you replace that flag with -d1 then action output appears but so do 
executed action names as well as status messages like '...found 4 
targets...' or '...updated 3 targets...'.

   I looked into using the ACTION_RULE__ rule and have attached a patch 
for the timedata test that makes it pass on Windows with the new -d0 
semantics using that rule. Besides using the __ACTION_RULE__ rule the 
test needed slight tweaks in the used regular expressions in order to 
cope with additional end-of-line characters in the output.

   I found no way to avoid problems with end-of-line characters getting 
messed up between each two separate action results. If I display both 
the original command's output and the output received by the 
__ACTION_RULE__ on Windows I get 0xd 0xa characters between them and 0xd 
0xd 0xa 0xd characters after them. Most likely the first 0xd, 0xa are 
added by the command and then Boost.Jam and/or Python mess up with their 
end-of-line handling by twice replacing a trailing 0xa with 0xd 0xa.

   This means that there is now no way for a test to compare the 
complete output constructed of multiple action results (e.g. the 
module_actions test) without resorting to using a complicated regular 
expression to work around extra 0xd & 0xa characters between separate 
action outputs.

   My vote is that this makes action output testing way too convoluted.

   Options I can see at the moment:

   * Refactor tests not to depend on action output directly at all and 
perhaps use the __ACTION_RULE__ instead. Requires fixing the end-of-line 
problem.

   * Update tests to use the -d1 option and compensate for the extra 
output that will result. Requires checking all tests using stdout but 
should not cause false positives.

   * Update Boost.Jam to allow the old -d0 behavior - displaying 
executed action outputs but no Boost.Jam progress messages like those 
mentioned above. Besides reverting to the original behavior, one 
suggestion is to update debug levels as follows:
      -d0 = As 'bjam help-options' says - only errors are reported. Only 
rules may output and that is allowed only so build scripts could output 
additional error messages. There should also be a way for scripts to 
detect this level so they can avoid displaying non-error messages.
      -d1 = As -d0 was before - no Boost.Jam or Boost Build progress 
messages. Only explicit build script and action output is displayed. 
That would be the level used by most tests.
      -d2 = As -d1 is now - display simple Boost.Jam and Boost Build 
progress messages, including names of non-quiet actions.
      -d3 = As -d2 is now...
      etc...

   I prefer the third solution but am unsure whether if that could cause 
too much backward compatibility problems.

   Second solution could work out as well if tests were made to run with 
-d0 by default and be able to specify a different debug level if needed. 
This would take just a minor in BoostBuild.py but all tests relying on 
stdout would need to be rechecked for false positives such as 'expecting 
some output not being displayed to mean that an action has not been run'.

   Any other thoughts on this?

   Anyway, good thing is that these are now the only test failures left 
besides the one I sent related to the alias warnings defect report... :-)

   Hope this helps...

   Best regards,
     Jurko Gospodnetiæ


--- X:\Boost_Build\20071223_nightly_build\Original\boost-build\test\timedata.py	2007-12-23 15:33:26.000000000 +-0100
+++ X:\Boost_Build\20071223_nightly_build\Modified\boost-build\test\timedata.py	2007-12-23 21:21:33.000000000 +-0100
@@ -13,23 +13,29 @@
 rule time
 {
     DEPENDS $(<) : $(>) ;
     __TIMING_RULE__ on $(>) = record_time $(<) ;
     DEPENDS all : $(<) ;
 }
+
 actions time
 {
     echo $(>) user: $(__USER_TIME__) system: $(__SYSTEM_TIME__)
     echo timed from $(>) >> $(<)
 }
 
+rule display-action-output ( args * : target : command status start end user system : output ? )
+{
+    ECHO $(output) ;
+}
+
 rule record_time ( target : source : start end user system )
 {
-    ECHO record_time called: $(target) / $(source) / $(user) / $(system) ;
-    __USER_TIME__ on $(target) = $(user) ;
+    __USER_TIME__   on $(target) = $(user) ;
     __SYSTEM_TIME__ on $(target) = $(system) ;
+    __ACTION_RULE__ on $(target) = display-action-output ;
 }
 
 rule make
 {
     DEPENDS $(<) : $(>) ;
 }
@@ -44,14 +50,14 @@
 ''')
 
 import re
 t.write('baz', 'nothing\n')
 t.run_build_system(
     '-ffile.jam',
-    stdout=r'bar +user: [0-9\.]+ +system: +[0-9\.]+ *$',
+    stdout=r'bar +user: [0-9.]+ +system: +[0-9.]+[ \r\n]*$',
     match = lambda actual,expected: re.search(expected,actual,re.DOTALL)
     )
 t.expect_addition('foo')
 t.expect_addition('bar')
 t.expect_nothing_more()
 
 t.cleanup()