T864 - Separate log file for unparsed queries #295

storojs72 · 2018-12-21T08:09:24Z

No description provided.

Lagovas · 2018-12-21T10:25:50Z

acra-censor/acra-censor_implementation.go

 }

 // NewAcraCensor creates new censor object.
 func NewAcraCensor() *AcraCensor {
 	acraCensor := &AcraCensor{}
 	acraCensor.logger = log.WithField("service", ServiceName)
 	acraCensor.ignoreParseError = false
+	acraCensor.parseErrorsLogPath = ""


we don't need such initialization because it's already initialized with empty string. Above assigning is redundant too

Lagovas · 2018-12-21T10:26:59Z

acra-censor/acra-censor_configuration_provider.go

+		if err != nil {
+			return err
+		}
+		defer openedFile.Close()


if we doesn't use this file after creation we can close it here without defer. but better to store file descriptor as censor field to avoid opening every write operation and reduce count of syscalls (open/close)

When and where should I close it is such case when acraserver stops?

just here) openedFile.Close() instead defer openedFile.Close() because this file doesn't used anywhere after creation. As I understand here we just create file and check that we can do this and close it before next write.
But if we will store opened file in censor then we don't need .Close() here even with defer

Lagovas · 2018-12-21T10:29:27Z

acra-censor/acra-censor_implementation.go

