// 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 }