Optimize log viewer

Till now, log viewer was rendered in handlebars, which was the simplest
solution, but it had a major drawback - every append to log caused it to
rerender which was not efficient and memory consuming.

The new approach is to make Travis.Log interpret the log and send lines
with instructions to the view, so for example if view should add a line,
it gets something like:

    { number: 1, content: '$ bundle install' }

Such approach is required to handle cases where data coming from pusher
is not actually a new line. For example output containing dots from
tests needs to be appended:

    $ rake
    ....

Such output could be sent to client in 2 chunks: "$ rake\n.." and "..".
In such situation we would need to send 3 instructions:

  { number: 1, content: '$ rake' }
  { number: 2, content: '..'     }
  { number: 2, content: '..', append: true }

The third instruction can come much later, because tests can take a
while to run, so we can't assume that each line will come in one piece.

The other scenario is \r, for example when showing progress:

    \rDownloading: 10%
    \rDownloading: 50%
    \rDownloading: 100%

Such input should be changed into such instructions:

  { number: 1, content: 'Downloading: 10%' }
  { number: 1, content: 'Downloading: 50%',  replace: true }
  { number: 1, content: 'Downloading: 100%', replace: true }

Travis.Log also supports folds, for example on bundle install, the code
was rewritten to make folds management simpler.
This commit is contained in:
Piotr Sarnacki 2012-11-03 18:30:03 +01:00
parent 26def07b9d
commit fc40190c29
9 changed files with 557 additions and 53 deletions

View File

@ -34,7 +34,7 @@ input assets.scripts do
safe_concat assets.vendor_order, 'vendor.js'
end
match '{spec,spec/unit}/*.js' do
match '{spec,spec/unit,spec/unit/views}/*.js' do
concat 'spec/specs.js'
end

View File

@ -5,6 +5,7 @@ require 'travis/model'
init: ->
@_super.apply this, arguments
@set 'queue', Ember.A([])
@set 'parts', Ember.ArrayProxy.create(content: [])
@addObserver 'body', @fetchWorker
@fetchWorker()
@ -13,20 +14,26 @@ require 'travis/model'
@set('body', '')
append: (body) ->
if @get('isLoaded')
if @get('isInitialized')
@get('parts').pushObject body
@set('body', @get('body') + body)
else
@get('queue').pushObject(body)
recordDidLoad: (->
if @get('isLoaded')
if (body = @get 'body') && @get('parts.length') == 0
@get('parts').pushObject body
@set 'isInitialized', true
queue = @get('queue')
if queue.get('length') > 0
@append queue.toArray().join('')
).observes('isLoaded')
fetchWorker: ->
if body = @get('body')
if !@get('workerName') && (body = @get('body'))
line = body.split("\n")[0]
if line && (match = line.match /Using worker: (.*)/)
if worker = match[1]

View File

