Assorted cleanup

Fixes some logging issues, reducing the number of lines logged per query
and supressing some queries that were not respecting the suppress rules.

Fixes a datarace in our mocks that rarely happens.

It also adds some additional locking around BounceDatabase to avoid
running queries when we know the database is transitioning between
start/stop.

Updates kubebuilder-tools to k8s 1.24 to match our k8s library versions.
This also requires a fix for exiting our controllers before shutting
down the testenv.

Change-Id: Ia532f974d442d0925f9b2fd2a20c9956bf36afaa

WORKSPACE

@@ -133,9 +133,9 @@ filegroup(
     srcs = glob(["**"]),
     visibility = ["//visibility:public"],
 )""",
-    sha256 = "fb13a93a800389029b06fcc74ab6a3b969ff74178252709a040e4756251739d2",
+    sha256 = "6d9f0a6ab0119c5060799b4b8cbd0a030562da70b7ad4125c218eaf028c6cc28",
     strip_prefix = "kubebuilder",
-    urls = ["https://storage.googleapis.com/kubebuilder-tools/kubebuilder-tools-1.19.2-linux-amd64.tar.gz"],
+    urls = ["https://storage.googleapis.com/kubebuilder-tools/kubebuilder-tools-1.24.2-linux-amd64.tar.gz"],
 )
 
 http_archive(

oracle/cmd/logging/logging_main.go

@@ -232,7 +232,7 @@ func queryDB(ctx context.Context, query string) (string, error) {
 	}
 	defer closeConn()
 
-	resp, err := dbdClient.RunSQLPlusFormatted(ctx, &dbdpb.RunSQLPlusCMDRequest{Commands: []string{query}, Suppress: true, Quiet: true})
+	resp, err := dbdClient.RunSQLPlusFormatted(ctx, &dbdpb.RunSQLPlusCMDRequest{Commands: []string{query}, Suppress: false, Quiet: true})
 	if err != nil {
 		return "", err
 	}

oracle/controllers/testhelpers/envtest.go

@@ -181,6 +181,12 @@ func RunFunctionalTestSuiteWithWebhooks(
 		testEnv.BinaryAssetsDirectory = filepath.Join(runfiles, "external/kubebuilder_tools/bin")
 	}
 
+	// k8s 1.21 introduced graceful shutdown so testEnv wont shutdown if we
+	// keep a connection open. By using a context with cancel we can
+	// shutdown our managers before we try to shutdown the testEnv and
+	// ensure no hanging connections keep the apiserver from stopping.
+	mgrCtx, mgrCancel := context.WithCancel(ctrl.SetupSignalHandler())
+
 	BeforeSuite(func(done Done) {
 		testEnvLock.Lock()
 		defer testEnvLock.Unlock()
@@ -246,7 +252,7 @@ func RunFunctionalTestSuiteWithWebhooks(
 
 		go func() {
 			defer GinkgoRecover()
-			err = (*k8sManager).Start(ctrl.SetupSignalHandler())
+			err = (*k8sManager).Start(mgrCtx)
 			Expect(err).ToNot(HaveOccurred())
 		}()
 
@@ -272,6 +278,7 @@ func RunFunctionalTestSuiteWithWebhooks(
 		testEnvLock.Lock()
 		defer testEnvLock.Unlock()
 		By("Stopping control plane")
+		mgrCancel()
 		Expect(testEnv.Stop()).To(Succeed())
 	})
 

oracle/controllers/testhelpers/grpcmocks.go

@@ -515,6 +515,8 @@ func (cli *FakeDatabaseClient) RemoveMethodToError(method string) {
 }
 
 func (cli *FakeDatabaseClient) getMethodRespErr(method string) (interface{}, error) {
+	cli.lock.Lock()
+	defer cli.lock.Unlock()
 	var err error
 	var resp interface{}
 	if cli.methodToResp != nil {

oracle/pkg/database/dbdaemon/dbdaemon_server.go

@@ -479,7 +479,9 @@ func (s *Server) stageAndCatalog(ctx context.Context, req *dbdpb.PhysicalRestore
 func (s *Server) PhysicalRestoreAsync(ctx context.Context, req *dbdpb.PhysicalRestoreAsyncRequest) (*lropb.Operation, error) {
 	job, err := lro.CreateAndRunLROJobWithID(ctx, req.GetLroInput().GetOperationId(), "PhysicalRestore", s.lroServer,
 		func(ctx context.Context) (proto.Message, error) {
-			return s.physicalRestore(ctx, req.SyncRequest)
+			msg, err := s.physicalRestore(ctx, req.SyncRequest)
+			klog.InfoS("Physical restore completed", "err", err)
+			return msg, err
 		})
 
 	if err != nil {
@@ -723,25 +725,25 @@ func open(ctx context.Context, dbURL string, prelim bool) (oracleDatabase, error
 	if err == nil {
 		// Force a connection with Ping.
 		err = db.Ping()
-		if err != nil {
-			// Connection pool opened but ping failed, close this pool.
-			if err := db.Close(); err != nil {
-				klog.Warningf("failed to close db connection: %v", err)
-			}
+		if err == nil {
+			return db, nil
+		}
+		// Connection pool opened but ping failed, close this pool.
+		if errC := db.Close(); errC != nil {
+			klog.Warningf("failed to close db connection: %v", errC)
 		}
 	}
 
-	if err != nil {
+	if !prelim {
 		klog.ErrorS(err, "dbdaemon/open: newDB failed", "prelim", prelim)
-		if prelim {
-			// If a prelim connection is requested (e.g. for creating
-			// an spfile, also enable DBMS_OUTPUT.
-			db, err = newDB("godror", dbURL+"&prelim=1")
-		}
+		return nil, err
 	}
 
+	// If a prelim connection is requested (e.g. for creating
+	// an spfile) retry with prelim argument.
+	db, err = newDB("godror", dbURL+"&prelim=1")
 	if err != nil {
-		klog.ErrorS(err, "dbdaemon/open: newDB failed", "prelim", prelim)
+		klog.ErrorS(err, "dbdaemon/open: newDB failed prelim retry", "prelim", prelim)
 		return nil, err
 	}
 
@@ -780,6 +782,7 @@ func (d *DB) runSQL(ctx context.Context, sqls []string, prelim, suppress bool, d
 }
 
 func (d *DB) runQuery(ctx context.Context, sqls []string, db oracleDatabase) ([]string, error) {
+	//TODO: Query suppression
 	klog.InfoS("dbdaemon/runQuery: running sql", "sql", sqls)
 	sqlLen := len(sqls)
 	for i := 0; i < sqlLen-1; i++ {
@@ -876,7 +879,6 @@ func (s *Server) runSQLPlusHelper(ctx context.Context, req *dbdpb.RunSQLPlusCMDR
 		}
 	}
 
-	klog.InfoS("dbdaemon/runSQLPlusHelper: updated env ", "sid", s.databaseSid.val)
 	db, err := open(ctx, connectString, prelim)
 	if err != nil {
 		return nil, fmt.Errorf("dbdaemon/RunSQLPlus failed to open a database connection: %v", err)
@@ -906,34 +908,34 @@ func (s *Server) runSQLPlusHelper(ctx context.Context, req *dbdpb.RunSQLPlusCMDR
 // This function only returns DBMS_OUTPUT and not any row data.
 // To read from SELECTs use RunSQLPlusFormatted.
 func (s *Server) RunSQLPlus(ctx context.Context, req *dbdpb.RunSQLPlusCMDRequest) (*dbdpb.RunCMDResponse, error) {
-	if req.GetSuppress() {
-		klog.InfoS("dbdaemon/RunSQLPlus", "req", "suppressed", "serverObj", s)
-	} else {
-		klog.InfoS("dbdaemon/RunSQLPlus", "req", req, "serverObj", s)
-	}
-
 	// Add lock to protect server state "databaseSid" and os env variable "ORACLE_SID".
 	// Only add lock in top level API to avoid deadlock.
 	s.databaseSid.Lock()
 	defer s.databaseSid.Unlock()
+
+	if req.GetSuppress() {
+		klog.InfoS("dbdaemon/RunSQLPlus", "req", "suppressed", "SID", s.databaseSid.val, "serverObj", s)
+	} else {
+		klog.InfoS("dbdaemon/RunSQLPlus", "req", req, "SID", s.databaseSid.val, "serverObj", s)
+	}
+
 	return s.runSQLPlusHelper(ctx, req, false)
 }
 
 // RunSQLPlusFormatted executes a SQL command and returns the row results.
 // If instead you want DBMS_OUTPUT please issue RunSQLPlus
 func (s *Server) RunSQLPlusFormatted(ctx context.Context, req *dbdpb.RunSQLPlusCMDRequest) (*dbdpb.RunCMDResponse, error) {
-	if req.GetSuppress() {
-		klog.InfoS("dbdaemon/RunSQLPlusFormatted", "req", "suppressed", "serverObj", s)
-	} else {
-		klog.InfoS("dbdaemon/RunSQLPlusFormatted", "req", req, "serverObj", s)
-	}
-	sqls := req.GetCommands()
-	klog.InfoS("dbdaemon/RunSQLPlusFormatted: executing formatted SQL commands", "sql", sqls)
 	// Add lock to protect server state "databaseSid" and os env variable "ORACLE_SID".
 	// Only add lock in top level API to avoid deadlock.
 	s.databaseSid.Lock()
 	defer s.databaseSid.Unlock()
 
+	if req.GetSuppress() {
+		klog.InfoS("dbdaemon/RunSQLPlusFormatted", "req", "suppressed", "SID", s.databaseSid.val, "serverObj", s)
+	} else {
+		klog.InfoS("dbdaemon/RunSQLPlusFormatted", "req", req, "SID", s.databaseSid.val, "serverObj", s)
+	}
+
 	return s.runSQLPlusHelper(ctx, req, true)
 }
 
@@ -1067,9 +1069,9 @@ func (s *Server) RunRMAN(ctx context.Context, req *dbdpb.RunRMANRequest) (*dbdpb
 	// Add lock to protect server state "databaseSid" and os env variable "ORACLE_SID".
 	// Only add lock in top level API to avoid deadlock.
 	if req.GetSuppress() {
-		klog.Info("RunRMAN", "request", "suppressed")
+		klog.InfoS("RunRMAN", "request", "suppressed")
 	} else {
-		klog.Info("RunRMAN", "request", req)
+		klog.InfoS("RunRMAN", "request", req)
 	}
 
 	s.databaseSid.RLock()
@@ -1317,6 +1319,8 @@ func (s *Server) GetDatabaseName(ctx context.Context, req *dbdpb.GetDatabaseName
 
 // BounceDatabase starts/stops request specified database.
 func (s *Server) BounceDatabase(ctx context.Context, req *dbdpb.BounceDatabaseRequest) (*dbdpb.BounceDatabaseResponse, error) {
+	s.databaseSid.RLock()
+	defer s.databaseSid.RUnlock()
 	klog.InfoS("BounceDatabase request delegated to proxy", "req", req)
 	database, err := s.dbdClient.BounceDatabase(ctx, req)
 	if err != nil {

oracle/pkg/database/provision/bootstrap_database_task.go

@@ -105,7 +105,7 @@ func (task *BootstrapTask) setParameters(ctx context.Context) error {
 	retry := 0
 	var err error
 	for ; retry < startupRetries; retry++ {
-		_, err := task.dbdClient.BounceDatabase(ctx, &dbdpb.BounceDatabaseRequest{
+		_, err = task.dbdClient.BounceDatabase(ctx, &dbdpb.BounceDatabaseRequest{
 			Operation:    dbdpb.BounceDatabaseRequest_STARTUP,
 			DatabaseName: task.db.GetDatabaseName(),
 			Option:       "nomount",