refactoring of log messages (#312)

* add codes for errors

* add metrics for decrypted acrastructs in mysql
remove redundant logs
synchronize log messages in postgresql/mysql backend
* avoid logging on failed decryption plain data [ci skip]
* sync trace attributes in mysql/postgresql backends
* log about send/receive trace to higher level
* kill all forked processes even after sighup
* remove legacy error log method
* remove log about error from low-level function to handle it in high-level function with correct verbose level

acra-censor/acra-censor_configuration_provider.go

@@ -19,6 +19,7 @@ package acracensor
 import (
 	"github.com/cossacklabs/acra/acra-censor/common"
 	"github.com/cossacklabs/acra/acra-censor/handlers"
+	"github.com/cossacklabs/acra/logging"
 	"gopkg.in/yaml.v2"
 	"strings"
 )
@@ -107,7 +108,9 @@ func (acraCensor *AcraCensor) LoadConfiguration(configuration []byte) error {
 			go queryCaptureHandler.Start()
 			acraCensor.AddHandler(queryCaptureHandler)
 		default:
-			acraCensor.logger.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")
 			return common.ErrCensorConfigurationError
 		}
 	}

acra-censor/acra-censor_implementation.go

@@ -19,6 +19,7 @@ package acracensor
 import (
 	"github.com/cossacklabs/acra/acra-censor/common"
 	"github.com/cossacklabs/acra/acra-censor/handlers"
+	"github.com/cossacklabs/acra/logging"
 	"github.com/cossacklabs/acra/sqlparser"
 	log "github.com/sirupsen/logrus"
 )
@@ -77,10 +78,12 @@ func (acraCensor *AcraCensor) HandleQuery(rawQuery string) error {
 	normalizedQuery, queryWithHiddenValues, parsedQuery, err := common.HandleRawSQLQuery(rawQuery)
 	// Unparsed query handling
 	if err == common.ErrQuerySyntaxError {
-		acraCensor.logger.WithError(err).Warning("Failed to parse input query")
 		acraCensor.saveUnparsedQuery(rawQuery)
-		if !acraCensor.ignoreParseError {
-			acraCensor.logger.Errorln("Unparsed query has been denied")
+		if acraCensor.ignoreParseError {
+			// log warning if we ignore such errors
+			acraCensor.logger.WithError(err).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorQueryParseError).Warning("Failed to parse input query")
+		} else {
+			acraCensor.logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorQueryParseError).Errorln("Unparsed query has been denied")
 			return err
 		}
 	}
@@ -129,13 +132,13 @@ func (acraCensor *AcraCensor) logAllowedQuery(queryWithHiddenValues string, pars
 
 func (acraCensor *AcraCensor) logDeniedQuery(queryWithHiddenValues string, handler QueryHandlerInterface, parsedQuery sqlparser.Statement) {
 	if parsedQuery != nil && queryWithHiddenValues != "" {
-		acraCensor.logger.Errorf("Denied query: '%s'", common.TrimStringToN(queryWithHiddenValues, common.LogQueryLength))
-		acraCensor.logger.Debugf("Denied query by %T", handler)
+		acraCensor.logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorQueryIsNotAllowed).Errorf("Denied query: '%s'", common.TrimStringToN(queryWithHiddenValues, common.LogQueryLength))
+		acraCensor.logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorQueryIsNotAllowed).Debugf("Denied query by %T", handler)
 		return
 	}
 	if parsedQuery == nil && queryWithHiddenValues == "" {
-		acraCensor.logger.Errorln("Denied query can't be shown in plaintext")
-		acraCensor.logger.Debugf("Denied query by %T", handler)
+		acraCensor.logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorQueryIsNotAllowed).Errorln("Denied query can't be shown in plaintext")
+		acraCensor.logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorQueryIsNotAllowed).Debugf("Denied query by %T", handler)
 		return
 	}
 	acraCensor.logger.Debugf("parsedQuery: %T, queryWithHiddenValues: %s", parsedQuery, queryWithHiddenValues)

