Edgewall Software
Modify

Opened 14 years ago

Closed 12 years ago

Last modified 12 years ago

#256 closed defect (fixed)

Win32 does not split stdout and stderr properly for log messages

Reported by: wbell Owned by: osimons
Priority: minor Milestone: 0.6
Component: Build slave Version: dev
Keywords: Cc: trac@…
Operating System: Windows

Description

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.

Attachments (3)

t256-win_combine_out_and_err-r687.diff (1.7 KB) - added by osimons 12 years ago.
Patch that combines stdout and stderr command output on Windows.
t256-subprocess-r687.diff (6.4 KB) - added by osimons 12 years ago.
Alternative execute() that uses subprocess module if available (identical support for Windows and Posix).
t256-subprocess-r696.diff (12.9 KB) - added by osimons 12 years ago.
Updated subprocess patch with many other command-line fixes from other tickets.

Download all attachments as: .zip

Change History (18)

comment:1 Changed 12 years ago by trac@…

  • Cc trac@… added
  • Version changed from 0.5.3 to dev

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

Changed 12 years ago by osimons

Patch that combines stdout and stderr command output on Windows.

comment:2 Changed 12 years ago by osimons

  • Owner changed from cmlenz to 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?

comment:3 Changed 12 years ago by 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.

comment:4 Changed 12 years ago by 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.

comment:5 follow-up: Changed 12 years ago by 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.

comment:6 in reply to: ↑ 5 ; follow-up: Changed 12 years ago by 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.

comment:7 in reply to: ↑ 6 Changed 12 years ago by 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.

Changed 12 years ago by osimons

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

comment:8 Changed 12 years ago by 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....

comment:9 Changed 12 years ago by osimons

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

comment:10 Changed 12 years ago by 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.

Changed 12 years ago by osimons

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

comment:11 Changed 12 years ago by 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...

comment:12 follow-up: Changed 12 years ago by 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.

comment:13 in reply to: ↑ 12 Changed 12 years ago by 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:

comment:14 Changed 12 years ago by osimons

  • Component changed from Recipe commands to Build slave
  • Resolution set to fixed
  • Status changed from new to closed

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.

comment:15 Changed 12 years ago by Mat Booth <trac@…>

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

Add Comment

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain osimons.
The resolution will be deleted. Next status will be 'reopened'.
Author


E-mail address and user name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.