summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
Diffstat
-rw-r--r--cmd/check/main.go3
-rw-r--r--cmd/gitlab-shell-authorized-keys-check/main.go3
-rw-r--r--cmd/gitlab-shell-authorized-principals-check/main.go3
-rw-r--r--cmd/gitlab-shell/main.go3
-rw-r--r--internal/gitlabnet/client.go14
-rw-r--r--internal/gitlabnet/client_test.go27
-rw-r--r--internal/logger/logger.go54
-rw-r--r--internal/logger/logger_test.go42
-rw-r--r--internal/testhelper/testhelper.go9
-rw-r--r--spec/support/gitlab_shell_setup.rb3
10 files changed, 143 insertions, 18 deletions
diff --git a/cmd/check/main.go b/cmd/check/main.go
index a72d38c..e88b9fe 100644
--- a/cmd/check/main.go
+++ b/cmd/check/main.go
@@ -8,6 +8,7 @@ import (
"gitlab.com/gitlab-org/gitlab-shell/internal/command/readwriter"
"gitlab.com/gitlab-org/gitlab-shell/internal/config"
"gitlab.com/gitlab-org/gitlab-shell/internal/executable"
+ "gitlab.com/gitlab-org/gitlab-shell/internal/logger"
)
func main() {
@@ -29,6 +30,8 @@ func main() {
os.Exit(1)
}
+ logger.Configure(config)
+
cmd, err := command.New(executable, os.Args[1:], config, readWriter)
if err != nil {
fmt.Fprintf(readWriter.ErrOut, "%v\n", err)
diff --git a/cmd/gitlab-shell-authorized-keys-check/main.go b/cmd/gitlab-shell-authorized-keys-check/main.go
index 8cc0bc8..4b3949c 100644
--- a/cmd/gitlab-shell-authorized-keys-check/main.go
+++ b/cmd/gitlab-shell-authorized-keys-check/main.go
@@ -9,6 +9,7 @@ import (
"gitlab.com/gitlab-org/gitlab-shell/internal/config"
"gitlab.com/gitlab-org/gitlab-shell/internal/console"
"gitlab.com/gitlab-org/gitlab-shell/internal/executable"
+ "gitlab.com/gitlab-org/gitlab-shell/internal/logger"
)
func main() {
@@ -30,6 +31,8 @@ func main() {
os.Exit(1)
}
+ logger.Configure(config)
+
cmd, err := command.New(executable, os.Args[1:], config, readWriter)
if err != nil {
// For now this could happen if `SSH_CONNECTION` is not set on
diff --git a/cmd/gitlab-shell-authorized-principals-check/main.go b/cmd/gitlab-shell-authorized-principals-check/main.go
index 328e11f..fc46180 100644
--- a/cmd/gitlab-shell-authorized-principals-check/main.go
+++ b/cmd/gitlab-shell-authorized-principals-check/main.go
@@ -9,6 +9,7 @@ import (
"gitlab.com/gitlab-org/gitlab-shell/internal/config"
"gitlab.com/gitlab-org/gitlab-shell/internal/console"
"gitlab.com/gitlab-org/gitlab-shell/internal/executable"
+ "gitlab.com/gitlab-org/gitlab-shell/internal/logger"
)
func main() {
@@ -30,6 +31,8 @@ func main() {
os.Exit(1)
}
+ logger.Configure(config)
+
cmd, err := command.New(executable, os.Args[1:], config, readWriter)
if err != nil {
// For now this could happen if `SSH_CONNECTION` is not set on
diff --git a/cmd/gitlab-shell/main.go b/cmd/gitlab-shell/main.go
index 7751e4d..8df781c 100644
--- a/cmd/gitlab-shell/main.go
+++ b/cmd/gitlab-shell/main.go
@@ -9,6 +9,7 @@ import (
"gitlab.com/gitlab-org/gitlab-shell/internal/config"
"gitlab.com/gitlab-org/gitlab-shell/internal/console"
"gitlab.com/gitlab-org/gitlab-shell/internal/executable"
+ "gitlab.com/gitlab-org/gitlab-shell/internal/logger"
)
func main() {
@@ -30,6 +31,8 @@ func main() {
os.Exit(1)
}
+ logger.Configure(config)
+
cmd, err := command.New(executable, os.Args[1:], config, readWriter)
if err != nil {
// For now this could happen if `SSH_CONNECTION` is not set on
diff --git a/internal/gitlabnet/client.go b/internal/gitlabnet/client.go
index bb8655a..7c8f431 100644
--- a/internal/gitlabnet/client.go
+++ b/internal/gitlabnet/client.go
@@ -8,8 +8,11 @@ import (
"io"
"net/http"
"strings"
+ "time"
+ log "github.com/sirupsen/logrus"
"gitlab.com/gitlab-org/gitlab-shell/internal/config"
+ "gitlab.com/gitlab-org/gitlab-shell/internal/logger"
)
const (
@@ -111,15 +114,26 @@ func (c *GitlabClient) DoRequest(method, path string, data interface{}) (*http.R
request.Header.Add("Content-Type", "application/json")
request.Close = true
+ start := time.Now()
response, err := c.httpClient.Do(request)
+ fields := log.Fields{
+ "method": method,
+ "url": request.URL.String(),
+ "duration_ms": logger.ElapsedTime(start),
+ }
+
if err != nil {
+ log.WithError(err).WithFields(fields).Error("Internal API unreachable")
return nil, fmt.Errorf("Internal API unreachable")
}
if err := parseError(response); err != nil {
+ log.WithError(err).WithFields(fields).Error("Internal API error")
return nil, err
}
+ log.WithFields(fields).Info("Finished HTTP request")
+
return response, nil
}
diff --git a/internal/gitlabnet/client_test.go b/internal/gitlabnet/client_test.go
index 3f96b41..d6ca91d 100644
--- a/internal/gitlabnet/client_test.go
+++ b/internal/gitlabnet/client_test.go
@@ -7,8 +7,11 @@ import (
"io/ioutil"
"net/http"
"path"
+ "strings"
"testing"
+ "github.com/sirupsen/logrus"
+
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
@@ -116,6 +119,7 @@ func TestClients(t *testing.T) {
func testSuccessfulGet(t *testing.T, client *GitlabClient) {
t.Run("Successful get", func(t *testing.T) {
+ hook := testhelper.SetupLogger()
response, err := client.Get("/hello")
require.NoError(t, err)
require.NotNil(t, response)
@@ -125,11 +129,17 @@ func testSuccessfulGet(t *testing.T, client *GitlabClient) {
responseBody, err := ioutil.ReadAll(response.Body)
assert.NoError(t, err)
assert.Equal(t, string(responseBody), "Hello")
+
+ assert.Equal(t, 1, len(hook.Entries))
+ assert.Equal(t, logrus.InfoLevel, hook.LastEntry().Level)
+ assert.True(t, strings.Contains(hook.LastEntry().Message, "method=GET"))
+ assert.True(t, strings.Contains(hook.LastEntry().Message, "Finished HTTP request"))
})
}
func testSuccessfulPost(t *testing.T, client *GitlabClient) {
t.Run("Successful Post", func(t *testing.T) {
+ hook := testhelper.SetupLogger()
data := map[string]string{"key": "value"}
response, err := client.Post("/post_endpoint", data)
@@ -141,20 +151,37 @@ func testSuccessfulPost(t *testing.T, client *GitlabClient) {
responseBody, err := ioutil.ReadAll(response.Body)
assert.NoError(t, err)
assert.Equal(t, "Echo: {\"key\":\"value\"}", string(responseBody))
+
+ assert.Equal(t, 1, len(hook.Entries))
+ assert.Equal(t, logrus.InfoLevel, hook.LastEntry().Level)
+ assert.True(t, strings.Contains(hook.LastEntry().Message, "method=POST"))
+ assert.True(t, strings.Contains(hook.LastEntry().Message, "Finished HTTP request"))
})
}
func testMissing(t *testing.T, client *GitlabClient) {
t.Run("Missing error for GET", func(t *testing.T) {
+ hook := testhelper.SetupLogger()
response, err := client.Get("/missing")
assert.EqualError(t, err, "Internal API error (404)")
assert.Nil(t, response)
+
+ assert.Equal(t, 1, len(hook.Entries))
+ assert.Equal(t, logrus.InfoLevel, hook.LastEntry().Level)
+ assert.True(t, strings.Contains(hook.LastEntry().Message, "method=GET"))
+ assert.True(t, strings.Contains(hook.LastEntry().Message, "Internal API error"))
})
t.Run("Missing error for POST", func(t *testing.T) {
+ hook := testhelper.SetupLogger()
response, err := client.Post("/missing", map[string]string{})
assert.EqualError(t, err, "Internal API error (404)")
assert.Nil(t, response)
+
+ assert.Equal(t, 1, len(hook.Entries))
+ assert.Equal(t, logrus.InfoLevel, hook.LastEntry().Level)
+ assert.True(t, strings.Contains(hook.LastEntry().Message, "method=POST"))
+ assert.True(t, strings.Contains(hook.LastEntry().Message, "Internal API error"))
})
}
diff --git a/internal/logger/logger.go b/internal/logger/logger.go
index f1db4b0..f9cf734 100644
--- a/internal/logger/logger.go
+++ b/internal/logger/logger.go
@@ -3,10 +3,13 @@ package logger
import (
"fmt"
"io"
+ "io/ioutil"
golog "log"
"log/syslog"
+ "math"
"os"
"sync"
+ "time"
"gitlab.com/gitlab-org/gitlab-shell/internal/config"
@@ -26,13 +29,19 @@ func Configure(cfg *config.Config) error {
defer mutex.Unlock()
pid = os.Getpid()
+ ProgName, _ = os.Executable()
- var err error
- logWriter, err = os.OpenFile(cfg.LogFile, os.O_WRONLY|os.O_APPEND, 0)
+ // Avoid leaking output if we can't set up the logging output
+ log.SetOutput(ioutil.Discard)
+
+ output, err := os.OpenFile(cfg.LogFile, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0644)
if err != nil {
+ setupBootstrapLogger()
+ logPrint("Unable to configure logging", err)
return err
}
+ logWriter = output
log.SetOutput(logWriter)
if cfg.LogFormat == "json" {
log.SetFormatter(&log.JSONFormatter{})
@@ -41,12 +50,14 @@ func Configure(cfg *config.Config) error {
return nil
}
+// If our log file is not available we want to log somewhere else, but
+// not to standard error because that leaks information to the user. This
+// function attempts to log to syslog.
func logPrint(msg string, err error) {
- mutex.Lock()
- defer mutex.Unlock()
-
if logWriter == nil {
- bootstrapLogPrint(msg, err)
+ if bootstrapLogger != nil {
+ bootstrapLogger.Print(ProgName+":", msg+":", err)
+ }
return
}
@@ -56,6 +67,10 @@ func logPrint(msg string, err error) {
}
func Fatal(msg string, err error) {
+ mutex.Lock()
+ defer mutex.Unlock()
+ setupBootstrapLogger()
+
logPrint(msg, err)
// We don't show the error to the end user because it can leak
// information that is private to the GitLab server.
@@ -63,20 +78,23 @@ func Fatal(msg string, err error) {
os.Exit(1)
}
-// If our log file is not available we want to log somewhere else, but
-// not to standard error because that leaks information to the user. This
-// function attempts to log to syslog.
-//
// We assume the logging mutex is already locked.
-func bootstrapLogPrint(msg string, err error) {
+func setupBootstrapLogger() {
if bootstrapLogger == nil {
- var err error
- bootstrapLogger, err = syslog.NewLogger(syslog.LOG_ERR|syslog.LOG_USER, 0)
- if err != nil {
- // The message will not be logged.
- return
- }
+ bootstrapLogger, _ = syslog.NewLogger(syslog.LOG_ERR|syslog.LOG_USER, 0)
}
+}
+
+func ElapsedTime(since time.Time) float64 {
+ // Later versions of Go support Milliseconds directly:
+ // https://go-review.googlesource.com/c/go/+/167387/
+ return roundFloat(time.Since(since).Seconds() * 1e3)
+}
+
+func roundFloat(x float64) float64 {
+ return round(x, 0.001)
+}
- bootstrapLogger.Print(ProgName+":", msg+":", err)
+func round(x, unit float64) float64 {
+ return math.Round(x/unit) * unit
}
diff --git a/internal/logger/logger_test.go b/internal/logger/logger_test.go
new file mode 100644
index 0000000..e14d01c
--- /dev/null
+++ b/internal/logger/logger_test.go
@@ -0,0 +1,42 @@
+package logger
+
+import (
+ "io/ioutil"
+ "os"
+ "strings"
+ "testing"
+ "time"
+
+ log "github.com/sirupsen/logrus"
+ "github.com/stretchr/testify/require"
+ "gitlab.com/gitlab-org/gitlab-shell/internal/config"
+)
+
+func TestConfigure(t *testing.T) {
+ tmpFile, err := ioutil.TempFile(os.TempDir(), "logtest-")
+ require.NoError(t, err)
+ defer tmpFile.Close()
+
+ config := config.Config{
+ LogFile: tmpFile.Name(),
+ LogFormat: "json",
+ }
+
+ err = Configure(&config)
+
+ require.NoError(t, err)
+
+ log.Info("this is a test")
+
+ tmpFile.Close()
+
+ data, err := ioutil.ReadFile(tmpFile.Name())
+ require.NoError(t, err)
+ require.True(t, strings.Contains(string(data), `msg":"this is a test"`))
+}
+
+func TestElapsedTime(t *testing.T) {
+ start := time.Now()
+ start = start.Add(1234567800 * time.Nanosecond)
+ require.InDelta(t, -1234.568, ElapsedTime(start), 0.01)
+}
diff --git a/internal/testhelper/testhelper.go b/internal/testhelper/testhelper.go
index a925c79..da781ce 100644
--- a/internal/testhelper/testhelper.go
+++ b/internal/testhelper/testhelper.go
@@ -8,6 +8,8 @@ import (
"runtime"
"github.com/otiai10/copy"
+ "github.com/sirupsen/logrus"
+ "github.com/sirupsen/logrus/hooks/test"
)
var (
@@ -91,3 +93,10 @@ func Setenv(key, value string) (func(), error) {
err := os.Setenv(key, value)
return func() { os.Setenv(key, oldValue) }, err
}
+
+func SetupLogger() *test.Hook {
+ logger, hook := test.NewNullLogger()
+ logrus.SetOutput(logger.Writer())
+
+ return hook
+}
diff --git a/spec/support/gitlab_shell_setup.rb b/spec/support/gitlab_shell_setup.rb
index dccafb3..6982aaa 100644
--- a/spec/support/gitlab_shell_setup.rb
+++ b/spec/support/gitlab_shell_setup.rb
@@ -1,4 +1,5 @@
require 'yaml'
+require 'tempfile'
RSpec.shared_context 'gitlab shell', shared_context: :metadata do
def original_root_path
@@ -10,6 +11,8 @@ RSpec.shared_context 'gitlab shell', shared_context: :metadata do
end
def write_config(config)
+ config['log_file'] ||= Tempfile.new.path
+
File.open(config_path, 'w') do |f|
f.write(config.to_yaml)
end
View Lorry Controller Status