diff --git a/_examples/logging/request-logger/accesslog-csv/access_log.csv.sample b/_examples/logging/request-logger/accesslog-csv/access_log.csv.sample
index 6e17fccf..13fe5734 100644
--- a/_examples/logging/request-logger/accesslog-csv/access_log.csv.sample
+++ b/_examples/logging/request-logger/accesslog-csv/access_log.csv.sample
@@ -1,7 +1,5 @@
Timestamp,Latency,Code,Method,Path,IP,Req Values,In,Out,Request,Response
-1599952696740,0s,200,GET,/,::1,,0,5,,Index
-1599952696774,0s,404,GET,/favicon.ico,::1,,0,9,,Not Found
-1599952697996,0s,200,GET,/,::1,,0,5,,Index
-1599952698130,0s,200,GET,/,::1,,0,5,,Index
-1599952698261,0s,200,GET,/,::1,,0,5,,Index
-1599952741189,1.01113s,200,GET,/,::1,sleep=1s,0,5,,Index
+1599996265254,0s,200,GET,/,::1,a=1 b=2,0,5,,Index
+1599996266138,0s,200,GET,/,::1,sleep=32ms,0,5,,Index
+1599996266778,1s,200,GET,/,::1,sleep=1s,0,5,,Index
+1599996267780,1s,200,GET,/,::1,sleep=1s,0,5,,Index
diff --git a/_examples/logging/request-logger/accesslog-csv/main.go b/_examples/logging/request-logger/accesslog-csv/main.go
index a80527b8..c156d1a1 100644
--- a/_examples/logging/request-logger/accesslog-csv/main.go
+++ b/_examples/logging/request-logger/accesslog-csv/main.go
@@ -11,6 +11,7 @@ func main() {
app := iris.New()
ac := accesslog.File("access_log.csv")
ac.ResponseBody = true
+ ac.LatencyRound = time.Second
ac.SetFormatter(&accesslog.CSV{
Header: true,
// DateScript: "FROM_UNIX",
diff --git a/_examples/logging/request-logger/accesslog-simple/access.log.sample b/_examples/logging/request-logger/accesslog-simple/access.log.sample
new file mode 100644
index 00000000..dabdd4ac
--- /dev/null
+++ b/_examples/logging/request-logger/accesslog-simple/access.log.sample
@@ -0,0 +1,2 @@
+{"timestamp":1599993744664,"latency":0,"code":404,"method":"GET","path":"/favicon.ico","ip":"::1","request":"","bytes_sent":9}
+{"timestamp":1599993774018,"latency":0,"code":200,"method":"GET","path":"/","ip":"::1","query":[{"key":"a","value":"1"},{"key":"b","value":"2"}],"request":"","bytes_sent":2}
diff --git a/_examples/logging/request-logger/accesslog/access.log.sample b/_examples/logging/request-logger/accesslog/access.log.sample
index 0b9d9ea0..ae988beb 100644
--- a/_examples/logging/request-logger/accesslog/access.log.sample
+++ b/_examples/logging/request-logger/accesslog/access.log.sample
@@ -1,9 +1,10 @@
-2020-09-08 13:34:42|0s|200|POST|/read_body|::1||324 B|217 B|{"name":"John","email":"example@example.com"}|{"data":{"email":"example@example.com","name":"John"},"message":"OK"}|
-2020-09-08 13:40:28|0s|400|POST|/read_body|::1|||85 B|error(invalid character '\r' in string literal)||
-2020-09-08 13:41:05|1.0024ms|200|GET|/|a=1 b=2|767 B|251 B||Hello index
|
-2020-09-08 13:41:26|0s|404|GET|/public|::1||765 B|83 B|||
-2020-09-08 13:41:36|0s|200|GET|/user/kataras|::1|username=kataras|771 B|91 B||Hello, kataras!|
-2020-09-08 13:41:47|0s|200|GET|/user/kataras|::1|username=kataras a_query_parameter=name|774 B|91 B||Hello, kataras!|
-2020-09-08 20:37:33|0s|200|GET|/admin|::1|auth=admin:admin|608 B|164 B||Username: admin
Password: admin
|
-2020-09-09 07:56:00|738.1µs|200|GET|/session|::1|session_id=23fe763f-c9d5-4d65-9e1a-2cc8d23d1aa3 session_test_key=session_test_value|818 B|302 B||OK|
-2020-09-09 08:36:47|2.0095505s|200|GET|/fields|::1|job_latency=2s|544 B|130 B||OK|
+2020-09-13 13:37:42 2.0057ms 200 POST /read_body ::1 61 B 94 B {"name":"John","email":"example@example.com"}
+2020-09-13 13:37:50 0s 400 POST /read_body ::1 0 B 0 B error(invalid character '\r' in string literal)
+2020-09-13 13:38:03 0s 404 GET /favicon.ico ::1 0 B 9 B
+2020-09-13 13:38:07 0s 404 GET /public ::1 0 B 9 B
+2020-09-13 13:38:09 1.0021ms 200 GET /user/kataras ::1 username=kataras 0 B 15 B
+2020-09-13 13:38:14 0s 200 GET /user/kataras ::1 username=kataras a_query_parameter=name 0 B 15 B
+2020-09-13 13:38:18 0s 401 GET /admin ::1 0 B 0 B
+2020-09-13 13:38:19 0s 200 GET /admin ::1 auth=admin:admin 0 B 48 B
+2020-09-13 13:38:22 0s 200 GET /session ::1 session_id=23fe763f-c9d5-4d65-9e1a-2cc8d23d1aa3 session_test_key=session_test_value auth=admin:admin 0 B 2 B
+2020-09-13 13:38:25 2.0001204s 200 GET /fields ::1 job_latency=2s auth=admin:admin 0 B 2 B
diff --git a/_examples/logging/request-logger/accesslog/main.go b/_examples/logging/request-logger/accesslog/main.go
index fe4e3cef..2666509d 100644
--- a/_examples/logging/request-logger/accesslog/main.go
+++ b/_examples/logging/request-logger/accesslog/main.go
@@ -31,6 +31,7 @@ func makeAccessLog() *accesslog.AccessLog {
// Initialize a new access log middleware.
// Accepts an `io.Writer`.
ac := accesslog.New(bufio.NewWriter(w))
+ ac.Delim = ' ' // change the separator from '|' to space.
// ac.TimeFormat = "2006-01-02 15:04:05" // default
// Example of adding more than one field to the logger.
diff --git a/i18n/loader.go b/i18n/loader.go
index 948fb8fa..56c1e2c8 100644
--- a/i18n/loader.go
+++ b/i18n/loader.go
@@ -23,7 +23,7 @@ import (
// See `Glob` and `Assets` package-level functions.
type (
LoaderConfig struct {
- // Template delimeters, defaults to {{ }}.
+ // Template delimiters, defaults to {{ }}.
Left, Right string
// Template functions map per locale, defaults to nil.
Funcs func(context.Locale) template.FuncMap
diff --git a/middleware/accesslog/accesslog.go b/middleware/accesslog/accesslog.go
index 5b9f99e0..99d5831a 100644
--- a/middleware/accesslog/accesslog.go
+++ b/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)
diff --git a/middleware/accesslog/accesslog_test.go b/middleware/accesslog/accesslog_test.go
index 1aa83143..612788db 100644
--- a/middleware/accesslog/accesslog_test.go
+++ b/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{}
diff --git a/middleware/accesslog/log.go b/middleware/accesslog/log.go
index 1a635b0f..684675eb 100644
--- a/middleware/accesslog/log.go
+++ b/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 (
diff --git a/sessions/sessiondb/redis/database.go b/sessions/sessiondb/redis/database.go
index 2b1898d6..51a0d94b 100644
--- a/sessions/sessiondb/redis/database.go
+++ b/sessions/sessiondb/redis/database.go
@@ -44,7 +44,7 @@ type Config struct {
Timeout time.Duration
// Prefix "myprefix-for-this-website". Defaults to "".
Prefix string
- // Delim the delimeter for the keys on the sessiondb. Defaults to "-".
+ // Delim the delimiter for the keys on the sessiondb. Defaults to "-".
Delim string
// TLSConfig will cause Dial to perform a TLS handshake using the provided