acra-censor/common/common.go

@@ -194,7 +194,6 @@ func HandleRawSQLQuery(sql string) (normalizedQuery, redactedQuery string, parse
 
 	stmt, err := sqlparser.Parse(sqlStripped)
 	if err != nil {
-		log.WithError(err).Errorln("Can't process raw query")
 		return "", "", nil, ErrQuerySyntaxError
 	}
 	outputStmt, _ := sqlparser.Parse(sqlStripped)

acra-censor/handlers/denyall_handler.go

@@ -2,6 +2,7 @@ package handlers
 
 import (
 	"github.com/cossacklabs/acra/acra-censor/common"
+	"github.com/cossacklabs/acra/logging"
 	"github.com/cossacklabs/acra/sqlparser"
 	log "github.com/sirupsen/logrus"
 )
@@ -20,7 +21,7 @@ func NewDenyallHandler() *DenyAllHandler {
 // CheckQuery blocks any input query
 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 denied by Denyall handler")
 	return false, common.ErrDenyAllError
 }
 

cmd/acra-addzone/acra-addzone.go

@@ -57,45 +57,45 @@ func main() {
 
 	err := cmd.Parse(defaultConfigPath, serviceName)
 	if err != nil {
-		log.WithError(err).Errorln("can't parse args")
+		log.WithError(err).Errorln("Can't parse args")
 		os.Exit(1)
 	}
 	//LoadFromConfig(defaultConfigPath)
 	//iniflags.Parse()
 
 	output, err := filepath.Abs(*outputDir)
 	if err != nil {
-		log.WithError(err).Errorln("can't get absolute path for output dir")
+		log.WithError(err).Errorln("Can't get absolute path for output dir")
 		os.Exit(1)
 	}
 	var keyStore keystore.KeyStore
 	if *fsKeystore {
 		masterKey, err := keystore.GetMasterKeyFromEnvironment()
 		if err != nil {
-			log.WithError(err).Errorln("can't load master key")
+			log.WithError(err).Errorln("Can't load master key")
 			os.Exit(1)
 		}
 		scellEncryptor, err := keystore.NewSCellKeyEncryptor(masterKey)
 		if err != nil {
-			log.WithError(err).Errorln("can't init scell encryptor")
+			log.WithError(err).Errorln("Can't init scell encryptor")
 			os.Exit(1)
 		}
 		keyStore, err = filesystem.NewFilesystemKeyStore(output, scellEncryptor)
 		if err != nil {
-			log.WithError(err).Errorln("can't create key store")
+			log.WithError(err).Errorln("Can't create key store")
 			os.Exit(1)
 		}
 	} else {
 		panic("No more supported keystores")
 	}
 	id, publicKey, err := keyStore.GenerateZoneKey()
 	if err != nil {
-		log.WithError(err).Errorln("can't add zone")
+		log.WithError(err).Errorln("Can't add zone")
 		os.Exit(1)
 	}
 	json, err := zone.ZoneDataToJSON(id, &keys.PublicKey{Value: publicKey})
 	if err != nil {
-		log.WithError(err).Errorln("can't encode to json")
+		log.WithError(err).Errorln("Can't encode to json")
 		os.Exit(1)
 	}
 	fmt.Println(string(json))

cmd/acra-authmanager/acra_authmanager.go

@@ -179,7 +179,7 @@ func main() {
 	debug := flag.Bool("d", false, "Turn on debug logging")
 
 	if err := cmd.Parse(defaultConfigPath, serviceName); err != nil {
-		log.WithError(err).Errorln("can't parse cmd arguments")
+		log.WithError(err).Errorln("Can't parse cmd arguments")
 		os.Exit(1)
 	}
 
@@ -193,12 +193,12 @@ func main() {
 
 	masterKey, err := keystore.GetMasterKeyFromEnvironment()
 	if err != nil {
-		log.WithError(err).Errorln("can't load master key")
+		log.WithError(err).Errorln("Can't load master key")
 		os.Exit(1)
 	}
 	encryptor, err := keystore.NewSCellKeyEncryptor(masterKey)
 	if err != nil {
-		log.WithError(err).Errorln("can't initialize scell encryptor")
+		log.WithError(err).Errorln("Can't initialize scell encryptor")
 		os.Exit(1)
 	}
 	keyStore, err := filesystem.NewFilesystemKeyStore(*keysDir, encryptor)

cmd/acra-connector/acra-connector.go

@@ -90,7 +90,7 @@ func handleConnection(config *Config, connection net.Conn) {
 	defer func() {
 		logger.Infoln("Close connection with client")
 		if err := connection.Close(); err != nil {
-			logger.WithError(err).Errorln("Error on closing client's connection")
+			logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCantCloseConnectionToService).WithError(err).Errorln("Error on closing client's connection")
 		}
 	}()
 
@@ -158,6 +158,7 @@ func handleConnection(config *Config, connection net.Conn) {
 		}
 	}()
 
+	logger.Debugln("Send trace")
 	if err := network.SendTrace(ctx, acraConnWrapped); err != nil {
 		logger.WithError(err).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorTracingCantSendTrace).
 			Errorln("Can't send trace data")
@@ -330,12 +331,12 @@ func main() {
 	log.Infof("Initializing keystore...")
 	masterKey, err := keystore.GetMasterKeyFromEnvironment()
 	if err != nil {
-		log.WithError(err).Errorln("can't load master key")
+		log.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCantLoadMasterKey).WithError(err).Errorln("Can't load master key")
 		os.Exit(1)
 	}
 	scellEncryptor, err := keystore.NewSCellKeyEncryptor(masterKey)
 	if err != nil {
-		log.WithError(err).Errorln("can't init scell encryptor")
+		log.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCantInitPrivateKeysEncryptor).WithError(err).Errorln("Can't init scell encryptor")
 		os.Exit(1)
 	}
 	keyStore, err := filesystem.NewConnectorFileSystemKeyStore(*keysDir, []byte(*clientID), scellEncryptor, connectorMode)
@@ -354,15 +355,15 @@ func main() {
 	exists, err := keyStore.CheckIfPrivateKeyExists([]byte(*clientID))
 	if !exists || err != nil {
 		log.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorWrongConfiguration).
-			Errorf("Configuration error: can't check that AcraConnector private key exists, got error - %v", err)
+			Errorf("Configuration error: Can't check that AcraConnector private key exists, got error - %v", err)
 		os.Exit(1)
 	}
 	log.Infof("Client id = %v, and client key is OK", *clientID)
 
 	_, err = keyStore.GetPeerPublicKey([]byte(*clientID))
 	if err != nil {
 		log.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorWrongConfiguration).
-			Errorf("Configuration error: can't check that %s public key exists, got error - %v", connectorMode, err)
+			Errorf("Configuration error: Can't check that %s public key exists, got error - %v", connectorMode, err)
 		os.Exit(1)
 	}
 	log.Infof("%v public key is OK", connectorMode)
@@ -394,7 +395,7 @@ func main() {
 		config.ConnectionWrapper, err = network.NewSecureSessionConnectionWrapper([]byte(*clientID), keyStore)
 		if err != nil {
 			log.WithError(err).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorTransportConfiguration).
-				Errorln("Configuration error: can't initialize secure session connection wrapper")
+				Errorln("Configuration error: Can't initialize secure session connection wrapper")
 			os.Exit(1)
 		}
 	}
