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.

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

Colocate auth logging with auth metric for consistency #83597

Merged
merged 1 commit into from
Jul 8, 2022
Merged

Colocate auth logging with auth metric for consistency #83597

merged 1 commit into from
Jul 8, 2022

Conversation

ecwall
Copy link
Contributor

@ecwall ecwall commented Jun 29, 2022

refs #83224

Release note (bug fix): Move connection OK log and metric to same location
after auth completes for consistency. This resolves an inconsistency
(see linked isssue) in the DB console where the log and metric did not match.

@ecwall ecwall requested a review from a team June 29, 2022 16:41
@ecwall ecwall requested review from a team as code owners June 29, 2022 16:41
@cockroach-teamcity
Copy link
Member

This change is Reviewable

@ecwall ecwall changed the title Add logging details to auth steps Colocate auth logging with auth metric for consistency Jul 6, 2022
@ecwall ecwall requested a review from rafiss July 6, 2022 21:31
@knz
Copy link
Contributor

knz commented Jul 6, 2022

that's cool but it looks like it needs a test

@rafiss
Copy link
Collaborator

rafiss commented Jul 7, 2022

I'm more convinced moving the place where we record the graph measurement would be correct

diff --git a/pkg/sql/pgwire/conn.go b/pkg/sql/pgwire/conn.go
index 3b9f7e5513..74a038624d 100644
--- a/pkg/sql/pgwire/conn.go
+++ b/pkg/sql/pgwire/conn.go
@@ -466,11 +466,6 @@ func (c *conn) serveImpl(
 					return true, isSimpleQuery, nil //nolint:returnerrcheck
 				}
 				authDone = true
-
-				// We count the connection establish latency until we are ready to
-				// serve a SQL query. It includes the time it takes to authenticate.
-				duration := timeutil.Since(c.startTime).Nanoseconds()
-				c.metrics.ConnLatency.RecordValue(duration)
 			}
 
 			switch typ {
@@ -714,6 +709,11 @@ func (c *conn) processCommandsAsync(
 		}
 		// Signal the connection was established to the authenticator.
 		ac.AuthOK(ctx)
+		// We count the connection establish latency until we are ready to
+		// serve a SQL query. It includes the time it takes to authenticate and
+		// send the initial ReadyForQuery message.
+		duration := timeutil.Since(c.startTime).Nanoseconds()
+		c.metrics.ConnLatency.RecordValue(duration)
 		// Mark the authentication as succeeded in case a panic
 		// is thrown below and we need to report to the client
 		// using the defer above.

The issue with doing things in the for loop of pgwire.serveImpl is that the code will only be executed when the server receives the first command that is sent after the connection is fully set up.

@ecwall
Copy link
Contributor Author

ecwall commented Jul 7, 2022

that's cool but it looks like it needs a test

Are there test examples that check log and metric output that I can look at?

@rafiss
Copy link
Collaborator

rafiss commented Jul 7, 2022

could you add a release note (bug fix) that mentions that this fixes possible inaccuracies in the connection latency graph?

i also am not too sure how to test this...

refs #83224

Release note (bug fix): Move connection OK log and metric to same location
after auth completes for consistency. This resolves an inconsistency
(see linked isssue) in the DB console where the log and metric did not match.
Copy link
Collaborator

@rafiss rafiss left a comment

Choose a reason for hiding this comment

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

lgtm from my end, but try asking one of the observability teams for ideas on how to test this. if you can't find anything, feel free to merge

@ecwall
Copy link
Contributor Author

ecwall commented Jul 8, 2022

bors r=rafiss

@craig craig bot merged commit 1764aab into cockroachdb:master Jul 8, 2022
@craig
Copy link
Contributor

craig bot commented Jul 8, 2022

Build succeeded:

@blathers-crl
Copy link

blathers-crl bot commented Jul 8, 2022

Encountered an error creating backports. Some common things that can go wrong:

  1. The backport branch might have already existed.
  2. There was a merge conflict.
  3. The backport branch contained merge commits.

You might need to create your backport manually using the backport tool.


error creating merge commit from 1ebd411 to blathers/backport-release-21.2-83597: POST https://api.github.com/repos/cockroachdb/cockroach/merges: 409 Merge conflict []

you may need to manually resolve merge conflicts with the backport tool.

Backport to branch 21.2.x failed. See errors above.


🦉 Hoot! I am a Blathers, a bot for CockroachDB. My owner is otan.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants