apps/workbench/test/integration/websockets_test.rb

   1 # Copyright (C) The Arvados Authors. All rights reserved.
   2 #
   3 # SPDX-License-Identifier: AGPL-3.0
   4
   5 require 'integration_helper'
   6
   7 class WebsocketTest < ActionDispatch::IntegrationTest
   8   setup do
   9     need_selenium "to make websockets work"
  10     @dispatch_client = ArvadosApiClient.new
  11   end
  12
  13   def dispatch_log(body)
  14     use_token :dispatch1 do
  15       @dispatch_client.api('logs', '', log: body)
  16     end
  17   end
  18
  19   test "test page" do
  20     visit(page_with_token("active", "/websockets"))
  21     fill_in("websocket-message-content", :with => "Stuff")
  22     click_button("Send")
  23     assert_text '"status":400'
  24   end
  25
  26   [
  27    ['pipeline_instances', 'pipeline_in_running_state', api_fixture('jobs')['running']],
  28    ['jobs', 'running'],
  29    ['containers', 'running'],
  30    ['container_requests', 'running', api_fixture('containers')['running']],
  31   ].each do |controller, view_fixture_name, log_target_fixture|
  32     view_fixture = api_fixture(controller)[view_fixture_name]
  33     log_target_fixture ||= view_fixture
  34
  35     test "test live logging and scrolling for #{controller}" do
  36
  37       visit(page_with_token("active", "/#{controller}/#{view_fixture['uuid']}\#Log"))
  38       assert_no_text '123 hello'
  39
  40       text = ""
  41       (1..1000).each do |i|
  42         text << "#{i} hello\n"
  43       end
  44
  45       dispatch_log(owner_uuid: log_target_fixture['owner_uuid'],
  46                    object_uuid: log_target_fixture['uuid'],
  47                    event_type: "stderr",
  48                    properties: {"text" => text})
  49       assert_text '1000 hello'
  50
  51       # First test that when we're already at the bottom of the page, it scrolls down
  52       # when a new line is added.
  53       old_top = page.evaluate_script("$('#event_log_div').scrollTop()")
  54
  55       dispatch_log(owner_uuid: log_target_fixture['owner_uuid'],
  56                    object_uuid: log_target_fixture['uuid'],
  57                    event_type: "dispatch",
  58                    properties: {"text" => "1001 hello\n"})
  59       assert_text '1001 hello'
  60
  61       # Check that new value of scrollTop is greater than the old one
  62       new_top = page.evaluate_script("$('#event_log_div').scrollTop()")
  63       assert_operator new_top, :>, old_top
  64
  65       # Now scroll to 30 pixels from the top
  66       page.execute_script "$('#event_log_div').scrollTop(30)"
  67       assert_equal 30, page.evaluate_script("$('#event_log_div').scrollTop()")
  68
  69       dispatch_log(owner_uuid: log_target_fixture['owner_uuid'],
  70                    object_uuid: log_target_fixture['uuid'],
  71                    event_type: "stdout",
  72                    properties: {"text" => "1002 hello\n"})
  73       assert_text '1002 hello'
  74
  75       # Check that we haven't changed scroll position
  76       assert_equal 30, page.evaluate_script("$('#event_log_div').scrollTop()")
  77     end
  78   end
  79
  80   test 'job graph appears when first data point is already in logs table' do
  81     job_graph_first_datapoint_test
  82   end
  83
  84   test 'job graph appears when first data point arrives by websocket' do
  85     use_token :admin do
  86       Log.find(api_fixture('logs')['crunchstat_for_running_job']['uuid']).destroy
  87     end
  88     job_graph_first_datapoint_test expect_existing_datapoints: false
  89   end
  90
  91   def job_graph_first_datapoint_test expect_existing_datapoints: true
  92     uuid = api_fixture('jobs')['running']['uuid']
  93
  94     visit page_with_token "active", "/jobs/#{uuid}"
  95     click_link "Log"
  96
  97     assert_selector '#event_log_div', visible: true
  98
  99     if expect_existing_datapoints
 100       assert_selector '#log_graph_div', visible: true
 101       # Magic numbers 12.99 etc come from the job log fixture:
 102       assert_last_datapoint 'T1-cpu', (((12.99+0.99)/10.0002)/8)
 103     else
 104       # Until graphable data arrives, we should see the text log but not the graph.
 105       assert_no_selector '#log_graph_div', visible: true
 106     end
 107
 108     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"
 109
 110     assert_triggers_dom_event 'arv-log-event' do
 111       dispatch_log(owner_uuid: api_fixture('jobs')['running']['owner_uuid'],
 112                    object_uuid: uuid,
 113                    event_type: "stderr",
 114                    properties: {"text" => text})
 115     end
 116
 117     # Graph should have appeared (even if it hadn't above). It's
 118     # important not to wait like matchers usually do: we are
 119     # confirming the graph is visible _immediately_ after the first
 120     # data point arrives.
 121     using_wait_time 0 do
 122       assert_selector '#log_graph_div', visible: true
 123     end
 124     assert_last_datapoint 'T1-cpu', (((35.39+0.86)/10.0002)/8)
 125   end
 126
 127   test "live log charting from replayed log" do
 128     uuid = api_fixture("jobs")['running']['uuid']
 129
 130     visit page_with_token "active", "/jobs/#{uuid}"
 131     click_link "Log"
 132
 133     assert_triggers_dom_event 'arv-log-event' do
 134       ApiServerForTests.new.run_rake_task("replay_job_log", "test/job_logs/crunchstatshort.log,1.0,#{uuid}")
 135     end
 136
 137     assert_last_datapoint 'T1-cpu', (((35.39+0.86)/10.0002)/8)
 138   end
 139
 140   def assert_last_datapoint series, value
 141     datum = page.evaluate_script("jobGraphData[jobGraphData.length-1]['#{series}']")
 142     assert_in_epsilon value, datum.to_f
 143   end
 144
 145   test "test running job with just a few previous log records" do
 146     job = api_fixture("jobs")['running']
 147
 148     # Create just one old log record
 149     dispatch_log(owner_uuid: job['owner_uuid'],
 150                  object_uuid: job['uuid'],
 151                  event_type: "stderr",
 152                  properties: {"text" => "Historic log message"})
 153
 154     visit page_with_token("active", "/jobs/#{job['uuid']}\#Log")
 155
 156     # Expect "all" historic log records because we have less than
 157     # default Rails.configuration.Workbench.RunningJobLogRecordsToFetch
 158     assert_text 'Historic log message'
 159
 160     # Create new log record and expect it to show up in log tab
 161     dispatch_log(owner_uuid: job['owner_uuid'],
 162                  object_uuid: job['uuid'],
 163                  event_type: "stderr",
 164                  properties: {"text" => "Log message after subscription"})
 165     assert_text 'Log message after subscription'
 166   end
 167
 168   test "test running job with too many previous log records" do
 169     max = 5
 170     Rails.configuration.Workbench.RunningJobLogRecordsToFetch = max
 171     job = api_fixture("jobs")['running']
 172
 173     # Create max+1 log records
 174     (0..max).each do |count|
 175       dispatch_log(owner_uuid: job['owner_uuid'],
 176                    object_uuid: job['uuid'],
 177                    event_type: "stderr",
 178                    properties: {"text" => "Old log message #{count}"})
 179     end
 180
 181     visit page_with_token("active", "/jobs/#{job['uuid']}\#Log")
 182
 183     # Expect all but the first historic log records,
 184     # because that was one too many than fetch count.
 185     (1..max).each do |count|
 186       assert_text "Old log message #{count}"
 187     end
 188     assert_no_text 'Old log message 0'
 189
 190     # Create one more log record after subscription
 191     dispatch_log(owner_uuid: job['owner_uuid'],
 192                  object_uuid: job['uuid'],
 193                  event_type: "stderr",
 194                  properties: {"text" => "Life goes on!"})
 195
 196     # Expect it to show up in log tab
 197     assert_text 'Life goes on!'
 198   end
 199 end