@@ -405,13 +406,13 @@ func main() {
 			tlsConfig, err := network.NewTLSConfig(network.SNIOrHostname(*tlsAcraserverSNI, *acraServerHost), *tlsCA, *tlsKey, *tlsCert, tls.ClientAuthType(*tlsAuthType))
 			if err != nil {
 				log.WithError(err).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorTransportConfiguration).
-					Errorln("Configuration error: can't get config for TLS")
+					Errorln("Configuration error: Can't get config for TLS")
 				os.Exit(1)
 			}
 			config.ConnectionWrapper, err = network.NewTLSConnectionWrapper(nil, tlsConfig)
 			if err != nil {
 				log.WithError(err).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorTransportConfiguration).
-					Errorln("Configuration error: can't initialize TLS connection wrapper")
+					Errorln("Configuration error: Can't initialize TLS connection wrapper")
 				os.Exit(1)
 			}
 		} else if *noEncryptionTransport {
@@ -422,7 +423,7 @@ func main() {
 			config.ConnectionWrapper, err = network.NewSecureSessionConnectionWrapper([]byte(*clientID), keyStore)
 			if err != nil {
 				log.WithError(err).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorTransportConfiguration).
-					Errorln("Configuration error: can't initialize secure session connection wrapper")
+					Errorln("Configuration error: Can't initialize secure session connection wrapper")
 				os.Exit(1)
 			}
 		}
