add trace to rake seed on test

[sureshc]

add trace to rake seed on test and send output to Slack

https://trello.com/c/6V3kp5mW/28-add-trace-to-seed-commands-on-test

[sureshc]

should I include ENV['CI'] as well? My understanding is that would detect the CircleCI environments

[balderdash]

RACK_ENV is test in our CircleCI builds as well:

code-dot-org/.circleci/config.yml

Lines 14 to 16 in cf86dfa

	environment:
	RAILS_ENV: test
	RACK_ENV: test

[sureshc]

thanks!

[ewjordan]

LGTM, though I don't know about the ENV['CI'] question - @wjordan may be better to ask about that one

[sureshc]

Am I correct in assuming that this line ensures the output of the pegasus and dashboard seed tasks will be logged to Slack?

code-dot-org/lib/rake/ci.rake

Line 43 in 23bf872

ChatClient.wrap('rake build') {Rake::Task['build'].invoke}

[wjordan]

👍 from me on trying this out. I'm not 100% confident that this will actually fix the underlying issue, but this is safe enough to try. Testing/verifying any attempted fix in our CI process is going to be the tricky part here.

To give a bit more details/context on this underlying issue (I'll update the Trello card with this added info as well):
The underlying issue that we hope adding --trace will solve is that in the event that one of the Rake tasks in our CI build (of which a failure within rake seed:all is one example) fails, we would like the error message (and associated backtraces, log statements, etc) to be captured by our CI-build process and either reported in Slack or included in the log file stored on S3. Currently, the only way to debug errors if this sort is to log into the host and re-run the command manually. As a first step in fixing this general problem, adding --trace to seed:all (and ensuring the rake-task trace gets forwarded to Slack and/or S3 correctly) would give a bit more debugging info to help track down this type of issue.

[wjordan]

Am I correct in assuming that this line ensures the output of the pegasus and dashboard seed tasks will be logged to Slack?

The ChatClient.wrap part only ensures that the 'start' and 'end' events of the block will be logged to Slack, I don't think there's any other output-capturing logic in its implementation that would do anything further than that. This means that whether the output of the seed tasks will be logged to slack and/or s3 depends on what happens in its implementation.

Here's a dig through the chain of events (with the help of GitHub's code linking), starting with that ci::build Rake task invoked:

code-dot-org/lib/rake/ci.rake

Lines 38 to 45 in ee3735f

	# Perform a normal local build by calling the top-level Rakefile.
	# Additionally run the lint task if specified for the environment.
	task build: [:chef_update] do
	Dir.chdir(deploy_dir) do
	ChatClient.wrap('rake lint') {Rake::Task['lint'].invoke} if CDO.lint
	ChatClient.wrap('rake build') {Rake::Task['build'].invoke}
	end
	end

which invokes the build Rake task:

code-dot-org/lib/rake/build.rake

Lines 154 to 157 in 3c7bca1

	desc 'Builds everything.'
	task :build do
	ChatClient.wrap('build') {Rake::Task['build:all'].invoke}
	end

which invokes build:all:

code-dot-org/lib/rake/build.rake

Lines 145 to 151 in 3c7bca1

	tasks = []
	tasks << :apps if CDO.build_apps
	tasks << :dashboard if CDO.build_dashboard
	tasks << :pegasus if CDO.build_pegasus
	tasks << :tools if rack_env?(:staging)
	tasks << :restart_process_queues if CDO.process_queues
	task all: tasks

which invokes build:dashboard, which calls the seed task:

code-dot-org/lib/rake/build.rake

Line 84 in 3c7bca1

RakeUtils.rake 'seed:all', (rack_env?(:test) ? '--trace' : nil)

Which is done by RakeUtils#rake:

code-dot-org/lib/cdo/rake_utils.rb

Lines 278 to 280 in cf86dfa

	def self.rake(*args)
	bundle_exec 'rake', *args
	end

code-dot-org/lib/cdo/rake_utils.rb

Lines 143 to 145 in cf86dfa

	def self.bundle_exec(*args)
	system "RAILS_ENV=#{rack_env}", "RACK_ENV=#{rack_env}", 'bundle', 'exec', *args
	end

code-dot-org/lib/cdo/rake_utils.rb

Lines 87 to 97 in cf86dfa

	def self.system(*args)
	return system_stream_output(*args) if ENV['RAKE_VERBOSE']
	command = command_(*args)
	status, output = system__ command
	unless status == 0
	error = RuntimeError.new("'#{command}' returned #{status}")
	raise error, error.message, CDO.filter_backtrace([output])
	end
	status
	end

The error-case in this system method looks like it raises an exception with the output from system__ provided as the callback information. For some reason that output isn't making its way either to the S3 log or to Slack.

[sureshc]

A little higher up the call chain, the main method in aws/ci_build invokes this nifty utility which seems to capture all standard out and standard error. I'm sorting through ci_build to see if it collects up that output and sends it to S3/Slack:

code-dot-org/lib/cdo/rake_utils.rb

Lines 331 to 361 in 673e657

	# Captures all stdout and stderr within a block, including subprocesses:
	# - redirect STDOUT and STDERR streams to a pipe
	# - have a background thread read from the pipe
	# - store data in a StringIO
	# - execute the block
	# - revert streams to original pipes and return output
	def self.capture(&block)
	old_stdout = STDOUT.clone
	old_stderr = STDERR.clone
	pipe_r, pipe_w = IO.pipe
	pipe_r.sync = true
	output = StringIO.new('', 'w')
	reader = Thread.new do
	begin
	loop do
	output << pipe_r.readpartial(1024)
	end
	rescue EOFError
	end
	end
	STDOUT.reopen(pipe_w)
	STDERR.reopen(pipe_w)
	yield
	ensure
	STDOUT.reopen(old_stdout)
	STDERR.reopen(old_stderr)
	pipe_w.close
	reader.join
	pipe_r.close
	return output.string # rubocop:disable Lint/EnsureReturn
	end

[wjordan]

Yeah, I added capture a while back (#11860) as part of an earlier attempt to unwind a bit of this- I think it ended up being only partly successful, I don't know exactly where parts of the output are getting left out in the failure case.

A bigger project would be to figure out a way to start adding unit-test coverage to parts of these scripts so we can test/verify bugs quicker and with more confidence. That be quite tricky to set up though, which is why we haven't done it yet 😅

[sureshc]

Possibly the cases where a rake task is being invoked with system() is causing them to be run in a different process with standard out not being captured (https://stackoverflow.com/questions/7212573/when-to-use-each-method-of-launching-a-subprocess-in-ruby/7263556#7263556)? Another reason to invoke rake tasks directly via ruby from other rake tasks and other ruby logic.