Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

CONSOLE-1523: Switch logging to klog #1862

Merged
merged 1 commit into from
Oct 23, 2020
Merged

CONSOLE-1523: Switch logging to klog #1862

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
64 changes: 27 additions & 37 deletions cmd/bridge/main.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -14,20 +14,16 @@ import (
"os"
"strings"

"github.com/coreos/pkg/capnslog"
"github.com/coreos/pkg/flagutil"

"github.com/openshift/console/pkg/auth"
"github.com/openshift/console/pkg/bridge"
"github.com/openshift/console/pkg/knative"
"github.com/openshift/console/pkg/proxy"
"github.com/openshift/console/pkg/server"
"github.com/openshift/console/pkg/serverconfig"
oscrypto "github.com/openshift/library-go/pkg/crypto"
)

var (
zherman0 marked this conversation as resolved.
Show resolved Hide resolved
log = capnslog.NewPackageLogger("github.com/openshift/console", "cmd/main")
"k8s.io/klog"
)

const (
Expand Down Expand Up @@ -61,10 +57,10 @@ const (
)

func main() {
rl := capnslog.MustRepoLogger("github.com/openshift/console")
capnslog.SetFormatter(capnslog.NewStringFormatter(os.Stderr))

fs := flag.NewFlagSet("bridge", flag.ExitOnError)
klog.InitFlags(fs)
defer klog.Flush()

fListen := fs.String("listen", "http://0.0.0.0:9000", "")

fBaseAddress := fs.String("base-address", "", "Format: <http | https>://domainOrIPAddress[:port]. Example: https://openshift.example.com.")
Expand Down Expand Up @@ -137,7 +133,7 @@ func main() {

if *fConfig != "" {
if err := serverconfig.SetFlagsFromConfig(fs, *fConfig); err != nil {
log.Fatalf("Failed to load config: %v", err)
klog.Fatalf("Failed to load config: %v", err)
}
}

Expand Down Expand Up @@ -207,18 +203,18 @@ func main() {

if *fCustomLogoFile != "" {
if _, err := os.Stat(*fCustomLogoFile); err != nil {
log.Fatalf("could not read logo file: %v", err)
klog.Fatalf("could not read logo file: %v", err)
}
}

if *fInactivityTimeout < 300 {
log.Warning("Flag inactivity-timeout is set to less then 300 seconds and will be ignored!")
klog.Warning("Flag inactivity-timeout is set to less then 300 seconds and will be ignored!")
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@zherman0 For changes from log to klog, when viewing console logs, how can we differentiate them?
On a 4.6 cluster, I see console log is showing:

2020-10-19T23:47:06Z cmd/main: Flag inactivity-timeout is set to less then 300 seconds and will be ignored!

While on a cluster with changes in this PR, it shows:

sh-4.4$ /opt/bridge/bin/bridge --log-level 5
W1020 05:55:37.303295      25 main.go:211] Flag inactivity-timeout is set to less then 300 seconds and will be ignored!
W1020 05:55:37.303578      25 main.go:254] DEPRECATED: --log-level is now deprecated, use verbosity flag --v=Level instead

How can I know Flag inactivity-timeout is set to less then 300 seconds and will be ignored! is printed with klog?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@yapei not sure why we need to differentiate between them?

How can I know Flag inactivity-timeout is set to less then 300 seconds and will be ignored! is printed with klog?

Since we will be using just klog for the backend logging we dont need to differentiate between anything.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agreed, not sure why you need to tell the difference, but the new klog stuff shows the file name and line number main.go:211 if that helps.

Copy link
Contributor

@yapei yapei Oct 21, 2020 •
edited

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, the line number tells the truth @zherman0
When verifying the bug Logging is broken due to mix of k8s.io/klog v1 and v2 we need to confirm whether klog v2 is used. So I thought for this PR we may have same verification process which means I need to confirm klog is used instead of old logging. That's' my thought but maybe I'm wrong @jhadvig @zherman0

Copy link
Member

@jhadvig jhadvig Oct 21, 2020 •
edited

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@yapei @spadgett @zherman0 just one thing to notice here. The console backend will be using the klog/v1 since we need to update helm pkg if we want to use the klog/v2. On the other hand the console-operator moved by this PR to using the klog/v2. This should not do any harm since those are two different binaries.
Just want to point out the difference here and also think out loud about the upgrading to klog/v2 for the console backend binary.

The issue with the helm is that the release we are using (and the latest as well) is using k8s 1.18.0 pkgs version. In order not to have import collisions they need to be on the 1.19.2., which their master is on currently , they just need to release it.

} else {
if *fK8sAuth != "oidc" && *fK8sAuth != "openshift" {
fmt.Fprintln(os.Stderr, "In order activate the user inactivity timout, flag --user-auth must be one of: oidc, openshift")
os.Exit(1)
}
log.Infof("Setting user inactivity timout to %d seconds", *fInactivityTimeout)
klog.Infof("Setting user inactivity timout to %d seconds", *fInactivityTimeout)
}

srv := &server.Server{
Expand Down Expand Up @@ -254,14 +250,8 @@ func main() {
os.Exit(1)
}

capnslog.SetGlobalLogLevel(capnslog.INFO)
if *fLogLevel != "" {
llc, err := rl.ParseLogLevelConfig(*fLogLevel)
if err != nil {
log.Fatal(err)
}
rl.SetLogLevel(llc)
log.Infof("Setting log level to %s", *fLogLevel)
klog.Warningf("DEPRECATED: --log-level is now deprecated, use verbosity flag --v=Level instead")
}

var (
Expand All @@ -277,17 +267,17 @@ func main() {
var err error

if srv.DexClient, err = auth.NewDexClient(*fDexAPIHost, *fDexClientCAFile, *fDexClientCertFile, *fDexClientKeyFile); err != nil {
log.Fatalf("Failed to create a Dex API client: %v", err)
klog.Fatalf("Failed to create a Dex API client: %v", err)
}
}

var secureCookies bool
if baseURL.Scheme == "https" {
secureCookies = true
log.Info("cookies are secure!")
klog.Info("cookies are secure!")
zherman0 marked this conversation as resolved.
Show resolved Hide resolved
} else {
secureCookies = false
log.Warning("cookies are not secure because base-address is not https!")
klog.Warning("cookies are not secure because base-address is not https!")
}

var k8sEndpoint *url.URL
Expand All @@ -298,19 +288,19 @@ func main() {
var err error
k8sCertPEM, err = ioutil.ReadFile(k8sInClusterCA)
if err != nil {
log.Fatalf("Error inferring Kubernetes config from environment: %v", err)
klog.Fatalf("Error inferring Kubernetes config from environment: %v", err)
}
rootCAs := x509.NewCertPool()
if !rootCAs.AppendCertsFromPEM(k8sCertPEM) {
log.Fatalf("No CA found for the API server")
klog.Fatal("No CA found for the API server")
}
tlsConfig := oscrypto.SecureTLSConfig(&tls.Config{
RootCAs: rootCAs,
})

bearerToken, err := ioutil.ReadFile(k8sInClusterBearerToken)
if err != nil {
log.Fatalf("failed to read bearer token: %v", err)
klog.Fatalf("failed to read bearer token: %v", err)
}

srv.K8sProxyConfig = &proxy.Config{
Expand All @@ -325,11 +315,11 @@ func main() {
if *fServiceCAFile != "" {
serviceCertPEM, err := ioutil.ReadFile(*fServiceCAFile)
if err != nil {
log.Fatalf("failed to read service-ca.crt file: %v", err)
klog.Fatalf("failed to read service-ca.crt file: %v", err)
}
serviceProxyRootCAs := x509.NewCertPool()
if !serviceProxyRootCAs.AppendCertsFromPEM(serviceCertPEM) {
log.Fatalf("no CA found for Kubernetes services")
klog.Fatal("no CA found for Kubernetes services")
}
serviceProxyTLSConfig := oscrypto.SecureTLSConfig(&tls.Config{
RootCAs: serviceProxyRootCAs,
Expand Down Expand Up @@ -502,7 +492,7 @@ func main() {
if *fUserAuthOIDCClientSecretFile != "" {
buf, err := ioutil.ReadFile(*fUserAuthOIDCClientSecretFile)
if err != nil {
log.Fatalf("Failed to read client secret file: %v", err)
klog.Fatalf("Failed to read client secret file: %v", err)
}
oidcClientSecret = string(buf)
}
Expand Down Expand Up @@ -545,10 +535,10 @@ func main() {
}

if srv.Auther, err = auth.NewAuthenticator(context.Background(), oidcClientConfig); err != nil {
log.Fatalf("Error initializing authenticator: %v", err)
klog.Fatalf("Error initializing authenticator: %v", err)
}
case "disabled":
log.Warningf("running with AUTHENTICATION DISABLED!")
klog.Warning("running with AUTHENTICATION DISABLED!")
default:
bridge.FlagFatalf("user-auth", "must be one of: oidc, openshift, disabled")
}
Expand Down Expand Up @@ -660,17 +650,17 @@ func main() {
http.Redirect(res, req, redirectURL.String(), http.StatusMovedPermanently)
})
redirectPort := fmt.Sprintf(":%d", *fRedirectPort)
log.Infof("Listening on %q for custom hostname redirect...", redirectPort)
log.Fatal(http.ListenAndServe(redirectPort, redirectServer))
klog.Infof("Listening on %q for custom hostname redirect...", redirectPort)
klog.Fatal(http.ListenAndServe(redirectPort, redirectServer))
}()
}

log.Infof("Binding to %s...", httpsrv.Addr)
klog.Infof("Binding to %s...", httpsrv.Addr)
if listenURL.Scheme == "https" {
log.Info("using TLS")
log.Fatal(httpsrv.ListenAndServeTLS(*fTlSCertFile, *fTlSKeyFile))
klog.Info("using TLS")
klog.Fatal(httpsrv.ListenAndServeTLS(*fTlSCertFile, *fTlSKeyFile))
} else {
log.Info("not using TLS")
log.Fatal(httpsrv.ListenAndServe())
klog.Info("not using TLS")
klog.Fatal(httpsrv.ListenAndServe())
}
}
31 changes: 15 additions & 16 deletions pkg/auth/auth.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,13 +18,14 @@ import (

"github.com/coreos/dex/api"
oidc "github.com/coreos/go-oidc"
"github.com/coreos/pkg/capnslog"
"golang.org/x/oauth2"

"google.golang.org/grpc"
"google.golang.org/grpc/credentials"

oscrypto "github.com/openshift/library-go/pkg/crypto"

"k8s.io/klog"
)

const (
Expand All @@ -42,8 +43,6 @@ const (
)

var (
log = capnslog.NewPackageLogger("github.com/openshift/console", "auth")
zherman0 marked this conversation as resolved.
Show resolved Hide resolved

// Cache HTTP clients to avoid recreating them for each request to the
// OAuth server. The key is the ca.crt bytes cast to a string and the
// value is a pointer to the http.Client. Keep two maps: one that
Expand Down Expand Up @@ -137,7 +136,7 @@ func newHTTPClient(issuerCA string, includeSystemRoots bool) (*http.Client, erro
}
certPool, err = x509.SystemCertPool()
if err != nil {
log.Errorf("error copying system cert pool: %v", err)
klog.Errorf("error copying system cert pool: %v", err)
certPool = x509.NewCertPool()
}
} else {
Expand Down Expand Up @@ -229,11 +228,11 @@ func NewAuthenticator(ctx context.Context, c *Config) (*Authenticator, error) {
if err != nil {
steps++
if steps > maxSteps {
log.Errorf("error contacting auth provider: %v", err)
klog.Errorf("error contacting auth provider: %v", err)
return nil, err
}

log.Errorf("error contacting auth provider (retrying in %s): %v", backoff, err)
klog.Errorf("error contacting auth provider (retrying in %s): %v", backoff, err)

time.Sleep(backoff)
continue
Expand All @@ -251,7 +250,7 @@ func NewAuthenticator(ctx context.Context, c *Config) (*Authenticator, error) {

currentEndpoint, currentLoginMethod, errAuthSource := authSourceFunc()
if errAuthSource != nil {
log.Errorf("failed to get latest auth source data: %v", errAuthSource)
klog.Errorf("failed to get latest auth source data: %v", errAuthSource)
return &baseOAuth2Config, fallbackLoginMethod
}

Expand All @@ -273,7 +272,7 @@ func newUnstartedAuthenticator(c *Config) (*Authenticator, error) {
clientFunc := func() *http.Client {
currentClient, err := newHTTPClient(c.IssuerCA, true)
if err != nil {
log.Errorf("failed to get latest http client: %v", err)
klog.Errorf("failed to get latest http client: %v", err)
return fallbackClient
}
return currentClient
Expand Down Expand Up @@ -358,7 +357,7 @@ func (a *Authenticator) CallbackFunc(fn func(loginInfo LoginJSON, successURL str

cookieState, err := r.Cookie(stateCookieName)
if err != nil {
log.Errorf("failed to parse state cookie: %v", err)
klog.Errorf("failed to parse state cookie: %v", err)
a.redirectAuthError(w, errorMissingState)
return
}
Expand All @@ -370,33 +369,33 @@ func (a *Authenticator) CallbackFunc(fn func(loginInfo LoginJSON, successURL str
}

if code == "" {
log.Infof("missing auth code in query param")
klog.Info("missing auth code in query param")
a.redirectAuthError(w, errorMissingCode)
return
}

if urlState != cookieState.Value {
log.Errorf("State in url does not match State cookie")
klog.Error("State in url does not match State cookie")
a.redirectAuthError(w, errorInvalidState)
return
}
ctx := oidc.ClientContext(context.TODO(), a.clientFunc())
oauthConfig, lm := a.authFunc()
token, err := oauthConfig.Exchange(ctx, code)
if err != nil {
log.Infof("unable to verify auth code with issuer: %v", err)
klog.Infof("unable to verify auth code with issuer: %v", err)
a.redirectAuthError(w, errorInvalidCode)
return
}

ls, err := lm.login(w, token)
if err != nil {
log.Errorf("error constructing login state: %v", err)
klog.Errorf("error constructing login state: %v", err)
a.redirectAuthError(w, errorInternal)
return
}

log.Infof("oauth success, redirecting to: %q", a.successURL)
klog.Infof("oauth success, redirecting to: %q", a.successURL)
fn(ls.toLoginJSON(), a.successURL, w)
}
}
Expand Down Expand Up @@ -502,12 +501,12 @@ func NewDexClient(hostAndPort string, caCrt, clientCrt, clientKey string) (api.D
var err error

if caPEM, err = ioutil.ReadFile(caCrt); err != nil {
log.Fatalf("Failed to read cert file: %v", err)
klog.Fatalf("Failed to read cert file: %v", err)
}

certPool = x509.NewCertPool()
if !certPool.AppendCertsFromPEM(caPEM) {
log.Fatalf("No certs found in %q", caCrt)
klog.Fatalf("No certs found in %q", caCrt)
}
}

Expand Down
10 changes: 6 additions & 4 deletions pkg/auth/session.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,8 @@ import (
"fmt"
"sync"
"time"

"k8s.io/klog"
)

const openshiftSessionCookieName = "openshift-session-token"
Expand Down Expand Up @@ -62,7 +64,7 @@ func (ss *SessionStore) deleteSession(token string) error {
return nil
}
}
log.Errorf("ss.byAge did not contain session %v", token)
klog.Errorf("ss.byAge did not contain session %v", token)
return fmt.Errorf("ss.byAge did not contain session %v", token)
}

Expand All @@ -78,17 +80,17 @@ func (ss *SessionStore) pruneSessions() {
expired++
}
}
log.Debugf("Pruned %v expired sessions.", expired)
klog.V(4).Infof("Pruned %v expired sessions.", expired)
zherman0 marked this conversation as resolved.
Show resolved Hide resolved
toRemove := len(ss.byAge) - ss.maxSessions
if toRemove > 0 {
log.Debugf("Still too many sessions. Pruning oldest %v sessions...", toRemove)
klog.V(4).Infof("Still too many sessions. Pruning oldest %v sessions...", toRemove)
// TODO: account for user ids when pruning old sessions. Otherwise one user could log in 16k times and boot out everyone else.
for _, s := range ss.byAge[:toRemove] {
delete(ss.byToken, s.token)
}
ss.byAge = ss.byAge[toRemove:]
}
if expired+toRemove > 0 {
log.Debugf("Pruned %v old sessions.", expired+toRemove)
klog.V(4).Infof("Pruned %v old sessions.", expired+toRemove)
}
}
7 changes: 2 additions & 5 deletions pkg/bridge/validate.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,12 +2,9 @@ package bridge

import (
"fmt"
"github.com/coreos/pkg/capnslog"
"net/url"
)

var (
plog = capnslog.NewPackageLogger("github.com/openshift/console", "bridge")
zherman0 marked this conversation as resolved.
Show resolved Hide resolved
"k8s.io/klog"
)

func ValidateFlagNotEmpty(name string, value string) string {
Expand Down Expand Up @@ -50,5 +47,5 @@ func ValidateFlagIs(name string, value string, expectedValues ...string) string
}

func FlagFatalf(name string, format string, a ...interface{}) {
plog.Fatalf("Invalid flag: %s, error: %s", name, fmt.Sprintf(format, a...))
klog.Fatalf("Invalid flag: %s, error: %s", name, fmt.Sprintf(format, a...))
}