[ARVADOS] created: ea344b06c94a386355ad040edd9bd3e4726ac964
git at public.curoverse.com
git at public.curoverse.com
Thu Mar 19 14:26:42 EDT 2015
at ea344b06c94a386355ad040edd9bd3e4726ac964 (commit)
commit ea344b06c94a386355ad040edd9bd3e4726ac964
Author: Tom Clegg <tom at curoverse.com>
Date: Thu Mar 19 14:26:55 2015 -0400
5276: Reveal and update the log graph as soon as the first data point arrives,
ather than waiting for the redraw timer.
diff --git a/apps/workbench/app/assets/javascripts/job_log_graph.js b/apps/workbench/app/assets/javascripts/job_log_graph.js
index 9daabe1..123f448 100644
--- a/apps/workbench/app/assets/javascripts/job_log_graph.js
+++ b/apps/workbench/app/assets/javascripts/job_log_graph.js
@@ -267,16 +267,44 @@ function isJobSeriesRescalable( series ) {
return !/-cpu$/.test(series);
}
-$(document).on('arv-log-event', '#log_graph_div', function(event, eventData) {
+function processLogEventForGraph(event, eventData) {
if( eventData.properties.text ) {
eventData.properties.text.split('\n').forEach( function( logLine ) {
processLogLineForChart( logLine );
} );
}
-} );
+}
+
+$(document).on('arv-log-event', '#log_graph_div', function(event, eventData) {
+ processLogEventForGraph(event, eventData);
+ if (!window.jobGraphShown) {
+ // Draw immediately, instead of waiting for the 5-second
+ // timer.
+ redrawIfNeeded.call(window, this);
+ }
+});
+
+function redrawIfNeeded(graph_div) {
+ if (!window.redraw) {
+ return;
+ }
+ window.redraw = false;
+ if (window.recreate) {
+ // series have changed, draw entirely new graph.
+ createJobGraph($(graph_div).html('').attr('id'));
+ window.recreate = false;
+ } else {
+ window.jobGraph.setData(window.jobGraphData);
+ }
+ if (!window.jobGraphShown) {
+ $(graph_div).show(500);
+ window.jobGraphShown = true;
+ }
+}
$(document).on('ready ajax:complete', function() {
$('#log_graph_div').not('.graph-is-setup').addClass('graph-is-setup').each( function( index, graph_div ) {
+ window.jobGraphShown = false;
window.jobGraphData = [];
window.jobGraphSeries = [];
window.jobGraphSortedSeries = [];
@@ -285,29 +313,20 @@ $(document).on('ready ajax:complete', function() {
window.redraw = false;
createJobGraph($(graph_div).attr('id'));
- var object_uuid = $(graph_div).data('object-uuid');
- // if there are any listeners for this object uuid or "all", we will trigger the event
- var matches = ".arv-log-event-listener[data-object-uuid=\"" + object_uuid + "\"],.arv-log-event-listener[data-object-uuids~=\"" + object_uuid + "\"]";
$(document).trigger('ajax:send');
+
$.get('/jobs/' + $(graph_div).data('object-uuid') + '/logs.json', function(data) {
data.forEach( function( entry ) {
- $(matches).trigger('arv-log-event', entry);
+ processLogEventForGraph({}, entry);
});
+ // Update the graph now to show the recent data points
+ // received via /logs.json (along with any new data points
+ // we received via websockets while waiting for /logs.json
+ // to respond).
+ redrawIfNeeded(graph_div);
});
- setInterval( function() {
- if (window.recreate || window.redraw) {
- if (window.recreate) {
- // series have changed, draw entirely new graph.
- $(graph_div).html('').show(500);
- createJobGraph($(graph_div).attr('id'));
- } else {
- jobGraph.setData(jobGraphData);
- }
- window.recreate = false;
- window.redraw = false;
- }
- }, 5000);
+ setInterval(redrawIfNeeded.bind(window, graph_div), 5000);
});
});
commit b4e040f6864ba10b19009e21744119194a86567f
Author: Tom Clegg <tom at curoverse.com>
Date: Thu Mar 19 13:08:23 2015 -0400
5276: Improve job log graph tests.
* Run tests as a non-admin user. (This just needed an update in the
log simulator to insert the logs with the same owner_uuid as the
target job.)
* Test graph display/update behavior both with and without an existing
log entry in the database during initial page display.
diff --git a/apps/workbench/test/integration/websockets_test.rb b/apps/workbench/test/integration/websockets_test.rb
index 4b7f472..2b3ba8c 100644
--- a/apps/workbench/test/integration/websockets_test.rb
+++ b/apps/workbench/test/integration/websockets_test.rb
@@ -142,58 +142,71 @@ class WebsocketTest < ActionDispatch::IntegrationTest
})
assert_text 'test dashboard arv-refresh-on-log-event'
+ end
+ 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"
- # Until graphable data arrives, we should see the text log but not the graph.
assert_selector '#event_log_div', visible: true
- assert_no_selector '#log_graph_div', visible: true
- api = ArvadosApiClient.new
+ 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"
- Thread.current[:arvados_api_token] = @@API_AUTHS["admin"]['api_token']
- api.api("logs", "", {log: {
- object_uuid: uuid,
- event_type: "stderr",
- properties: {"text" => text}}})
-
- # Log div should appear when the first data point arrives by websocket.
- assert_selector '#log_graph_div', visible: true
-
- # Using datapoint 1 instead of datapoint 0 because there will be a
- # "dummy" datapoint with no actual stats 10 minutes previous to
- # the one we're looking for, for the sake of making the x-axis of
- # the graph show a full 10 minutes of time even though there is
- # only a single real datapoint.
- cpu_stat = page.evaluate_script("jobGraphData[1]['T1-cpu']")
-
- assert_equal 45.3, (cpu_stat.to_f*100).round(1)
+ 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
- Thread.current[:arvados_api_token] = nil
+ # Graph should have appeared (even if it hadn't above). We don't
+ # use capybara's matcher function because we don't want to wait:
+ # we are confirming the graph is visible _immediately_ after the
+ # first data point arrives.
+ assert page.evaluate_script("$('#log_graph_div').is(':visible')")
+ 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 "admin", "/jobs/#{uuid}"
+ visit page_with_token "active", "/jobs/#{uuid}"
click_link "Log"
- ApiServerForTests.new.run_rake_task("replay_job_log", "test/job_logs/crunchstatshort.log,1.0,#{uuid}")
- wait_for_ajax
-
- # see above comment as to why we use datapoint 1 rather than 0
- cpu_stat = page.evaluate_script("jobGraphData[1]['T1-cpu']")
+ 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_equal 45.3, (cpu_stat.to_f*100).round(1)
+ 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
end
diff --git a/services/api/lib/simulate_job_log.rb b/services/api/lib/simulate_job_log.rb
index fc124c8..860513f 100644
--- a/services/api/lib/simulate_job_log.rb
+++ b/services/api/lib/simulate_job_log.rb
@@ -8,6 +8,12 @@ module SimulateJobLog
actual_start_time = Time.now
log_start_time = nil
+ if simulated_job_uuid and (job = Job.where(uuid: simulated_job_uuid).first)
+ job_owner_uuid = job.owner_uuid
+ else
+ job_owner_uuid = system_user_uuid
+ end
+
act_as_system_user do
File.open(filename).each.with_index do |line, index|
cols = {}
@@ -34,9 +40,9 @@ module SimulateJobLog
modified_elapsed_time = log_elapsed_time / multiplier
pause_time = modified_elapsed_time - actual_elapsed_time
sleep pause_time if pause_time > 0
- # output log entry for debugging and create it in the current environment's database
- puts "#{index} #{cols.to_yaml}\n"
+
Log.new({
+ owner_uuid: job_owner_uuid,
event_at: Time.zone.local_to_utc(cols[:timestamp]),
object_uuid: cols[:job_uuid],
event_type: cols[:event_type],
diff --git a/services/api/test/fixtures/logs.yml b/services/api/test/fixtures/logs.yml
index 058c387..9862700 100644
--- a/services/api/test/fixtures/logs.yml
+++ b/services/api/test/fixtures/logs.yml
@@ -44,3 +44,21 @@ log_owned_by_active:
object_owner_uuid: zzzzz-tpzed-xurymjxw79nv3jz # active user
event_at: <%= 2.minute.ago.to_s(:db) %>
summary: non-admin use can read own logs
+
+crunchstat_for_running_job:
+ uuid: zzzzz-57u5n-tmymyrojrbtnxh1
+ owner_uuid: zzzzz-tpzed-xurymjxw79nv3jz
+ modified_by_client_uuid: zzzzz-ozdt8-obw7foaks3qjyej
+ modified_by_user_uuid: zzzzz-tpzed-xurymjxw79nv3jz
+ object_uuid: zzzzz-8i9sb-pshmckwoma9plh7
+ event_at: 2014-11-07 23:33:42.347455000 Z
+ event_type: stderr
+ summary: ~
+ properties:
+ text: '2014-11-07_23:33:41 zzzzz-8i9sb-pshmckwoma9plh7 31708 1 stderr crunchstat:
+ cpu 1935.4300 user 59.4100 sys 8 cpus -- interval 10.0002 seconds 12.9900 user
+ 0.9900 sys'
+ created_at: 2014-11-07 23:33:42.351913000 Z
+ updated_at: 2014-11-07 23:33:42.347455000 Z
+ modified_at: 2014-11-07 23:33:42.347455000 Z
+ object_owner_uuid: zzzzz-j7d0g-v955i6s2oi1cbso
commit 52f124ea43c941d8500a365945fb9bd9b4b99177
Author: Tom Clegg <tom at curoverse.com>
Date: Thu Mar 19 12:24:49 2015 -0400
5276: Remove redundant test teardown.
diff --git a/apps/workbench/test/integration/websockets_test.rb b/apps/workbench/test/integration/websockets_test.rb
index 4885129..4b7f472 100644
--- a/apps/workbench/test/integration/websockets_test.rb
+++ b/apps/workbench/test/integration/websockets_test.rb
@@ -25,7 +25,6 @@ class WebsocketTest < ActionDispatch::IntegrationTest
event_type: "stderr",
properties: {"text" => "123 hello"}}})
assert_text '123 hello'
- Thread.current[:arvados_api_token] = nil
end
@@ -80,8 +79,6 @@ class WebsocketTest < ActionDispatch::IntegrationTest
# 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
@@ -111,8 +108,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
@@ -130,8 +125,6 @@ class WebsocketTest < ActionDispatch::IntegrationTest
assert_text 'complete'
assert_text 'Re-run job'
-
- Thread.current[:arvados_api_token] = nil
end
test "dashboard arv-refresh-on-log-event" do
@@ -150,7 +143,6 @@ class WebsocketTest < ActionDispatch::IntegrationTest
assert_text 'test dashboard arv-refresh-on-log-event'
- Thread.current[:arvados_api_token] = nil
end
test "live log charting" do
-----------------------------------------------------------------------
hooks/post-receive
--
More information about the arvados-commits
mailing list