+		if acraCensor.parseErrorsLogPath != "" {
+			err := acraCensor.saveQuery(rawQuery)
+			if err != nil {
+				acraCensor.logger.WithError(err).Errorf("An error occurred while saving unparsable query")


use Errorln to append '\n' at end of log msg. Errorf useful to create msg with some format of string

Lagovas · 2018-12-21T10:31:10Z

acra-censor/acra-censor_implementation.go

+			err := acraCensor.saveQuery(rawQuery)
+			if err != nil {
+				acraCensor.logger.WithError(err).Errorf("An error occurred while saving unparsable query")
+				return err


I think if censor configured with acracensor.ignoreParseError then we should not stop processing on error related with unparsed query and enough log error and try to save without stopping processing.

@vixentael what you think about this?

agree, if acracensor.ignoreParseError is true, then log error and move forward

Lagovas · 2018-12-21T10:32:39Z

acra-censor/acra-censor_implementation.go

+	defer openedFile.Close()
+
+	_, err = openedFile.WriteString(rawQuery + "\n")
+	if err != nil {


return err enough imho :)

plus better to use opened file on loading configuration and use it to avoid open/close on every save

Lagovas · 2018-12-21T10:38:45Z

configs/acra-censor.example.yaml

@@ -1,4 +1,5 @@
 ignore_parse_error: false
+parse_errors_log: unparsed_queries_log


what about uparsed_queries.log name? to add some common extension to avoid meaning some binary file without extension on linux

Lagovas · 2018-12-21T10:49:19Z

acra-censor/acra-censor_implementation.go

+
+	defer openedFile.Close()
+
+	_, err = openedFile.WriteString(rawQuery + "\n")


here we will have same problem which we had with querycapture handler where we try to buffer data before dumping to file to avoid slow write on each query. here we will have same problem with situation when client will use not supported queries. plus we don't need repeated queries, only unique. maybe would be good to write some QueryWriter (and use in querycapture if we can to avoid duplicated code) which will do this logic with buffered write and timeouts and store unique queries in memory to avoid repeated queries

Ok, I will write additional handler for this (with functionality like QueryCapture)

agree, it makes sense to allocate same functionality into some object lke QueryWriter and use it for both QueryCapture and here

Lagovas · 2018-12-23T09:11:19Z

acra-censor/acra-censor_implementation.go

 }

 // NewAcraCensor creates new censor object.
 func NewAcraCensor() *AcraCensor {
 	acraCensor := &AcraCensor{}
 	acraCensor.logger = log.WithField("service", ServiceName)
 	acraCensor.ignoreParseError = false
+	acraCensor.parsedQueriesWriter = nil
+	acraCensor.unparsedQueriesWriter = nil


we can skip it because its already nil

Lagovas · 2018-12-23T09:39:06Z

acra-censor/common/logging_logic.go

+	// read existing queries from file
+	err = handler.readAllQueriesFromFile()
+	if err != nil {
+		handler.logger.WithError(ErrCantReadQueriesFromFileError).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorIOError).Errorln("Can't create QueryWriter instance")


I think we should log original error err using WithError

Lagovas · 2018-12-23T09:39:43Z

acra-censor/common/logging_logic.go

+	err = handler.readAllQueriesFromFile()
+	if err != nil {
+		handler.logger.WithError(ErrCantReadQueriesFromFileError).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorIOError).Errorln("Can't create QueryWriter instance")
+		openedFile.Close()


we should process error to by logging it

Lagovas · 2018-12-23T09:40:29Z

acra-censor/common/logging_logic.go

+			case <-handler.serializationTicker.C:
+				err := handler.dumpBufferedQueriesToFile(openedFile)
+				if err != nil {
+					handler.logger.WithError(ErrComplexSerializationError).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorIOError).Errorln("Can't create QueryWriter instance")


log original error

Lagovas · 2018-12-23T09:40:48Z

acra-censor/common/logging_logic.go

+			case <-signalBackgroundExit:
+				err := handler.finishAndCloseFile(openedFile)
+				if err != nil {
+					handler.logger.WithError(ErrComplexSerializationError).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorIOError).Errorln("Can't create QueryWriter instance")


Lagovas · 2018-12-23T09:42:42Z

acra-censor/common/logging_logic.go

+// DumpAllQueriesToFile writes stored queries into file.
+func (queryWriter *QueryWriter) DumpAllQueriesToFile() error {
+	// open or create file, NO APPEND
+	f, err := os.OpenFile(queryWriter.filePath, os.O_TRUNC|os.O_RDWR|os.O_CREATE, 0600)


better to close file in function which open it with defer

Lagovas · 2018-12-23T09:44:09Z

acra-censor/common/logging_logic.go

+	return nil
+}
+
+func (queryWriter *QueryWriter) appendQueries(queries []*QueryInfo, openedFile *os.File) error {


because we don't use any os.File specific API then we can take io.Writer as param.

We use openedFile.Write(lines) in this function

Lagovas · 2018-12-23T09:45:41Z

acra-censor/common/logging_logic.go

+	return linesToAppend
+}
+
+func (queryWriter *QueryWriter) finishAndCloseFile(openedFile *os.File) error {


https://golang.org/pkg/io/#Closer enough here. interfaces better to use instead specific types

Can you please, explain in more details

Lagovas · 2018-12-23T09:49:23Z

acra-censor/common/logging_logic.go

+	signalBackgroundExit := make(chan bool)
+
+	// create handler
+	handler := &QueryWriter{}


I think we should assign openedFile to the related writer which use it to not forget to close it on Release/Close. resource owner responsible for releasing resources. plus it allow to avoid extra OpenFile calls because file already opened

Lagovas · 2018-12-23T09:50:42Z

acra-censor/common/logging_logic.go

+				handler.serializationTicker = time.NewTicker(handler.serializationTimeout)
+
+			case <-signalBackgroundExit:
+				err := handler.finishAndCloseFile(openedFile)


imho better to call handler.Release here and rename finishAndCloseFile to Release, which should dump data and close file

Lagovas · 2018-12-26T11:50:56Z

acra-censor/acra-censor_implementation.go

@@ -110,3 +103,39 @@ func (acraCensor *AcraCensor) HandleQuery(rawQuery string) error {
 	acraCensor.logger.Infof("Allowed query: '%s'", queryWithHiddenValues)
 	return nil
 }
+
+// GetLoggingTimeout returns current timeout of censor's logging process
+func (acraCensor *AcraCensor) GetLoggingTimeout() time.Duration {


I think we doesn't need such methods because they will not called anywhere and logging timeout we set once at first censor configurations with some constant and it will not changed during acra-server run. so I think we don't need extend AcraCensorInterface. anyway it's specific settings for handler, not censor at all.

Lagovas · 2018-12-26T11:51:03Z

acra-censor/acra-censor_implementation.go

+}
+
+// SetLoggingTimeout sets timeout of censor's logging process
+func (acraCensor *AcraCensor) SetLoggingTimeout(duration time.Duration) {


save as above

Lagovas · 2018-12-26T11:53:01Z

acra-censor/acra-censor_implementation.go

+
+func saveQuery(writer *common.QueryWriter, query string) {
+	//skip already captured queries
+	for _, capturedQuery := range writer.Queries {


it is logic of QueryWriter, not censor. better to move this logic to query writer and add some method like handler.WriteQuery(query string) where it will check is this query exists or not and create new QueryInfo and append or not

after moving we will not need writer.Queries as public field and change to private

Lagovas · 2018-12-26T11:53:15Z

acra-censor/acra-censor_interfaces.go

@@ -36,4 +39,6 @@ type AcraCensorInterface interface {
 	AddHandler(handler QueryHandlerInterface)
 	RemoveHandler(handler QueryHandlerInterface)
 	ReleaseAll()
+	GetLoggingTimeout() time.Duration


imho we don't need it

Lagovas · 2018-12-26T12:05:28Z

acra-censor/common/file_log_storage.go

+// WriteAll writes raw queries that need to be stored to internal file
+func (storage *FileLogStorage) WriteAll(p []byte) error {
+	if storage.openedToAppend {
+		openedFile, err := os.OpenFile(storage.filePath, os.O_TRUNC|os.O_RDWR|os.O_CREATE, 0600)


we don't use already opened file in our constructor. we didn't close it and didn't reuse. I prefer to reuse:

if err := storage.file.Truncate(0); err != nil {return err} // drop all data but leave file already opened and ready to write

Lagovas · 2018-12-26T12:23:46Z

acra-censor/common/logging_logic.go

+
+// DumpQueries writes all queries into file.
+func (queryWriter *QueryWriter) DumpQueries() error {
+	rawData := queryWriter.serializeQueries(queryWriter.Queries)


here we need lock to avoid background append to Queries

after serialization, we can unlock and avoid lock on writing to file because we have serialized copy of data

Lagovas · 2018-12-26T12:25:08Z

acra-censor/common/logging_logic.go

+// GetAllInputQueries returns a list of non-masked RawQueries.
+func (queryWriter *QueryWriter) GetAllInputQueries() []string {
+	var queries []string
+	for _, queryInfo := range queryWriter.Queries {


here we need Rlock. we read shareable resource that may be changed during read. and go runtime will panic on loop through map that was changed at this time.

Can you please explain what is Rlock? I googled but only usual Mutex.lock found

Lagovas · 2018-12-26T12:29:12Z

acra-censor/common/logging_logic.go

+// It will be written to file on Stop, Reset or Release.
+// Expects redacted query
+func (queryWriter *QueryWriter) MarkQueryAsForbidden(queryWithHiddenValues string) {
+	for index, queryInfo := range queryWriter.Queries {


here too RLock

Lagovas · 2018-12-26T12:29:31Z

acra-censor/common/logging_logic.go

+	queryInfo := &QueryInfo{}
+	queryInfo.RawQuery = queryWithHiddenValues
+	queryInfo.IsForbidden = false
+	queryWriter.Queries = append(queryWriter.Queries, queryInfo)


Lock on write

Lagovas · 2018-12-26T12:30:57Z

acra-censor/acra-censor_implementation.go

+
+func (acraCensor *AcraCensor) saveUnparsedQuery(query string) {
+	if acraCensor.unparsedQueriesWriter != nil {
+		saveQuery(acraCensor.unparsedQueriesWriter, query)


imho better to use unparsedQueriesWriter.WriteQuery(query) or move saveQuery to file with this handler

Lagovas · 2018-12-26T14:28:14Z

acra-censor/common/logging_logic.go

@@ -69,7 +69,7 @@ func NewFileQueryWriter(filePath string) (*QueryWriter, error) {
 	// read existing queries
 	err = writer.readStoredQueries()
 	if err != nil {
-		writer.logger.WithError(ErrCantReadQueriesFromFileError).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorIOError).Errorln("Can't create QueryWriter instance")
+		writer.logger.WithError(ErrCantReadQueriesFromStorageError).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorIOError).Errorln("Can't create QueryWriter instance")


we should log origin error too

It will be logged from readStoredQueries function

Lagovas · 2018-12-26T14:29:17Z

acra-censor/common/logging_logic.go

+
+// DumpQueries writes all queries into file.
+func (queryWriter *QueryWriter) DumpQueries() error {
+	rawData := queryWriter.serializeQueries(queryWriter.Queries)


after serialization, we can unlock and avoid lock on writing to file because we have serialized copy of data

Lagovas · 2018-12-26T14:33:09Z

acra-censor/common/logging_logic.go

@@ -134,13 +127,13 @@ func (queryWriter *QueryWriter) Release() {
 }

 func (queryWriter *QueryWriter) reset() {
+	queryWriter.mutex.Lock()
+	defer queryWriter.mutex.Unlock()


defer good to use if we have a lot of points of exit to avoid multiple calls of Unlock. For example

func t(){ l.Lock() _, err := func1() if err != nil{ l.Unlock() return } _, err := func2() if err != nil{ l.Unlock() return } _, err := func3() if err != nil{ l.Unlock() return } }

In such case to not forget unlock and call it once we should use defer l.Unlock and it simple
But defer has a small overhead. It's really small but it have. And when we have simple cases such this we can avoid it without any care that we can forget

Lagovas · 2018-12-26T14:35:59Z

acra-censor/common/file_log_storage.go

-		}
-		storage.file = openedFile
-		storage.openedToAppend = false
+	if err := storage.file.Truncate(0); err != nil {


looks better)

Sure. I just didn't know that Truncate method exists

Lagovas · 2018-12-26T14:36:17Z

acra-censor/common/file_log_storage.go

@@ -7,7 +7,6 @@ import (

 // FileLogStorage is a file-based implementation of LogStorage interface
 type FileLogStorage struct {
-	filePath       string
 	file           *os.File
 	openedToAppend bool


do we need it more?

no it seems we didn't. I used it when reopening file with other modes set, but now Truncate allows to avoid it

Lagovas · 2018-12-26T15:02:31Z

acra-censor/common/logging_logic.go

+
+// Release dumps all Captured queries to file and resets Captured queries list.
+func (queryWriter *QueryWriter) Release() {
+	queryWriter.DumpQueries()


we should handle error and log about it

DumpQueries logs errors inside

then would be better to assign error to anonym variable to be compliant with linters (goland in last versions highlight such code with unhandled error message :) plus it's good to log twice. with one more log we add some context where this function was called (DumpQueries is public function that may be called in a lot of places in a future who will use this writer). Here we will have error on Release, not on serialization by timeout

Lagovas · 2018-12-26T15:11:49Z

acra-censor/common/logging_logic_test.go

+			t.Fatal(err)
+		}
+	}
+	time.Sleep(DefaultSerializationTimeout + 100*time.Millisecond)


in previous PR's we decreased time of tests twice just by decreasing granulation of timeouts. and there we can't it handle more deterministic because we can't control environment fully
but here in unit-tests we can. what about to move background goroutine in our constructor NewFileQueryWriter to some function like start() and rewrite like something:

func (writer *QueryWriter) start(){ for { select { case <-writer.serializationTicker.C: err := writer.dumpBufferedQueries() if err != nil { writer.logger.WithError(err).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorIOError).Errorln("Can't dump buffered queries") } writer.serializationTicker.Stop() writer.serializationTicker = time.NewTicker(writer.serializationTimeout) case <-signalBackgroundExit: writer.serializationTicker.Stop() err := writer.logStorage.Close() if err != nil { writer.logger.WithError(err).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorIOError).Errorln("Error occurred on exit QueryWriter instance") } case <-signalShutdown: writer.serializationTicker.Stop() err := writer.logStorage.Close() if err != nil { writer.logger.WithError(err).WithField(logging.FieldKeyEventCode, logging.EventCodeErrorCensorIOError).Errorln("Error occurred on shutdown QueryWriter instance") } return default: //do nothing. This means that channel has no data to read yet } } } // NewFileQueryWriter creates QueryWriter instance func NewFileQueryWriter(filePath string) (*QueryWriter, error) { writer := &QueryWriter{} // initialization logic go writer.Start() return writer, nil }

after that we can in our tests do:

writer, err := NewFileQueryWriter(tmpFile.Name()) for _, query := range testQueries { _, err = writer.RedactAndCheckQuery(query) if err != nil { t.Fatal(err) } } writer.Release() // or writer.DumpQueries() or any other private method go writer.start() // here we restart our background goroutine

plus we need this background goroutine only to test logic with background serialization and stop. in other tests (dumping/serialization/deserialization) we can test without it, just call direct methods with writer.dumpBlaBla, writer.deserializeBlaBla

Lagovas

fix last comments (tests should not pass gofmt check) and ok to merge

Lagovas · 2018-12-27T12:30:04Z

acra-censor/common/logging_logic.go

@@ -52,26 +52,24 @@ type QueryWriter struct {
 // NewFileQueryWriter creates QueryWriter instance
 func NewFileQueryWriter(filePath string) (*QueryWriter, error) {
 	// create writer
-	writer := &QueryWriter{}
+	writer := &QueryWriter{
+		queryIndex:0,


i'm not sure, but 90% that this file not formatted with gofmt )

Lagovas · 2018-12-27T12:30:10Z

acra-censor/handlers/querycapture_handler.go

 		}
+		return nil
+	})
+	if err != nil {


return err : )

It's output value of internal function that passed as argument to WalkQueries

Add separate log for unparsed queries

3530243

storojs72 requested review from vixentael, Lagovas and shadinua December 21, 2018 08:09

gofmt

de2c4ff

Lagovas requested changes Dec 21, 2018

View reviewed changes

vixentael added the acra-censor label Dec 21, 2018

storojs72 added 4 commits December 22, 2018 16:10

Requested changes

eed25c6

gofmt

b527a53

golint

182083e

gofmt

c0aa689

Lagovas requested changes Dec 23, 2018

View reviewed changes

Requested changes

e4a67cf

Lagovas reviewed Dec 26, 2018

View reviewed changes

storojs72 added 2 commits December 26, 2018 16:25

Requested changes

7022de4

gofmt

8d30a6f

Lagovas reviewed Dec 26, 2018

View reviewed changes

requested changes

53edf56

Lagovas reviewed Dec 26, 2018

View reviewed changes

storojs72 added 3 commits December 27, 2018 12:54

Requested changes

41717f1

golint & gofmt

5cd5f7d

Requested changes

21d7207

Lagovas approved these changes Dec 27, 2018

View reviewed changes

storojs72 added 3 commits December 27, 2018 14:39

gofmt & golint

8645634

requested changes

c74fd15

requested changes

c5b571b

Lagovas approved these changes Dec 27, 2018

View reviewed changes

storojs72 merged commit 334ee25 into cossacklabs:master Dec 27, 2018

		@@ -1,4 +1,5 @@
		ignore_parse_error: false
		parse_errors_log: unparsed_queries_log


		defer openedFile.Close()

		_, err = openedFile.WriteString(rawQuery + "\n")

T864 - Separate log file for unparsed queries #295

T864 - Separate log file for unparsed queries #295

Conversation

storojs72 commented Dec 21, 2018

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

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

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

Choose a reason for hiding this comment

Lagovas left a 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