Analyze Rails CI

Rails Developers Meetup 2019

https://railsdm.github.io/

Transcript

1. #railsdm2019 Analyze Rails CI Analyze Rails CI @mtsmfm Fumiaki Matsushima RailsDM 2019 #railsdm2019
2. #railsdm2019 Analyze Rails CI ➔ Web Dev at Quipper ➔ Ruby, Mahjong, Dead by Daylight ➔ Nishi-nippori.rb organizer ➔ GraphQL Tokyo organizer @mtsmfm.inspect
3. #railsdm2019 Analyze Rails CI https://studysapuri.jp/
4. #railsdm2019 Analyze Rails CI
5. #railsdm2019 Analyze Rails CI https://nishinipporirb.doorkeeper.jp/events/88540 Nishi-nippori.rb meetup #53
6. #railsdm2019 Analyze Rails CI https://nishinipporirb.doorkeeper.jp/events/88540 Meetup place Nishi- nippori
7. #railsdm2019 Analyze Rails CI I gave a talk about flaky tests before https://speakerdeck.com/mtsmfm/how-do-e2e-tests-fail-randomly
8. #railsdm2019 Analyze Rails CI I’ve been writing flaky tests
9. #railsdm2019 Analyze Rails CI I’m going to write new variation of flaky tests
10. #railsdm2019 Analyze Rails CI “100% is the wrong reliability target for basically everything” Site Reliability Engineering Edited by Betsy Beyer, Chris Jones, Jennifer Petoff and Niall Richard Murphy https://landing.google.com/sre/sre-book/chapters/introduction/
11. #railsdm2019 Analyze Rails CI The same with flaky tests
12. #railsdm2019 Analyze Rails CI 97.3 %
13. #railsdm2019 Analyze Rails CI The percentage of passed jobs on master branch in Feb 2019 in rails/rails repo
14. #railsdm2019 Analyze Rails CI https://github.com/rails/rails/pull/33829#issuecomment-420586191 Rails also has flaky tests
15. #railsdm2019 Analyze Rails CI
16. #railsdm2019 Analyze Rails CI https://has-it-failed.herokuapp.com
17. #railsdm2019 Analyze Rails CI https://has-it-failed.herokuapp.com/?q=test_invoke_when_generator_is_not_found
18. #railsdm2019 Analyze Rails CI What I’d like to talk - I’ve published Rails CI result as a public dataset on BigQuery https://console.cloud.google.com/bigquery?p=rails-travis -result&d=rails_travis_result&page=dataset - You can find the test was failed before or not on Rails CI via http://has-it-failed.herokuapp.com - There’s a room for improvement if we have CI result database (e.g. Make CI result passed if failed one is a flaky test)
19. #railsdm2019 Analyze Rails CI Browser rails-ci-result-importer BigQuery PostgreSQL has-it-failed TravisCI API Overview of systems I created for this talk
20. #railsdm2019 Analyze Rails CI Agenda 1. rails-ci-result-importer 2. has-it-failed app 3. Future work
21. #railsdm2019 Analyze Rails CI 1. rails-ci-result-importer
22. #railsdm2019 Analyze Rails CI rails-ci-result-importer BigQuery TravisCI API
23. #railsdm2019 Analyze Rails CI https://github.com/mtsmfm/rails-ci-result-importer
24. #railsdm2019 Analyze Rails CI Heroku Scheduler Embulk BigQuery Redis diff.yml TravisCI API bin/import embulk-input-travis embulk-output-bigquery
25. #railsdm2019 Analyze Rails CI https://www.embulk.org/docs/
26. #railsdm2019 Analyze Rails CI Why embulk? - Just curious - Embulk plugin can be written in (J)Ruby
27. #railsdm2019 Analyze Rails CI Heroku Scheduler Embulk BigQuery Redis diff.yml TravisCI API bin/import embulk-input-travis embulk-output-bigquery
28. #railsdm2019 Analyze Rails CI https://github.com/mtsmfm/embulk-input-travis
29. #railsdm2019 Analyze Rails CI Resources on TravisCI Commit d8d6bd5 Build 59740 Job 59740.1 GEM=railties Ruby: 2.5.3 $ git push xxx Repository rails/rails Job 59740.2 GEM=railties Ruby: 2.6.0 Job 59740.3 GEM=ap,ac Ruby: 2.6.0 ...
30. #railsdm2019 Analyze Rails CI Table schema on BigQuery Field name Type Description id INTEGER Job id on TravisCI data STRING Job attributes in JSON log STRING Job log started_at TIMESTAMP When this job started build_number INTEGER Build number job belongs to build_data STRING Build attributes job belongs to commit_data STRING Commit attributes job belongs to
31. #railsdm2019 Analyze Rails CI Important notice - This dataset doesn’t have all results (for now) - Some rows don’t have commit_data (for now) - I paid to store this dataset but you need to pay money to run query
32. #railsdm2019 Analyze Rails CI Table schema on BigQuery Field name Type Description id INTEGER Job id on TravisCI data STRING Job attributes in JSON log STRING Job log started_at TIMESTAMP When this job started build_number INTEGER Build number job belongs to build_data STRING Build attributes job belongs to commit_data STRING Commit attributes job belongs to Partitioned by started_at
33. #railsdm2019 Analyze Rails CI Be sure to query with “WHERE started_at”
34. #railsdm2019 Analyze Rails CI 40 / 1024 * 5 ≒ 0.2 (USD) https://cloud.google.com/bigquery/pricing
35. #railsdm2019 Analyze Rails CI Important notice - This dataset doesn’t have all results (for now) - Some rows don’t have commit_data (for now) - I paid to store this dataset but you need to pay money to run query - Be sure to query with “WHERE started_at” - Full scan costs only $0.2 for now but amount of data keeps increasing
36. #railsdm2019 Analyze Rails CI 2. has-it-failed app
37. #railsdm2019 Analyze Rails CI https://github.com/mtsmfm/has-it-failed
38. #railsdm2019 Analyze Rails CI Browser BigQuery PostgreSQL Find all failed tests via SQL ImportJob Store PG (cache) Web server
39. #railsdm2019 Analyze Rails CI Browser BigQuery PostgreSQL Find all failed tests via SQL ImportJob Store PG (cache) Web server
40. #railsdm2019 Analyze Rails CI It’s just raw log... /home/travis/.rvm/rubies/ruby-head/bin/ruby -w -Itest -Ilib -I../activesupport/lib -I../actionpack/lib -I../actionview/lib -I../activemodel/lib test/commands/server_test.rb Run options: --seed 10052 # Running: ....F Failure: Rails::Command::ServerCommandTest#test_using_server_mistype_without_suggestion [test/commands/server_test.rb:38]: Expected /Maybe you meant/ to not match "Could not find server \"t\". Maybe you meant \"cgi\"?\nRun `rails server --help` for more options.\n". rails test test/commands/server_test.rb:35 ..................... Finished in 0.760100s, 34.2060 runs/s, 71.0433 assertions/s. 26 runs, 54 assertions, 1 failures, 0 errors, 0 skips ^^^ +++ --- test/configuration/middleware_stack_proxy_test.rb
41. #railsdm2019 Analyze Rails CI It’s just raw log... /home/travis/.rvm/rubies/ruby-head/bin/ruby -w -Itest -Ilib -I../activesupport/lib -I../actionpack/lib -I../actionview/lib -I../activemodel/lib test/commands/server_test.rb Run options: --seed 10052 # Running: ....F Failure: Rails::Command::ServerCommandTest#test_using_server_mistype_without_suggestion [test/commands/server_test.rb:38]: Expected /Maybe you meant/ to not match "Could not find server \"t\". Maybe you meant \"cgi\"?\nRun `rails server --help` for more options.\n". rails test test/commands/server_test.rb:35 ..................... Finished in 0.760100s, 34.2060 runs/s, 71.0433 assertions/s. 26 runs, 54 assertions, 1 failures, 0 errors, 0 skips ^^^ +++ --- test/configuration/middleware_stack_proxy_test.rb Test class, test method Failed info
42. #railsdm2019 Analyze Rails CI Browser BigQuery PostgreSQL Find all failed tests via SQL ImportJob Store PG (cache) Web server
43. #railsdm2019 Analyze Rails CI SELECT * FROM( SELECT DISTINCT id, data, build_number, build_data, extractCiResult(log) AS parse_result FROM `rails-travis-result.rails_travis_result.jobs` WHERE "#{from.iso8601}" < started_at AND started_at < "#{to.iso8601}" ) WHERE parse_result <> "error" AND JSON_EXTRACT_SCALAR(data, "$.state") = "failed" AND JSON_ARRAY_LENGTH( JSON_EXTRACT(parse_result, "$.failedTests") ) > 0
44. #railsdm2019 Analyze Rails CI SELECT * FROM( SELECT DISTINCT id, data, build_number, build_data, extractCiResult(log) AS parse_result FROM `rails-travis-result.rails_travis_result.jobs` WHERE "#{from.iso8601}" < started_at AND started_at < "#{to.iso8601}" ) WHERE parse_result <> "error" AND JSON_EXTRACT_SCALAR(data, "$.state") = "failed" AND JSON_ARRAY_LENGTH( JSON_EXTRACT(parse_result, "$.failedTests") ) > 0
45. #railsdm2019 Analyze Rails CI CREATE TEMP FUNCTION extractCiResult (log STRING) RETURNS STRING LANGUAGE js AS """ try { const railsCiResult = (TravisResultParser.parse(log)).find( command => command.includes('[Travis CI]') ); return JSON.stringify(RailsCiParser.parse(railsCiResult)); } catch { return 'error'; } """ OPTIONS ( library=[ "gs://rails-travis-result/parser/v0.1.0/rails_ci.js", "gs://rails-travis-result/parser/v0.1.0/travis_result.js" ] );
46. #railsdm2019 Analyze Rails CI BigQuery supports JavaScript UDF - Let’s write a parser in JavaScript and run on BigQuery directly!
47. #railsdm2019 Analyze Rails CI PEG and PEG.js - Parsing Expression Grammar - PEG.js is one of the most popular parser generator - Export parser from PEG - Online editor
48. #railsdm2019 Analyze Rails CI https://pegjs.org/online
49. #railsdm2019 Analyze Rails CI Result = (Noise command:Command Noise { return command; })+ Noise = (!Command .)* Command = TimeStart commandBody:CommandBody TimeEnd { return commandBody; } CommandBody = chars:(!TimeEnd char:. {return char})* { return chars.join('').replace(/\x1B\[([0-9]{1,2}(;[0-9]{1,2})?)?[mGK]/g, '').replace(/\r\n/g, "\n") } TimeStart = "travis_time:start:" (!"\n" .)+ "\n" TimeEnd = "travis_time:end:" (!"\n" .)+ "\n"
50. #railsdm2019 Analyze Rails CI How to parse Rails CI log 1. Find output from entrypoint (ci/travis.rb) 2. Find test command e.g. $ ruby foo_test.rb 3. Find finished messages
51. #railsdm2019 Analyze Rails CI CREATE TEMP FUNCTION extractCiResult (log STRING) RETURNS STRING LANGUAGE js AS """ try { const railsCiResult = (TravisResultParser.parse(log)).find( command => command.includes('[Travis CI]') ); return JSON.stringify(RailsCiParser.parse(railsCiResult)); } catch { return 'error'; } """ OPTIONS ( library=[ "gs://rails-travis-result/parser/v0.1.0/rails_ci.js", "gs://rails-travis-result/parser/v0.1.0/travis_result.js" ] );
52. #railsdm2019 Analyze Rails CI Log contains infrastructure info https://api.travis-ci.org/v3/job/505038092/log.txt ...
53. #railsdm2019 Analyze Rails CI Result = (Noise command:Command Noise { return command; })+ Noise = (!Command .)* Command = TimeStart commandBody:CommandBody TimeEnd { return commandBody; } CommandBody = chars:(!TimeEnd char:. {return char})* { return chars.join('').replace(/\x1B\[([0-9]{1,2}(;[0-9]{1,2})?)?[mGK]/g, '').replace(/\r\n/g, "\n") } TimeStart = "travis_time:start:" (!"\n" .)+ "\n" TimeEnd = "travis_time:end:" (!"\n" .)+ "\n"
54. #railsdm2019 Analyze Rails CI travis_fold:start:worker_info … travis_fold:end:worker_info … travis_time:start:08cc8690 $ bundle install --jobs 3 --retry 3 travis_time:end:08cc8690 … ... travis_time:start:262254e0 $ ci/travis.rb [Travis CI] railties Running command: bundle exec rake test travis_time:end:262254e0 … Done. Your build exited with 0. Result = (Noise command:Command Noise { return command; })+
55. #railsdm2019 Analyze Rails CI travis_fold:start:worker_info … travis_fold:end:worker_info … travis_time:start:08cc8690 $ bundle install --jobs 3 --retry 3 travis_time:end:08cc8690 … ... travis_time:start:262254e0 $ ci/travis.rb [Travis CI] railties Running command: bundle exec rake test travis_time:end:262254e0 … Done. Your build exited with 0. Noise Result = (Noise command:Command Noise { return command; })+ Noise Command Noise Noise Command
56. #railsdm2019 Analyze Rails CI CREATE TEMP FUNCTION extractCiResult (log STRING) RETURNS STRING LANGUAGE js AS """ try { const railsCiResult = (TravisResultParser.parse(log)).find( command => command.includes('[Travis CI]') ); return JSON.stringify(RailsCiParser.parse(railsCiResult)); } catch { return 'error'; } """ OPTIONS ( library=[ "gs://rails-travis-result/parser/v0.1.0/rails_ci.js", "gs://rails-travis-result/parser/v0.1.0/travis_result.js" ] );
57. #railsdm2019 Analyze Rails CI https://github.com/rails/rails/blob/d8d6bd5e63a9a4a6c06a4dde3c7137ee2be105fd/ci/travis.rb#L45
58. #railsdm2019 Analyze Rails CI CREATE TEMP FUNCTION extractCiResult (log STRING) RETURNS STRING LANGUAGE js AS """ try { const railsCiResult = (TravisResultParser.parse(log)).find( command => command.includes('[Travis CI]') ); return JSON.stringify(RailsCiParser.parse(railsCiResult)); } catch { return 'error'; } """ OPTIONS ( library=[ "gs://rails-travis-result/parser/v0.1.0/rails_ci.js", "gs://rails-travis-result/parser/v0.1.0/travis_result.js" ] );
59. #railsdm2019 Analyze Rails CI RailsCiResult = Noise tests:Test+ { return { failedTests: tests.filter(t => t.summary).filter(({summary: {failuresCount, errorsCount}}) => failuresCount + errorsCount > 0), coreDumpedTests: tests.filter(t => t.dump), noises: tests.filter(t => t.noise) } } Noise = (!Test .)* Test = command:TestCommand result:( results:TestFailureOrErrorResult* summary:TestFinished TestOutputNoise { return { summary, results } } / results:TestSuccessResult summary:TestFinished TestOutputNoise { return { summary, results } } / dump:RubyCoreDump { return { dump } } / noise:TestOutputNoise { return { noise } } ) { return { command, ...result }; } TestCommand = command:$("/home/travis/.rvm" $(!("/bin/" "j"? "ruby -w" / "\n") .)* "/bin/" "j"? "ruby -w" $(!"\n" .)*) "\n" { return command } TestOutputNoise = (!TestCommand .)* TestSuccessResult = message:$(!TestFinished .)* { return { message } } TestFailureOrErrorResult = (!(TestFailureOrErrorResultKeyword / TestFinished) .)* meta:TestFailureOrErrorResultKeyword message:TestFailureMessage { return { ...meta, message } } TestFailureMessage = $(!(TestFailureOrErrorResultKeyword / TestFinished) .)* TestFailureOrErrorResultKeyword = "\n" type:("Failure" / "Error") ":\n" testClass:TestClass "#" method:TestMethod (" [" file:TestFile ":" line:Int "]")? ":\n" { return { type, testClass, method } } TestClass = $[a-zA-Z:]+ TestMethod = $[a-zA-Z_]+ TestFile = $[a-z/\._]+ TestFinished = "\n" runsCount:Int " runs, " assertionsCount:Int " assertions, " failuresCount:Int " failures, " errorsCount:Int " errors, " skipsCount:Int " skips" "\n" { return { runsCount, assertionsCount, failuresCount, errorsCount, skipsCount } } RubyCoreDump = $((!RubyCoreDumpNote .)* RubyCoreDumpNote) RubyCoreDumpNote = "\n" "[NOTE]\n" "You may have encountered a bug in the Ruby interpreter or extension libraries.\n" "Bug reports are welcome.\n" "For details: https://www.ruby-lang.org/bugreport.html\n" "\n" "Aborted (core dumped)\n" Int = chars:$[0-9]+ { return parseInt(chars) }
60. #railsdm2019 Analyze Rails CI RailsCiResult = Noise tests:Test+ { return { failedTests: tests.filter(t => t.summary).filter(({summary: {failuresCount, errorsCount}}) => failuresCount + errorsCount > 0), coreDumpedTests: tests.filter(t => t.dump), noises: tests.filter(t => t.noise) } }
61. #railsdm2019 Analyze Rails CI Test = command:TestCommand result:( TestFailureOrErrorResult* TestFinished TestOutputNoise / TestSuccessResult TestFinished TestOutputNoise / RubyCoreDump / TestOutputNoise )
62. #railsdm2019 Analyze Rails CI TestCommand = command:$("/home/travis/.rvm" $(!("/bin/" "j"? "ruby -w" / "\n") .)* "/bin/" "j"? "ruby -w" $(!"\n" .)*) "\n" TestFailureOrErrorResult = (!(TestFailureOrErrorResultKeyword / TestFinished) .)* TestFailureOrErrorResultKeyword TestFailureMessage TestFailureOrErrorResultKeyword = "\n" type:("Failure" / "Error") ":\n" testClass:TestClass "#" method:TestMethod (" [" file:TestFile ":" line:Int "]")? ":\n" TestClass = $[a-zA-Z:]+ TestMethod = $[a-zA-Z_]+ TestFile = $[a-z/\._]+ TestFinished = "\n" runsCount:Int " runs, " assertionsCount:Int " assertions, " failuresCount:Int " failures, " errorsCount:Int " errors, " skipsCount:Int " skips" "\n"
63. #railsdm2019 Analyze Rails CI /home/travis/.rvm/rubies/ruby-head/bin/ruby -w -Itest -Ilib -I../activesupport/lib -I../actionpack/lib -I../actionview/lib -I../activemodel/lib test/commands/server_test.rb Run options: --seed 10052 # Running: ....F Failure: Rails::Command::ServerCommandTest#test_using_server_mistype_without_suggestion [test/commands/server_test.rb:38]: Expected /Maybe you meant/ to not match "Could not find server \"t\". Maybe you meant \"cgi\"?\nRun `rails server --help` for more options.\n". rails test test/commands/server_test.rb:35 ..................... Finished in 0.760100s, 34.2060 runs/s, 71.0433 assertions/s. 26 runs, 54 assertions, 1 failures, 0 errors, 0 skips ^^^ +++ --- test/configuration/middleware_stack_proxy_test.rb /home/travis/.rvm/rubies/ruby-head/bin/ruby -w -Itest -Ilib -I../activesupport/lib -I../actionpack/lib -I../actionview/lib -I../activemodel/lib test/configuration/middleware_stack_proxy_test.rb
64. #railsdm2019 Analyze Rails CI /home/travis/.rvm/rubies/ruby-head/bin/ruby -w -Itest -Ilib -I../activesupport/lib -I../actionpack/lib -I../actionview/lib -I../activemodel/lib test/commands/server_test.rb Run options: --seed 10052 # Running: ....F Failure: Rails::Command::ServerCommandTest#test_using_server_mistype_without_suggestion [test/commands/server_test.rb:38]: Expected /Maybe you meant/ to not match "Could not find server \"t\". Maybe you meant \"cgi\"?\nRun `rails server --help` for more options.\n". rails test test/commands/server_test.rb:35 ..................... Finished in 0.760100s, 34.2060 runs/s, 71.0433 assertions/s. 26 runs, 54 assertions, 1 failures, 0 errors, 0 skips ^^^ +++ --- test/configuration/middleware_stack_proxy_test.rb /home/travis/.rvm/rubies/ruby-head/bin/ruby -w -Itest -Ilib -I../activesupport/lib -I../actionpack/lib -I../actionview/lib -I../activemodel/lib test/configuration/middleware_stack_proxy_test.rb TestCommand Noise TestFailureOrErrorResultKeyword FailureMessage TestFinished
65. #railsdm2019 Analyze Rails CI { "failedTests": [ { "command": "/home/travis/.rvm/rubies/ruby-head/bin/ruby -w -Itest -Ilib -I../activesupport/lib -I../actionpack/lib -I../actionview/lib -I../activemodel/lib test/commands/server_test.rb", "summary": { "runsCount": 26, "assertionsCount": 54, "failuresCount": 1, "errorsCount": 0, "skipsCount": 0 }, "results": [ { "type": "Failure", "testClass": "Rails::Command::ServerCommandTest", "method": "test_using_server_mistype_without_suggestion", "message": "Expected /Maybe you meant/ to not match \"Could not find server \\\"t\\\". Maybe you meant \\\"cgi\\\"?\\nRun `rails server --help` for more options.\\n\".\n\nrails test test/commands/server_test.rb:35\n\n.....................\n\nFinished in 0.760100s, 34.2060 runs/s, 71.0433 assertions/s." } ...
66. #railsdm2019 Analyze Rails CI Yay!
67. #railsdm2019 Analyze Rails CI Browser BigQuery PostgreSQL Find all failed tests via SQL ImportJob Store PG (cache) Web server
68. #railsdm2019 Analyze Rails CI has-it-failed web - Rails 6.0.0.beta3 - Heroku - Nothing special
69. #railsdm2019 Analyze Rails CI 3. Future work
70. #railsdm2019 Analyze Rails CI CREATE TEMP FUNCTION extractCiResult (log STRING) RETURNS STRING LANGUAGE js AS """ try { const railsCiResult = (TravisResultParser.parse(log)).find( command => command.includes('[Travis CI]') ); return JSON.stringify(RailsCiParser.parse(railsCiResult)); } catch { return 'error'; } """ OPTIONS ( library=[ "gs://rails-travis-result/parser/v0.1.0/rails_ci.js", "gs://rails-travis-result/parser/v0.1.0/travis_result.js" ] );
71. #railsdm2019 Analyze Rails CI This parser is also flaky
72. #railsdm2019 Analyze Rails CI It’s much better to collect test report in future
73. #railsdm2019 Analyze Rails CI https://docs.travis-ci.com/user/uploading-artifacts/ TravisCI doesn’t provide the place to store artifacts
74. #railsdm2019 Analyze Rails CI Buildkite can store artifacts https://buildkite.com/pricing
75. #railsdm2019 Analyze Rails CI https://github.com/rails/rails/pull/35698
76. #railsdm2019 Analyze Rails CI [Idea] Make CI passed if failed one is flaky 1. Generate JUnit format XML test report 2. Send test report to the service 3. The service collects flaky tests data and returns 0 or 1 4. Use the value in step 3 as exit code
77. #railsdm2019 Analyze Rails CI $ bin/ruby -I test || true Flaky tests Data Web server $ test $(curl --form "data=@result.xml" https://server) = ‘0’ result.xml
78. #railsdm2019 Analyze Rails CI $ bin/ruby -I test || true Flaky tests Data 1. Generate XML and always returns 0 Web server $ test $(curl --form "data=@result.xml" https://server) = ‘0’ result.xml
79. #railsdm2019 Analyze Rails CI $ bin/ruby -I test || true Flaky tests Data 1. Generate XML and always returns 0 Web server $ test $(curl --form "data=@result.xml" https://server) = ‘0’ result.xml 2. Send test report to the service
80. #railsdm2019 Analyze Rails CI $ bin/ruby -I test || true Flaky tests Data 1. Generate XML and always returns 0 Web server $ test $(curl --form "data=@result.xml" https://server) = ‘0’ result.xml 3. Service returns 0 or 1 2. Send test report to the service
81. #railsdm2019 Analyze Rails CI $ bin/ruby -I test || true Flaky tests Data 1. Generate XML and always returns 0 Web server $ test $(curl --form "data=@result.xml" https://server) = ‘0’ result.xml 3. Service returns 0 or 1 4. Verify returned value 2. Send test report to the service
82. #railsdm2019 Analyze Rails CI Conclusion - I’ve published Rails CI result as a public dataset on BigQuery https://console.cloud.google.com/bigquery?p=rails-travis -result&d=rails_travis_result&page=dataset - You can find the test was failed before or not on Rails CI via http://has-it-failed.herokuapp.com - There’s a room for improvement if we have CI result database (e.g. Make CI result passed if failed one is a flaky test)