logging system, syslog and abstraction improvements #54

mcuadros · 2014-10-07T00:25:28Z

This is a WIP, this is a little roadmad and some questions I have.

Create server.Logger interface and add server.SetLogger method
Modify all the actual call to the new format
Network syslog
gnatsd options and link Network syslog
fix this race condition on server.SetLogger()
Tests
Transform error message in real Errors

Questions:

Is really needed the alreadyFormatted function? We can control this in the codebase
Some options like LogFile, FidFile are related more to the daemon than the Server class, we can move away? and keep it at the gnatsd.go?

Related to: #7

derekcollison · 2014-10-07T02:44:47Z

The logger is also designed for very high-performance, so be aware of that as well.

derekcollison · 2014-10-07T02:46:59Z

In regards to questions. No problem with the alreadyFormatted()

In terms of the LogFile and PidFile, where would you move them to? They are part of the options package. I understand your thoughts on server vs daemon, but not sure where we would place them or if it is worth it to move them from the core options struct.

mcuadros · 2014-10-07T06:55:21Z

Performance
Yes, I saw it use a int vs a boolean is a performance matter or just a taste one?
https://github.com/apcera/gnatsd/blob/master/server/log.go#L98

I kept this kind of logic of course, to prevent extra call to deeper functions:
https://github.com/apcera/gnatsd/blob/master/server/log.go#L98
https://github.com/apcera/gnatsd/blob/master/server/client.go#L317

Options
All the LogFile, Syslog options are handle at the gnatsd.go and server.Server dont used for nothing, so for me this must be removed. The debug and trace are needed at the server for performance reasons.

Tests
gocheck is a very good unnitest packages what do you think about?

mcuadros · 2014-10-07T21:12:15Z

I added to all the client message the cid following the same pattern:

2014/10/07 23:10:54 Starting gnatsd version 0.5.6
2014/10/07 23:10:54 Starting http monitor on port 8080
2014/10/07 23:10:54 Listening for client connections on 0.0.0.0:4222
2014/10/07 23:10:54 gnatsd is ready
2014/10/07 23:10:57 [cid: 1] Client connection created: [127.0.0.1, 57171]
2014/10/07 23:10:57 [cid: 1] OP: [CONNECT OP CONNECT {"verbose":false,"pedantic":false,"ssl_required":false,"name":""}]
2014/10/07 23:10:57 [cid: 1] OP: [PING OP]
2014/10/07 23:10:59 [cid: 1] OP: [SUB OP SUB foo  1]
2014/10/07 23:11:01 [cid: 1] OP: [PUB OP PUB foo 61]
2014/10/07 23:11:01 [cid: 1] MSG: [Processing Client msg: 1 foo  {"Client":"d7a10da3-b7d2-4a4a-8732-0e7d9a6680f0","Msg":"foo"}]

Too I simplified the Log API remove the "f" functions

derekcollison · 2014-10-08T00:09:30Z

I prefer no external dependencies, even for tests.

In terms of log output, the cid was on the end of the log line, but I am happy to consider others.

Looping in @cee-dub and @krobertson

mcuadros · 2014-10-08T00:19:03Z

The gocheck improve the quality of the tests and make less tedious use it. Is a very well know library and a quasi-standard. I have beed using it the last 2 years.

This library supports versioning so you are using a tag and this will be there forever https://labix.org/gocheck

About the cid, just tell me the format and i will make the modifications.

cee-dub · 2014-10-08T00:36:27Z

Máximo, do you have a specific proposal for how gocheck would improve the
tests? Deciding to use a different test framework requires careful
consideration.

Cameron Walters
Apcera, Inc. San Francisco, CA

On Tue, Oct 7, 2014 at 5:19 PM, Máximo Cuadros notifications@github.com
wrote:

The gocheck improve the quality of the test and make less tedious use it.
Is a very well know library and a quasi-standard. I have beed using the
last 2 years.

This library supports versioning so you are using a tag and this will be
there forever https://labix.org/gocheck

About the cid, just tell me the format and i will make the modifications.

—
Reply to this email directly or view it on GitHub
#54 (comment).

mcuadros · 2014-10-08T00:44:29Z

mcuadros · 2014-10-08T00:51:38Z

gocheck provides tons of asserts, instead make for each assert the condition and the message by hand like:

    if resp.StatusCode != 200 {
        t.Fatalf("Expected a 200 response, got %d\n", resp.StatusCode)
    }

you only need write the assert like this:

c.Assert(resp.StatusCode , Equals, 200)