@@ -436,23 +437,23 @@ func main() {
 				commandsListener, err := network.Listen(*connectionAPIString)
 				if err != nil {
 					log.WithError(err).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCantStartListenConnections).
-						Errorln("System error: can't start listen connections to http API")
+						Errorln("System error: Can't start listen connections to HTTP API")
 					os.Exit(1)
 				}
 				sigHandler.AddListener(commandsListener)
 				for {
 					connection, err := commandsListener.Accept()
 					if err != nil {
 						log.WithError(err).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCantAcceptNewConnections).
-							Errorf("System error: can't accept new connection")
+							Errorf("System error: Can't accept new connection")
 						continue
 					}
 					connectionCounter.WithLabelValues(apiConnectionType).Inc()
 					// unix socket and value == '@'
 					if len(connection.RemoteAddr().String()) == 1 {
-						log.Infof("Got new connection to http API: %v", connection.LocalAddr())
+						log.Infof("Got new connection to HTTP API: %v", connection.LocalAddr())
 					} else {
-						log.Infof("Got new connection to http API: %v", connection.RemoteAddr())
+						log.Infof("Got new connection to HTTP API: %v", connection.RemoteAddr())
 					}
 					go handleAPIConnection(&commandsConfig, connection)
 				}
@@ -482,7 +483,7 @@ func main() {
 		}
 		log.Infof("Configured to send metrics and stats to `incoming_connection_prometheus_metrics_string`")
 		sigHandler.AddCallback(func() {
-			log.Infoln("Stop prometheus http exporter")
+			log.Infoln("Stop prometheus HTTP exporter")
 			prometheusHTTPServer.Close()
 		})
 	}

cmd/acra-rollback/acra-rollback.go

