// Emit encodes and sends a Heka log message. Implements LogEmitter.Emit.
func (he *HekaEmitter) Emit(level LogLevel, messageType, payload string,
fields LogFields) (err error) {
hm := newHekaMessage()
defer hm.free()
messageID, _ := id.GenerateBytes()
hm.msg.SetUuid(messageID)
hm.msg.SetTimestamp(time.Now().UnixNano())
hm.msg.SetType(messageType)
hm.msg.SetLogger(he.LogName)
hm.msg.SetSeverity(int32(level))
hm.msg.SetPayload(payload)
hm.msg.SetEnvVersion(he.EnvVersion)
hm.msg.SetPid(he.Pid)
hm.msg.SetHostname(he.Hostname)
for _, name := range fields.Names() {
message.NewStringField(hm.msg, name, fields[name])
}
if err = he.StreamEncoder.EncodeMessageStream(hm.msg, &hm.outBytes); err != nil {
return fmt.Errorf("Error encoding log message: %s", err)
}
if err = he.Sender.SendMessage(hm.outBytes); err != nil {
return fmt.Errorf("Error sending log message: %s", err)
}
return nil
}
func (di *DockerLogInput) Run(ir pipeline.InputRunner, h pipeline.PluginHelper) error {
var (
pack *pipeline.PipelinePack
ok bool
)
hostname := h.Hostname()
go di.attachMgr.Listen(di.logstream, di.closer)
// Get the InputRunner's chan to receive empty PipelinePacks
packSupply := ir.InChan()
ok = true
var err error
for ok {
select {
case logline := <-di.logstream:
pack = <-packSupply
pack.Message.SetType("DockerLog")
pack.Message.SetLogger(logline.Type) // stderr or stdout
pack.Message.SetHostname(hostname) // Use the host's hosntame
pack.Message.SetPayload(logline.Data)
pack.Message.SetTimestamp(time.Now().UnixNano())
pack.Message.SetUuid(uuid.NewRandom())
message.NewStringField(pack.Message, "ContainerID", logline.ID)
message.NewStringField(pack.Message, "ContainerName", logline.Name)
ir.Deliver(pack)
case err, ok = <-di.attachErrors:
if !ok {
err = errors.New("Docker event channel closed")
break
}
ir.LogError(fmt.Errorf("Attacher error: %s", err))
case err = <-di.stopChan:
ok = false
}
}
di.closer <- struct{}{}
close(di.logstream)
return err
}
func (input *NsqInput) HandleMessage(msg *nsq.Message) error {
pack := <-input.packSupply
// If we're using protobuf, then the entire message is in the
// nats message body
if *input.UseMsgBytes {
pack.MsgBytes = msg.Body
} else {
pack.Message.SetUuid(uuid.NewRandom())
pack.Message.SetTimestamp(time.Now().UnixNano())
pack.Message.SetType("nsq.input")
pack.Message.SetHostname(input.pConfig.Hostname())
pack.Message.SetPayload(string(msg.Body))
message.NewStringField(pack.Message, "topic", input.Topic)
message.NewStringField(pack.Message, "channel", input.Channel)
}
input.sendPack(pack)
return nil
}
func (foRunner *foRunner) exit() {
// Just exit if we're stopping.
if foRunner.pConfig.Globals.IsShuttingDown() {
return
}
// If we're stoppable unregister ourself
if foRunner.IsStoppable() {
foRunner.LogMessage("has stopped, exiting plugin without shutting down.")
err := foRunner.Unregister(foRunner.pConfig)
if err != nil {
foRunner.LogError(
fmt.Errorf("err: %s. could not unregister plugin. ",
"Shutting down.", err))
foRunner.pConfig.Globals.ShutDown()
return
}
// Once the inchan is closed we know the router has closed the matcher
// and we wont leak any packs.
<-foRunner.inChan
// A TerminatedError means the plugin was terminated, and has generated
// its own termination message, so we can return now.
if _, ok := foRunner.lastErr.(TerminatedError); ok {
return
}
pack := foRunner.pConfig.PipelinePack(0)
pack.Message.SetType("heka.terminated")
pack.Message.SetLogger(HEKA_DAEMON)
message.NewStringField(pack.Message, "plugin", foRunner.Name())
var errMsg string
if foRunner.lastErr != nil {
errMsg = foRunner.lastErr.Error()
} else if foRunner.pluginGlobals.Typ == "SandboxFilter" {
errMsg = "Filter unloaded."
} else {
// This is simply when run returns no errors, but the plugin has
// exited anyway
errMsg = "Run exited."
}
errMsg = "Error: " + errMsg
payload := fmt.Sprintf("%s (type %s) terminated. "+errMsg,
foRunner.Name(), foRunner.pluginGlobals.Typ)
pack.Message.SetPayload(payload)
// Do not call inject, we need to avoid matching a message to ourself
foRunner.pConfig.router.inChan <- pack
} else {
foRunner.LogMessage("has stopped, shutting down.")
foRunner.pConfig.Globals.ShutDown()
}
}
func (m *MultiOutputDecoder) Decode(pack *PipelinePack) (packs []*PipelinePack, err error) {
if _, ok := pack.Message.GetFieldValue("skipit"); ok {
return nil, errors.New("Skipped")
}
pack2 := NewPipelinePack(m.recycleChan)
pack3 := NewPipelinePack(m.recycleChan)
pack2.Message = new(message.Message)
pack3.Message = new(message.Message)
pack.Message.Copy(pack2.Message)
pack.Message.Copy(pack3.Message)
message.NewStringField(pack2.Message, "skipit", "skipit")
packs = append(packs, pack, pack2, pack3)
return
}
// ReportMsg provides plugin state to Heka report and dashboard.
func (li *LogstreamerInput) ReportMsg(msg *message.Message) error {
li.logstreamSetLock.RLock()
defer li.logstreamSetLock.RUnlock()
for _, name := range li.logstreamSet.GetLogstreamNames() {
logstream, ok := li.logstreamSet.GetLogstream(name)
if ok {
fname, bytes := logstream.ReportPosition()
message.NewStringField(msg, fmt.Sprintf("%s-filename", name), fname)
message.NewInt64Field(msg, fmt.Sprintf("%s-bytes", name), bytes, "count")
}
}
return nil
}
func (dei *DockerEventInput) Run(ir pipeline.InputRunner, h pipeline.PluginHelper) error {
defer dei.dockerClient.RemoveEventListener(dei.eventStream)
defer close(dei.eventStream)
var (
ok bool
err error
pack *pipeline.PipelinePack
)
hostname := h.Hostname()
// Provides empty PipelinePacks
packSupply := ir.InChan()
ok = true
for ok {
select {
case event := <-dei.eventStream:
pack = <-packSupply
pack.Message.SetType("DockerEvent")
pack.Message.SetLogger(event.ID)
pack.Message.SetHostname(hostname)
payload := fmt.Sprintf("id:%s status:%s from:%s time:%d", event.ID, event.Status, event.From, event.Time)
pack.Message.SetPayload(payload)
pack.Message.SetTimestamp(time.Now().UnixNano())
pack.Message.SetUuid(uuid.NewRandom())
message.NewStringField(pack.Message, "ID", event.ID)
message.NewStringField(pack.Message, "Status", event.Status)
message.NewStringField(pack.Message, "From", event.From)
message.NewInt64Field(pack.Message, "Time", event.Time, "ts")
ir.Deliver(pack)
case err = <-dei.stopChan:
ok = false
}
}
return err
}
// Generate recycle channel and plugin report messages and put them on the
// provided channel as they're ready.
func (pc *PipelineConfig) reports(reportChan chan *PipelinePack) {
var (
f *message.Field
pack *PipelinePack
msg *message.Message
err, e error
)
pack = <-pc.reportRecycleChan
msg = pack.Message
message.NewIntField(msg, "InChanCapacity", cap(pc.inputRecycleChan), "count")
message.NewIntField(msg, "InChanLength", len(pc.inputRecycleChan), "count")
msg.SetType("heka.input-report")
message.NewStringField(msg, "name", "inputRecycleChan")
message.NewStringField(msg, "key", "globals")
reportChan <- pack
pack = <-pc.reportRecycleChan
msg = pack.Message
message.NewIntField(msg, "InChanCapacity", cap(pc.injectRecycleChan), "count")
message.NewIntField(msg, "InChanLength", len(pc.injectRecycleChan), "count")
msg.SetType("heka.inject-report")
message.NewStringField(msg, "name", "injectRecycleChan")
message.NewStringField(msg, "key", "globals")
reportChan <- pack
pack = <-pc.reportRecycleChan
msg = pack.Message
message.NewIntField(msg, "InChanCapacity", cap(pc.router.InChan()), "count")
message.NewIntField(msg, "InChanLength", len(pc.router.InChan()), "count")
message.NewInt64Field(msg, "ProcessMessageCount", atomic.LoadInt64(&pc.router.processMessageCount), "count")
msg.SetType("heka.router-report")
message.NewStringField(msg, "name", "Router")
message.NewStringField(msg, "key", "globals")
reportChan <- pack
getReport := func(runner PluginRunner) (pack *PipelinePack) {
pack = <-pc.reportRecycleChan
if err = PopulateReportMsg(runner, pack.Message); err != nil {
msg = pack.Message
f, e = message.NewField("Error", err.Error(), "")
if e == nil {
msg.AddField(f)
}
msg.SetType("heka.plugin-report")
}
return
}
pc.inputsLock.Lock()
for name, runner := range pc.InputRunners {
if runner.Transient() {
continue
}
pack = getReport(runner)
message.NewStringField(pack.Message, "name", name)
message.NewStringField(pack.Message, "key", "inputs")
reportChan <- pack
}
pc.inputsLock.Unlock()
for _, runner := range pc.allDecoders {
pack = getReport(runner)
message.NewStringField(pack.Message, "name", runner.Name())
message.NewStringField(pack.Message, "key", "decoders")
reportChan <- pack
}
pc.filtersLock.Lock()
for name, runner := range pc.FilterRunners {
pack = getReport(runner)
message.NewStringField(pack.Message, "name", name)
message.NewStringField(pack.Message, "key", "filters")
reportChan <- pack
}
pc.filtersLock.Unlock()
for name, runner := range pc.OutputRunners {
pack = getReport(runner)
message.NewStringField(pack.Message, "name", name)
message.NewStringField(pack.Message, "key", "outputs")
reportChan <- pack
}
close(reportChan)
}
func (foRunner *foRunner) exit() {
if !foRunner.useBuffering {
defer func() {
var orphaned int
for pack := range foRunner.inChan {
// drain and recycle the orphaned packs
orphaned++
pack.recycle()
}
if orphaned == 1 {
foRunner.LogError(fmt.Errorf("Lost/Dropped 1 message"))
} else if orphaned > 1 {
foRunner.LogError(fmt.Errorf("Lost/Dropped %d messages", orphaned))
}
}()
}
// Just exit if we're stopping.
if foRunner.pConfig.Globals.IsShuttingDown() {
return
}
// Also, if this isn't a "stoppable" plugin we shut everything down.
if !foRunner.IsStoppable() {
foRunner.LogMessage("has stopped, shutting down.")
foRunner.pConfig.Globals.ShutDown(1)
return
}
// If we're stoppable we unregister the plugin and, if necessary, send a
// termination message.
foRunner.LogMessage("has stopped, exiting plugin without shutting down.")
foRunner.Unregister(foRunner.pConfig)
// A TerminatedError means the plugin was terminated, and has generated
// its own termination message, so we can return now.
if _, ok := foRunner.lastErr.(TerminatedError); ok {
return
}
pack, e := foRunner.pConfig.PipelinePack(0)
if e != nil {
LogError.Printf("can't generate termination message: %s", e.Error())
return
}
pack.Message.SetType("heka.terminated")
pack.Message.SetLogger(HEKA_DAEMON)
message.NewStringField(pack.Message, "plugin", foRunner.name)
var errMsg string
if foRunner.lastErr != nil {
errMsg = foRunner.lastErr.Error()
} else if foRunner.pluginType == "SandboxFilter" {
errMsg = "Filter unloaded."
} else {
// This is simply when run returns no errors, but the plugin has
// exited anyway.
errMsg = "Run exited."
}
errMsg = "Error: " + errMsg
payload := fmt.Sprintf("%s (type %s) terminated. %s", foRunner.name,
foRunner.pluginType, errMsg)
pack.Message.SetPayload(payload)
// Do not call the Inject method b/c we might get burned by the explicit
// message matcher check in cases where it looks like we'd be injecting a
// message to ourself.
pack.EncodeMsgBytes()
foRunner.pConfig.router.inChan <- pack
}
func (this *SandboxFilter) Run(fr pipeline.FilterRunner, h pipeline.PluginHelper) (err error) {
inChan := fr.InChan()
ticker := fr.Ticker()
var (
ok = true
terminated = false
sample = true
blocking = false
backpressure = false
pack *pipeline.PipelinePack
retval int
msgLoopCount uint
injectionCount uint
startTime time.Time
slowDuration int64 = int64(this.pConfig.Globals.MaxMsgProcessDuration)
duration int64
capacity = cap(inChan) - 1
)
// We assign to the return value of Run() for errors in the closure so that
// the plugin runner can determine what caused the SandboxFilter to return.
this.sb.InjectMessage(func(payload, payload_type, payload_name string) int {
if injectionCount == 0 {
err = pipeline.TerminatedError("exceeded InjectMessage count")
return 2
}
injectionCount--
pack := h.PipelinePack(msgLoopCount)
if pack == nil {
err = pipeline.TerminatedError(fmt.Sprintf("exceeded MaxMsgLoops = %d",
this.pConfig.Globals.MaxMsgLoops))
return 3
}
if len(payload_type) == 0 { // heka protobuf message
hostname := pack.Message.GetHostname()
err := proto.Unmarshal([]byte(payload), pack.Message)
if err == nil {
// do not allow filters to override the following
pack.Message.SetType("heka.sandbox." + pack.Message.GetType())
pack.Message.SetLogger(fr.Name())
pack.Message.SetHostname(hostname)
} else {
return 1
}
} else {
pack.Message.SetType("heka.sandbox-output")
pack.Message.SetLogger(fr.Name())
pack.Message.SetPayload(payload)
ptype, _ := message.NewField("payload_type", payload_type, "file-extension")
pack.Message.AddField(ptype)
pname, _ := message.NewField("payload_name", payload_name, "")
pack.Message.AddField(pname)
}
if !fr.Inject(pack) {
return 4
}
atomic.AddInt64(&this.injectMessageCount, 1)
return 0
})
for ok {
select {
case pack, ok = <-inChan:
if !ok {
break
}
atomic.AddInt64(&this.processMessageCount, 1)
injectionCount = this.pConfig.Globals.MaxMsgProcessInject
msgLoopCount = pack.MsgLoopCount
if this.manager != nil { // only check for backpressure on dynamic plugins
// reading a channel length is generally fast ~1ns
// we need to check the entire chain back to the router
backpressure = len(inChan) >= capacity ||
fr.MatchRunner().InChanLen() >= capacity ||
len(h.PipelineConfig().Router().InChan()) >= capacity
}
// performing the timing is expensive ~40ns but if we are
// backpressured we need a decent sample set before triggering
// termination
if sample ||
(backpressure && this.processMessageSamples < int64(capacity)) ||
this.sbc.Profile {
startTime = time.Now()
sample = true
}
retval = this.sb.ProcessMessage(pack)
if sample {
duration = time.Since(startTime).Nanoseconds()
this.reportLock.Lock()
this.processMessageDuration += duration
this.processMessageSamples++
if this.sbc.Profile {
this.profileMessageDuration = this.processMessageDuration
this.profileMessageSamples = this.processMessageSamples
if this.profileMessageSamples == int64(capacity)*10 {
this.sbc.Profile = false
// reset the normal sampling so it isn't heavily skewed by the profile values
// i.e. process messages fast during profiling and then switch to malicious code
this.processMessageDuration = this.profileMessageDuration / this.profileMessageSamples
this.processMessageSamples = 1
}
}
this.reportLock.Unlock()
}
if retval <= 0 {
if backpressure && this.processMessageSamples >= int64(capacity) {
if this.processMessageDuration/this.processMessageSamples > slowDuration ||
fr.MatchRunner().GetAvgDuration() > slowDuration/5 {
terminated = true
blocking = true
}
}
if retval < 0 {
atomic.AddInt64(&this.processMessageFailures, 1)
em := this.sb.LastError()
if len(em) > 0 {
fr.LogError(errors.New(em))
}
}
sample = 0 == rand.Intn(this.sampleDenominator)
} else {
terminated = true
}
pack.Recycle()
case t := <-ticker:
injectionCount = this.pConfig.Globals.MaxMsgTimerInject
startTime = time.Now()
if retval = this.sb.TimerEvent(t.UnixNano()); retval != 0 {
terminated = true
}
duration = time.Since(startTime).Nanoseconds()
this.reportLock.Lock()
this.timerEventDuration += duration
this.timerEventSamples++
this.reportLock.Unlock()
}
if terminated {
pack := h.PipelinePack(0)
pack.Message.SetType("heka.sandbox-terminated")
pack.Message.SetLogger(pipeline.HEKA_DAEMON)
message.NewStringField(pack.Message, "plugin", fr.Name())
if blocking {
pack.Message.SetPayload("sandbox is running slowly and blocking the router")
// no lock on the ProcessMessage variables here because there are no active writers
message.NewInt64Field(pack.Message, "ProcessMessageCount", this.processMessageCount, "count")
message.NewInt64Field(pack.Message, "ProcessMessageFailures", this.processMessageFailures, "count")
message.NewInt64Field(pack.Message, "ProcessMessageSamples", this.processMessageSamples, "count")
message.NewInt64Field(pack.Message, "ProcessMessageAvgDuration",
this.processMessageDuration/this.processMessageSamples, "ns")
message.NewInt64Field(pack.Message, "MatchAvgDuration", fr.MatchRunner().GetAvgDuration(), "ns")
message.NewIntField(pack.Message, "FilterChanLength", len(inChan), "count")
message.NewIntField(pack.Message, "MatchChanLength", fr.MatchRunner().InChanLen(), "count")
message.NewIntField(pack.Message, "RouterChanLength", len(h.PipelineConfig().Router().InChan()), "count")
} else {
pack.Message.SetPayload(this.sb.LastError())
}
fr.Inject(pack)
break
}
}
if this.manager != nil {
this.manager.PluginExited()
}
this.reportLock.Lock()
var destroyErr error
if this.sbc.PreserveData {
destroyErr = this.sb.Destroy(this.preservationFile)
} else {
destroyErr = this.sb.Destroy("")
}
if destroyErr != nil {
err = destroyErr
}
this.sb = nil
this.reportLock.Unlock()
return
}
func (this *SandboxManagerFilter) Run(fr pipeline.FilterRunner,
h pipeline.PluginHelper) (err error) {
inChan := fr.InChan()
var ok = true
var pack *pipeline.PipelinePack
var delta int64
this.restoreSandboxes(fr, h, this.workingDirectory)
for ok {
select {
case pack, ok = <-inChan:
if !ok {
break
}
atomic.AddInt64(&this.processMessageCount, 1)
delta = time.Now().UnixNano() - pack.Message.GetTimestamp()
if math.Abs(float64(delta)) >= 5e9 {
fr.UpdateCursor(pack.QueueCursor)
pack.Recycle(fmt.Errorf("Discarded control message: %d seconds skew",
delta/1e9))
break
}
action, _ := pack.Message.GetFieldValue("action")
switch action {
case "load":
current := int(atomic.LoadInt32(&this.currentFilters))
if current < this.maxFilters {
err := this.loadSandbox(fr, h, this.workingDirectory, pack.Message)
if err != nil {
p, e := h.PipelinePack(0)
if e != nil {
fr.LogError(err)
fr.LogError(fmt.Errorf("can't send termination message: %s", e.Error()))
break
}
p.Message.SetType("heka.sandbox-terminated")
p.Message.SetLogger(pipeline.HEKA_DAEMON)
message.NewStringField(p.Message, "plugin", fr.Name())
p.Message.SetPayload(err.Error())
fr.Inject(p)
fr.LogError(err)
}
} else {
fr.LogError(fmt.Errorf("%s attempted to load more than %d filters",
fr.Name(), this.maxFilters))
}
case "unload":
fv, _ := pack.Message.GetFieldValue("name")
if name, ok := fv.(string); ok {
name = getSandboxName(fr.Name(), name)
if this.pConfig.RemoveFilterRunner(name) {
removeAll(this.workingDirectory, fmt.Sprintf("%s.*", name))
}
}
}
pack.Recycle(nil)
}
}
return
}