refactoring of log messages #312

Lagovas · 2019-02-12T11:47:08Z

added error codes for all warning/error messages
synchronized some messages for mysql/postgresql
removed old/redundant messages
added killing processes in integrations tests via pidof to catch situations with sighup/restart on acra-server
change blocking method in main function for acra-server, swapped SIGHUP with SIGTERM handler. actually it doesn't change any logic but tried it to fix unknown sighup messages on circleci. thought that maybe it is some golang runtime special behavior with closing channel at end or something like that...
pass logger's with context to inner functions to log debug messages with related client/zone id
avoid error logs with decryption failures when it expected and are allowed (binary data but not acrastruct) and use warnings instead errors when it failure on acrastruct (to notify clients because may be situation when clients think that all data correctly encrypted but it's not)

remove redundant logs synchronize log messages in postgresql/mysql backend

…evel function with correct verbose level

…ut decryption failure

vixentael

I have few suggestions about logs wording, but overall it looks great!

vixentael · 2019-02-12T12:09:09Z

acra-censor/acra-censor_configuration_provider.go

 			acraCensor.AddHandler(queryCaptureHandler)
 		default:
-			acraCensor.logger.Errorln("Unexpected handler in configuration")
+			acraCensor.logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorSetupError).Errorln("Unexpected handler in configuration")


Suggested change

acraCensor.logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorSetupError).Errorln("Unexpected handler in configuration")

acraCensor.logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorSetupError).Errorln("Unexpected handler in configuration: probably AcraCensor configuration (acra-censor.yaml) is outdated.")

vixentael · 2019-02-12T12:11:17Z

acra-censor/handlers/denyall_handler.go

 func (handler *DenyAllHandler) CheckQuery(sqlQuery string, parsedQuery sqlparser.Statement) (bool, error) {
 	// deny any query and stop further checks
-	handler.logger.Errorf("Query has been block by Denyall handler")
+	handler.logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorQueryIsNotAllowed).Errorf("Query has been block by Denyall handler")


Sounds a bit weird, but we started using "deny" everywhere, so..

Suggested change

handler.logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorQueryIsNotAllowed).Errorf("Query has been block by Denyall handler")

handler.logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorQueryIsNotAllowed).Errorf("Query has been denied by Denyall handler")

vixentael · 2019-02-12T12:31:09Z

cmd/acra-server/listener.go

 		spanContext, err := network.ReadTrace(wrappedConnection)
 		if err != nil {
-			log.WithError(err).Errorln("Can't read trace from Acra-Proxy")
+			log.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorTracingCantReadTrace).WithError(err).Errorln("Can't read trace from Acra-Proxy")


Suggested change

log.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorTracingCantReadTrace).WithError(err).Errorln("Can't read trace from Acra-Proxy")

log.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorTracingCantReadTrace).WithError(err).Errorln("Can't read trace from AcraConnector")

vixentael · 2019-02-12T12:33:05Z

cmd/prometheus.go

 		err := server.Serve(listener)
 		if err != nil {
-			logrus.WithError(err).Errorln("Error from http server that process prometheus metrics")
+			logrus.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorPrometheusHTTPHandler).WithError(err).Errorln("Error from http server that process prometheus metrics")


I saw that you prefer HTTP now :)

Suggested change

logrus.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorPrometheusHTTPHandler).WithError(err).Errorln("Error from http server that process prometheus metrics")

logrus.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorPrometheusHTTPHandler).WithError(err).Errorln("Error from HTTP server that process prometheus metrics")

vixentael · 2019-02-12T12:39:57Z

decryptor/postgresql/pg_decryptor.go

 			span.AddAttributes(trace.BoolAttribute("failed_decryption", true))
 			base.AcrastructDecryptionCounter.WithLabelValues(base.DecryptionTypeFail).Inc()
-			logger.WithError(err).Warningln("Can't unwrap symmetric key")
+			logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorDecryptorCantDecryptBinary).WithError(err).Warningln("Can't decrypt AcraStruct")


Imagine we get these logs from customer. How could we understand where exactly decryption failed.

Suggested change

logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorDecryptorCantDecryptBinary).WithError(err).Warningln("Can't decrypt AcraStruct")

logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorDecryptorCantDecryptBinary).WithError(err).Warningln("Can't decrypt AcraStruct: can't unwrap symmetric key")

im not agree. this info will be available in debug mode. but I removed logging as warnings such deep information where it was failed. now it's general warning that can't decrypt probably matched AcraStruct. and in common cases it should not be often logged

ok, makes sense

vixentael · 2019-02-12T12:40:21Z

decryptor/postgresql/pg_decryptor.go

 			span.AddAttributes(trace.BoolAttribute("failed_decryption", true))
 			base.AcrastructDecryptionCounter.WithLabelValues(base.DecryptionTypeFail).Inc()
-			logger.WithError(err).Warningln("Can't decrypt data with unwrapped symmetric key")
+			logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorDecryptorCantDecryptBinary).WithError(err).Warningln("Can't decrypt data with unwrapped symmetric key")


Do you think we could improve this error message too?

Suggested change

logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorDecryptorCantDecryptBinary).WithError(err).Warningln("Can't decrypt data with unwrapped symmetric key")

logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorDecryptorCantDecryptBinary).WithError(err).Warningln("Can't decrypt AcraStruct: can't decrypt data with unwrapped symmetric key")

vixentael · 2019-02-12T12:42:58Z

utils/logging.go

-
-import "fmt"
-
-// TODO: move to /logging and refactor everything


ilammy

I have no opinion on appropriateness of log levels (yet) but here are some general comments on readability at least 😃

ilammy · 2019-02-12T12:15:26Z

acra-censor/acra-censor_configuration_provider.go

 			acraCensor.AddHandler(queryCaptureHandler)
 		default:
-			acraCensor.logger.Errorln("Unexpected handler in configuration")
+			acraCensor.logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorSetupError).Errorln("Unexpected handler in configuration")


I find long lines like this a bit hard to read. Something like this would be clearer, I think.

Suggested change

acraCensor.logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorSetupError).Errorln("Unexpected handler in configuration")

acraCensor.logger.

WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorSetupError).

Errorln("Unexpected handler in configuration")

Though I don't know if one can convince gofmt that this code style is okay.

ilammy · 2019-02-12T12:17:00Z

cmd/acra-server/acra-server.go

 		go server.Start()
 	}

 	// on sighup we run callback that stop all listeners (that stop background goroutine of server.Start())


It seems that this comment line now belongs to line 426 where we install SIGHUP handler.

ilammy · 2019-02-12T12:21:51Z

decryptor/postgresql/pg_decryptor.go

 				proxy.TLSCh <- true
 				return
 			}
+			// log message with debug level because onlt here we expect and can meet errors with closed connections .ioEOF


Typo

Suggested change

// log message with debug level because onlt here we expect and can meet errors with closed connections .ioEOF

// log message with debug level because only here we expect and can meet errors with closed connections .ioEOF

ilammy · 2019-02-12T12:23:23Z

keystore/filesystem/server_keystore.go

