MinGW and parallel tests #27

MSP-Greg · 2017-06-20T14:28:24Z

When trying to get make test-spec work parallel, Windows / MinGW has an issue with temp files, often when they're used in a block. Seems to be due to a process not closing all files before ending.

This generates the error in lib/mspec/helpers/tmp.rb at_exit.

I added the following patch file, tests report the same, CAPI *.so files are created, etc. I tested both using make test-spec and mspec.

I'm just not sure if this allows other possible failures/errors/skips to not be reported...

diff --git a/spec/mspec/lib/mspec/commands/mspec.rb b/spec/mspec/lib/mspec/commands/mspec.rb
index 6b4354c2b0..5f90647858 100755
--- a/spec/mspec/lib/mspec/commands/mspec.rb
+++ b/spec/mspec/lib/mspec/commands/mspec.rb
@@ -1,3 +1,4 @@
+# frozen_string_literal: true
 #!/usr/bin/env ruby

 require 'mspec/version'
@@ -7,6 +8,7 @@
 require 'mspec/runner/actions/filter'
 require 'mspec/runner/actions/timer'

+SPEC_WIN = /mswin|mingw/ =~ RUBY_PLATFORM

 class MSpecMain < MSpecScript
   def initialize
@@ -100,7 +102,7 @@ def multi_exec(argv)
     output_files = []
     processes = cores(@files.size)
     children = processes.times.map { |i|
-      name = tmp "mspec-multi-#{i}"
+      name = tmp String.new("mspec-multi-#{i}")
       output_files << name

       env = {
@@ -127,7 +129,7 @@ def multi_exec(argv)
           while chunk = (io.read_nonblock(4096) rescue nil)
             reply += chunk
           end
-          raise reply
+          raise reply unless SPEC_WIN
         end
         io.puts @files.shift unless @files.empty?
       }

The text was updated successfully, but these errors were encountered:

eregon · 2017-06-20T15:00:53Z

Hello,

The raise reply should be kept and the source problem be fixed.

So if I understand, what happens is one of the mspec-run subprocesses do not clear their rubyspec_temp_#{i}, causing the main process to fail?
The warning about non-empty temp dir is printed on STDERR, so it should not be transferred to the parent process but just written directly on stderr in the terminal.

Could you try running with CHECK_LEAKS=true, in both parallel and sequential and post the output?
This should reveal which file descriptor is not closed.
Please also post the failing backtraces and the listing of rubyspec_temp*.

MSP-Greg · 2017-06-20T15:40:22Z

@eregon

Setting CHECK_LEAKS=True doesn't change the output.

The contents of rubyspec_temp are:

1-mspec-multi-0
2-mspec-multi-1
3-mspec-multi-2
4-mspec-multi-3

Log is essentially the same for both make test-spec and mspec. below is make test-spec

ruby 2.5.0dev (2017-06-20 trunk 59122) [x64-mingw32]


[/ |                   0%                     | 00:00:00] �[0;32m     0F �[0;32m     0E�[0m 
[- |                   0%                     | 00:00:00] �[0;32m     0F �[0;32m     0E�[0m 
[\ |                   0%                     | 00:00:00] �[0;32m     0F �[0;32m     0E�[0m 
[| |                   0%                     | 00:00:00] �[0;32m     0F �[0;32m     0E�[0m 
[/ |                   0%                     | 00:00:00] �[0;32m     0F �[0;32m     0E�[0m 
-----------------------------------------------------
The rubyspec temp directory is not empty. Ensure that
all specs are cleaning up temporary files:
  E:/GitHub/ruby-loco/src/build-x86_64/rubyspec_temp
-----------------------------------------------------

E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/commands/mspec.rb:130:in `block in multi_exec': 
 (RuntimeError)
E:/GitHub/ruby-loco/src/ruby/spec/rubyspec/command_line/dash_c_spec.rb                                                .
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/commands/mspec.rb:119:in `each'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/commands/mspec.rb:119:in `multi_exec'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/commands/mspec.rb:159:in `run'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/utils/script.rb:265:in `main'
	from ../ruby/spec/mspec/bin/mspec:7:in `<main>'
E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/runner/mspec.rb:56:in `each_file': undefined method `chomp' for nil:NilClass (NoMethodError)
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/runner/mspec.rb:69:in `files'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/runner/mspec.rb:48:in `process'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/commands/mspec-run.rb:83:in `run'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/utils/script.rb:265:in `main'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/bin/mspec-run:7:in `<main>'
make: [uncommon.mk:724: yes-test-spec] Error 1 (ignored)
E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/runner/mspec.rb:59:in `flush': Invalid argument (Errno::EINVAL)
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/runner/mspec.rb:59:in `each_file'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/runner/mspec.rb:69:in `files'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/runner/mspec.rb:48:in `process'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/commands/mspec-run.rb:83:in `run'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/utils/script.rb:265:in `main'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/bin/mspec-run:7:in `<main>'
E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/runner/mspec.rb:59:in `flush': Invalid argument (Errno::EINVAL)
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/runner/mspec.rb:59:in `each_file'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/runner/mspec.rb:69:in `files'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/runner/mspec.rb:48:in `process'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/commands/mspec-run.rb:83:in `run'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/utils/script.rb:265:in `main'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/bin/mspec-run:7:in `<main>'
E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/runner/mspec.rb:59:in `flush': Invalid argument (Errno::EINVAL)
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/runner/mspec.rb:59:in `each_file'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/runner/mspec.rb:69:in `files'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/runner/mspec.rb:48:in `process'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/commands/mspec-run.rb:83:in `run'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/lib/mspec/utils/script.rb:265:in `main'
	from E:/GitHub/ruby-loco/src/ruby/spec/mspec/bin/mspec-run:7:in `<main>'

eregon · 2017-06-20T15:43:33Z

mspec -j creates multiple temp directories, like rubyspec_temp_1, rubyspec_temp_2, etc.
Could you tell me if any of those is left and what they contain?

MSP-Greg · 2017-06-20T16:07:56Z

@eregon

All I've got is what's shown above. It fails/stops pretty quickly. Only the rubyspec_temp folder.

Using the patch file (before your real commit) the footer was

Finished in 85.011400 seconds

3535 files, 25848 examples, 201507 expectations, 2 failures, 0 errors, 0 tagged
make: [uncommon.mk:724: yes-test-spec] Error 1 (ignored)

eregon · 2017-06-20T16:13:26Z

OK, I pushed a few fixes to mspec (this repo), could you try running with that?
You can run .../mspec/bin/mspec -j path/to/specs/language directly.
From what I see above, it seems some spec prints a newline on Windows on STDOUT.
But when running mspec in parallel, it relies on nothing printed on STDOUT so this can be used to communicate between the parallel processes.

Parallel mspec is still new and experimental, sorry for that.
Maybe I can add some debug information showing the last spec when unexpected output is printed to STDOUT.

eregon · 2017-06-20T16:31:38Z

The last commit, b4236a6, should now show which file produced the extra output. Hopefully it will help to narrow down the issue.

MSP-Greg · 2017-06-20T18:07:25Z

@eregon Sorry for the delay, had to step out

One temp dir, rubyspec_temp, containing the four files listed above.

Below is the log file, I don't know if all the spaces after the quoted file name are significant --

ruby 2.5.0dev (2017-06-20 trunk 59122) [x64-mingw32]


[/ |                   0%                     | 00:00:00] �[0;32m     0F �[0;32m     0E�[0m 
[- |                   0%                     | 00:00:00] �[0;32m     0F �[0;32m     0E�[0m 
[\ |                   0%                     | 00:00:00] �[0;32m     0F �[0;32m     0E�[0m 
[| |                   0%                     | 00:00:00] �[0;32m     0F �[0;32m     0E�[0m 
[/ |                   0%                     | 00:00:00] �[0;32m     0F �[0;32m     0E�[0m 
A child mspec-run process printed unexpected output on STDOUT while running E:/GitHub/ruby/spec/rubyspec/command_line/dash_c_spec.rb: "\r\nE:/GitHub/ruby/spec/rubyspec/command_line/dash_c_spec.rb                                                "

-----------------------------------------------------
The rubyspec temp directory is not empty. Ensure that
all specs are cleaning up temporary files:
  E:/GitHub/ruby/spec/rubyspec/rubyspec_temp
-----------------------------------------------------

the parent did not send QUIT
E:/GitHub/mspec/lib/mspec/runner/mspec.rb:61:in `flush': Invalid argument (Errno::EINVAL)
	from E:/GitHub/mspec/lib/mspec/runner/mspec.rb:61:in `each_file'
	from E:/GitHub/mspec/lib/mspec/runner/mspec.rb:77:in `files'
	from E:/GitHub/mspec/lib/mspec/runner/mspec.rb:48:in `process'
	from E:/GitHub/mspec/lib/mspec/commands/mspec-run.rb:83:in `run'
	from E:/GitHub/mspec/lib/mspec/utils/script.rb:265:in `main'
	from E:/GitHub/mspec/bin/mspec-run:7:in `<main>'
E:/GitHub/mspec/lib/mspec/runner/mspec.rb:61:in `flush': Invalid argument (Errno::EINVAL)
	from E:/GitHub/mspec/lib/mspec/runner/mspec.rb:61:in `each_file'
	from E:/GitHub/mspec/lib/mspec/runner/mspec.rb:77:in `files'
	from E:/GitHub/mspec/lib/mspec/runner/mspec.rb:48:in `process'
	from E:/GitHub/mspec/lib/mspec/commands/mspec-run.rb:83:in `run'
	from E:/GitHub/mspec/lib/mspec/utils/script.rb:265:in `main'
	from E:/GitHub/mspec/bin/mspec-run:7:in `<main>'
E:/GitHub/mspec/lib/mspec/runner/mspec.rb:61:in `flush': Invalid argument (Errno::EINVAL)
	from E:/GitHub/mspec/lib/mspec/runner/mspec.rb:61:in `each_file'
	from E:/GitHub/mspec/lib/mspec/runner/mspec.rb:77:in `files'
	from E:/GitHub/mspec/lib/mspec/runner/mspec.rb:48:in `process'
	from E:/GitHub/mspec/lib/mspec/commands/mspec-run.rb:83:in `run'
	from E:/GitHub/mspec/lib/mspec/utils/script.rb:265:in `main'
	from E:/GitHub/mspec/bin/mspec-run:7:in `<main>'

eregon · 2017-06-20T18:43:14Z

Ah, you are probably running mspec with -V or --verbose, isn't it?
That prints the filename on STDOUT which is currently not supported when -j is used.
Does it work without -V/--verbose?

MSP-Greg · 2017-06-20T19:03:28Z

@eregon Sorry, I'm not sure when I added that. Maybe disable that options if -j is used?

It works, Thank you. Just ran mspec

Finished in 89.776600 seconds

3535 files, 25848 examples, 201353 expectations, 0 failures, 0 errors, 0 tagged

I just checked, and I've been running test-spec & mspec since 14-May, and I think shortly thereafter I went to parallel, as I can see the times drop. I wish I could say how, why, or when I added the -V. At present, I don't save the scripts for each build. Maybe I should start...

As builds are often logged, anyway to remove the line for each file? I'm logging with a Windows specific syntax that pipes both STDOUT and STDERR to one file...

Thanks again.

eregon · 2017-06-20T19:47:04Z

Great!

I think either we should forbid -V with -j or then print on STDERR instead of STDOUT with -V (but then it might not be synchronous with STDOUT output). Keeping -V available is probably useful for debugging with -j though.

As builds are often logged, anyway to remove the line for each file? I'm logging with a Windows specific syntax that pipes both STDOUT and STDERR to one file...

Remove which line(s)?
The output from the progress bar?

MSP-Greg · 2017-06-20T20:07:09Z

@eregon

The output from the progress bar?

Yes. or, any option that will just output results when using -j? IOW, for CI or full build systems, it might be helpful to have output option that is nothing more than critical error info (normally blank) and results.

Updating my MinGW test results page shortly, both test-spec and mspec pass. Thank you.

MSP-Greg · 2017-06-20T20:11:52Z

@eregon

On my TODO list is writing code to doc the test-spec tests and the test-all tests. My doc system is YARD based, and standard YARD can doc DSL code.

When I get to it, I may have some questions...

eregon · 2017-06-20T21:28:04Z

Yes. or, any option that will just output results when using -j? IOW, for CI or full build systems, it might be helpful to have output option that is nothing more than critical error info (normally blank) and results.

Right, currently this is a limitation that the formatter handling parallel mspec always uses a progress bar.
I want to fix it and allow to use any of the other formatters, but it is not yet done.

eregon · 2017-06-20T21:49:13Z

86c3bee now allows -V -j, although it is not that useful.

When I get to it, I may have some questions...

Please ask :) There is some old documentation at http://ruby.github.io/rubyspec.github.io/ but it's quite outdated and incomplete.

I filed #28 and #29 to track improvements to the parallel functionality of mspec.
I'll close this as I think it addresses your issue, feel free to file more issues or just ask questions.

MSP-Greg · 2017-06-20T22:15:22Z

@eregon

I apologize for the -V issue. I just got back to looking at this, and I noticed that my last build used the internal ruby/spec/mspec files, so it ran fine parallel without the -V.

MSYS2 / MinGW is kind of a combination of *nix and Windows. The make.exe file is normally in a msys64/usr/bin folder with a lot of other standard *nix exe files and commands. So, in my build, both test-spec and mspec run with that folder in the path.

I created a :mingw group in default.mspec (no CAPI), and I'm running it without the MSYS2 / MinGW msys64/usr/bin folder in the path. No failures, but 34 errors, mostly due to cat not being a windows command (at least on Win7) and a few others. Makes me wonder how the mswin build passes, or what its environment is...

Thanks again.

eregon · 2017-06-21T12:53:01Z

No worry, it was good to improve the error message and figure this out.

AppVeyor seems to have cat on PATH: https://ci.appveyor.com/project/eregon/windows-shell/build/28
And even then it seems the ruby/ruby AppVeyor build currently puts the DevKit on PATH, in addition to VS tools: https://github.com/ruby/ruby/blob/5dc1055a5897a237ed515aa1fbc456f7855ea070/appveyor.yml#L19

Feel free to post a ruby/spec issue with these failures if you want to test on that platform.

MSP-Greg · 2017-06-21T13:24:53Z

@eregon As long as we're here...

This is somewhat messy, as MinGW / MSYS / MSYS2 issues are somewhat messy. DevKit is part of RubyInstaller. DevKit was a 'hand-assembled' build system (based on MSYS & MinGW) that could build Ruby and extension gems. For all sorts of reasons, it was replaced with RubyInstaller2, which is what Ruby 2.4+ builds are using. RubyInstaller2 forgoes the 'hand-assembled' and uses the standard MSYS2 / MinGW build system.

Windows PATH is used for both exe and dll resolution. PATH was used by RubyInstaller. RubyInstaller2 uses a dll specific technique to add dll's, so fewer exe's are in the path. For instance, on my 2.5 trunk build, in IRB, the make, sh, and cat commands are not found. They are all in msys64/usr/bin, which is a folder that gets added to PATH when I'm doing a build.

Re cat, I believe it's included in some versions of Powershell, which is a more powerful command line processor (typically used by developers).

So, yes, at present, the appveyor configuration used by ruby does include cat. I think the Ruby windows community needs to have some discussion about what configuration should be expected for using Ruby and testing Ruby.

Sorry for the history, but I thought it might explain some things...

eregon · 2017-06-21T15:37:20Z

I think it would be worth discussing this on the CRuby tracker.
It also sounds like the current AppVeyor configuration is not optimal.
I'm happy to help making tests more portable though.

eregon closed this as completed Jun 20, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

MinGW and parallel tests #27

MinGW and parallel tests #27

MSP-Greg commented Jun 20, 2017

eregon commented Jun 20, 2017

MSP-Greg commented Jun 20, 2017

eregon commented Jun 20, 2017

MSP-Greg commented Jun 20, 2017

eregon commented Jun 20, 2017

eregon commented Jun 20, 2017

MSP-Greg commented Jun 20, 2017 •

edited

Loading

eregon commented Jun 20, 2017

MSP-Greg commented Jun 20, 2017

eregon commented Jun 20, 2017

MSP-Greg commented Jun 20, 2017

MSP-Greg commented Jun 20, 2017

eregon commented Jun 20, 2017

eregon commented Jun 20, 2017

MSP-Greg commented Jun 20, 2017

eregon commented Jun 21, 2017

MSP-Greg commented Jun 21, 2017 •

edited

Loading

eregon commented Jun 21, 2017

MinGW and parallel tests #27

MinGW and parallel tests #27

Comments

MSP-Greg commented Jun 20, 2017

eregon commented Jun 20, 2017

MSP-Greg commented Jun 20, 2017

eregon commented Jun 20, 2017

MSP-Greg commented Jun 20, 2017

eregon commented Jun 20, 2017

eregon commented Jun 20, 2017

MSP-Greg commented Jun 20, 2017 • edited Loading

eregon commented Jun 20, 2017

MSP-Greg commented Jun 20, 2017

eregon commented Jun 20, 2017

MSP-Greg commented Jun 20, 2017

MSP-Greg commented Jun 20, 2017

eregon commented Jun 20, 2017

eregon commented Jun 20, 2017

MSP-Greg commented Jun 20, 2017

eregon commented Jun 21, 2017

MSP-Greg commented Jun 21, 2017 • edited Loading

eregon commented Jun 21, 2017

MSP-Greg commented Jun 20, 2017 •

edited

Loading

MSP-Greg commented Jun 21, 2017 •

edited

Loading