@ -1,10 +1,18 @@
{{view.logSubscriber}}
{{#if view.job.log.isLoaded}}
<pre id="log" class="ansi"><a href="#" id="tail" {{action toggleTailing target="view"}}>
<span class="status"></span>
<label>Follow logs</label>
</a>{{{formatLog log.body repo="repository" item="parentView.currentItem"}}}</pre>
{{! this #with + #if is needed because I want to rerender 'pre' when log changes to properly clean it up,
this should probably be refactored to use container view}}
{{#with view.job.log}}
{{#if id}}
{{#view view.PreView logBinding="view.context.log" logUrlBinding="view.logUrl"}}
<pre id="log" class="ansi"><a href="#" id="tail" {{action toggleTailing target="view"}}>
<span class="status"></span>
<label>Follow logs</label>
</a></pre>
{{/view}}
{{/if}}
{{/with}}
{{#if sponsor.name}}
<p class="sponsor">

View File

@ -50,6 +50,10 @@
templateName: 'jobs/log'
logBinding: 'job.log'
didInsertElement: ->
@_super.apply this, arguments
@tryScrollingToHashLineNumber()
scrollTo: (hash) ->
# and this is even more weird, when changing hash in URL in firefox
# to other value, for example #L10, it actually scrolls just #main
@ -81,11 +85,6 @@
checker()
didInsertElement: ->
@_super.apply this, arguments
@tryScrollingToHashLineNumber()
click: (event) ->
target = $(event.target)
@ -115,3 +114,83 @@
job.subscribe()
null
).property('job', 'job.state')
logUrl: (->
repo = @get('job.repo')
item = @get('parentView.currentItem')
if repo && item
event = if item.constructor == Travis.Build
'showBuild'
else
'showJob'
Travis.app.get('router').urlForEvent(event, repo, item)
).property('job.repo', 'parentView.currentItem')
PreView: Em.View.extend
init: ->
@_super.apply this, arguments
@set 'logManager', Travis.Log.create(target: this)
didInsertElement: ->
@_super.apply this, arguments
Ember.run.next this, ->
if @get 'log.isInitialized'
@logDidChange()
willDestroy: ->
@get('logManager').destroy()
@get('log.parts').removeArrayObserver this,
didChange: 'logContentsDidChange'
willChange: 'logContentsWillChange'
logDidChange: (->
if @get('log.isInitialized') && @state == 'inDOM'
@attachLogObservers()
).observes('log', 'log.isInitialized')
attachLogObservers: ->
return if @get('logPartsObserversAttached') == Ember.guidFor(@get('log'))
@set 'logPartsObserversAttached', Ember.guidFor(@get('log'))
Ember.run.next this, ->
@get('logManager').append @get('log.parts')
@get('log.parts').addArrayObserver this,
didChange: 'logContentsDidChange'
willChange: 'logContentsWillChange'
logContentsDidChange: (lines, index, removedCount, addedCount) ->
addedLines = lines.slice(index, index + addedCount)
@get('logManager').append addedLines
logContentsWillChange: (-> )
appendLog: (payloads) ->
url = @get('logUrl')
for payload in payloads
line = payload.content
number = payload.number
unless payload.append
pathWithNumber = "#{url}#L#{number}"
line = '<p><a href="%@" id="L%@" class="log-line-number" name="L%@">%@</a>%@</p>'.fmt(pathWithNumber, number, number, number, line)
if payload.fold && !payload.foldContinuation
line = "<div class='fold #{payload.fold} show-first-line'>#{line}</div>"
if payload.replace
this.$("#log #L#{number}").parent().replaceWith line
else if payload.append
this.$("#log #L#{number}").parent().append line
else if payload.foldContinuation
this.$("#log .fold.#{payload.fold}:last").append line
else
this.$('#log').append(line)
if payload.foldEnd
this.$("#log .fold.#{payload.fold}:last").removeClass('show-first-line')

View File

@ -1,41 +1,111 @@
@Travis.Log =
FOLDS:
schema: /(<p.*?\/a>\$ (?:bundle exec )?rake( db:create)? db:schema:load[\s\S]*?<p.*?\/a>-- assume_migrated_upto_version[\s\S]*?<\/p>\n<p.*?\/a>.*<\/p>)/g
migrate: /(<p.*?\/a>\$ (?:bundle exec )?rake( db:create)? db:migrate[\s\S]*== +\w+: migrated \(.*\) =+)/g
bundle: /(<p.*?\/a>\$ bundle install.*<\/p>\n(<p.*?\/a>(Updating|Using|Installing|Fetching|remote:|Receiving|Resolving).*?<\/p>\n|<p.*?\/a><\/p>\n)*)/g
exec: /(<p.*?\/a>[\/\w]*.rvm\/rubies\/[\S]*?\/(ruby|rbx|jruby) .*?<\/p>)/g
# TODO: revisit those patterns
FOLDS = [
Em.Object.create(name: 'schema', startPattern: /^\$ (?:bundle exec )?rake( db:create)? db:schema:load/, endPattern: /^\$/)
Em.Object.create(name: 'migrate', startPattern: /^\$ (?:bundle exec )?rake( db:create)? db:migrate/, endPattern: /^\$/)
Em.Object.create(name: 'bundle', startPattern: /^\$ bundle install/, endPattern: /^\$/)
]
filter: (log, path) ->
log = @escape(log)
log = @deansi(log)
log = log.replace(/\r/g, '')
log = @number(log, path)
log = @fold(log)
log = log.replace(/\n/g, '')
log
@Travis.Log = Em.Object.extend
init: ->
@set 'folds', []
@set 'line', 1
stripPaths: (log) ->
log.replace /\/home\/vagrant\/builds(\/[^\/\n]+){2}\//g, ''
for fold in FOLDS
@addFold fold
append: (lines) ->
log = @join lines
log = @escape log
log = @deansi log
lines = @split log
target = @get 'target'
index = 0
currentFold = @currentFold
@set 'lineNumber', 1 unless @get 'lineNumber'
result = []
for line in lines
if line == '\r'
@set 'replace', true
else if line == '\n'
@set 'newline', true
index += 1
else
if currentFold && ( @isFoldEnding(currentFold, line) )
# end of the fold, send fold to target
if result.length > 0
result.slice(-1)[0].foldEnd = true
target.appendLog result
@currentFold = currentFold = null
@set 'foldContinuation', false
result = []
if !currentFold && ( currentFold = @foldByStart(line) )
# beginning new fold, send current lines to target
if result.length > 0
target.appendLog result
result = []
start = index
payload = { content: line }
if currentFold
payload.fold = currentFold.get('name')
if @get 'foldContinuation'
payload.foldContinuation = true
payload.number = @get('lineNumber') + index
if @get 'replace'
@set 'replace', false
payload.replace = true
else if @get 'newline'
@set 'newline', false
else if payload.number != 1
payload.append = true
result.pushObject payload
if currentFold
@set 'foldContinuation', true
if result.length > 0
if currentFold
@currentFold = currentFold
target.appendLog result
nextLineNumber = @get('lineNumber') + index
@set 'lineNumber', nextLineNumber
join: (lines) ->
if typeof lines == 'string'
lines
else
lines.toArray().join ''
split: (log) ->
log = log.replace /\r\n/g, '\n'
lines = log.split(/(\n)/)
result = []
for line in lines
result.pushObjects line.split(/(\r)/)
result
escape: (log) ->
Handlebars.Utils.escapeExpression log
escapeRuby: (log) ->
log.replace /#<(\w+.*?)>/, '#&lt;$1&gt;'
number: (log, path) ->
path = "#{path}/"
result = ''
$.each log.trim().split('\n'), (ix, line) ->
number = ix + 1
pathWithNumber = "#{path}#L#{number}"
result += '<p><a href="%@" id="L%@" class="log-line-number" name="L%@">%@</a>%@</p>\n'.fmt(pathWithNumber, number, number, number, line)
result.trim()
deansi: (log) ->
log = log.replace(/\r\r/g, '\r')
.replace(/\033\[K\r/g, '\r')
.replace(/^.*\r(?!$)/gm, '')
.replace(/\[2K/g, '')
.replace(/\033\(B/g, '')
.replace(/\033\[\d+G/, '')
@ -52,17 +122,11 @@
text += (if classes.length then ('<span class=\'' + classes.join(' ') + '\'>' + part.text + '</span>') else part.text)
text.replace /\033/g, ''
fold: (log) ->
log = @unfold(log)
$.each Travis.Log.FOLDS, (name, pattern) ->
log = log.replace(pattern, ->
'<div class=\'fold ' + name + '\'>' + arguments[1].trim() + '</div>'
)
log
addFold: (fold) ->
@get('folds').pushObject fold
unfold: (log) ->
log.replace /<div class='fold[^']*'>([\s\S]*?)<\/div>/g, '$1\n'
location: ->
window.location.hash
foldByStart: (line) ->
@get('folds').find (fold) -> line.match(fold.get('startPattern'))
isFoldEnding: (fold, line) ->
line.match(fold.get('endPattern'))

View File

@ -0,0 +1,36 @@
store = null
record = null
describe 'Travis.Artifact', ->
beforeEach ->
store = Travis.Store.create()
afterEach ->
store.destroy()
describe 'with part of the body loaded', ->
beforeEach =>
store.load Travis.Artifact, 1, { id: 1, body: 'first\nsecond\n' }
record = store.find(Travis.Artifact, 1)
it 'packs the existing part of the body to parts', ->
expect( record.get('parts').toArray() ).toEqual( ['first\nsecond\n'] )
it 'adds new chunks of log to parts', ->
record.append('third\n')
expect( record.get('parts').toArray() ).toEqual( ['first\nsecond\n', 'third\n'] )
it 'properly handles array observers', ->
called = 0
observer = {
arrayDidChange: -> called += 1
arrayWillChange: -> called += 1
}
record.get('parts').addArrayObserver observer,
willChange: 'arrayWillChange'
didChange: 'arrayDidChange'
record.append('something')
expect(called).toEqual 2

View File

@ -0,0 +1,232 @@
log = null
target = null
describe 'Travis.Log', ->
beforeEach ->
target = Em.Object.create
calls: []
appendLog: (payloads) ->
lines = payloads.map (p) ->
line = p.content
delete p.content
line
@get('calls').pushObject
options: payloads
lines: lines
log = Travis.Log.create(target: target)
it 'works with log passed as a string', ->
log.append '1\n2'
expect( target.get('calls.firstObject.lines') ).toEqual ['1', '2']
it 'splits lines', ->
log.append ['1\r\n2\n\n', '3']
expect( target.get('calls.length') ).toEqual 1
expect( target.get('calls.firstObject.lines') ).toEqual ['1', '2', '', '3']
it 'escapes html characters', ->
log.append '<>'
expect( target.get('calls.firstObject.lines') ).toEqual ['&lt;&gt;']
it 'normalizes ansi mess', ->
log.append ['foo\r\r', 'bar']
expect( target.get('calls.firstObject.lines') ).toEqual [ 'foo', 'bar' ]
it 'calls target with folds separation', ->
fold = Em.Object.create name: 'foo', startPattern: /^\$ foo/, endPattern: /^\$/
log.addFold fold
fold = Em.Object.create name: 'qux', startPattern: /^\$ qux/, endPattern: /^\$/
log.addFold fold
log.append [
'1\n', '2\n'
'$ foo --foo\n', '1\n'
'$ bar\n'
'$ baz\n'
'$ qux\n', '1\n', '2\n'
'$ end\n'
]
# expect( target.get('calls.length') ).toEqual 5
lines = target.get('calls').map (call) -> call.lines
options = target.get('calls').map (call) -> call.options
expect( lines[0] ).toEqual ['1', '2']
expect( options[0]).toEqual [ { number: 1 }, { number: 2 } ]
expect( lines[1] ).toEqual ['$ foo --foo', '1']
expect( options[1]).toEqual [
{ number: 3, fold: 'foo' },
{ number: 4, fold: 'foo', foldContinuation: true, foldEnd: true }]
expect( lines[2] ).toEqual ['$ bar', '$ baz']
expect( options[2]).toEqual [{ number: 5 }, { number: 6 }]
expect( lines[3] ).toEqual ['$ qux', '1', '2']
expect( options[3]).toEqual [
{ number: 7, fold: 'qux' },
{ number: 8, fold: 'qux', foldContinuation: true },
{ number: 9, fold: 'qux', foldContinuation: true, foldEnd: true }]
expect( lines[4] ).toEqual ['$ end', '']
expect( options[4]).toEqual [{ number: 10 }, { number: 11 }]
it 'works properly when log is started with fold', ->
fold = Em.Object.create name: 'foo', startPattern: /^\$ foo/, endPattern: /^\$/
log.addFold fold
log.append [
'$ foo --foo\n', '1\n'
'$ bar\n'
]
expect( target.get('calls.length') ).toEqual 2
lines = target.get('calls').map (call) -> call.lines
options = target.get('calls').map (call) -> call.options
expect( lines[0] ).toEqual ['$ foo --foo', '1']
expect( options[0]).toEqual [
{ number: 1, fold: 'foo' },
{ number: 2, fold: 'foo', foldContinuation: true, foldEnd: true }]
expect( lines[1] ).toEqual ['$ bar', '']
expect( options[1]).toEqual [{ number: 3 }, { number: 4 }]
it 'works properly for 2 consecutive folds', ->
fold = Em.Object.create name: 'foo', startPattern: /^\$ foo/, endPattern: /^\$/
log.addFold fold
log.append [
'$ foo --foo\n', '1\n'
'$ foo --bar\n', '2\n'
'$ bar\n'
]
expect( target.get('calls.length') ).toEqual 3
lines = target.get('calls').map (call) -> call.lines
options = target.get('calls').map (call) -> call.options
expect( lines[0] ).toEqual ['$ foo --foo', '1']
expect( options[0]).toEqual [
{ number: 1, fold: 'foo' },
{ number: 2, fold: 'foo', foldContinuation: true, foldEnd: true }]
expect( lines[1] ).toEqual ['$ foo --bar', '2']
expect( options[1]).toEqual [
{ number: 3, fold: 'foo' },
{ number: 4, fold: 'foo', foldContinuation: true, foldEnd: true }]
expect( lines[2] ).toEqual ['$ bar', '']
expect( options[2]).toEqual [{ number: 5 }, { number: 6 }]
it 'works fine with not finalized fold', ->
fold = Em.Object.create name: 'foo', startPattern: /^\$ foo/, endPattern: /^\$/
log.addFold fold
log.append [
'$ foo --foo\n', '1\n'
]
expect( target.get('calls.length') ).toEqual 1
lines = target.get('calls').map (call) -> call.lines
options = target.get('calls').map (call) -> call.options
expect( lines[0] ).toEqual ['$ foo --foo', '1', '']
expect( options[0]).toEqual [
{ fold: 'foo', number: 1 },
{ fold: 'foo', number: 2, foldContinuation: true },
{ fold: 'foo', number: 3, foldContinuation: true }]
it 'allows to continue fold', ->
fold = Em.Object.create name: 'foo', startPattern: /^\$ foo/, endPattern: /^\$/
log.addFold fold
log.append [
'$ foo --foo\n', '1\n'
]
log.append '2\n'
log.append [
'3\n'
'$ bar\n'
]
expect( target.get('calls.length') ).toEqual 4
lines = target.get('calls').map (call) -> call.lines
options = target.get('calls').map (call) -> call.options
expect( lines[0] ).toEqual ['$ foo --foo', '1', '']
expect( options[0]).toEqual [
{ fold: 'foo', number: 1 },
{ fold: 'foo', number: 2, foldContinuation: true },
{ fold: 'foo', number: 3, foldContinuation: true }]
expect( lines[1] ).toEqual ['2', '']
expect( options[1]).toEqual [
{ fold: 'foo', number: 3, foldContinuation: true, append: true }
{ fold: 'foo', number: 4, foldContinuation: true }
]
expect( lines[2] ).toEqual ['3']
expect( options[2]).toEqual [
{ fold: 'foo', number: 4, foldContinuation: true, append: true, foldEnd: true }
]
expect( lines[3] ).toEqual ['$ bar', '']
expect( options[3]).toEqual [{ number: 5 }, { number: 6 }]
it 'notifies that the line should be appended', ->
log.append '$ foo\n.'
log.append '...'
log.append '..\n$ bar\n'
expect( target.get('calls.length') ).toEqual 3
lines = target.get('calls').map (call) -> call.lines
options = target.get('calls').map (call) -> call.options
expect( lines[0] ).toEqual ['$ foo', '.']
expect( options[0]).toEqual [{ number: 1 }, { number: 2 }]
expect( lines[1] ).toEqual ['...']
expect( options[1]).toEqual [{ append: true, number: 2 }]
expect( lines[2] ).toEqual ['..', '$ bar', '']
expect( options[2]).toEqual [{ append: true, number: 2 }, { number: 3 }, { number: 4 }]
it 'notifies that the line should be replaced', ->
log.append '$ foo\n'
log.append '\rDownloading 50%'
log.append '\rDownloading 100%\r\n'
log.append '$ bar\n'
expect( target.get('calls.length') ).toEqual 4
lines = target.get('calls').map (call) -> call.lines
options = target.get('calls').map (call) -> call.options
expect( lines[0] ).toEqual ['$ foo', '']
expect( options[0]).toEqual [{ number: 1 }, { number: 2 }]
expect( lines[1] ).toEqual ['', 'Downloading 50%']
expect( options[1]).toEqual [{ number: 2, append: true }, { number: 2, replace: true }]
expect( lines[2] ).toEqual ['', 'Downloading 100%', '']
expect( options[2]).toEqual [{ number: 2, append: true }, { number: 2, replace: true }, { number: 3 }]
expect( lines[3] ).toEqual ['$ bar', '']
expect( options[3]).toEqual [{ number: 3, append: true }, { number: 4 }]
it 'notifies that the line should be replaced even if carriage return is in the middle', ->

View File

@ -0,0 +1,74 @@
view = null
store = null
record = null
describe 'Travis.LogView', ->
beforeEach ->
store = Travis.Store.create()
afterEach ->
store.destroy()
view.remove()
view.destroy()
it 'works fine with existing log, which is appended', ->
store.load Travis.Artifact, 1, { id: 1, body: '$ start' }
log = Travis.Artifact.find(1)
Ember.run ->
view = Travis.LogView.create(context: null)
view.append()
expect( $('#log').length ).toEqual 1
console.log $('#log')
job = Ember.Object.create log: log, subscribe: (-> )
Ember.run ->
view.set 'context', job
log.set 'isLoaded', true
expect( view.$('#log p').length ).toEqual 1
expect( view.$('#log p').text().trim() ).toEqual '1$ start'
Ember.run ->
log.append('$ end')
expect( view.$('#log p').length ).toEqual 2
expect( view.$('#log p').text().trim() ).toEqual '1$ start2$ end'
it 'works fine with log already attahed to view', ->
store.load Travis.Artifact, 1, { id: 1, body: '$ start' }
log = Travis.Artifact.find(1)
job = Ember.Object.create log: log, subscribe: (-> )
Ember.run ->
view = Travis.LogView.create()
view.set('context', job)
view.append()
Ember.run ->
log.append('end')
expect( view.$('#log p').length ).toEqual 2
expect( view.$('#log p').text().trim() ).toEqual '1$ start2end'
it 'folds items', ->
store.load Travis.Artifact, 1, { id: 1, body: '$ start' }
log = Travis.Artifact.find(1)
job = Ember.Object.create log: log, subscribe: (-> )
Ember.run ->
view = Travis.LogView.create()
view.set('context', job)
view.append()
Ember.run ->
log.append '$ bundle install\n1\n2'
Ember.run ->
log.append '3\n4\n$ something'
expect( view.$('#log > p').length ).toEqual 2
expect( view.$('#log .fold.bundle').length ).toEqual 1
expect( view.$('#log .fold.bundle > p').length ).toEqual 5

View File

@ -39,6 +39,10 @@ pre#log
&.open
height: auto
background-image: inline-image('ui/log.fold.open.2.png')
&.show-first-line:not(.open)
height: 36px
p:not(:first-child):not(:last-child)
display: none
#log.loading
padding: 25px 0 0 10px