Merge pull request #11 from Financial-Times/format-logging

Format logging

README.md

@@ -78,8 +78,3 @@ Shows ES cluster health details
 An example of event structure is here [testdata/exampleEnrichedContentModel.json](testdata/exampleEnrichedContentModel.json)
 
 The reference mappings for Elasticsearch are found here [runtime/referenceSchema.json](runtime/referenceSchema.json)
-
-### Logging
-
-* The application uses [logrus](https://github.com/Sirupsen/logrus); the log file is initialised in [main.go](main.go).
-* NOTE: `/__build-info` and `/__gtg` endpoints are not logged as they are called every second from varnish/vulcand and this information is not needed in logs/splunk.

content_indexer.go

@@ -3,15 +3,15 @@ package main
 import (
 	"encoding/json"
 	health "github.com/Financial-Times/go-fthealth/v1_1"
+	"github.com/Financial-Times/go-logger"
 	"github.com/Financial-Times/message-queue-gonsumer/consumer"
 	status "github.com/Financial-Times/service-status-go/httphandlers"
-	log "github.com/Sirupsen/logrus"
+	"github.com/dchest/uniuri"
 	"net"
 	"net/http"
 	"strings"
 	"sync"
 	"time"
-	"github.com/dchest/uniuri"
 )
 
 const (
@@ -49,11 +49,11 @@ func (indexer *contentIndexer) start(appSystemCode string, appName string, index
 		for {
 			ec, err := newAmazonClient(accessConfig)
 			if err == nil {
-				log.Infof("connected to Elasticsearch")
+				logger.Info("Connected to Elasticsearch")
 				channel <- ec
 				return
 			}
-			log.Errorf("could not connect to Elasticsearch: %s", err.Error())
+			logger.Error("Could not connect to Elasticsearch")
 			time.Sleep(time.Minute)
 		}
 	}()
@@ -80,7 +80,7 @@ func (indexer *contentIndexer) stop() {
 		indexer.mu.Unlock()
 	}()
 	if err := indexer.server.Close(); err != nil {
-		log.Errorf("Unable to stop http server: %v", err)
+		logger.WithError(err).Error("Unable to stop http server")
 	}
 	indexer.wg.Wait()
 }
@@ -101,7 +101,7 @@ func (indexer *contentIndexer) serveAdminEndpoints(appSystemCode string, appName
 	indexer.wg.Add(1)
 	go func() {
 		if err := indexer.server.ListenAndServe(); err != nil {
-			log.Infof("HTTP server closing with message: %v", err)
+			logger.WithError(err).Error("HTTP server is closing")
 		}
 		indexer.wg.Done()
 	}()
@@ -135,33 +135,33 @@ func (indexer *contentIndexer) handleMessage(msg consumer.Message) {
 	tid := msg.Headers[transactionIDHeader]
 	if tid == "" {
 		tid = "tid_" + uniuri.NewLen(10) + "_content-rw-elasticsearch"
-		log.Infof("Generated tid: %d", tid)
+		logger.WithTransactionID(tid).Info("Generated tid")
 	}
 
 	if strings.Contains(tid, syntheticRequestPrefix) {
-		log.Infof("[%s] Ignoring synthetic message", tid)
+		logger.WithTransactionID(tid).Info("Ignoring synthetic message")
 		return
 	}
 
 	var combinedPostPublicationEvent enrichedContentModel
 	err := json.Unmarshal([]byte(msg.Body), &combinedPostPublicationEvent)
 	if err != nil {
-		log.Errorf("[%s] Cannot unmarshal message body:[%v]", tid, err.Error())
+		logger.WithTransactionID(tid).WithError(err).Error("Cannot unmarshal message body")
 		return
 	}
 
 	if !contains(allowedTypes, combinedPostPublicationEvent.Content.Type) {
-		log.Infof("[%s] Ignoring message of type %s", tid, combinedPostPublicationEvent.Content.Type)
+		logger.WithTransactionID(tid).Infof("Ignoring message of type %s", combinedPostPublicationEvent.Content.Type)
 		return
 	}
 
 	if combinedPostPublicationEvent.Content.UUID == "" {
-		log.Infof("[%s] Ignoring message with no content for UUID: %s", tid, combinedPostPublicationEvent.UUID)
+		logger.WithTransactionID(tid).WithUUID(combinedPostPublicationEvent.UUID).Info("Ignoring message with no content for UUID")
 		return
 	}
 
 	uuid := combinedPostPublicationEvent.UUID
-	log.Infof("[%s] Processing combined post publication event for uuid [%s]", tid, uuid)
+	logger.WithTransactionID(tid).WithUUID(uuid).Info("Processing combined post publication event")
 
 	var contentType string
 	for _, identifier := range combinedPostPublicationEvent.Content.Identifiers {
@@ -183,25 +183,27 @@ func (indexer *contentIndexer) handleMessage(msg consumer.Message) {
 		} else if strings.Contains(origin, videoOrigin) {
 			contentType = videoType
 		} else {
-			log.Errorf("[%s] Failed to index content with UUID %s. Could not infer type of content.", tid, uuid)
+			logger.WithTransactionID(tid).WithUUID(uuid).WithError(err).Error("Failed to index content. Could not infer type of content")
 			return
 		}
 	}
 
 	if combinedPostPublicationEvent.Content.MarkedDeleted {
 		_, err = indexer.esServiceInstance.deleteData(contentTypeMap[contentType].collection, uuid)
 		if err != nil {
-			log.Errorf("[%s] Failed to index content with UUID %s. Error: [%s]", tid, uuid, err.Error())
+			logger.WithTransactionID(tid).WithUUID(uuid).WithError(err).Error("Failed to index content")
 			return
 		}
+		logger.WithMonitoringEvent("ContentDeleteElasticsearch", tid, "").WithUUID(uuid).Info("Successfully deleted")
 	} else {
 		payload := convertToESContentModel(combinedPostPublicationEvent, contentType, tid)
 
 		_, err = indexer.esServiceInstance.writeData(contentTypeMap[contentType].collection, uuid, payload)
 		if err != nil {
-			log.Errorf("[%s] Failed to index content with UUID %s. Error: [%s]", tid, uuid, err.Error())
+			logger.WithTransactionID(tid).WithUUID(uuid).WithError(err).Error("Failed to index content")
 			return
 		}
+		logger.WithMonitoringEvent("ContentWriteElasticsearch", tid, "").WithUUID(uuid).Info("Successfully saved")
 	}
 }
 

content_indexer_test.go

@@ -1,17 +1,17 @@
 package main
 
 import (
+	logTest "github.com/Financial-Times/go-logger/test"
 	"github.com/Financial-Times/message-queue-gonsumer/consumer"
-	"github.com/Sirupsen/logrus"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/mock"
 	"gopkg.in/olivere/elastic.v2"
 	"io/ioutil"
 	"net/url"
 	"strings"
-	"sync"
 	"testing"
 	"time"
+	"github.com/stretchr/testify/require"
 )
 
 type esServiceMock struct {
@@ -75,36 +75,6 @@ func (client elasticClientMock) PerformRequest(method, path string, params url.V
 	return args.Get(0).(*elastic.Response), args.Error(1)
 }
 
-type logHook struct {
-	sync.Mutex
-	Entries []*logrus.Entry
-}
-
-func (hook *logHook) Fire(e *logrus.Entry) error {
-	hook.Lock()
-	defer hook.Unlock()
-	hook.Entries = append(hook.Entries, e)
-	return nil
-}
-
-func (hook *logHook) Levels() []logrus.Level {
-	return logrus.AllLevels
-}
-
-func (hook *logHook) LastEntry() (l *logrus.Entry) {
-	hook.Lock()
-	defer hook.Unlock()
-	if i := len(hook.Entries) - 1; i >= 0 {
-		return hook.Entries[i]
-	}
-	return nil
-}
-
-// Reset removes all Entries from this test hook.
-func (hook *logHook) Reset() {
-	hook.Entries = make([]*logrus.Entry, 0)
-}
-
 func TestStartClient(t *testing.T) {
 	assert := assert.New(t)
 
@@ -143,8 +113,7 @@ func TestStartClient(t *testing.T) {
 func TestStartClientError(t *testing.T) {
 	assert := assert.New(t)
 
-	hook := &logHook{}
-	logrus.AddHook(hook)
+	hook := logTest.NewTestHook("content-rw-elasticsearch")
 
 	accessConfig := esAccessConfig{
 		accessKey:  "key",
@@ -171,6 +140,7 @@ func TestStartClientError(t *testing.T) {
 
 	time.Sleep(100 * time.Millisecond)
 
+	require.NotNil(t, hook.LastEntry())
 	assert.Equal("error", hook.LastEntry().Level.String(), "Wrong log")
 	assert.NotNil(indexer.esServiceInstance, "Elastic Service should be initialized")
 	assert.Equal("index", (indexer.esServiceInstance).(*esService).indexName, "Wrong index")
@@ -264,8 +234,7 @@ func TestHandleWriteMessageUnknownType(t *testing.T) {
 func TestHandleWriteMessageNoUUIDForMetadataPublish(t *testing.T) {
 	assert := assert.New(t)
 
-	hook := &logHook{}
-	logrus.AddHook(hook)
+	hook := logTest.NewTestHook("content-rw-elasticsearch")
 
 	inputJSON, err := ioutil.ReadFile("testdata/testInput4.json")
 	assert.NoError(err, "Unexpected error")
@@ -278,14 +247,15 @@ func TestHandleWriteMessageNoUUIDForMetadataPublish(t *testing.T) {
 	serviceMock.AssertNotCalled(t, "writeData", mock.Anything, "b17756fe-0f62-4cf1-9deb-ca7a2ff80172", mock.Anything)
 	serviceMock.AssertNotCalled(t, "deleteData", mock.Anything, "b17756fe-0f62-4cf1-9deb-ca7a2ff80172")
 	serviceMock.AssertExpectations(t)
+
+	require.NotNil(t, hook.LastEntry())
 	assert.Equal("info", hook.LastEntry().Level.String(), "Wrong log")
 }
 
 func TestHandleWriteMessageNoType(t *testing.T) {
 	assert := assert.New(t)
 
-	hook := &logHook{}
-	logrus.AddHook(hook)
+	hook := logTest.NewTestHook("content-rw-elasticsearch")
 
 	inputJSON, err := ioutil.ReadFile("testdata/exampleEnrichedContentModel.json")
 	assert.NoError(err, "Unexpected error")
@@ -298,14 +268,14 @@ func TestHandleWriteMessageNoType(t *testing.T) {
 
 	serviceMock.AssertNotCalled(t, "writeData", mock.Anything, mock.Anything, mock.Anything)
 	serviceMock.AssertNotCalled(t, "deleteData", mock.Anything, mock.Anything)
+	require.NotNil(t, hook.LastEntry())
 	assert.Equal("error", hook.LastEntry().Level.String(), "Wrong log")
 }
 
 func TestHandleWriteMessageError(t *testing.T) {
 	assert := assert.New(t)
 
-	hook := &logHook{}
-	logrus.AddHook(hook)
+	hook := logTest.NewTestHook("content-rw-elasticsearch")
 
 	inputJSON, err := ioutil.ReadFile("testdata/exampleEnrichedContentModel.json")
 	assert.NoError(err, "Unexpected error")
@@ -318,6 +288,7 @@ func TestHandleWriteMessageError(t *testing.T) {
 	indexer.handleMessage(consumer.Message{Body: string(inputJSON)})
 
 	serviceMock.AssertExpectations(t)
+	require.NotNil(t, hook.LastEntry())
 	assert.Equal("error", hook.LastEntry().Level.String(), "Wrong log")
 }
 
@@ -341,8 +312,7 @@ func TestHandleDeleteMessage(t *testing.T) {
 func TestHandleDeleteMessageError(t *testing.T) {
 	assert := assert.New(t)
 
-	hook := &logHook{}
-	logrus.AddHook(hook)
+	hook := logTest.NewTestHook("content-rw-elasticsearch")
 
 	inputJSON, err := ioutil.ReadFile("testdata/exampleEnrichedContentModel.json")
 	assert.NoError(err, "Unexpected error")
@@ -356,20 +326,21 @@ func TestHandleDeleteMessageError(t *testing.T) {
 	indexer.handleMessage(consumer.Message{Body: input})
 
 	serviceMock.AssertExpectations(t)
+	require.NotNil(t, hook.LastEntry())
 	assert.Equal("error", hook.LastEntry().Level.String(), "Wrong log")
 }
 
 func TestHandleMessageJsonError(t *testing.T) {
 	assert := assert.New(t)
 
-	hook := &logHook{}
-	logrus.AddHook(hook)
+	hook := logTest.NewTestHook("content-rw-elasticsearch")
 
 	serviceMock := &esServiceMock{}
 
 	indexer := &contentIndexer{esServiceInstance: serviceMock}
 	indexer.handleMessage(consumer.Message{Body: "malformed json"})
 
+	require.NotNil(t, hook.LastEntry())
 	assert.Equal("error", hook.LastEntry().Level.String(), "Wrong log")
 	serviceMock.AssertNotCalled(t, "writeData", mock.Anything, mock.Anything, mock.Anything)
 	serviceMock.AssertNotCalled(t, "deleteData", mock.Anything, mock.Anything)
@@ -378,13 +349,13 @@ func TestHandleMessageJsonError(t *testing.T) {
 func TestHandleSyntheticMessage(t *testing.T) {
 	assert := assert.New(t)
 
-	hook := &logHook{}
-	logrus.AddHook(hook)
+	hook := logTest.NewTestHook("content-rw-elasticsearch")
 
 	serviceMock := &esServiceMock{}
 	indexer := &contentIndexer{esServiceInstance: serviceMock}
 	indexer.handleMessage(consumer.Message{Headers: map[string]string{"X-Request-Id": "SYNTHETIC-REQ-MON_WuLjbRpCgh"}})
 
+	require.NotNil(t, hook.LastEntry())
 	assert.Equal("info", hook.LastEntry().Level.String(), "Wrong log")
 	serviceMock.AssertNotCalled(t, "writeData", mock.Anything, mock.Anything, mock.Anything)
 	serviceMock.AssertNotCalled(t, "deleteData", mock.Anything, mock.Anything)

es_client.go

@@ -1,10 +1,10 @@
 package main
 
 import (
-	log "github.com/Sirupsen/logrus"
 	awsauth "github.com/smartystreets/go-aws-auth"
 	"gopkg.in/olivere/elastic.v2"
 	"net/http"
+	"github.com/Financial-Times/go-logger"
 )
 
 type esClientI interface {
@@ -47,6 +47,6 @@ var newAmazonClient = func(config esAccessConfig) (esClientI, error) {
 		elastic.SetScheme("https"),
 		elastic.SetHttpClient(signingClient),
 		elastic.SetSniff(false), //needs to be disabled due to EAS behavior. Healthcheck still operates as normal.
-		elastic.SetErrorLog(log.New()),
+		elastic.SetErrorLog(logger.Logger()),
 	)
 }

healthcheck.go

@@ -10,7 +10,7 @@ import (
 	health "github.com/Financial-Times/go-fthealth/v1_1"
 	"github.com/Financial-Times/message-queue-gonsumer/consumer"
 	"github.com/Financial-Times/service-status-go/gtg"
-	log "github.com/Sirupsen/logrus"
+	"github.com/Financial-Times/go-logger"
 )
 
 type healthService struct {
@@ -150,6 +150,6 @@ func (service *healthService) HealthDetails(writer http.ResponseWriter, req *htt
 
 	_, err = writer.Write(response)
 	if err != nil {
-		log.Errorf(err.Error())
+		logger.WithError(err).Error(err.Error())
 	}
 }