Another good reason is the TestCase pattern with the SetUpTest and TearDownTest functions. This provide a standard tests enabling to any understand your tests.

cee-dub · 2014-10-08T01:28:05Z

Saving a line of conditional statement does not seem like a winning
tradeoff in the long run. Anyone who reads the tests must learn a new
framework (gocheck) to understand them. The site hosting gocheck's code
must also be available at the time any new user invokes go get -t to
obtain the testing dependencies, or else the tests will fail to build.
These problems do not exist when using only the standard library.

Cameron Walters
Apcera, Inc. San Francisco, CA

On Tue, Oct 7, 2014 at 5:51 PM, Máximo Cuadros notifications@github.com
wrote:

gocheck provides tons of asserts, instead make for each assert the
condition and the message by hand like:
if resp.StatusCode != 200 {
    t.Fatalf("Expected a 200 response, got %d\n", resp.StatusCode)
}
you only need write the assert like this:

c.Assert(resp.StatusCode , Equals, 200)

Another good reason is the TestCase pattern with the SetUpTest and
TearDownTest functions. This provide a standard tests enabling to any
understand your tests.

—
Reply to this email directly or view it on GitHub
#54 (comment).

cee-dub · 2014-10-08T01:31:00Z

This presentation also makes a strong case for using the standard library's
testing facilities directly (though it compares against Ginkgo not against
gocheck).

http://present.go-steel-programmers.org/unit_testing/2014-08-28.slide

mcuadros · 2014-10-08T08:27:29Z

I never seen this kind of problems with go-check, just makes the asserting and he is using the unnitest library for make it, why be involved in the traces in this way. In fact is a wrapper over the std library.

Gustavo Niemeyer is one of the biggest contributors to Go outside of Google and his packages (this and others like mongo driver, yaml, etc) are used for thousands of projects.

Anyway is a taste problem so dont worry :D

mcuadros · 2014-10-09T17:27:36Z

@derekcollison can you take a look? I checked the benchmarks and the times are exactly the same.

derekcollison · 2014-10-09T19:58:01Z

Yes apologize, might be a day or two but will.. I will try tonight.

@ken, @cameron - you ok with new syntax?

On Thu, Oct 9, 2014 at 10:27 AM, Máximo Cuadros notifications@github.com
wrote:

@derekcollison https://github.com/derekcollison can you take a look? I
checked the benchmarks and the times are exactly the same.

—
Reply to this email directly or view it on GitHub
#54 (comment).

derekcollison · 2014-10-09T19:58:27Z

/cc @krobertson @cee-dub

krobertson · 2014-10-10T17:54:10Z

