X-Git-Url: https://git.arvados.org/arvados.git/blobdiff_plain/f8991d36180bf9c2c261dee519b0c878306a35d5..2755c8e5060fc5f84c91e089b43d5019c84cd93b:/apps/workbench/test/integration/websockets_test.rb diff --git a/apps/workbench/test/integration/websockets_test.rb b/apps/workbench/test/integration/websockets_test.rb index 7a8d7742f2..e9f5a799c0 100644 --- a/apps/workbench/test/integration/websockets_test.rb +++ b/apps/workbench/test/integration/websockets_test.rb @@ -1,13 +1,8 @@ require 'integration_helper' -require 'selenium-webdriver' -require 'headless' class WebsocketTest < ActionDispatch::IntegrationTest - setup do - headless = Headless.new - headless.start - Capybara.current_driver = :selenium + need_selenium "to make websockets work" end test "test page" do @@ -30,16 +25,19 @@ class WebsocketTest < ActionDispatch::IntegrationTest event_type: "stderr", properties: {"text" => "123 hello"}}}) assert_text '123 hello' - Thread.current[:arvados_api_token] = nil end - - [["pipeline_instances", api_fixture("pipeline_instances")['pipeline_with_newer_template']['uuid']], - ["jobs", api_fixture("jobs")['running']['uuid']]].each do |c| + [ + ["pipeline_instances", api_fixture("pipeline_instances")['pipeline_with_newer_template']['uuid']], + ["jobs", api_fixture("jobs")['running']['uuid']], + ["containers", api_fixture("containers")['running']['uuid']], + ["container_requests", api_fixture("container_requests")['running']['uuid'], api_fixture("containers")['running']['uuid']], + ].each do |c| test "test live logging scrolling #{c[0]}" do controller = c[0] uuid = c[1] + log_uuid = c[2] || c[1] visit(page_with_token("admin", "/#{controller}/#{uuid}")) click_link("Log") @@ -54,7 +52,7 @@ class WebsocketTest < ActionDispatch::IntegrationTest Thread.current[:arvados_api_token] = @@API_AUTHS["admin"]['api_token'] api.api("logs", "", {log: { - object_uuid: uuid, + object_uuid: log_uuid, event_type: "stderr", properties: {"text" => text}}}) assert_text '1000 hello' @@ -64,28 +62,27 @@ class WebsocketTest < ActionDispatch::IntegrationTest old_top = page.evaluate_script("$('#event_log_div').scrollTop()") api.api("logs", "", {log: { - object_uuid: uuid, + object_uuid: log_uuid, event_type: "stderr", properties: {"text" => "1001 hello\n"}}}) assert_text '1001 hello' # Check that new value of scrollTop is greater than the old one - assert page.evaluate_script("$('#event_log_div').scrollTop()") > old_top + new_top = page.evaluate_script("$('#event_log_div').scrollTop()") + assert_operator new_top, :>, old_top # Now scroll to 30 pixels from the top page.execute_script "$('#event_log_div').scrollTop(30)" assert_equal 30, page.evaluate_script("$('#event_log_div').scrollTop()") api.api("logs", "", {log: { - object_uuid: uuid, + object_uuid: log_uuid, event_type: "stderr", properties: {"text" => "1002 hello\n"}}}) assert_text '1002 hello' # Check that we haven't changed scroll position assert_equal 30, page.evaluate_script("$('#event_log_div').scrollTop()") - - Thread.current[:arvados_api_token] = nil end end @@ -115,8 +112,6 @@ class WebsocketTest < ActionDispatch::IntegrationTest assert page.has_no_link? 'Pause' assert_text 'Complete' assert page.has_link? 'Re-run with latest' - - Thread.current[:arvados_api_token] = nil end test "job arv-refresh-on-log-event" do @@ -127,15 +122,13 @@ class WebsocketTest < ActionDispatch::IntegrationTest visit(page_with_token("admin", "/jobs/#{p.uuid}")) assert_no_text 'complete' - assert_no_text 'Re-run same version' + assert_no_text 'Re-run job' p.state = "Complete" p.save! assert_text 'complete' - assert_text 'Re-run same version' - - Thread.current[:arvados_api_token] = nil + assert_text 'Re-run job' end test "dashboard arv-refresh-on-log-event" do @@ -153,47 +146,137 @@ class WebsocketTest < ActionDispatch::IntegrationTest }) assert_text 'test dashboard arv-refresh-on-log-event' + end - Thread.current[:arvados_api_token] = nil + test 'job graph appears when first data point is already in logs table' do + job_graph_first_datapoint_test end - test "live log charting" do - uuid = api_fixture("jobs")['running']['uuid'] + test 'job graph appears when first data point arrives by websocket' do + use_token :admin do + Log.find(api_fixture('logs')['crunchstat_for_running_job']['uuid']).destroy + end + job_graph_first_datapoint_test expect_existing_datapoints: false + end + + def job_graph_first_datapoint_test expect_existing_datapoints: true + uuid = api_fixture('jobs')['running']['uuid'] - visit page_with_token "admin", "/jobs/#{uuid}" + visit page_with_token "active", "/jobs/#{uuid}" click_link "Log" - api = ArvadosApiClient.new + assert_selector '#event_log_div', visible: true + + if expect_existing_datapoints + assert_selector '#log_graph_div', visible: true + # Magic numbers 12.99 etc come from the job log fixture: + assert_last_datapoint 'T1-cpu', (((12.99+0.99)/10.0002)/8) + else + # Until graphable data arrives, we should see the text log but not the graph. + assert_no_selector '#log_graph_div', visible: true + end - # should give 45.3% or (((36.39+0.86)/10.0002)/8)*100 rounded to 1 decimal place text = "2014-11-07_23:33:51 #{uuid} 31708 1 stderr crunchstat: cpu 1970.8200 user 60.2700 sys 8 cpus -- interval 10.0002 seconds 35.3900 user 0.8600 sys" + assert_triggers_dom_event 'arv-log-event' do + use_token :active do + api = ArvadosApiClient.new + api.api("logs", "", {log: { + object_uuid: uuid, + event_type: "stderr", + properties: {"text" => text}}}) + end + end + + # Graph should have appeared (even if it hadn't above). It's + # important not to wait like matchers usually do: we are + # confirming the graph is visible _immediately_ after the first + # data point arrives. + using_wait_time 0 do + assert_selector '#log_graph_div', visible: true + end + assert_last_datapoint 'T1-cpu', (((35.39+0.86)/10.0002)/8) + end + + test "live log charting from replayed log" do + uuid = api_fixture("jobs")['running']['uuid'] + + visit page_with_token "active", "/jobs/#{uuid}" + click_link "Log" + + assert_triggers_dom_event 'arv-log-event' do + ApiServerForTests.new.run_rake_task("replay_job_log", "test/job_logs/crunchstatshort.log,1.0,#{uuid}") + end + + assert_last_datapoint 'T1-cpu', (((35.39+0.86)/10.0002)/8) + end + + def assert_last_datapoint series, value + datum = page.evaluate_script("jobGraphData[jobGraphData.length-1]['#{series}']") + assert_in_epsilon value, datum.to_f + end + + test "test running job with just a few previous log records" do Thread.current[:arvados_api_token] = @@API_AUTHS["admin"]['api_token'] + job = Job.where(uuid: api_fixture("jobs")['running']['uuid']).results.first + visit page_with_token("admin", "/jobs/#{job.uuid}") + + api = ArvadosApiClient.new + + # Create just one old log record api.api("logs", "", {log: { - object_uuid: uuid, + object_uuid: job.uuid, event_type: "stderr", - properties: {"text" => text}}}) - wait_for_ajax + properties: {"text" => "Historic log message"}}}) - cpu_stat = page.evaluate_script("jobGraphData[0]['cpu-1']") + click_link("Log") - assert_equal 45.3, (cpu_stat.to_f*100).round(1) + # Expect "all" historic log records because we have less than + # default Rails.configuration.running_job_log_records_to_fetch count + assert_text 'Historic log message' - Thread.current[:arvados_api_token] = nil + # Create new log record and expect it to show up in log tab + api.api("logs", "", {log: { + object_uuid: job.uuid, + event_type: "stderr", + properties: {"text" => "Log message after subscription"}}}) + assert_text 'Log message after subscription' end - test "live log charting from replayed log" do - uuid = api_fixture("jobs")['running']['uuid'] + test "test running job with too many previous log records" do + Rails.configuration.running_job_log_records_to_fetch = 5 - visit page_with_token "admin", "/jobs/#{uuid}" - click_link "Log" + Thread.current[:arvados_api_token] = @@API_AUTHS["admin"]['api_token'] + job = Job.where(uuid: api_fixture("jobs")['running']['uuid']).results.first - ApiServerForTests.new.run_rake_task("replay_job_log", "test/job_logs/crunchstatshort.log,#{uuid}") - wait_for_ajax + visit page_with_token("admin", "/jobs/#{job.uuid}") - cpu_stat = page.evaluate_script("jobGraphData[0]['cpu-1']") + api = ArvadosApiClient.new - assert_equal 45.3, (cpu_stat.to_f*100).round(1) - end + # Create Rails.configuration.running_job_log_records_to_fetch + 1 log records + (0..Rails.configuration.running_job_log_records_to_fetch).each do |count| + api.api("logs", "", {log: { + object_uuid: job.uuid, + event_type: "stderr", + properties: {"text" => "Old log message #{count}"}}}) + end + # Go to log tab, which results in subscribing to websockets + click_link("Log") + + # Expect all but the first historic log records, + # because that was one too many than fetch count. + (1..Rails.configuration.running_job_log_records_to_fetch).each do |count| + assert_text "Old log message #{count}" + end + assert_no_text 'Old log message 0' + + # Create one more log record after subscription + api.api("logs", "", {log: { + object_uuid: job.uuid, + event_type: "stderr", + properties: {"text" => "Life goes on!"}}}) + # Expect it to show up in log tab + assert_text 'Life goes on!' + end end