c197206897
* fix(s3): return ETag header for directory marker PutObject requests The PutObject handler has a special path for keys ending with "/" (directory markers) that creates the entry via mkdir. This path never computed or set the ETag response header, unlike the regular PutObject path. AWS S3 always returns an ETag header, even for empty-body puts. Compute the MD5 of the content (empty or otherwise), store it in the entry attributes and extended attributes, and set the ETag response header. Fixes #8682 * fix: handle io.ReadAll error and chunked encoding for directory markers Address review feedback: - Handle error from io.ReadAll instead of silently discarding it - Change condition from ContentLength > 0 to ContentLength != 0 to correctly handle chunked transfer encoding (ContentLength == -1) * fix hanging tests
469 lines
13 KiB
Go
469 lines
13 KiB
Go
// Go support for leveled logs, analogous to https://code.google.com/p/google-glog/
|
|
//
|
|
// Copyright 2013 Google Inc. All Rights Reserved.
|
|
//
|
|
// Licensed under the Apache License, Version 2.0 (the "License");
|
|
// you may not use this file except in compliance with the License.
|
|
// You may obtain a copy of the License at
|
|
//
|
|
// http://www.apache.org/licenses/LICENSE-2.0
|
|
//
|
|
// Unless required by applicable law or agreed to in writing, software
|
|
// distributed under the License is distributed on an "AS IS" BASIS,
|
|
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
|
// See the License for the specific language governing permissions and
|
|
// limitations under the License.
|
|
|
|
package glog
|
|
|
|
import (
|
|
"bytes"
|
|
"fmt"
|
|
stdLog "log"
|
|
"path/filepath"
|
|
"runtime"
|
|
"strconv"
|
|
"strings"
|
|
"testing"
|
|
"time"
|
|
)
|
|
|
|
// Test that shortHostname works as advertised.
|
|
func TestShortHostname(t *testing.T) {
|
|
for hostname, expect := range map[string]string{
|
|
"": "",
|
|
"host": "host",
|
|
"host.google.com": "host",
|
|
} {
|
|
if got := shortHostname(hostname); expect != got {
|
|
t.Errorf("shortHostname(%q): expected %q, got %q", hostname, expect, got)
|
|
}
|
|
}
|
|
}
|
|
|
|
// flushBuffer wraps a bytes.Buffer to satisfy flushSyncWriter.
|
|
type flushBuffer struct {
|
|
bytes.Buffer
|
|
}
|
|
|
|
func (f *flushBuffer) Flush() error {
|
|
return nil
|
|
}
|
|
|
|
func (f *flushBuffer) Sync() error {
|
|
return nil
|
|
}
|
|
|
|
// swap sets the log writers and returns the old array.
|
|
func (l *loggingT) swap(writers [numSeverity]flushSyncWriter) (old [numSeverity]flushSyncWriter) {
|
|
l.mu.Lock()
|
|
defer l.mu.Unlock()
|
|
old = l.file
|
|
for i, w := range writers {
|
|
logging.file[i] = w
|
|
}
|
|
return
|
|
}
|
|
|
|
// newBuffers sets the log writers to all new byte buffers and returns the old array.
|
|
func (l *loggingT) newBuffers() [numSeverity]flushSyncWriter {
|
|
return l.swap([numSeverity]flushSyncWriter{new(flushBuffer), new(flushBuffer), new(flushBuffer), new(flushBuffer)})
|
|
}
|
|
|
|
// contents returns the specified log value as a string.
|
|
func contents(s severity) string {
|
|
return logging.file[s].(*flushBuffer).String()
|
|
}
|
|
|
|
// contains reports whether the string is contained in the log.
|
|
func contains(s severity, str string, t *testing.T) bool {
|
|
return strings.Contains(contents(s), str)
|
|
}
|
|
|
|
// setFlags configures the logging flags how the test expects them.
|
|
func setFlags() {
|
|
logging.toStderr = false
|
|
}
|
|
|
|
// Test that Info works as advertised.
|
|
func TestInfo(t *testing.T) {
|
|
setFlags()
|
|
defer logging.swap(logging.newBuffers())
|
|
Info("test")
|
|
if !contains(infoLog, "I", t) {
|
|
t.Errorf("Info has wrong character: %q", contents(infoLog))
|
|
}
|
|
if !contains(infoLog, "test", t) {
|
|
t.Error("Info failed")
|
|
}
|
|
}
|
|
|
|
func TestInfoDepth(t *testing.T) {
|
|
setFlags()
|
|
defer logging.swap(logging.newBuffers())
|
|
|
|
f := func() { InfoDepth(1, "depth-test1") }
|
|
|
|
// The next three lines must stay together
|
|
_, _, wantLine, _ := runtime.Caller(0)
|
|
InfoDepth(0, "depth-test0")
|
|
f()
|
|
|
|
msgs := strings.Split(strings.TrimSuffix(contents(infoLog), "\n"), "\n")
|
|
if len(msgs) != 2 {
|
|
t.Fatalf("Got %d lines, expected 2", len(msgs))
|
|
}
|
|
|
|
for i, m := range msgs {
|
|
if !strings.HasPrefix(m, "I") {
|
|
t.Errorf("InfoDepth[%d] has wrong character: %q", i, m)
|
|
}
|
|
w := fmt.Sprintf("depth-test%d", i)
|
|
if !strings.Contains(m, w) {
|
|
t.Errorf("InfoDepth[%d] missing %q: %q", i, w, m)
|
|
}
|
|
|
|
// pull out the line number (between : and ])
|
|
msg := m[strings.LastIndex(m, ":")+1:]
|
|
x := strings.Index(msg, " ")
|
|
if x < 0 {
|
|
t.Errorf("InfoDepth[%d]: missing ' ': %q", i, m)
|
|
continue
|
|
}
|
|
line, err := strconv.Atoi(msg[:x])
|
|
if err != nil {
|
|
t.Errorf("InfoDepth[%d]: bad line number: %q", i, m)
|
|
continue
|
|
}
|
|
wantLine++
|
|
if wantLine != line {
|
|
t.Errorf("InfoDepth[%d]: got line %d, want %d", i, line, wantLine)
|
|
}
|
|
}
|
|
}
|
|
|
|
func init() {
|
|
CopyStandardLogTo("INFO")
|
|
}
|
|
|
|
// Test that CopyStandardLogTo panics on bad input.
|
|
func TestCopyStandardLogToPanic(t *testing.T) {
|
|
defer func() {
|
|
if s, ok := recover().(string); !ok || !strings.Contains(s, "LOG") {
|
|
t.Errorf(`CopyStandardLogTo("LOG") should have panicked: %v`, s)
|
|
}
|
|
}()
|
|
CopyStandardLogTo("LOG")
|
|
}
|
|
|
|
// Test that using the standard log package logs to INFO.
|
|
func TestStandardLog(t *testing.T) {
|
|
setFlags()
|
|
defer logging.swap(logging.newBuffers())
|
|
stdLog.Print("test")
|
|
if !contains(infoLog, "I", t) {
|
|
t.Errorf("Info has wrong character: %q", contents(infoLog))
|
|
}
|
|
if !contains(infoLog, "test", t) {
|
|
t.Error("Info failed")
|
|
}
|
|
}
|
|
|
|
// Test that the header has the correct format.
|
|
func TestHeader(t *testing.T) {
|
|
setFlags()
|
|
defer logging.swap(logging.newBuffers())
|
|
defer func(previous func() time.Time) { timeNow = previous }(timeNow)
|
|
timeNow = func() time.Time {
|
|
return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local)
|
|
}
|
|
pid = 1234
|
|
Info("test")
|
|
var line int
|
|
format := "I0102 15:04:05.067890 glog_test.go:%d test\n"
|
|
n, err := fmt.Sscanf(contents(infoLog), format, &line)
|
|
if n != 1 || err != nil {
|
|
t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(infoLog))
|
|
}
|
|
// Scanf treats multiple spaces as equivalent to a single space,
|
|
// so check for correct space-padding also.
|
|
want := fmt.Sprintf(format, line)
|
|
if contents(infoLog) != want {
|
|
t.Errorf("log format error: got:\n\t%q\nwant:\t%q", contents(infoLog), want)
|
|
}
|
|
}
|
|
|
|
// Test that an Error log goes to Warning and Info.
|
|
// Even in the Info log, the source character will be E, so the data should
|
|
// all be identical.
|
|
func TestError(t *testing.T) {
|
|
setFlags()
|
|
defer logging.swap(logging.newBuffers())
|
|
Error("test")
|
|
if !contains(errorLog, "E", t) {
|
|
t.Errorf("Error has wrong character: %q", contents(errorLog))
|
|
}
|
|
if !contains(errorLog, "test", t) {
|
|
t.Error("Error failed")
|
|
}
|
|
str := contents(errorLog)
|
|
if !contains(warningLog, str, t) {
|
|
t.Error("Warning failed")
|
|
}
|
|
if !contains(infoLog, str, t) {
|
|
t.Error("Info failed")
|
|
}
|
|
}
|
|
|
|
// Test that a Warning log goes to Info.
|
|
// Even in the Info log, the source character will be W, so the data should
|
|
// all be identical.
|
|
func TestWarning(t *testing.T) {
|
|
setFlags()
|
|
defer logging.swap(logging.newBuffers())
|
|
Warning("test")
|
|
if !contains(warningLog, "W", t) {
|
|
t.Errorf("Warning has wrong character: %q", contents(warningLog))
|
|
}
|
|
if !contains(warningLog, "test", t) {
|
|
t.Error("Warning failed")
|
|
}
|
|
str := contents(warningLog)
|
|
if !contains(infoLog, str, t) {
|
|
t.Error("Info failed")
|
|
}
|
|
}
|
|
|
|
// Test that a V log goes to Info.
|
|
func TestV(t *testing.T) {
|
|
setFlags()
|
|
defer logging.swap(logging.newBuffers())
|
|
logging.verbosity.Set("2")
|
|
defer logging.verbosity.Set("0")
|
|
V(2).Info("test")
|
|
if !contains(infoLog, "I", t) {
|
|
t.Errorf("Info has wrong character: %q", contents(infoLog))
|
|
}
|
|
if !contains(infoLog, "test", t) {
|
|
t.Error("Info failed")
|
|
}
|
|
}
|
|
|
|
// Test that a vmodule enables a log in this file.
|
|
func TestVmoduleOn(t *testing.T) {
|
|
setFlags()
|
|
defer logging.swap(logging.newBuffers())
|
|
logging.vmodule.Set("glog_test=2")
|
|
defer logging.vmodule.Set("")
|
|
if !V(1) {
|
|
t.Error("V not enabled for 1")
|
|
}
|
|
if !V(2) {
|
|
t.Error("V not enabled for 2")
|
|
}
|
|
if V(3) {
|
|
t.Error("V enabled for 3")
|
|
}
|
|
V(2).Info("test")
|
|
if !contains(infoLog, "I", t) {
|
|
t.Errorf("Info has wrong character: %q", contents(infoLog))
|
|
}
|
|
if !contains(infoLog, "test", t) {
|
|
t.Error("Info failed")
|
|
}
|
|
}
|
|
|
|
// Test that a vmodule of another file does not enable a log in this file.
|
|
func TestVmoduleOff(t *testing.T) {
|
|
setFlags()
|
|
defer logging.swap(logging.newBuffers())
|
|
logging.vmodule.Set("notthisfile=2")
|
|
defer logging.vmodule.Set("")
|
|
for i := 1; i <= 3; i++ {
|
|
if V(Level(i)) {
|
|
t.Errorf("V enabled for %d", i)
|
|
}
|
|
}
|
|
V(2).Info("test")
|
|
if contents(infoLog) != "" {
|
|
t.Error("V logged incorrectly")
|
|
}
|
|
}
|
|
|
|
// vGlobs are patterns that match/don't match this file at V=2.
|
|
var vGlobs = map[string]bool{
|
|
// Easy to test the numeric match here.
|
|
"glog_test=1": false, // If -vmodule sets V to 1, V(2) will fail.
|
|
"glog_test=2": true,
|
|
"glog_test=3": true, // If -vmodule sets V to 1, V(3) will succeed.
|
|
// These all use 2 and check the patterns. All are true.
|
|
"*=2": true,
|
|
"?l*=2": true,
|
|
"????_*=2": true,
|
|
"??[mno]?_*t=2": true,
|
|
// These all use 2 and check the patterns. All are false.
|
|
"*x=2": false,
|
|
"m*=2": false,
|
|
"??_*=2": false,
|
|
"?[abc]?_*t=2": false,
|
|
}
|
|
|
|
// Test that vmodule globbing works as advertised.
|
|
func testVmoduleGlob(pat string, match bool, t *testing.T) {
|
|
setFlags()
|
|
defer logging.swap(logging.newBuffers())
|
|
defer logging.vmodule.Set("")
|
|
logging.vmodule.Set(pat)
|
|
if V(2) != Verbose(match) {
|
|
t.Errorf("incorrect match for %q: got %t expected %t", pat, V(2), match)
|
|
}
|
|
}
|
|
|
|
// Test that a vmodule globbing works as advertised.
|
|
func TestVmoduleGlob(t *testing.T) {
|
|
for glob, match := range vGlobs {
|
|
testVmoduleGlob(glob, match, t)
|
|
}
|
|
}
|
|
|
|
func TestRollover(t *testing.T) {
|
|
setFlags()
|
|
var err error
|
|
defer func(previous func(error)) { logExitFunc = previous }(logExitFunc)
|
|
logExitFunc = func(e error) {
|
|
err = e
|
|
}
|
|
|
|
Info("x") // Be sure we have a file (also triggers createLogDirs via sync.Once).
|
|
|
|
// Set MaxSize after the first Info call so that createLogDirs (which
|
|
// overwrites MaxSize from the flag default) has already executed.
|
|
defer func(previous uint64) { MaxSize = previous }(MaxSize)
|
|
MaxSize = 512
|
|
info, ok := logging.file[infoLog].(*syncBuffer)
|
|
if !ok {
|
|
t.Fatal("info wasn't created")
|
|
}
|
|
if err != nil {
|
|
t.Fatalf("info has initial error: %v", err)
|
|
}
|
|
fname0 := info.file.Name()
|
|
Info(strings.Repeat("x", int(MaxSize))) // force a rollover
|
|
if err != nil {
|
|
t.Fatalf("info has error after big write: %v", err)
|
|
}
|
|
|
|
// Make sure the next log file gets a file name with a different
|
|
// time stamp.
|
|
//
|
|
// TODO: determine whether we need to support subsecond log
|
|
// rotation. C++ does not appear to handle this case (nor does it
|
|
// handle Daylight Savings Time properly).
|
|
time.Sleep(1 * time.Second)
|
|
|
|
Info("x") // create a new file
|
|
if err != nil {
|
|
t.Fatalf("error after rotation: %v", err)
|
|
}
|
|
fname1 := info.file.Name()
|
|
if fname0 == fname1 {
|
|
t.Errorf("info.f.Name did not change: %v", fname0)
|
|
}
|
|
if info.nbytes >= MaxSize {
|
|
t.Errorf("file size was not reset: %d", info.nbytes)
|
|
}
|
|
}
|
|
|
|
func TestTimeBasedRollover(t *testing.T) {
|
|
setFlags()
|
|
var err error
|
|
defer func(previous func(error)) { logExitFunc = previous }(logExitFunc)
|
|
logExitFunc = func(e error) {
|
|
err = e
|
|
}
|
|
|
|
// Disable size-based rotation by setting a very large MaxSize.
|
|
defer func(previous uint64) { MaxSize = previous }(MaxSize)
|
|
MaxSize = 1024 * 1024 * 1024
|
|
|
|
// Enable time-based rotation with a 1-hour interval.
|
|
defer func(previous int) { *logRotateHours = previous }(*logRotateHours)
|
|
*logRotateHours = 1
|
|
|
|
Info("x") // Create initial file.
|
|
info, ok := logging.file[infoLog].(*syncBuffer)
|
|
if !ok {
|
|
t.Fatal("info wasn't created")
|
|
}
|
|
if err != nil {
|
|
t.Fatalf("info has initial error: %v", err)
|
|
}
|
|
fname0 := info.file.Name()
|
|
createdAt := info.createdAt
|
|
|
|
// Mock time to 30 minutes after file creation — should NOT rotate.
|
|
defer func(previous func() time.Time) { timeNow = previous }(timeNow)
|
|
timeNow = func() time.Time { return createdAt.Add(30 * time.Minute) }
|
|
Info("still within interval")
|
|
if err != nil {
|
|
t.Fatalf("error after write within interval: %v", err)
|
|
}
|
|
if info.file.Name() != fname0 {
|
|
t.Error("file rotated before interval elapsed")
|
|
}
|
|
|
|
// Advance mock time past the 1-hour interval — should rotate.
|
|
timeNow = func() time.Time { return createdAt.Add(61 * time.Minute) }
|
|
Info("past interval")
|
|
if err != nil {
|
|
t.Fatalf("error after time-based rotation: %v", err)
|
|
}
|
|
fname1 := info.file.Name()
|
|
if fname0 == fname1 {
|
|
t.Error("file did not rotate after interval elapsed")
|
|
}
|
|
}
|
|
|
|
func TestLogBacktraceAt(t *testing.T) {
|
|
setFlags()
|
|
defer logging.swap(logging.newBuffers())
|
|
// The peculiar style of this code simplifies line counting and maintenance of the
|
|
// tracing block below.
|
|
var infoLine string
|
|
setTraceLocation := func(file string, line int, ok bool, delta int) {
|
|
if !ok {
|
|
t.Fatal("could not get file:line")
|
|
}
|
|
_, file = filepath.Split(file)
|
|
infoLine = fmt.Sprintf("%s:%d", file, line+delta)
|
|
err := logging.traceLocation.Set(infoLine)
|
|
if err != nil {
|
|
t.Fatal("error setting log_backtrace_at: ", err)
|
|
}
|
|
}
|
|
{
|
|
// Start of tracing block. These lines know about each other's relative position.
|
|
_, file, line, ok := runtime.Caller(0)
|
|
setTraceLocation(file, line, ok, +2) // Two lines between Caller and Info calls.
|
|
Info("we want a stack trace here")
|
|
}
|
|
numAppearances := strings.Count(contents(infoLog), infoLine)
|
|
if numAppearances < 2 {
|
|
// Need 2 appearances, one in the log header and one in the trace:
|
|
// log_test.go:281: I0511 16:36:06.952398 02238 log_test.go:280] we want a stack trace here
|
|
// ...
|
|
// github.com/glog/glog_test.go:280 (0x41ba91)
|
|
// ...
|
|
// We could be more precise but that would require knowing the details
|
|
// of the traceback format, which may not be dependable.
|
|
t.Fatal("got no trace back; log is ", contents(infoLog))
|
|
}
|
|
}
|
|
|
|
func BenchmarkHeader(b *testing.B) {
|
|
for i := 0; i < b.N; i++ {
|
|
buf, _, _ := logging.header(infoLog, 0)
|
|
logging.putBuffer(buf)
|
|
}
|
|
}
|