@@ -54,7 +54,7 @@ var (
 
 // ErrorExit prints error and exits.
 func ErrorExit(msg string, err error) {
-	fmt.Println(utils.ErrorMessage(msg, err))
+	log.WithError(err).Errorln(msg)
 	os.Exit(1)
 }
 

cmd/acra-server/acra-server.go

@@ -95,7 +95,7 @@ func main() {
 	flag.Bool("acrastruct_wholecell_enable", true, "Acrastruct will stored in whole data cell")
 	injectedcell := flag.Bool("acrastruct_injectedcell_enable", false, "Acrastruct may be injected into any place of data cell")
 
-	debugServer := flag.Bool("ds", false, "Turn on http debug server")
+	debugServer := flag.Bool("ds", false, "Turn on HTTP debug server")
 	closeConnectionTimeout := flag.Int("incoming_connection_close_timeout", defaultAcraserverWaitTimeout, "Time that AcraServer will wait (in seconds) on restart before closing all connections")
 
 	detectPoisonRecords := flag.Bool("poison_detect_enable", true, "Turn on poison record detection, if server shutdown is disabled, AcraServer logs the poison record detection and returns decrypted data")
@@ -346,7 +346,7 @@ func main() {
 		}
 		log.Infof("Configured to send metrics and stats to `incoming_connection_prometheus_metrics_string`")
 		stopPrometheusServer := func() {
-			log.Infoln("Stop prometheus http exporter")
+			log.Infoln("Stop prometheus HTTP exporter")
 			if err := prometheusHTTPServer.Close(); err != nil {
 				log.WithError(err).Errorln("Error on prometheus server close")
 			}
@@ -355,7 +355,6 @@ func main() {
 		sigHandlerSIGTERM.AddCallback(stopPrometheusServer)
 	}
 
-	go sigHandlerSIGTERM.Register()
 	sigHandlerSIGTERM.AddCallback(func() {
 		log.Infof("Received incoming SIGTERM or SIGINT signal")
 		log.Debugf("Stop accepting new connections, waiting until current connections close")
@@ -372,6 +371,7 @@ func main() {
 		log.Infof("Server graceful shutdown completed, bye PID: %v", os.Getpid())
 		os.Exit(0)
 	})
+	go sigHandlerSIGTERM.Register()
 
 	sigHandlerSIGHUP.AddCallback(func() {
 		log.Infof("Received incoming SIGHUP signal")

cmd/acra-server/client_commands_session.go

@@ -34,7 +34,6 @@ import (
 
 	"github.com/cossacklabs/acra/cmd"
 	"github.com/cossacklabs/acra/keystore"
-	"github.com/cossacklabs/acra/utils"
 	"github.com/cossacklabs/acra/zone"
 	"github.com/cossacklabs/themis/gothemis/cell"
 	"github.com/cossacklabs/themis/gothemis/keys"
@@ -104,11 +103,11 @@ func (clientSession *ClientCommandsSession) HandleSession() {
 		logger.Debugln("Got /getNewZone request")
 		id, publicKey, err := clientSession.keystorage.GenerateZoneKey()
 		if err != nil {
-			logger.WithError(err).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCantGenerateZone).Errorln("Can't generate zone key")
+			logger.WithError(err).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorHTTPAPICantGenerateZone).Errorln("Can't generate zone key")
 		} else {
 			zoneData, err := zone.ZoneDataToJSON(id, &keys.PublicKey{Value: publicKey})
 			if err != nil {
-				logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCantGenerateZone).WithError(err).Errorln("Can't create json with zone key")
+				logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorHTTPAPICantGenerateZone).WithError(err).Errorln("Can't create json with zone key")
 			} else {
 				logger.Debugln("Handled request correctly")
 				response = fmt.Sprintf("HTTP/1.1 200 OK Found\r\n\r\n%s\r\n\r\n", string(zoneData))
@@ -123,20 +122,20 @@ func (clientSession *ClientCommandsSession) HandleSession() {
 		response = Response500Error
 		key, err := clientSession.keystore.GetAuthKey(false)
 		if err != nil {
-			logger.WithError(err).Error("loadAuthData: keystore.GetAuthKey()")
+			logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorHTTPAPICantLoadAuthKey).WithError(err).Error("loadAuthData: keystore.GetAuthKey()")
 			response = Response500Error
 			break
 		}
 		authDataCrypted, err := getAuthDataFromFile(*authPath)
 		if err != nil {
-			logger.Warningf("%v\n", utils.ErrorMessage("loadAuthData: no auth data", err))
+			logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorHTTPAPICantLoadAuthData).WithError(err).Warningln("loadAuthData: no auth data")
 			response = Response500Error
 			break
 		}
 		SecureCell := cell.New(key, cell.CELL_MODE_SEAL)
 		authData, err := SecureCell.Unprotect(authDataCrypted, nil, nil)
 		if err != nil {
-			logger.WithError(err).Error("loadAuthData: SecureCell.Unprotect")
+			logger.WithField(logging.FieldKeyEventCode, logging.EventCodeErrorHTTPAPICantDecryptAuthData).WithError(err).Error("loadAuthData: SecureCell.Unprotect")
 
 			break
 		}