*: replace verbose with log-level #892

antihax · 2017-05-13T01:15:21Z

Removed verbose option and added a log-level option so users can customize what they receive in logs.
Should resolve issue #798

ploxiln · 2017-05-13T21:28:50Z

I think this incremental approach to enhancing nsq logging is not a bad one. Some comments though:

We might want to keep backwards-compatibility with the --verbose flag (just have it set log-level to debug). Or maybe not, we're still just before 1.0
There's some redundancy in logf(LOG_ERROR, "ERROR: failed ... that could be avoided by having the logger add the level text prefix
Is there some way to avoid having a separate copy of logging.go for each app? (Also, each app has its own logger.go with just a minimal Logger interface, I wonder if that can be consolidated.)

@judwhite probably has opinions on how nsq logging evolves ...

antihax · 2017-05-13T22:41:31Z

Agree with the --verbose compatibility, should be easy enough to handle.
The redundancy could be easily removed. I did not want to go through altering messages too much without a discussion.
logger.go and logging.go could be consolidated, but the logf functions are subtly different between nsqd and nsqadmin. It looks possible to make them similar, but opts would still be different between the three packages.

ploxiln · 2017-05-16T00:13:28Z

nsqd/http.go

+				return nil, http_api.Err{400, "INVALID_VALUE"}
+			}
+			if verbose {
+				opts.LogLevel = LOG_INFO


should this be LOG_DEBUG for verbose?

... or should it actually change opts.Verbose?

It sure should! :D

ploxiln · 2017-05-16T00:19:26Z

nsqd/nsqd.go

 		os.Exit(1)
 	}

 	if opts.StatsdPrefix != "" {
 		var port string
 		_, port, err = net.SplitHostPort(opts.HTTPAddress)
 		if err != nil {
-			n.logf("ERROR: failed to parse HTTP address (%s) - %s", opts.HTTPAddress, err)
+			n.logf(LOG_ERROR, "failed to parse HTTP address (%s) - %s", opts.HTTPAddress, err)


Pre-existing bug: looks like this should be LOG_FATAL

ploxiln · 2017-05-16T00:23:29Z

This is looking good to me.

I'm still interested in consolidating the common parts between nsqd / nsqlookupd / nsqadmin, but that can be done in a later pull request. I might do that part myself :)
I think what you have here is a good improvement.

mreiferson · 2017-05-16T00:32:26Z

apps/nsqd/nsqd.go

@@ -15,7 +15,7 @@ import (

 	"github.com/BurntSushi/toml"
 	"github.com/judwhite/go-svc/svc"
-	"github.com/mreiferson/go-options"
+	options "github.com/mreiferson/go-options"


can we drop this change in all places?

Sure thing.

mreiferson · 2017-05-16T00:32:53Z

apps/nsqadmin/main.go

+
+	logLevel  = flagSet.Int("log-level", nsqadmin.LOG_INFO, "set log verbosity: 1 through 5 (Debug, Info, Warn, Error, Fatal)")
+	logPrefix = flagSet.String("log-prefix", "[nsqadmin] ", "log message prefix")
+	verbose   = flagSet.Bool("verbose", false, "depreceated in favor of log-level")


minor typo: should be deprecated

mreiferson · 2017-05-16T00:34:07Z

apps/nsqlookupd/nsqlookupd.go

@@ -20,8 +20,10 @@ func nsqlookupdFlagSet(opts *nsqlookupd.Options) *flag.FlagSet {

 	flagSet.String("config", "", "path to config file")
 	flagSet.Bool("version", false, "print version string")
-	flagSet.Bool("verbose", false, "enable verbose logging")
+
+	flagSet.Int("log-level", nsqlookupd.LOG_WARN, "set log verbosity: 1 through 5 (Debug, Info, Warn, Error, Fatal)")


Is it a better UX for these to be strings rather than ints?

It would be. Could process the string into an int once the flag parsing is done, deal with errors, etc.

Is it worth the extra effort?

Probably yes. Command-line arguments are a sort of API in which changes should be avoided, so better to polish it now.

Let me take a crack at it then.

antihax · 2017-05-16T00:49:58Z

Odd error on the go 1.7 386 node, twice in a row:

Bad response status from coveralls: 422
{"message":"Couldn't find a repository matching this job.","error":true}
The command "./coverage.sh --coveralls" exited with 1.

ploxiln · 2017-05-16T00:52:58Z

Don't worry about random coveralls failures, we won't complain about them :)

antihax · 2017-05-16T02:46:57Z

There may be a more elegant way of handling this, but it is escaping me at this time.

ploxiln · 2017-05-16T03:02:01Z

I think LogLevel does need to have its default set in NewOptions() for each app, even though that's redundant with the flags ... unfortunate but true ...

(this comment was originally added to a commit accidentally, then deleted and copied here)

antihax · 2017-05-16T03:10:58Z

I will throw a default in there tomorrow night.

ploxiln · 2017-05-16T03:23:50Z

contrib/nsqd.cfg.example

+# 3 = Warning
+# 4 = Error
+# 5 = Fatal
+log-level = 1


config file value should be strings too

antihax · 2017-05-17T14:32:41Z

I wrote a test to check the http configuration side of it and discovered it was racing on logLevel defined in the NSQD struct; I moved it to opts but not left unexported.

Similar issue appears with nsqlookupd as opts is not atomic.Value there.

Check it out and give me some feedback on how you folks feel about this.

ploxiln · 2017-05-17T15:40:47Z

I think only nsqadmin and nsqd have an http interface for configuration changes after startup, so nsqlookupd shouldn't need atomic.Value. I also think it's fine if the integer logLevel is "eventually consistent", such that other threads see the new integer logLevel a few seconds after it has changed. I don't know if there's a way to make the race detector just ignore this detail...

ploxiln · 2017-05-17T15:42:39Z

nsqadmin/logger.go

+	LOG_FATAL = 5
+)
+
+func (n *NSQAdmin) logLevelFromString(level string) int {


This doesn't need to be a method of the app, it doesn't use the app struct at all.

I had a similar thought, but additionally was going to suggest that we make levels a type that can be shared across applications. We can provide a function that takes a string and returns an appropriately typed value and also implement the Stringer interface on the type to satisfy the purpose here.

I think it should also be possible to cast an int directly to this type if its signature is type LogLevel int?

Agreed about sharing across applications, but was thinking it would be OK if @antihax did not want to do that refactoring in this pull request. We could have the cmdline flags and http interfaces finalized in this PR, and I could do internal refactoring in a follow-up (and we could "bikeshed" as necessary).

I normally don't entertain promises to clean up in a later pull-request, but since it's me ¯\(ツ)/¯

Or, instead of directly merging this, I could include and then build on it in a separate PR.

OK with deferring if you're going to finish this up @ploxiln

I've been mulling over moving it to a separate package.

Concerned that it will end up looking like nsdq.logf(logger.LOG_WARN, "something") and a little baffled how to handle the config side. Normally could write custom marshaling functions to deal with the mapping from string to int but i do not see how to support with go-options.

I am ok with you folks refactoring it later; I am still learning atm.

My first idea was to move this stuff into internal/lg/ and rename the constants without the LOG_ prefix, so you would end up typing nsqd.logf(lg.WARN, "something")

(I didn't want to use internal/log/ and possibly conflict with the stdlib in files that import it, but maybe that's not really a problem in practice)

@antihax 👍 SGTM, we can follow up. I appreciate your work on this!

ploxiln · 2017-05-17T15:43:55Z

nsqadmin/logger.go

+	case "fatal":
+		return LOG_FATAL
+	case "":
+		return LOG_INFO


I don't think you need to handle the blank case, this can be considered invalid.

I also don't think you need ToLower(), you can just require the lowercase strings. This is not a big deal though.

I can change these easily, concern would be if log-level was missing from the .cfg; a blank case would silently load a default rather than fail.

Likewise if a user had Debug in a config instead of debug, may take them a moment to notice case matters.

Right, I was proposing erroring/exiting for anything but the expected lowercase strings. Blank not "silently loading a default" like you have here, but instead failing as invalid.

(I think that if log-level is missing in the config file you'll get the default "info" from NewOptions().)

Yes, you are correct, i see now where the defaults would be loaded.

ploxiln · 2017-05-17T15:44:58Z

nsqadmin/logger.go

+	}
+
+	if level >= n.getOpts().logLevel || n.getOpts().Verbose {
+		n.getOpts().Logger.Output(2, fmt.Sprintf(levelString+": "+f, args...))


How about you do opts = n.GetOpts() just once above, so the atomic.Value is fetched and cast just once.

Fixed in last commit.

ploxiln · 2017-05-17T15:45:57Z

nsqadmin/nsqadmin.go

+	// check log-level is valid and translate to int
+	switch strings.ToLower(opts.LogLevel) {
+	case "debug":
+		opts.logLevel = LOG_DEBUG


should use logLevelFromString() here

ploxiln · 2017-05-18T03:02:53Z

nsqlookupd/nsqlookupd.go

+		n.logLevel = LOG_ERROR
+	case "fatal":
+		n.logLevel = LOG_FATAL
+	case "":


another blank

but actually, should use logLevelFromString()

ploxiln · 2017-05-19T05:49:55Z

nsqadmin/http.go

@@ -732,6 +732,21 @@ func (s *httpServer) doConfig(w http.ResponseWriter, req *http.Request, ps httpr
 			if err != nil {
 				return nil, http_api.Err{400, "INVALID_VALUE"}
 			}
+		case "log_level":
+			var logLevelStr string // temporary variable in case the value is invalid
+			err := json.Unmarshal(body, &logLevelStr)


I was testing this PR locally and ran into this - I don't think this should be json, it should just be a plain string.

Treating the body as json representation of a single string means you need to include the quotes e.g. "info" instead of info and that seems a bit silly.

(Same comment applies for nsqd.)

To justify this opinion a bit more: "nsqlookupd_tcp_addresses" is a list so json makes sense, and "verbose" is a boolean which has non-quoted representation in json so that's convenient. But adding quotes around a single word, particularly for a manual tool like curl where you end up running curl --data-binary '"info"' ..., is a bit unexpected.

ploxiln · 2017-05-19T06:05:09Z

Interesting complication: internal/http_api/ and internal/clusterinfo/ use the Logger from the app, but have their own Log() and logf() functions (and http_api is relatively complicated). This could be something I work on during the refactoring...

ploxiln · 2017-05-19T07:17:30Z

This seems to me to be close to ready for merge.
We prefer for the commits to be squashed together before merge, I hope that's not too much trouble :)

ploxiln · 2017-05-19T21:31:39Z

nsqd/options.go

@@ -90,6 +92,8 @@ func NewOptions() *Options {
 	return &Options{
 		ID:        defaultID,
 		LogPrefix: "[nsqd] ",
+		LogLevel:  "info",
+		logLevel:  2,


I think putting the logLevel int default in nsqd.NewOptions() isn't needed, because it's set from the string in nsqd.New(). (The same goes for nsqadmin, but you didn't set the logLevel int default in nsqadmin.NewOptions().)

But this doesn't hurt (except a tiny bit of code redundancy), and I think it may be fine to wait to fix it in my planned follow-up PR.

ploxiln · 2017-05-19T21:32:32Z

I think this is ready to merge. @mreiferson any objections?

mreiferson · 2017-05-20T00:09:22Z

nsqadmin/logger.go

+	case "fatal":
+		return LOG_FATAL
+	default:
+		return -1


(This can be fixed in a follow up).

This feels like a C idiom, not Go. If this function has error conditions, it should return (int, error) and this should be a case that returns an error.

mreiferson · 2017-05-20T00:11:47Z

I'm good, nice work @antihax!

Cryptophobia · 2018-05-16T16:50:53Z

Is this actually working? I set log-level to "fatal" in the config and still getting lots of these messages:

[nsqd] 2018/05/16 16:48:14.474918 200 GET /stats?format=json (172.17.0.7:34458) 28.505µs
[nsqd] 2018/05/16 16:48:15.438242 200 GET /stats?format=json (172.17.0.7:34458) 81.649µs
[nsqd] 2018/05/16 16:48:16.055924 200 GET /ping (172.17.0.1:49356) 1.394µs
[nsqd] 2018/05/16 16:48:16.502575 200 GET /stats?format=json (172.17.0.7:34458) 81.476µs
[nsqd] 2018/05/16 16:48:17.469571 200 GET /ping (172.17.0.1:49362) 1.533µs
[nsqd] 2018/05/16 16:48:17.628870 200 GET /stats?format=json (172.17.0.7:34458) 98.366µs
[nsqd] 2018/05/16 16:48:18.592711 200 GET /stats?format=json (172.17.0.7:34458) 28.124µs
[nsqd] 2018/05/16 16:48:20.095872 200 GET /stats?format=json (172.17.0.7:34458) 87.2µs
[nsqd] 2018/05/16 16:48:21.096870 200 GET /stats?format=json (172.17.0.7:34458) 23.456µs
[nsqd] 2018/05/16 16:48:22.147546 200 GET /stats?format=json (172.17.0.7:34458) 47.282µs
[nsqd] 2018/05/16 16:48:22.665315 200 GET /stats?format=json (172.17.0.7:34458) 24.41µs
[nsqd] 2018/05/16 16:48:23.936802 200 GET /stats?format=json (172.17.0.7:34458) 35.987µs
[nsqd] 2018/05/16 16:48:25.298011 200 GET /stats?format=json (172.17.0.7:34458) 36.1µs
[nsqd] 2018/05/16 16:48:26.055191 200 GET /ping (172.17.0.1:49418) 834ns
[nsqd] 2018/05/16 16:48:26.287143 200 GET /stats?format=json (172.17.0.7:34458) 34.374µs
[nsqd] 2018/05/16 16:48:26.368759 200 GET /stats?format=json (172.17.0.7:34458) 26.843µs

ploxiln · 2018-05-16T17:43:07Z

This was merged after version "1.0.0-compat" was released. We need to cut another release.

Cryptophobia · 2018-05-16T18:31:53Z

@ploxiln : Oh nooo! I did not notice that this was merged after the last release! I assumed it was in the last release.

Well my birthday is coming up... and it has been almost a year since this was merged in, can we get a new release soon?

Cryptophobia · 2018-05-17T17:40:56Z

@mreiferson : nsqd is a dependency of ours on the hephy project (deis workflow) fork and we would like to limit log level in order to remove noise in the logs. Any idea of when we can get a new release?

tmedford · 2018-05-17T17:45:45Z

@mreiferson I need this too. Not being able to limit logs levels is creating extra cost to our logging solution.

sacus · 2018-05-21T07:52:00Z

@mreiferson @ploxiln I need this too. Not being able to limit logs levels is creating extra cost to our logging solution.

mreiferson · 2018-05-21T15:25:20Z

I'll issue a release this week, thanks everyone 🙏

Cryptophobia · 2018-06-04T21:00:58Z

@mreiferson Any news on this release?

tmedford · 2018-07-08T16:44:20Z

@mreiferson @ploxiln Can we get a release? This needs to be addressed.

Cryptophobia · 2018-07-09T18:53:08Z

@mreiferson : We really would like to limit log-level in our Hephy Workflow nsqd component. A new release with this feature would be really nice. Is there any way we can assist and help out with the release?

We can fork and create a release but I would rather someone who knows where exactly to tag even though Travis builds seem to be passing!

mreiferson · 2018-07-10T14:01:39Z

Yep, sorry for the delay 🙏.

Cryptophobia · 2018-07-18T19:17:41Z

@mreiferson , don't get side-tracked and distracted now ... You have almost finished making this release. 💵 💰

tmedford · 2018-07-31T11:14:47Z

@mreiferson Bump release please.

ploxiln · 2018-07-31T15:38:24Z

There was just a v1.1.0-rc1 "release candidate" which you can try :)

ploxiln reviewed May 16, 2017

View reviewed changes

mreiferson reviewed May 16, 2017

View reviewed changes

mreiferson changed the title ~~Replace verbose with log-level to reduce log sizes.~~ *: replace verbose with log-level May 16, 2017

mreiferson added the chore label May 16, 2017

ploxiln reviewed May 16, 2017

View reviewed changes

contrib/nsqd.cfg.example Outdated

# 3 = Warning

# 4 = Error

# 5 = Fatal

log-level = 1

Copy link

Member

ploxiln May 16, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

config file value should be strings too

ploxiln reviewed May 17, 2017

View reviewed changes

ploxiln reviewed May 18, 2017

View reviewed changes

This was referenced May 18, 2017

nsq_to_file: log less (or support a "quiet mode") #880

Closed

*: switch to glog #853

Open

nsqd: a way to configure logging verbosity #798

Closed

*: consider merging absolute8511/nsq fork (HA, replication, in-order delivery, log-based) #887

Open

ploxiln reviewed May 19, 2017

View reviewed changes

replace verbose with log-level to reduce log sizes

f767f8c

antihax force-pushed the master branch from 0a3cad5 to f767f8c Compare May 19, 2017 20:14

ploxiln reviewed May 19, 2017

View reviewed changes

mreiferson reviewed May 20, 2017

View reviewed changes

ploxiln merged commit 9168c0f into nsqio:master May 20, 2017

ploxiln mentioned this pull request May 20, 2017

*: internal logging package refactor #898

Merged

Thermi mentioned this pull request Sep 8, 2017

nsqd and nsqlookupd syslog severity error #941

Closed

This was referenced May 16, 2018

nsqd log-level does not work? #1034

Closed

Update nsq version, add config, lower log-level, fix URLs and emails teamhephy/nsqd#4

Merged

*: replace verbose with log-level #892

*: replace verbose with log-level #892

Conversation

antihax commented May 13, 2017

ploxiln commented May 13, 2017

antihax commented May 13, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ploxiln commented May 16, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

antihax commented May 16, 2017

ploxiln commented May 16, 2017

antihax commented May 16, 2017

ploxiln commented May 16, 2017 • edited Loading

antihax commented May 16, 2017

Choose a reason for hiding this comment

antihax commented May 17, 2017

ploxiln commented May 17, 2017

Choose a reason for hiding this comment

mreiferson May 17, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

antihax May 18, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ploxiln commented May 19, 2017

ploxiln commented May 19, 2017

Choose a reason for hiding this comment

ploxiln commented May 19, 2017

Choose a reason for hiding this comment

mreiferson commented May 20, 2017

Cryptophobia commented May 16, 2018 • edited Loading

ploxiln commented May 16, 2018

Cryptophobia commented May 16, 2018 • edited Loading

Cryptophobia commented May 17, 2018

tmedford commented May 17, 2018

sacus commented May 21, 2018

mreiferson commented May 21, 2018

Cryptophobia commented Jun 4, 2018

tmedford commented Jul 8, 2018 • edited Loading

Cryptophobia commented Jul 9, 2018 • edited Loading

mreiferson commented Jul 10, 2018

Cryptophobia commented Jul 18, 2018

tmedford commented Jul 31, 2018

ploxiln commented Jul 31, 2018

antihax commented May 13, 2017 •

edited

Loading

ploxiln commented May 16, 2017 •

edited

Loading

mreiferson May 17, 2017 •

edited

Loading

antihax May 18, 2017 •

edited

Loading

Cryptophobia commented May 16, 2018 •

edited

Loading

Cryptophobia commented May 16, 2018 •

edited

Loading

tmedford commented Jul 8, 2018 •

edited

Loading

Cryptophobia commented Jul 9, 2018 •

edited

Loading