Win32 does not split stdout and stderr properly for log messages

[wbell]

Output from commands isn't interleaved properly on win32 as it is on unix. Typically, you'll see all the stderr output at the top, and the stdout after it.

[trac@…]

I see this on our installation, using Bitten r679. Consider the following log:

make: Entering directory `/d/build/C/src/V10184'
tar: R\://29617//V10184//MINGW32_NT-5.1/file_2: Cannot open: I/O error
make create_install -C scope
tar: Error is not recoverable: exiting now
make[1]: Entering directory `/d/build/C/src/V10184/scope'
make[1]: *** [create_install] Error 1
/d/build/C/src/V10184/scope/maint/scope_issue /d/build/C/src/V10184/scope /d/build/C/V10184_localscope 4.29617.V10184 29617 V10184
make: *** [create_install] Error 2
/d/build/C/src/V10184/scope/..
Ensuring that tgt_data directory is up to date
Ensuring that types directory is up to date
Ensuring that tgtruntime directory is up to date
Ensuring that create directory is up to date
Ensuring that dcl directory is up to date
Ensuring that utility directory is up to date
Ensuring that wsave directory is up to date
Copying mgl library files to wsave
Copying mimicedit files to wsave
Copying XTEL files to wsave
Copying std library files to wsave
Copying TREND VIEW files to wsave
Generating LOAD_ALL_UTIL
Ensuring that workstation server configuration files are up to date
Ensuring that workstation server is up to date
Saving s_extract_unbundled
Saving Copyright File
Saving install_unbundled
   Failed, exiting!
make[1]: Leaving directory `/d/build/C/src/V10184/scope'
make: Leaving directory `/d/build/C/src/V10184'

The following lines are in stderr and should come before the line that reads Failed, exiting!

tar: R\://29617//V10184//MINGW32_NT-5.1/file_2: Cannot open: I/O error
tar: Error is not recoverable: exiting now

And these lines should come after Failed, exiting!

make[1]: *** [create_install] Error 1
make: *** [create_install] Error 2

[osimons]

Patch that combines stdout and stderr command output on Windows.

[osimons]

I've made a patch for this. It joins stdout and stderr at the command-level, so the price to pay is no more nicely formatted error lines in logs from Windows slaves - lines that looked good, but usually was completely out of context...

Could you please invalidate the failing build, and try the output again with patch and compare?

[osimons]

Oh, one problem. Command output errors will not be detected as no errors will be recorded, and hence steps won't fail as expected. Hmm. Some more thinking needed.

[osimons]

Actually, they don't seem to be anyway - as cmd.exe always returns 0 if it manages to execute the command, regardless of how the command behaves.

[trac@…]

Hi, I've tested this patch on one of my windows build slaves and it seems to work (i.e. the logs are now in the correct and it still recognises the build as failed.)

I've not tested it on any of our other platforms as the builds are all succeeding (and some take more than 4 hours to complete) though I could engineer a test if you really think it would be necessary. (They are various Solarises, HP-UX and Linuxes.)

Thanks for your work.

[anonymous]

Replying to trac@…:

Hi, I've tested this patch on one of my windows build slaves and it seems to work (i.e. the logs are now in the correct and it still recognises the build as failed.)

Well, it seems to work except for the fact that stuff printed to stderr is no longer red, which I guess it what you meant by sacrificing the nice formatting.

[osimons]

Replying to trac@…:

Hi, I've tested this patch on one of my windows build slaves and it seems to work (i.e. the logs are now in the correct and it still recognises the build as failed.)

Thanks for testing, and happy that it is working. I'm currently also playing with using subprocess.Popen() as alternative for all slaves >= Python 2.4, so that may even bring the highlighting back.

I've not tested it on any of our other platforms as the builds are all succeeding (and some take more than 4 hours to complete) though I could engineer a test if you really think it would be necessary. (They are various Solarises, HP-UX and Linuxes.)

The patch is fully contained inside a if os.name == 'nt' conditional, and should not affect any behaviour on other platforms. Other testing than NT/Win32 won't be needed.

The command-line processing is quite an important bit of Bitten code, so I'll keep trying some alternative approaches too before committing any changes. Stay tuned!

Replying to anonymous:

Well, it seems to work except for the fact that stuff printed to stderr is no longer red, which I guess it what you meant by sacrificing the nice formatting.

Correct - this patch joins stdout and stderr when calling the process (2>&1), so all Bitten receives is stdout content.

[osimons]

Alternative execute() that uses subprocess module if available (identical support for Windows and Posix).

[osimons]

In attachment:t256-subprocess-r687.diff​ I've made a third alternative to the execute() method, that uses subprocess module for all execution. I've made it default for both Windows and Posix if the module is available - which it is if slave is on Python 2.4 or the subprocess module is installed separately.

This patch keeps streams separate, but hopefully corrects the order on Windows - and additionally it implements missing timeout support (see #257).

It works well for my OSX + XP testing, and all unittests pass. However, other real-life testing would be much appreciated/needed....

[osimons]

See also #425 - popen2 module is deprecated, so a subprocess implementation is needed.

[trac@…]

Hi, sorry the delay in testing this, I can only really do it outside of business hours when no-one is making any code changes.

Your new patch seems to work great. I tested on a Windows slave once again and the logs are correctly ordered and correctly highlighted.

Thanks.

[osimons]

Updated subprocess patch with many other command-line fixes from other tickets.

[osimons]

Thanks for testing! I've updated the patch, this time including a lot of other command-line related fixes. In addition to this ticket (#256) and including the original patch for merging stdout and stderr for non-subprocess enabled slaves, it should also solve:

• #257 (missing timeout on windows)
• #425 (popen2 is deprecated)
• #346 (trapping execution errors)
• #311 (trapping command argument errors)
• #262 (add 1 second delay between really short steps for correct ordering)
• #226 (ambiguity for errors/warnings)
• #101 (better logging for os errors)

Could you please also try this latest patch? Should be ready for commit unless you find anything unexpected...

[mgood]

The args test in bitten.recipe will fail even if the recipe command allows for kwargs. It looks like ctools:configure may be the only built-in one that does, but you should also check the argspec to see if it allows for kwargs.

[osimons]

Replying to mgood:

The args test in bitten.recipe will fail even if the recipe command allows for kwargs. It looks like ctools:configure may be the only built-in one that does, but you should also check the argspec to see if it allows for kwargs.

Thanks. I hadn't notcied that one - I'd only seen naming of all arguments. Good catch. I've updated my patch to contain:

function_args, has_kwargs = inspect.getargspec(function)[0:3:2]
for arg in args:
    if not arg in function_args or not has_kwargs:

[osimons]

The subprocess-based execute() is committed in [702]. It makes posix and nt clients use the same code and work more or less the same. For non-subprocess Windows slaves it includes the redirection of stderr to stdout meaning logs arrive in correct order, but errors won't be highlighted as all Bitten sees is regular output.

[Mat Booth <trac@…>]

I tested this again this evening (r708) and everything still works. ;-)