-		log.Errorln("Key store folder has an incorrect permissions")
+	const expectedPermission = "-rwx------"
+	if nil == err && runtime.GOOS == "linux" && fi.Mode().Perm().String() != expectedPermission {
+		log.Errorf("Key store folder has an incorrect permissions, expected: %s", expectedPermission)


It may be useful to log actual permissions as well. Like we do in utils/utils.go for files.

ilammy · 2019-02-12T12:32:40Z

logging/logging.go

 type loggerKey struct{}

+// IsDebugLevel return true if logger configured to log debug messages
+func IsDebugLevel(logger *log.Entry) bool {


An idea of (possibly) more convenient interface for debug logging:

some.logger.OnlyForLevel(log.DebugLevel). WithField("machine_readable", data). Debugf("human-readable message")

No idea how to implement this tho (at the moment), but with this we should avoid one unnecessary nesting level of the if check before logging.

Though, I believe the current approach has its merits as well. We may use IsDebugLevel to avoid doing some heavy computations for debug logging if it is not actually enabled.

now this method used to check that logging configured with DebugLevel and we can add to logger's context more data (now used only for mode of decryption whole|inline) which will be used in inner functions but not unnecessary for default InfoLevel

ilammy · 2019-02-12T12:35:33Z

tests/utils.py

+        return
+    output = output.strip().decode('utf-8').split(separator)
+    for pid in output:
+        os.kill(int(pid), signal)


If we're using subprocess anyway then it may be more simple to call killall utility which sends a signal to processes by their name pattern. It's a pretty old BSD utility which should be generally available everywhere.

yes but killall is not installed on all systems by default. but pidof is posix utility that available in more OS's. it more useful for local running tests without requirement to install killall on local/docker machine.
p.s. debian which used in our tests hasn't installed killall by default

Lagovas · 2019-02-12T13:13:04Z

return usage of sighup handler as last block function because it didn't fix sighup problem
applied your suggestions as one commit to avoid many commits for each suggestion

storojs72 · 2019-02-13T16:14:45Z

decryptor/postgresql/pg_escape_decryptor.go

 		}
 		if n != 1 {
-			log.Debugln("readOctalData read 0 bytes")
+			decryptor.logger.Debugln("readOctalData read 0 bytes")


As I understand, now we write logs from capital letter

yes but I leaved readOctalData as is because it's name of method

Lagovas added 12 commits February 5, 2019 19:33

add codes for errors

f439c72

block on sigterm signal instead sighup

1bc11a2

add metrics for decrypted acrastructs in mysql

25d3999

remove redundant logs synchronize log messages in postgresql/mysql backend

avoid logging on failed decryption plain data [ci skip]

ee75151

sync trace attributes in mysql/postgresql backends

5c509df

log about send/receive trace to higher level

3dbc258

kill all forked processes even after sighup

5eab761

remove legacy error log method

a33eafd

remove log about error from low-level function to handle it in high-l…

5d25aab

…evel function with correct verbose level

log decryption errors with debug level and log high level message abo…

5762052

…ut decryption failure

remove legacy log message and add original error to log

4cf6862

remove separator parameter for pidof

3a477bc

Lagovas requested review from storojs72 and vixentael February 12, 2019 11:47

vixentael added refactoring logging / tracing labels Feb 12, 2019

vixentael reviewed Feb 12, 2019

View reviewed changes

ilammy reviewed Feb 12, 2019

View reviewed changes

suggested fixes

c720de5

vixentael approved these changes Feb 12, 2019

View reviewed changes

storojs72 reviewed Feb 13, 2019

View reviewed changes

storojs72 approved these changes Feb 13, 2019

View reviewed changes

Lagovas merged commit 47c33ac into cossacklabs:master Feb 13, 2019

Lagovas deleted the lagovas/T935-refactoring-of-log-messages branch February 20, 2019 15:01

	acraCensor.logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorSetupError).Errorln("Unexpected handler in configuration")
	acraCensor.logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorSetupError).Errorln("Unexpected handler in configuration: probably AcraCensor configuration (acra-censor.yaml) is outdated.")

	handler.logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorQueryIsNotAllowed).Errorf("Query has been block by Denyall handler")
	handler.logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorQueryIsNotAllowed).Errorf("Query has been denied by Denyall handler")

	log.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorTracingCantReadTrace).WithError(err).Errorln("Can't read trace from Acra-Proxy")
	log.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorTracingCantReadTrace).WithError(err).Errorln("Can't read trace from AcraConnector")

	logrus.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorPrometheusHTTPHandler).WithError(err).Errorln("Error from http server that process prometheus metrics")
	logrus.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorPrometheusHTTPHandler).WithError(err).Errorln("Error from HTTP server that process prometheus metrics")

	logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorDecryptorCantDecryptBinary).WithError(err).Warningln("Can't decrypt AcraStruct")
	logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorDecryptorCantDecryptBinary).WithError(err).Warningln("Can't decrypt AcraStruct: can't unwrap symmetric key")


		import "fmt"

		// TODO: move to /logging and refactor everything

	// log message with debug level because onlt here we expect and can meet errors with closed connections .ioEOF
	// log message with debug level because only here we expect and can meet errors with closed connections .ioEOF

refactoring of log messages #312

refactoring of log messages #312

Uh oh!

Conversation

Lagovas commented Feb 12, 2019

Uh oh!

vixentael left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ilammy left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Lagovas commented Feb 12, 2019

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants