Feature #5694
closed[Workbench] Log tab of running job should include logs from before you opened the tab
Added by Bryan Cosca over 9 years ago. Updated almost 9 years ago.
100%
Description
If I have a current running job and I noticed that one task failed, I would like to see what failed about it while the other tasks are running. Currently when you go to the log tab, you can only see the log from where you started viewing it. So I cannot go back to what happened in the logs before.
There's a possibility to fix that by requesting past events from Websockets. Start with that approach. If it's not expedient, implement the fix in #5694-2.
Updated by Brett Smith over 9 years ago
- Subject changed from [Workbench] View log output from before you opened log tab to [Workbench] Log tab of running job should include logs from before you opened the tab
- Category set to Workbench
- Target version set to Arvados Future Sprints
Updated by Tom Clegg almost 9 years ago
source:apps/workbench/app/models/pipeline_instance.rb has
def stderr_log_lines(limit=2000)
stderr_log_query(limit).results.reverse.
flat_map { |log| log.properties[:text].split("\n") rescue [] }
end
and source:apps/workbench/app/views/pipeline_instances/_show_log.html.erb has
><%= @object.stderr_log_lines.join("\n") %></div>
I'm hoping we just need to add analogous lines to job model/view.
Updated by Peter Amstutz almost 9 years ago
Alternately, in job_log_graph.js:
$.get('/jobs/' + $(graph_div).data('object-uuid') + '/logs.json', function(data) { data.forEach( function( entry ) { processLogEventForGraph({}, entry); }); });
The forEach()
loop could add each entry to the log window.
Updated by Tom Clegg almost 9 years ago
Yes, using the logs we're already fetching sounds even better.
edit: ...except that -- unlike the chart -- the log window doesn't know how to deal with logs that arrive out of order. If we connect to websocket and request historical logs at the same time, we sometimes log messages will arrive twice and sometimes the current logs will arrive before the 10-minute history. Showing duplicated/out-of-order logs would be really confusing/annoying. I don't think we should go with this approach unless we also tackle the de-dup/reordering problem.
Updated by Brett Smith almost 9 years ago
- Target version changed from Arvados Future Sprints to 2016-03-02 sprint
Updated by Brett Smith almost 9 years ago
- Description updated (diff)
- Target version changed from 2016-03-02 sprint to Arvados Future Sprints
Updated by Brett Smith almost 9 years ago
- Description updated (diff)
- Target version changed from Arvados Future Sprints to 2016-03-02 sprint
- Story points set to 1.0
Tom and Radhika to meet up to hash out a possible Websockets fix.
Updated by Tom Clegg almost 9 years ago
- when subscribing to websockets, use
filters=['created_at', '>=', (now - 10 minutes)]
- currently we subscribe to everything, in one place: source:apps/workbench/app/assets/javascripts/event_log.js#L34 ...asking for 10 minutes worth of history (before getting to now) here would make the whole auto-update system even more wasteful/slow.
- instead we could add a new function "addEventLogSubscription" in event_log.js which sends an additional "subscribe" message to the server, and invoke this from the job log tab. We could also include the relevant job UUID so we don't get useless historical messages from other jobs. (We'd still get useless live updates, because of the "subscribe to everything" thing we already do, but at least we don't have to make it even worse.)
Updated by Radhika Chippada almost 9 years ago
- Status changed from New to In Progress
Branch 5694-running-job-log 320f479b1af2a8fb5233415e18e93582d50df848
I tried to subscribe to web sockets for the current running job for last 10 mins, and didn't have much luck. Tom and I had discussed and agreed that we use stderr_log_lines as in note 2 in that case.
- Added stderr_log_lines to current job log tab that fetches 2000 most recent historic log lines
- Added a config param running_job_log_lines_to_fetch to enable writing test that fetches "max allowed" log lines when there are many more log lines in history.
Updated by Peter Amstutz almost 9 years ago
Great!
Just one thing, at the very top it is rendering like this:
2016-02-24_12:40:31 wx7k5-8i9sb-4f4cixopdp1inoq 65450 0 stderr crunchstat: cpu 70.2600 user 24.5800 sys 16 cpus -- interval 10.0006 seconds 0.0000 user 0.0000 sys 2016-02-24_12:40:31 wx7k5-8i9sb-4f4cixopdp1inoq 65450 0 stderr crunchstat: net:eth0 2625454730 tx 48905114 rx -- interval 10.0015 seconds 0 tx 0 rx
Instead of this:
2016-02-24_12:40:31 wx7k5-8i9sb-4f4cixopdp1inoq 65450 0 stderr crunchstat: cpu 70.2600 user 24.5800 sys 16 cpus -- interval 10.0006 seconds 0.0000 user 0.0000 sys 2016-02-24_12:40:31 wx7k5-8i9sb-4f4cixopdp1inoq 65450 0 stderr crunchstat: net:eth0 2625454730 tx 48905114 rx -- interval 10.0015 seconds 0 tx 0 rx
I think you need to remove the whitespace between the closing >
of the <div tag and the start of the template:
<div id="event_log_div" class="arv-log-event-listener arv-log-event-handler-append-logs arv-job-log-window" data-object-uuid="<%= @object.uuid %>" > <%= @object.stderr_log_lines(Rails.configuration.running_job_log_lines_to_fetch).join("\n") %> </div>
<div id="event_log_div" class="arv-log-event-listener arv-log-event-handler-append-logs arv-job-log-window" data-object-uuid="<%= @object.uuid %>" ><%= @object.stderr_log_lines(Rails.configuration.running_job_log_lines_to_fetch).join("\n") %> </div>
Updated by Peter Amstutz almost 9 years ago
Also, running_job_log_lines_to_fetch
is not quite an accurate name, it is actually the number of log records (which may include multiple lines of text).
Updated by Radhika Chippada almost 9 years ago
Renamed running_job_log_lines_to_fetch as running_job_log_records_to_fetch
Updated by Radhika Chippada almost 9 years ago
- Status changed from In Progress to Resolved
- % Done changed from 0 to 100
Applied in changeset arvados|commit:d41ed1ac354d07c8b32796a784ece9f852bcf40f.