Feature #5694

[Workbench] Log tab of running job should include logs from before you opened the tab

Added by Bryan Cosca over 6 years ago. Updated almost 6 years ago.

Status:
Resolved
Priority:
Normal
Assigned To:
Radhika Chippada
Category:
Workbench
Target version:
Start date:
04/10/2015
Due date:
% Done:

100%

Estimated time:
(Total: 0.00 h)
Story points:
1.0

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.


Subtasks

Task #8473: Review branch 5694-running-job-logResolvedRadhika Chippada


Related issues

Related to Arvados - Bug #8807: [Crunch] crunch-job doesn't save logs when exiting EX_TEMPFAILClosed03/31/2016

Associated revisions

Revision d41ed1ac
Added by Radhika Chippada almost 6 years ago

closes #5694
Merge branch '5694-running-job-log'

History

#1 Updated by Brett Smith over 6 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

#2 Updated by Tom Clegg almost 6 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.

#3 Updated by Peter Amstutz almost 6 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.

#4 Updated by Tom Clegg almost 6 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.

#5 Updated by Brett Smith almost 6 years ago

  • Target version changed from Arvados Future Sprints to 2016-03-02 sprint

#6 Updated by Brett Smith almost 6 years ago

  • Assigned To set to Radhika Chippada

#7 Updated by Brett Smith almost 6 years ago

  • Description updated (diff)
  • Target version changed from 2016-03-02 sprint to Arvados Future Sprints

#8 Updated by Brett Smith almost 6 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.

#9 Updated by Tom Clegg almost 6 years ago

The possible websocket fix:
  • 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.)

#10 Updated by Radhika Chippada almost 6 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.

#11 Updated by Peter Amstutz almost 6 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>

#12 Updated by Peter Amstutz almost 6 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).

#13 Updated by Radhika Chippada almost 6 years ago

Renamed running_job_log_lines_to_fetch as running_job_log_records_to_fetch

#14 Updated by Radhika Chippada almost 6 years ago

  • Status changed from In Progress to Resolved
  • % Done changed from 0 to 100

Applied in changeset arvados|commit:d41ed1ac354d07c8b32796a784ece9f852bcf40f.

Also available in: Atom PDF