Beispiel #1
0
// 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
}
Beispiel #2
0
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
}
Beispiel #3
0
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
}
Beispiel #4
0
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()
	}
}
Beispiel #5
0
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
}
Beispiel #6
0
// 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
}
Beispiel #7
0
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
}
Beispiel #8
0
// 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)
}
Beispiel #9
0
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
}
Beispiel #10
0
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
}
Beispiel #11
0
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
}