server/client.go

 	// Check to see if we have this remote already registered.
 	// This can happen when both servers have routes to each other.
 	s := c.srv
 	c.mu.Unlock()

 	if s.addRoute(c) {
-		Debug("Registering remote route", info.ID)
+		Debug("[cid: %d] Registering remote route '%s'", c.cid, info.ID)


minor nit, but may be better to use %q over %s

yep, good one. i need review some message too.

mcuadros · 2014-10-10T21:49:52Z

This is the new format:

2014/10/10 23:47:33 [LOG] Starting gnatsd version 0.5.6
2014/10/10 23:47:33 [LOG] Starting http monitor on port 8080
2014/10/10 23:47:33 [LOG] Listening for client connections on 0.0.0.0:4222
2014/10/10 23:47:33 [LOG] gnatsd is ready
2014/10/10 23:47:44 [DBG] 127.0.0.1:56403 - cid:1 - Client connection created
2014/10/10 23:47:44 [TRA] 127.0.0.1:56403 - cid:1 - OP: [CONNECT OP CONNECT {"verbose":false,"pedantic":false,"ssl_required":false,"name":""}]
2014/10/10 23:47:44 [TRA] 127.0.0.1:56403 - cid:1 - OP: [PING OP]
2014/10/10 23:47:47 [TRA] 127.0.0.1:56403 - cid:1 - OP: [SUB OP SUB foo  1]
2014/10/10 23:47:49 [TRA] 127.0.0.1:56403 - cid:1 - OP: [PUB OP PUB foo 61]
2014/10/10 23:47:49 [TRA] 127.0.0.1:56403 - cid:1 - MSG: [Processing Client msg: 1 foo  {"Client":"766e913c-0d42-40ee-8e0a-47819f2bce8f","Msg":"bar"}]
2014/10/10 23:47:51 [DBG] 127.0.0.1:56403 - cid:1 - Client connection closed

The execution of clientConnStr not is at logger.go, to avoid unnecessary executions

mcuadros · 2014-10-10T23:07:18Z

These are the new options, the PR is finished, I am waiting for comments:

    -s, --syslog                     Enable syslog as log method.
    -r, --remote_syslog              Syslog server addr (udp://localhost:514).

mcuadros · 2014-10-14T23:40:45Z

ping

derekcollison · 2014-10-14T23:47:45Z

@krobertson @cee-dub Can you two take a look and lmk. Want to make sure that the new format does not perturb any of our tooling, etc.

mcuadros · 2014-10-14T23:57:41Z

I want add some things. Some times errors are printed as DEBUG or LOG and this should be printed as and ERROR even the verbose or debug are disabled.

So i suggest add a Error function for this type of messages

https://github.com/apcera/gnatsd/blob/master/server/route.go#L49
https://github.com/apcera/gnatsd/blob/master/server/client.go#L304
https://github.com/apcera/gnatsd/blob/master/server/client.go#L627
https://github.com/apcera/gnatsd/blob/master/server/client.go#L735

mcuadros · 2014-10-14T23:59:13Z

If you are parsing the message, then will breaks your production environment. The format message has changed.

derekcollison · 2014-10-15T00:52:54Z

I agree with that..

On Tue, Oct 14, 2014 at 4:57 PM, Máximo Cuadros notifications@github.com
wrote:

I want add some things. Some times errors are printed as DEBUG or LOG and
this should be printed as and ERROR even the verbose or debug are disabled.

So i suggest add a Error
https://github.com/apcera/gnatsd/pull/54/files#diff-d98140289c3f18c5af80fde41be84a81R78
function for this cad of messages

https://github.com/apcera/gnatsd/blob/master/server/route.go#L49
https://github.com/apcera/gnatsd/blob/master/server/client.go#L304
https://github.com/apcera/gnatsd/blob/master/server/client.go#L627
https://github.com/apcera/gnatsd/blob/master/server/client.go#L735

—
Reply to this email directly or view it on GitHub
#54 (comment).

krobertson · 2014-10-15T21:42:50Z

I think it looks good. @mcuadros could you squash the branch down to a single commit, and I can go ahead and merge.

coveralls · 2014-10-15T23:18:30Z

Coverage increased (+1.81%) when pulling 7c7578a on mcuadros:logger into 7fb5358 on apcera:master.

mcuadros · 2014-10-15T23:22:40Z

I just squashed a bit the commits, is a big PR if i mixed all will, lose sense.

Too i added theError method and renamed Log to Notice

krobertson · 2014-10-15T23:37:36Z

Thanks, its ok. We normally squash to a single commit with detailed commit messages, but it isn't a biggie.

logging system, syslog and abstraction improvements

krobertson · 2014-10-15T23:44:19Z

Arg, it looks like the govet script we're using for travis isn't working properly...

 ./travis/govet.sh
logger/log.go:46: possible formatting directive in Fatal call
exit status 1
server/client.go:147: possible formatting directive in Error call
server/client.go:239: possible formatting directive in Error call
server/monitor.go:91: possible formatting directive in Error call
server/monitor.go:117: possible formatting directive in Error call
server/monitor.go:164: possible formatting directive in Error call
server/route.go:49: possible formatting directive in Error call
server/route.go:240: possible formatting directive in Fatal call
server/route.go:297: possible formatting directive in Fatal call
server/server.go:114: possible formatting directive in Fatal call
server/server.go:267: possible formatting directive in Fatal call
server/server.go:281: possible formatting directive in Fatal call
server/server.go:286: possible formatting directive in Fatal call
server/server.go:324: possible formatting directive in Fatal call
server/server.go:337: possible formatting directive in Fatal call
exit status 1
The command "./travis/govet.sh" exited with 0.

Travis failed to have it exit non-zero, so it looked green on the PR, however merging it triggered our internal build server to run it and it failed there. This is due to all the Fatal calls that are doing formatting and govet wants them to be Fatalf.

mcuadros · 2014-10-15T23:47:48Z

This is a false positive, because the number of args dont match the number of tokens in the string, if a client is given in the list of args will be transformed:
https://github.com/apcera/gnatsd/blob/master/server/log.go#L87

krobertson · 2014-10-15T23:50:18Z

func Fatal(format string, v ...interface{}) {

That is the argument signature for formatting directive functions, so govet's rule processing is to recommend it being called Fatalf.

derekcollison · 2014-10-17T20:26:04Z

go test -v -race ./... fails, we need to fix.

On Wed, Oct 15, 2014 at 4:50 PM, Ken Robertson notifications@github.com
wrote:

func Fatal(format string, v ...interface{}) {

That is the argument signature for formatting directive functions, so
govet's rule processing is to recommend it being called Fatalf.

—
Reply to this email directly or view it on GitHub
#54 (comment).

mcuadros · 2014-10-17T21:36:26Z

How is possible my PR was ok

derekcollison · 2014-10-17T21:45:19Z

Not sure..

On Oct 17, 2014, at 2:36 PM, Máximo Cuadros notifications@github.com
wrote:

How is possible my PR was ok

—
Reply to this email directly or view it on GitHub
#54 (comment).

mcuadros · 2014-10-17T22:10:15Z

https://travis-ci.org/apcera/gnatsd/builds/38102363

On Fri, Oct 17, 2014 at 11:45 PM, Derek Collison notifications@github.com
wrote:

Not sure..

On Oct 17, 2014, at 2:36 PM, Máximo Cuadros notifications@github.com
wrote:

How is possible my PR was ok

—
Reply to this email directly or view it on GitHub
#54 (comment).

—
Reply to this email directly or view it on GitHub
#54 (comment).

cee-dub · 2014-10-17T23:39:12Z

Travis built against master. Can you pull in this change?

738227a#diff-354f30a63fb0907d4ad57269548329e3

Cameron Walters
Apcera, Inc. San Francisco, CA

On Fri, Oct 17, 2014 at 3:10 PM, Máximo Cuadros notifications@github.com
wrote:

https://travis-ci.org/apcera/gnatsd/builds/38102363

On Fri, Oct 17, 2014 at 11:45 PM, Derek Collison notifications@github.com

wrote:

Not sure..

On Oct 17, 2014, at 2:36 PM, Máximo Cuadros notifications@github.com
wrote:

How is possible my PR was ok

—
Reply to this email directly or view it on GitHub
#54 (comment).

—
Reply to this email directly or view it on GitHub
#54 (comment).

—
Reply to this email directly or view it on GitHub
#54 (comment).

mcuadros · 2014-10-17T23:50:23Z

https://travis-ci.org/apcera/gnatsd/builds/38102363#L12

On Sat, Oct 18, 2014 at 1:39 AM, Cameron Walters (cee-dub) <
notifications@github.com> wrote:

Travis built against master. Can you pull in this change?

738227a#diff-354f30a63fb0907d4ad57269548329e3

Cameron Walters
Apcera, Inc. San Francisco, CA

On Fri, Oct 17, 2014 at 3:10 PM, Máximo Cuadros notifications@github.com

wrote:

https://travis-ci.org/apcera/gnatsd/builds/38102363

On Fri, Oct 17, 2014 at 11:45 PM, Derek Collison <
notifications@github.com>

wrote:

Not sure..

On Oct 17, 2014, at 2:36 PM, Máximo Cuadros notifications@github.com

wrote:

How is possible my PR was ok

—
Reply to this email directly or view it on GitHub
#54 (comment).

—
Reply to this email directly or view it on GitHub
#54 (comment).

—
Reply to this email directly or view it on GitHub
#54 (comment).

—
Reply to this email directly or view it on GitHub
#54 (comment).

cee-dub · 2014-10-18T00:17:33Z

Please bring your branch up to date with master.

–cw
(via my iPhone)

On Oct 17, 2014, at 16:50, Máximo Cuadros notifications@github.com wrote:

https://travis-ci.org/apcera/gnatsd/builds/38102363#L12

On Sat, Oct 18, 2014 at 1:39 AM, Cameron Walters (cee-dub) <
notifications@github.com> wrote:

Travis built against master. Can you pull in this change?

738227a#diff-354f30a63fb0907d4ad57269548329e3

Cameron Walters
Apcera, Inc. San Francisco, CA

On Fri, Oct 17, 2014 at 3:10 PM, Máximo Cuadros notifications@github.com

wrote:

https://travis-ci.org/apcera/gnatsd/builds/38102363

On Fri, Oct 17, 2014 at 11:45 PM, Derek Collison <
notifications@github.com>

wrote:

Not sure..

On Oct 17, 2014, at 2:36 PM, Máximo Cuadros notifications@github.com

wrote:

How is possible my PR was ok

—
Reply to this email directly or view it on GitHub
#54 (comment).

—
Reply to this email directly or view it on GitHub
#54 (comment).

—
Reply to this email directly or view it on GitHub
#54 (comment).

—
Reply to this email directly or view it on GitHub
#54 (comment).

—
Reply to this email directly or view it on GitHub.

mcuadros · 2014-10-18T00:57:31Z

This PR was merged and was working you can see the last test execution over my pr at:
https://travis-ci.org/apcera/gnatsd/builds/38102363#L12

I just made:

git clone git clone git@github.com:apcera/gnatsd.git
cd gnatsd
go test -v -race ./...
....
echo $?
0

And all looks correct, the last travis over master is saying something strange about Debugf, but i cannot find this string at the repository.

https://travis-ci.org/apcera/gnatsd#L93
https://github.com/apcera/gnatsd/search?utf8=%E2%9C%93&q=Debugf

Can you execute again the the travis tests?

Maybe was @krobertson :) #54 (comment)

krobertson · 2014-10-18T01:03:42Z

The build is failing because of govet. There was an issue with the build script where it wasn't failing properly though. I fixed it after merging this PR here: bc84847

Even in the build output on travis, can see the govet failure, just the govet.sh script didn't exit non-zero.

I haven't seen go test or race failures.

I started fixing the vet issues, but still stuck with two where the cid is passed in... 8332dfd

mcuadros · 2014-10-18T01:08:29Z

Ok, so tell me if something is need it from this side.

I am working in a new PR about auth.

Good night! I need go to the bed Is too late here in Spain.

On Sat, Oct 18, 2014 at 3:03 AM, Ken Robertson notifications@github.com
wrote:

The build is failing because of govet. There was an issue with the build
script where it wasn't failing properly though. I fixed it after merging
this PR here: bc84847
bc84847

Even in the build output on travis, can see the govet failure, just the
govet.sh script didn't exit non-zero.

I haven't seen go test or race failures.

I started fixing the vet issues, but still stuck with two where the cid is
passed in... 8332dfd
8332dfd

—
Reply to this email directly or view it on GitHub
#54 (comment).

mcuadros changed the title ~~basic syslog abstraction and concreate classes for syslog and file loggi...~~ logging system, syslog and abstraction improvements Oct 7, 2014

krobertson reviewed Oct 10, 2014
View reviewed changes

login system abstraction

96d044d

mcuadros added 3 commits October 16, 2014 00:44

better client identification at logs and some performances improves

6586ac4

remote syslog support

d99c6ae

Notice and Logger messages

7c7578a

krobertson added a commit that referenced this pull request Oct 15, 2014

Merge pull request #54 from mcuadros/logger

82ab50f

logging system, syslog and abstraction improvements

krobertson merged commit 82ab50f into nats-io:master Oct 15, 2014

logging system, syslog and abstraction improvements #54

logging system, syslog and abstraction improvements #54

Conversation

mcuadros commented Oct 7, 2014

derekcollison commented Oct 7, 2014

derekcollison commented Oct 7, 2014

mcuadros commented Oct 7, 2014

mcuadros commented Oct 7, 2014

derekcollison commented Oct 8, 2014

mcuadros commented Oct 8, 2014

cee-dub commented Oct 8, 2014

mcuadros commented Oct 8, 2014

mcuadros commented Oct 8, 2014

cee-dub commented Oct 8, 2014

cee-dub commented Oct 8, 2014

mcuadros commented Oct 8, 2014

mcuadros commented Oct 9, 2014

derekcollison commented Oct 9, 2014

derekcollison commented Oct 9, 2014

krobertson Oct 10, 2014

Choose a reason for hiding this comment

mcuadros Oct 10, 2014

Choose a reason for hiding this comment

mcuadros commented Oct 10, 2014

mcuadros commented Oct 10, 2014

mcuadros commented Oct 14, 2014

derekcollison commented Oct 14, 2014

mcuadros commented Oct 14, 2014

mcuadros commented Oct 14, 2014

derekcollison commented Oct 15, 2014

krobertson commented Oct 15, 2014

coveralls commented Oct 15, 2014

mcuadros commented Oct 15, 2014

krobertson commented Oct 15, 2014

krobertson commented Oct 15, 2014

mcuadros commented Oct 15, 2014

krobertson commented Oct 15, 2014

derekcollison commented Oct 17, 2014

mcuadros commented Oct 17, 2014

derekcollison commented Oct 17, 2014

mcuadros commented Oct 17, 2014

cee-dub commented Oct 17, 2014

mcuadros commented Oct 17, 2014

cee-dub commented Oct 18, 2014

mcuadros commented Oct 18, 2014

krobertson commented Oct 18, 2014

mcuadros commented Oct 18, 2014