logrus_syslog ignoring log level

[tommyblue]

Following the docs at https://github.com/sirupsen/logrus/#hooks I'm trying to use an external syslog server to send only WARNING (and above) logs there, while sending debug to local logs. Unfortunately it doesn't seem to work. The external syslog server receives whatever I setup with log.SetLevel() instead of the priority argument passed to logrus_syslog.NewSyslogHook.

Am I doing anything wrong here? Maybe I misinterpreted the docs?

package main

import (
	log "github.com/sirupsen/logrus"
	logrus_syslog "github.com/sirupsen/logrus/hooks/syslog"
)

func main() {
	log.SetLevel(log.DebugLevel)

	hook, err := logrus_syslog.NewSyslogHook("tcp", "localhost:5140", syslog.LOG_WARNING, "test")
	if err != nil {
		panic(err)
	}
	log.AddHook(hook)

	// These 2 should go both to local and remote logs
	log.Warn("ciao with warn")
	log.Error("ciao with error")
	
	// These should only go to local logs and not to external syslog,
	// but instead they're shown there too :(
	log.Debug("ciao with debug")
	log.Info("ciao with info")
}

[thaJeztah]

I only had a quick glance, but would have to look up what the intended design was for this.

Having a look at the code, I see that the loglevel passed to NewSyslogHook is passed through to syslog.Dial();

logrus/hooks/syslog/syslog.go

Lines 23 to 26 in a448f82

	func NewSyslogHook(network, raddr string, priority syslog.Priority, tag string) (*SyslogHook, error) {
	w, err := syslog.Dial(network, raddr, priority, tag)
	return &SyslogHook{w, network, raddr}, err
	}

Where syslog.Dial() uses that level for each log message sent;

Each write to the returned writer sends a log message with the facility and severity (from priority) and tag

However, the Hook itself advertises what log-levels it supports, which is "all log levels" in this case;

logrus/hooks/syslog/syslog.go

Lines 53 to 55 in a448f82

	func (hook *SyslogHook) Levels() []logrus.Level {
	return logrus.AllLevels
	}

When the hook is added, that information is used to add a hook for each level it supports;

logrus/hooks.go

Lines 16 to 22 in a448f82

	// Add a hook to an instance of logger. This is called with
	// `log.Hooks.Add(new(MyHook))` where `MyHook` implements the `Hook` interface.
	func (hooks LevelHooks) Add(hook Hook) {
	for _, level := range hook.Levels() {
	hooks[level] = append(hooks[level], hook)
	}
	}

Which, when hooks are triggered, is used to fire the hook;

logrus/hooks.go

Lines 26 to 34 in a448f82

	func (hooks LevelHooks) Fire(level Level, entry *Entry) error {
	for _, hook := range hooks[level] {
	if err := hook.Fire(entry); err != nil {
	return err
	}
	}
	return nil
	}

From the above, this either was by design (hooks always are tiggered for any level they support), or this was an oversight, and either the LevelHooks.Add() should only add hooks for levels above the logger's level, or entry.firehooks() should exclude it when firing;

logrus/entry.go

Lines 274 to 283 in a448f82

	tmpHooks = make(LevelHooks, len(entry.Logger.Hooks))
	for k, v := range entry.Logger.Hooks {
	tmpHooks[k] = v
	}
	entry.Logger.mu.Unlock()
	err := tmpHooks.Fire(entry.Level, entry)
	if err != nil {
	fmt.Fprintf(os.Stderr, "Failed to fire hook: %v\n", err)
	}

[thaJeztah]

Would probably be worth (if you have time for that) to look into history to find what the intended design was here (and if it was by design, or an oversight).

[tommyblue]

yup, implementing the interface changing what Levels() returns does the trick:

package main

import (
	"log/syslog"

	log "github.com/sirupsen/logrus"
	logrus_syslog "github.com/sirupsen/logrus/hooks/syslog"
)

type testHook struct {
	*logrus_syslog.SyslogHook
}

func (h *testHook) Levels() []log.Level {
	return []log.Level{log.WarnLevel}
}

func main() {
	log.SetLevel(log.DebugLevel)

	hook, err := logrus_syslog.NewSyslogHook("tcp", "localhost:5140", syslog.LOG_WARNING, "test")
	if err != nil {
		panic(err)
	}

	log.AddHook(&testHook{hook})

	//...
}

The original behaviour seems very strange to me. You can specify a level but then it is ignored 🤔
But at the same time is seems strange nobody noticed this until now... That's why I was thinking I was misusing it

[github-actions]

This issue is stale because it has been open for 30 days with no activity.

[github-actions]

This issue was closed because it has been inactive for 14 days since being marked as stale.