mirror of
https://github.com/balena-os/balena-supervisor.git
synced 2025-02-08 12:20:23 +00:00
932a6f2997
Changes in the node engine related to streams would cause the gzip streams flush function to be called at the wrong times. The sinon fake timers were also interacting with this. We use setImmediate to call the flush function, and remove sinon timers for the logging tests. Change-type: patch Signed-off-by: Cameron Diver <cameron@balena.io>
117 lines
3.4 KiB
CoffeeScript
117 lines
3.4 KiB
CoffeeScript
https = require 'https'
|
|
stream = require 'stream'
|
|
zlib = require 'zlib'
|
|
|
|
Promise = require 'bluebird'
|
|
m = require 'mochainon'
|
|
{ expect } = m.chai
|
|
{ stub } = m.sinon
|
|
|
|
{ Logger } = require '../src/logger'
|
|
{ ContainerLogs } = require '../src/logging/container'
|
|
describe 'Logger', ->
|
|
beforeEach ->
|
|
@_req = new stream.PassThrough()
|
|
@_req.flushHeaders = m.sinon.spy()
|
|
@_req.end = m.sinon.spy()
|
|
|
|
@_req.body = ''
|
|
@_req
|
|
.pipe(zlib.createGunzip())
|
|
.on 'data', (chunk) =>
|
|
@_req.body += chunk
|
|
|
|
stub(https, 'request').returns(@_req)
|
|
|
|
@fakeEventTracker = {
|
|
track: m.sinon.spy()
|
|
}
|
|
|
|
@logger = new Logger({ eventTracker: @fakeEventTracker })
|
|
@logger.init({
|
|
apiEndpoint: 'https://example.com'
|
|
uuid: 'deadbeef'
|
|
deviceApiKey: 'secretkey'
|
|
unmanaged: false
|
|
enableLogs: true
|
|
localMode: false
|
|
})
|
|
|
|
afterEach ->
|
|
https.request.restore()
|
|
|
|
it 'waits the grace period before sending any logs', ->
|
|
clock = m.sinon.useFakeTimers()
|
|
@logger.log({ message: 'foobar', serviceId: 15 })
|
|
clock.tick(4999)
|
|
clock.restore()
|
|
|
|
Promise.delay(100)
|
|
.then =>
|
|
expect(@_req.body).to.equal('')
|
|
|
|
it 'tears down the connection after inactivity', ->
|
|
clock = m.sinon.useFakeTimers()
|
|
@logger.log({ message: 'foobar', serviceId: 15 })
|
|
clock.tick(61000)
|
|
clock.restore()
|
|
|
|
Promise.delay(100)
|
|
.then =>
|
|
expect(@_req.end.calledOnce).to.be.true
|
|
|
|
|
|
it 'sends logs as gzipped ndjson', ->
|
|
timestamp = Date.now()
|
|
@logger.log({ message: 'foobar', serviceId: 15 })
|
|
@logger.log({ timestamp: 1337, message: 'foobar', serviceId: 15 })
|
|
@logger.log({ message: 'foobar' }) # shold be ignored
|
|
|
|
Promise.delay(5500).then =>
|
|
expect(https.request.calledOnce).to.be.true
|
|
opts = https.request.firstCall.args[0]
|
|
|
|
expect(opts.href).to.equal('https://example.com/device/v2/deadbeef/log-stream')
|
|
expect(opts.method).to.equal('POST')
|
|
expect(opts.headers).to.deep.equal({
|
|
'Authorization': 'Bearer secretkey'
|
|
'Content-Type': 'application/x-ndjson'
|
|
'Content-Encoding': 'gzip'
|
|
})
|
|
|
|
lines = @_req.body.split('\n')
|
|
expect(lines.length).to.equal(3)
|
|
expect(lines[2]).to.equal('')
|
|
|
|
msg = JSON.parse(lines[0])
|
|
expect(msg).to.have.property('message').that.equals('foobar')
|
|
expect(msg).to.have.property('serviceId').that.equals(15)
|
|
expect(msg).to.have.property('timestamp').that.is.at.least(timestamp)
|
|
msg = JSON.parse(lines[1])
|
|
expect(msg).to.deep.equal({ timestamp: 1337, message: 'foobar', serviceId: 15 })
|
|
|
|
it 'allows logging system messages which are also reported to the eventTracker', ->
|
|
timestamp = Date.now()
|
|
@logger.logSystemMessage('Hello there!', { someProp: 'someVal' }, 'Some event name')
|
|
|
|
Promise.delay(5500)
|
|
.then =>
|
|
expect(@fakeEventTracker.track).to.be.calledWith('Some event name', { someProp: 'someVal' })
|
|
lines = @_req.body.split('\n')
|
|
expect(lines.length).to.equal(2)
|
|
expect(lines[1]).to.equal('')
|
|
|
|
msg = JSON.parse(lines[0])
|
|
expect(msg).to.have.property('message').that.equals('Hello there!')
|
|
expect(msg).to.have.property('isSystem').that.equals(true)
|
|
expect(msg).to.have.property('timestamp').that.is.at.least(timestamp)
|
|
|
|
it 'should support non-tty log lines', ->
|
|
message = '\u0001\u0000\u0000\u0000\u0000\u0000\u0000?2018-09-21T12:37:09.819134000Z this is the message'
|
|
buffer = Buffer.from(message)
|
|
|
|
expect(ContainerLogs.extractMessage(buffer)).to.deep.equal({
|
|
message: 'this is the message',
|
|
timestamp: 1537533429819
|
|
})
|