more tiny improvements

middleware/accesslog/accesslog.go

@@ -133,11 +133,11 @@ type AccessLog struct {
 	//
 	// Defaults to false.
 	Async bool
-	// The delimeter between fields when logging with the default format.
+	// The delimiter between fields when logging with the default format.
 	// See `SetFormatter` to customize the log even further.
 	//
 	// Defaults to '|'.
-	Delim rune
+	Delim byte
 	// The time format for current time on log print.
 	// Set it to empty to inherit the Iris Application's TimeFormat.
 	//
@@ -221,7 +221,7 @@ type AccessLog struct {
 	// remaining logs when Close is called, we wait for timeout (see CloseContext).
 	remaining uint32
 	// reports whether the logger is already closed, see `Close` & `CloseContext` methods.
-	isClosed bool
+	isClosed uint32
 }
 
 // PanicLog holds the type for the available panic log levels.
@@ -236,7 +236,11 @@ const (
 	LogStack
 )
 
-const defaultTimeFormat = "2006-01-02 15:04:05"
+const (
+	defaultDelim      = '|'
+	defaultTimeFormat = "2006-01-02 15:04:05"
+	newLine           = '\n'
+)
 
 // New returns a new AccessLog value with the default values.
 // Writes to the "w". Output can be further modified through its `Set/AddOutput` methods.
@@ -298,7 +302,7 @@ func New(w io.Writer) *AccessLog {
 
 // File returns a new AccessLog value with the given "path"
 // as the log's output file destination.
-// The Writer is now a buffered file writer.
+// The Writer is now a buffered file writer & reader.
 // Register by its `Handler` method.
 //
 // A call of its `Close` method to unlock the underline
@@ -313,7 +317,7 @@ func File(path string) *AccessLog {
 		panic(err)
 	}
 
-	return New(bufio.NewWriter(f))
+	return New(bufio.NewReadWriter(bufio.NewReader(f), bufio.NewWriter(f)))
 }
 
 // Broker creates or returns the broker.
@@ -379,11 +383,17 @@ func (ac *AccessLog) AddOutput(writers ...io.Writer) *AccessLog {
 // Write writes to the log destination.
 // It completes the io.Writer interface.
 // Safe for concurrent use.
-func (ac *AccessLog) Write(p []byte) (int, error) {
+func (ac *AccessLog) Write(p []byte) (n int, err error) {
+	if ac.Async {
+		if atomic.LoadUint32(&ac.isClosed) > 0 {
+			return 0, io.ErrClosedPipe
+		}
+	}
+
 	ac.mu.Lock()
-	n, err := ac.Writer.Write(p)
+	n, err = ac.Writer.Write(p)
 	ac.mu.Unlock()
-	return n, err
+	return
 }
 
 // Flush writes any buffered data to the underlying Fluser Writer.
@@ -449,10 +459,6 @@ func (ac *AccessLog) AddFields(setters ...FieldSetter) *AccessLog {
 //
 // After Close is called the AccessLog is not accessible.
 func (ac *AccessLog) Close() (err error) {
-	if ac.isClosed {
-		return nil
-	}
-
 	ctx, cancelFunc := stdContext.WithTimeout(stdContext.Background(), 10*time.Second)
 	defer cancelFunc()
 
@@ -461,10 +467,9 @@ func (ac *AccessLog) Close() (err error) {
 
 // CloseContext same as `Close` but waits until given "ctx" is done.
 func (ac *AccessLog) CloseContext(ctx stdContext.Context) (err error) {
-	if ac.isClosed {
-		return nil
+	if !atomic.CompareAndSwapUint32(&ac.isClosed, 0, 1) {
+		return
 	}
-	ac.isClosed = true
 
 	if ac.broker != nil {
 		ac.broker.close <- struct{}{}
@@ -717,9 +722,6 @@ func (ac *AccessLog) after(ctx *context.Context, lat time.Duration, method, path
 	}
 }
 
-const defaultDelim = '|'
-const newLine = '\n'
-
 // Print writes a log manually.
 // The `Handler` method calls it.
 func (ac *AccessLog) Print(ctx *context.Context,
@@ -786,60 +788,60 @@ func (ac *AccessLog) Print(ctx *context.Context,
 		}
 	}
 
-	// url parameters, path parameters and custom fields separated by space,
-	// key=value key2=value2.
-	requestValues := parseRequestValues(code, params, query, fields)
-
 	// the number of separators is the same, in order to be easier
 	// for 3rd-party programs to read the result log file.
 	builder := ac.bufPool.Get().(*bytes.Buffer)
 
 	builder.WriteString(now.Format(timeFormat))
-	builder.WriteRune(ac.Delim)
+	builder.WriteByte(ac.Delim)
 
 	builder.WriteString(latency.String())
-	builder.WriteRune(ac.Delim)
+	builder.WriteByte(ac.Delim)
 
 	builder.WriteString(strconv.Itoa(code))
-	builder.WriteRune(ac.Delim)
+	builder.WriteByte(ac.Delim)
 
 	builder.WriteString(method)
-	builder.WriteRune(ac.Delim)
+	builder.WriteByte(ac.Delim)
 
 	builder.WriteString(path)
-	builder.WriteRune(ac.Delim)
+	builder.WriteByte(ac.Delim)
 
 	if ac.IP {
 		builder.WriteString(ip)
-		builder.WriteRune(ac.Delim)
+		builder.WriteByte(ac.Delim)
 	}
 
-	builder.WriteString(requestValues)
-	builder.WriteRune(ac.Delim)
+	// url parameters, path parameters and custom fields separated by space,
+	// key=value key2=value2.
+	if n, all := parseRequestValues(builder, code, params, query, fields); n > 0 {
+		builder.Truncate(all - 1) // remove the last space.
+		builder.WriteByte(ac.Delim)
+	}
 
 	if ac.BytesReceived || ac.BytesReceivedBody {
 		builder.WriteString(formatBytes(bytesReceived))
-		builder.WriteRune(ac.Delim)
+		builder.WriteByte(ac.Delim)
 	}
 
 	if ac.BytesSent || ac.BytesSentBody {
 		builder.WriteString(formatBytes(bytesSent))
-		builder.WriteRune(ac.Delim)
+		builder.WriteByte(ac.Delim)
 	}
 
 	if ac.RequestBody {
 		builder.WriteString(reqBody)
-		builder.WriteRune(ac.Delim)
+		builder.WriteByte(ac.Delim)
 	}
 
 	if ac.ResponseBody {
 		builder.WriteString(respBody)
-		builder.WriteRune(ac.Delim)
+		builder.WriteByte(ac.Delim)
 	}
 
-	builder.WriteRune(newLine)
+	builder.WriteByte(newLine)
 
-	ac.Write(builder.Bytes())
+	_, err = ac.Write(builder.Bytes())
 	builder.Reset()
 	ac.bufPool.Put(builder)
 

middleware/accesslog/accesslog_test.go

@@ -18,8 +18,7 @@ import (
 )
 
 func TestAccessLogPrint_Simple(t *testing.T) {
-	t.Parallel()
-	const goroutinesN = 420
+	const goroutinesN = 42
 
 	w := new(bytes.Buffer)
 	ac := New(w)
@@ -31,14 +30,12 @@ func TestAccessLogPrint_Simple(t *testing.T) {
 		expected      string
 		expectedLines int
 		mu            sync.Mutex
-		wg            sync.WaitGroup
 	)
-	wg.Add(goroutinesN)
 
+	now := time.Now()
 	for i := 0; i < goroutinesN; i++ {
 		go func() {
-			defer wg.Done()
-			ac.Print(
+			err := ac.Print(
 				nil,
 				1*time.Second,
 				ac.TimeFormat,
@@ -59,25 +56,38 @@ func TestAccessLogPrint_Simple(t *testing.T) {
 				[]memstore.Entry{
 					{Key: "custom", ValueRaw: "custom_value"},
 				})
+
+			if err == nil {
+				mu.Lock()
+				expected += "0001-01-01 00:00:00|1s|200|GET|/path_value?url_query=url_query_value|::1|path_param=path_param_value url_query=url_query_value custom=custom_value|0 B|0 B|Incoming|Outcoming|\n"
+				expectedLines++
+				mu.Unlock()
+			}
 		}()
 
-		mu.Lock()
-		expected += "0001-01-01 00:00:00|1s|200|GET|/path_value?url_query=url_query_value|::1|path_param=path_param_value url_query=url_query_value custom=custom_value|0 B|0 B|Incoming|Outcoming|\n"
-		expectedLines++
-		mu.Unlock()
 	}
 
-	wg.Wait()
-	ac.Close() // TODO: Close waits for current messages but does allow future writes, I should change that.
+	// give some time to write at least some messages or all
+	// (depends on the machine the test is running).
+	time.Sleep(42 * time.Millisecond)
+	ac.Close()
+	end := time.Since(now)
 
 	if got := atomic.LoadUint32(&ac.remaining); got > 0 { // test wait.
 		t.Fatalf("expected remaining: %d but got: %d", 0, got)
 	}
 
-	if got := w.String(); expected != got {
+	mu.Lock()
+	expectedSoFoar := expected
+	expectedLinesSoFar := expectedLines
+	mu.Unlock()
+
+	if got := w.String(); expectedSoFoar != got {
 		gotLines := strings.Count(got, "\n")
-		t.Logf("expected printed result to be[%d]:\n'%s'\n\nbut got[%d]:\n'%s'", expectedLines, expected, gotLines, got)
-		t.Fatalf("expected[%d]: %d but got: %d lines", goroutinesN, expectedLines, gotLines)
+		t.Logf("expected printed result to be[%d]:\n'%s'\n\nbut got[%d]:\n'%s'", expectedLinesSoFar, expectedSoFoar, gotLines, got)
+		t.Fatalf("expected: %d | got: %d lines", expectedLinesSoFar, gotLines)
+	} else {
+		t.Logf("We've got [%d/%d] lines of logs in %s", expectedLinesSoFar, goroutinesN, end.String())
 	}
 }
 
@@ -92,31 +102,34 @@ func TestAccessLogBroker(t *testing.T) {
 	n := 4
 	wg.Add(4)
 	go func() {
-		defer wg.Done()
-
 		i := 0
 		ln := broker.NewListener()
 		for {
 			select {
 			case log, ok := <-ln:
 				if !ok {
-					t.Log("Log Listener Closed")
+					if i != n {
+						for i < n {
+							wg.Done()
+							i++
+						}
+					}
+
+					t.Log("Log Listener Closed: interrupted")
 					return
 				}
+
 				lat := log.Latency
 				t.Log(lat.String())
 				wg.Done()
 				if expected := time.Duration(i) * time.Second; expected != lat {
 					panic(fmt.Sprintf("expected latency: %s but got: %s", expected, lat))
 				}
-				i++
 				time.Sleep(1350 * time.Millisecond)
-				if i == 2 {
-					time.Sleep(2 * time.Second) // "random" sleep even more.
-				}
 				if log.Latency != lat {
 					panic("expected logger to wait for notifier before release the log")
 				}
+				i++
 			}
 		}
 	}()
@@ -153,10 +166,7 @@ func TestAccessLogBroker(t *testing.T) {
 	// wait for all listeners to finish.
 	wg.Wait()
 
-	// wait for close messages.
-	wg.Add(1)
 	ac.Close()
-	wg.Wait()
 }
 
 type noOpFormatter struct{}

middleware/accesslog/log.go

@@ -63,7 +63,18 @@ func (l *Log) Clone() Log {
 // RequestValuesLine returns a string line which
 // combines the path parameters, query and custom fields.
 func (l *Log) RequestValuesLine() string {
-	return parseRequestValues(l.Code, l.PathParams, l.Query, l.Fields)
+	buf := new(strings.Builder)
+	_, n := parseRequestValues(buf, l.Code, l.PathParams, l.Query, l.Fields)
+	if n == 0 {
+		return ""
+	}
+
+	requestValues := buf.String()
+	if n > 1 {
+		return requestValues[0 : n-1] // remove last space.
+	}
+
+	return requestValues
 }
 
 // BytesReceivedLine returns the formatted bytes received length.
@@ -100,38 +111,46 @@ func formatBytes(b int) string {
 		float64(b)/float64(div), "KMGTPE"[exp])
 }
 
-func parseRequestValues(code int, pathParams memstore.Store, query []memstore.StringEntry, fields memstore.Store) (requestValues string) {
-	var buf strings.Builder
+const (
+	eq    = '='
+	space = ' '
+)
 
+// parses the request values (params, query and fields).
+// returns the length of written bytes for parsing request values
+// and the total.
+func parseRequestValues(buf interface {
+	io.StringWriter
+	io.ByteWriter
+	Len() int
+}, code int, pathParams memstore.Store, query []memstore.StringEntry, fields memstore.Store) (int, int) {
+	n := buf.Len()
 	if !context.StatusCodeNotSuccessful(code) {
 		// collect path parameters on a successful request-response only.
 		for _, entry := range pathParams {
 			buf.WriteString(entry.Key)
-			buf.WriteByte('=')
+			buf.WriteByte(eq)
 			buf.WriteString(fmt.Sprintf("%v", entry.ValueRaw))
-			buf.WriteByte(' ')
+			buf.WriteByte(space)
 		}
 	}
 
 	for _, entry := range query {
 		buf.WriteString(entry.Key)
-		buf.WriteByte('=')
+		buf.WriteByte(eq)
 		buf.WriteString(entry.Value)
-		buf.WriteByte(' ')
+		buf.WriteByte(space)
 	}
 
 	for _, entry := range fields {
 		buf.WriteString(entry.Key)
-		buf.WriteByte('=')
+		buf.WriteByte(eq)
 		buf.WriteString(fmt.Sprintf("%v", entry.ValueRaw))
-		buf.WriteByte(' ')
+		buf.WriteByte(space)
 	}
 
-	if n := buf.Len(); n > 1 {
-		requestValues = buf.String()[0 : n-1] // remove last space.
-	}
-
-	return
+	total := buf.Len()
+	return total - n, total
 }
 
 type (