diff --git a/cmd/aro/main.go b/cmd/aro/main.go index 6d87f4c3080..691ea14d026 100644 --- a/cmd/aro/main.go +++ b/cmd/aro/main.go @@ -18,6 +18,7 @@ import ( utillog "github.com/Azure/ARO-RP/pkg/util/log" _ "github.com/Azure/ARO-RP/pkg/util/scheme" "github.com/Azure/ARO-RP/pkg/util/version" + "k8s.io/klog/v2" ) func usage() { @@ -36,9 +37,11 @@ func usage() { func main() { rand.Seed(time.Now().UnixNano()) + klog.InitFlags(nil) flag.Usage = usage flag.Parse() + klog.V(10).Info("Logging enabled.") ctx := context.Background() audit := utillog.GetAuditEntry() diff --git a/hack/db/db.go b/hack/db/db.go index 9aad937f583..0ff2959f814 100644 --- a/hack/db/db.go +++ b/hack/db/db.go @@ -7,6 +7,8 @@ import ( "context" "encoding/json" "fmt" + "net/http" + "net/http/httptrace" "os" "strings" @@ -28,18 +30,113 @@ const ( KeyVaultPrefix = "KEYVAULT_PREFIX" ) +var logger = utillog.GetLogger() + +type transport struct { + current *http.Request +} + +func (t *transport) WroteRequest(wri httptrace.WroteRequestInfo) { + log := logger.WithField("wri", wri).WithError(wri.Err).WithField("t", t) + log.Infof("WroteRequest") +} + +func (t *transport) RoundTrip(req *http.Request) (*http.Response, error) { + log := logger.WithField("t", t) + t.current = req + log.Infof("RoundTrip start") + fmt.Fprintf(os.Stderr, "%s %s %s\n", req.Method, req.URL, req.Proto) + for k, v := range req.Header { + for x, vv := range v { + if x > 0 { + k = strings.Repeat(" ", len(k)) + } + fmt.Fprintf(os.Stderr, "%s: %s\n", k, vv) + } + } + fmt.Fprintf(os.Stderr, "---\n%s\n---\n", req.Body) + resp, err := http.DefaultTransport.RoundTrip(req) + log.WithError(err).Infof("RoundTrip stop") + if resp != nil { + fmt.Fprintf(os.Stderr, "%d.%d %s\n", resp.ProtoMajor, resp.ProtoMinor, resp.Status) + for k, v := range resp.Header { + for x, vv := range v { + if x > 0 { + k = strings.Repeat(" ", len(k)) + } + fmt.Fprintf(os.Stderr, "%s: %s\n", k, vv) + } + } + fmt.Fprintf(os.Stderr, "---\n%s\n---\n", resp.Body) + } + return resp, err +} + +// GotConn prints whether the connection has been used previously +// for the current request. +func (t *transport) GotConn(info httptrace.GotConnInfo) { + log := logger.WithFields(logrus.Fields{ + "idle": info.IdleTime, + "reused": info.Reused, + "wasidle": info.WasIdle, + "localaddr": info.Conn.LocalAddr(), + "remoteaddr": info.Conn.RemoteAddr(), + "transport": t, + }) + log.Infof("Connection reused") +} + +func newTrace(ctx context.Context) context.Context { + t := &transport{} + log := logger.WithContext(ctx) + + trace := &httptrace.ClientTrace{ + GotConn: t.GotConn, + WroteRequest: t.WroteRequest, + GotFirstResponseByte: func() { + log.Infoln("GotFirstResponseByte") + }, + DNSStart: func(di httptrace.DNSStartInfo) { + log.WithField("host", di.Host).Infof("DNSStart") + }, + DNSDone: func(di httptrace.DNSDoneInfo) { + log.WithError(di.Err).WithField("coalesced", di.Coalesced).WithField("addrs", di.Addrs).Infof("DNSDone") + }, + // WroteHeaderField: func(key string, value []string) { + // log.WithField("key", key).WithField("value", value).Infof("WroteHeaderField") + // }, + // WroteHeaders: func() { + // log.Info("WroteHeaders") + // }, + ConnectStart: func(network, addr string) { + log.WithField("network", network).WithField("addr", addr).Info("ConnectStart") + }, + ConnectDone: func(network, addr string, err error) { + log.WithField("network", network).WithField("addr", addr).WithError(err).Info("ConnectDone") + }, + } + ctx = httptrace.WithClientTrace(ctx, trace) + return ctx +} + func run(ctx context.Context, log *logrus.Entry) error { if len(os.Args) != 2 { return fmt.Errorf("usage: %s resourceid", os.Args[0]) } + t := &transport{} + + ctx = newTrace(ctx) + _env, err := env.NewCore(ctx, log) if err != nil { + log.WithError(err).WithContext(ctx).WithField("fn", "env.NewCore").WithField("resourceid", os.Args[1]).Error("Failed to create environment") return err } tokenCredential, err := azidentity.NewAzureCLICredential(nil) if err != nil { + log.WithError(err).WithContext(ctx).WithField("fn", "azidentity.NewAzureCLICredential").WithField("resourceid", os.Args[1]).Error("Failed to create token credential") return err } @@ -48,10 +145,12 @@ func run(ctx context.Context, log *logrus.Entry) error { msiKVAuthorizer, err := _env.NewMSIAuthorizer(env.MSIContextRP, _env.Environment().KeyVaultScope) if err != nil { + log.WithError(err).WithContext(ctx).WithField("fn", "_env.NewMSIAuthorizer").WithField("resourceid", os.Args[1]).Error("Failed to create MSI authorizer") return err } if err := env.ValidateVars(KeyVaultPrefix); err != nil { + log.WithError(err).WithContext(ctx).WithField("fn", "keyvault.URI").WithField("resourceid", os.Args[1]).Error("Failed to create keyvault client") return err } keyVaultPrefix := os.Getenv(KeyVaultPrefix) @@ -60,6 +159,7 @@ func run(ctx context.Context, log *logrus.Entry) error { aead, err := encryption.NewMulti(ctx, serviceKeyvault, env.EncryptionSecretV2Name, env.EncryptionSecretName) if err != nil { + log.WithError(err).WithContext(ctx).WithField("fn", "encryption.NewMulti").WithField("resourceid", os.Args[1]).Error("Failed to create AEAD") return err } @@ -70,11 +170,13 @@ func run(ctx context.Context, log *logrus.Entry) error { dbAccountName := os.Getenv(DatabaseAccountName) dbAuthorizer, err := database.NewMasterKeyAuthorizer(ctx, _env, authorizer, dbAccountName) if err != nil { + log.WithError(err).WithContext(ctx).WithField("fn", "database.NewMasterKeyAuthorizer").WithField("resourceid", os.Args[1]).Error("Failed to create master key authorizer") return err } - dbc, err := database.NewDatabaseClient(log.WithField("component", "database"), _env, dbAuthorizer, &noop.Noop{}, aead, dbAccountName) + dbc, err := database.NewDatabaseClientWithTransport(log.WithField("component", "database"), _env, dbAuthorizer, &noop.Noop{}, aead, dbAccountName, t) if err != nil { + log.WithError(err).WithContext(ctx).WithField("fn", "database.NewDatabaseClient").WithField("resourceid", os.Args[1]).Error("Failed to create database client") return err } @@ -85,11 +187,13 @@ func run(ctx context.Context, log *logrus.Entry) error { openShiftClusters, err := database.NewOpenShiftClusters(ctx, dbc, dbName) if err != nil { + log.WithError(err).WithContext(ctx).WithField("fn", "database.NewOpenShiftClusters").WithField("resourceid", os.Args[1]).Error("Failed to connect to database") return err } doc, err := openShiftClusters.Get(ctx, strings.ToLower(os.Args[1])) if err != nil { + log.WithError(err).WithContext(ctx).WithField("fn", "openShiftClusters.Get").WithField("resourceid", os.Args[1]).Error("Failed to get cluster") return err } diff --git a/pkg/database/database.go b/pkg/database/database.go index 6233b7460c3..383b532a2ab 100644 --- a/pkg/database/database.go +++ b/pkg/database/database.go @@ -6,7 +6,9 @@ package database import ( "context" "crypto/tls" + "fmt" "net/http" + "os" "reflect" "time" @@ -53,7 +55,29 @@ func NewDatabaseClient(log *logrus.Entry, _env env.Core, authorizer cosmosdb.Aut return cosmosdb.NewDatabaseClient(log, c, h, databaseAccountName+"."+_env.Environment().CosmosDBDNSSuffix, authorizer), nil } +func NewDatabaseClientWithTransport(log *logrus.Entry, _env env.Core, authorizer cosmosdb.Authorizer, m metrics.Emitter, aead encryption.AEAD, databaseAccountName string, transport http.RoundTripper) (cosmosdb.DatabaseClient, error) { + h, err := NewJSONHandle(aead) + if err != nil { + return nil, err + } + + c := &http.Client{ + Transport: transport, + Timeout: 30 * time.Second, + } + + return cosmosdb.NewDatabaseClient(log, c, h, databaseAccountName+"."+_env.Environment().CosmosDBDNSSuffix, authorizer), nil +} + func NewMasterKeyAuthorizer(ctx context.Context, _env env.Core, msiAuthorizer autorest.Authorizer, databaseAccountName string) (cosmosdb.Authorizer, error) { + for _, key := range []string{ + "DATABASE_ACCOUNT_NAME", + } { + if _, found := os.LookupEnv(key); !found { + return nil, fmt.Errorf("environment variable %q unset", key) + } + } + databaseaccounts := documentdb.NewDatabaseAccountsClient(_env.Environment(), _env.SubscriptionID(), msiAuthorizer) keys, err := databaseaccounts.ListKeys(ctx, _env.ResourceGroup(), databaseAccountName) diff --git a/pkg/database/openshiftclusters.go b/pkg/database/openshiftclusters.go index e3cf392e408..60eba10eb4a 100644 --- a/pkg/database/openshiftclusters.go +++ b/pkg/database/openshiftclusters.go @@ -148,7 +148,7 @@ func (c *openShiftClusters) Get(ctx context.Context, key string) (*api.OpenShift case len(docs.OpenShiftClusterDocuments) == 1: return docs.OpenShiftClusterDocuments[0], nil default: - return nil, &cosmosdb.Error{StatusCode: http.StatusNotFound} + return nil, &cosmosdb.Error{StatusCode: http.StatusNotFound, Message: "No cluster documents found"} } }