Add query time to logger

server/handler.go

@@ -450,21 +450,21 @@ func (h *Handler) doQuery(
 	if queryStr != "" {
 		sqlCtx.SetLogger(sqlCtx.GetLogger().WithField("query", queryStr))
 	}
-	sqlCtx.GetLogger().Debugf("Starting query")
+	sqlCtx.GetLogger().WithField(sql.QueryTimeLogKey, time.Now()).Debugf("Starting query")
 
 	finish := observeQuery(sqlCtx, query)
 	defer func() {
 		finish(err)
 	}()
 
-	sqlCtx.GetLogger().Tracef("beginning execution")
+	sqlCtx.GetLogger().WithField(sql.QueryTimeLogKey, time.Now()).Tracef("beginning execution")
 
 	var schema sql.Schema
 	var rowIter sql.RowIter
 	qFlags.Set(sql.QFlagDeferProjections)
 	schema, rowIter, qFlags, err = queryExec(sqlCtx, query, parsed, analyzedPlan, bindings, qFlags)
 	if err != nil {
-		sqlCtx.GetLogger().WithError(err).Warn("error running query")
+		sqlCtx.GetLogger().WithField(sql.QueryTimeLogKey, time.Now()).WithError(err).Warn("error running query")
 		if verboseErrorLogging {
 			fmt.Printf("Err: %+v", err)
 		}
@@ -511,7 +511,7 @@ func (h *Handler) doQuery(
 		sqlCtx.GetLogger().Tracef("returning result %v", r)
 	}
 
-	sqlCtx.GetLogger().Debugf("Query finished in %d ms", time.Since(start).Milliseconds())
+	sqlCtx.GetLogger().WithField(sql.QueryTimeLogKey, time.Now()).Debugf("Query finished in %d ms", time.Since(start).Milliseconds())
 
 	// processedAtLeastOneBatch means we already called callback() at least
 	// once, so no need to call it if RowsAffected == 0.

server/handler_test.go

@@ -29,6 +29,7 @@ import (
 	"github.com/dolthub/vitess/go/race"
 	"github.com/dolthub/vitess/go/sqltypes"
 	"github.com/dolthub/vitess/go/vt/proto/query"
+	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 
@@ -1916,3 +1917,156 @@ func TestStatusVariableComUpdate(t *testing.T) {
 	checkSessionStatVar(t, sess1, "Com_update", uint64(5))
 	checkSessionStatVar(t, sess2, "Com_update", uint64(3))
 }
+
+// TestQueryTimeLogField tests that the QueryTimeLogKey constant is properly defined
+func TestQueryTimeLogField(t *testing.T) {
+	// Test that the constant is defined and has the expected value
+	require.Equal(t, "queryTime", sql.QueryTimeLogKey, "QueryTimeLogKey should be 'queryTime'")
+}
+
+// TestLoggerFieldsSetup tests that handler properly sets up logger fields including query time
+func TestLoggerFieldsSetup(t *testing.T) {
+	e, pro := setupMemDB(require.New(t))
+	dbFunc := pro.Database
+
+	handler := &Handler{
+		e: e,
+		sm: NewSessionManager(
+			sql.NewContext,
+			testSessionBuilder(pro),
+			sql.NoopTracer,
+			dbFunc,
+			sql.NewMemoryManager(nil),
+			sqle.NewProcessList(),
+			"foo",
+		),
+		readTimeout: time.Second,
+	}
+
+	conn := newConn(1)
+	handler.NewConnection(conn)
+	err := handler.ComInitDB(conn, "test")
+	require.NoError(t, err)
+
+	// Execute a query and verify basic logging setup
+	err = handler.ComQuery(context.Background(), conn, "SELECT 1", dummyCb)
+	require.NoError(t, err)
+
+	// Verify that the session's logger has the expected fields
+	session := handler.sm.session(conn)
+	logger := session.GetLogger()
+	require.NotNil(t, logger, "Session should have a logger")
+
+	// Verify that the logger has the expected fields
+	require.Contains(t, logger.Data, sql.ConnectTimeLogKey, "Logger should contain connect time")
+	require.Contains(t, logger.Data, sql.ConnectionIdLogField, "Logger should contain connection ID")
+
+	// Verify the values are of correct types
+	connectTime, ok := logger.Data[sql.ConnectTimeLogKey].(time.Time)
+	require.True(t, ok, "Connect time should be a time.Time")
+	require.False(t, connectTime.IsZero(), "Connect time should not be zero")
+
+	connID, ok := logger.Data[sql.ConnectionIdLogField].(uint32)
+	require.True(t, ok, "Connection ID should be a uint32")
+	require.Equal(t, conn.ConnectionID, connID, "Connection ID should match")
+}
+
+// TestQueryTimeConstantDefined tests that the QueryTimeLogKey constant is properly defined and available
+func TestQueryTimeConstantDefined(t *testing.T) {
+	// Verify the constant exists and has the expected value
+	require.Equal(t, "queryTime", sql.QueryTimeLogKey, "QueryTimeLogKey constant should be defined as 'queryTime'")
+
+	// Verify it's different from other log keys
+	require.NotEqual(t, sql.QueryTimeLogKey, sql.ConnectTimeLogKey, "QueryTimeLogKey should be different from ConnectTimeLogKey")
+	require.NotEqual(t, sql.QueryTimeLogKey, sql.ConnectionIdLogField, "QueryTimeLogKey should be different from ConnectionIdLogField")
+}
+
+// TestHandlerDoQueryIntegration tests the complete doQuery flow to ensure query time handling works
+func TestHandlerDoQueryIntegration(t *testing.T) {
+	e, pro := setupMemDB(require.New(t))
+	dbFunc := pro.Database
+
+	handler := &Handler{
+		e: e,
+		sm: NewSessionManager(
+			sql.NewContext,
+			testSessionBuilder(pro),
+			sql.NoopTracer,
+			dbFunc,
+			sql.NewMemoryManager(nil),
+			sqle.NewProcessList(),
+			"foo",
+		),
+		readTimeout: time.Second,
+	}
+
+	conn := newConn(1)
+	handler.NewConnection(conn)
+	err := handler.ComInitDB(conn, "test")
+	require.NoError(t, err)
+
+	// Execute a query - this will go through our modified doQuery code path
+	err = handler.ComQuery(context.Background(), conn, "SELECT 1", dummyCb)
+	require.NoError(t, err)
+
+	// Verify that the session has a logger with the expected fields
+	session := handler.sm.session(conn)
+	require.NotNil(t, session, "Session should exist")
+
+	logger := session.GetLogger()
+	require.NotNil(t, logger, "Session should have a logger")
+
+	// Verify base logging fields are present
+	require.Contains(t, logger.Data, sql.ConnectTimeLogKey, "Logger should contain connect time")
+	require.Contains(t, logger.Data, sql.ConnectionIdLogField, "Logger should contain connection ID")
+
+	// Verify the connect time is reasonable
+	connectTime, ok := logger.Data[sql.ConnectTimeLogKey].(time.Time)
+	require.True(t, ok, "Connect time should be a time.Time")
+	require.False(t, connectTime.IsZero(), "Connect time should not be zero")
+	require.True(t, connectTime.Before(time.Now()) || connectTime.Equal(time.Now()),
+		"Connect time should be before or equal to current time")
+
+	// Verify connection ID matches
+	connID, ok := logger.Data[sql.ConnectionIdLogField].(uint32)
+	require.True(t, ok, "Connection ID should be a uint32")
+	require.Equal(t, conn.ConnectionID, connID, "Connection ID should match the connection")
+
+	// The test verifies that our code changes compile and execute without error
+	// The actual query time field will be set temporarily during query execution in doQuery
+	// but won't persist in the session logger (which is the expected behavior)
+}
+
+// TestQueryTimeLoggerBehavior tests that query time field can be added to logger entries
+func TestQueryTimeLoggerBehavior(t *testing.T) {
+	// Test demonstrates that the QueryTimeLogKey constant is available and can be used
+	// for setting up logger fields with time.Now() calls during query execution
+	require.NotEmpty(t, sql.QueryTimeLogKey, "QueryTimeLogKey should not be empty")
+
+	// Create a time value like what would be used in query logging
+	queryTime := time.Now()
+
+	// Simulate what happens during query execution: create a logger with query time field
+	baseLogger := &logrus.Entry{
+		Data: make(logrus.Fields),
+	}
+	baseLogger.Data[sql.ConnectTimeLogKey] = time.Now().Add(-1 * time.Minute) // connection established 1 minute ago
+	baseLogger.Data[sql.ConnectionIdLogField] = uint32(123)
+
+	// Add query time field using time.Now() (this is what our modified handler does)
+	loggerWithQueryTime := baseLogger.WithField(sql.QueryTimeLogKey, queryTime)
+
+	// Verify the query time field was added
+	require.Contains(t, loggerWithQueryTime.Data, sql.QueryTimeLogKey, "Logger should contain query time")
+	require.Contains(t, loggerWithQueryTime.Data, sql.ConnectTimeLogKey, "Logger should still contain connect time")
+	require.Contains(t, loggerWithQueryTime.Data, sql.ConnectionIdLogField, "Logger should still contain connection ID")
+
+	// Verify the query time value
+	actualQueryTime, ok := loggerWithQueryTime.Data[sql.QueryTimeLogKey].(time.Time)
+	require.True(t, ok, "Query time should be a time.Time")
+	require.Equal(t, queryTime, actualQueryTime, "Query time should match the set value")
+
+	// Verify that query time and connect time are different (as expected)
+	connectTime := loggerWithQueryTime.Data[sql.ConnectTimeLogKey].(time.Time)
+	require.True(t, queryTime.After(connectTime), "Query time should be after connect time")
+}

sql/log.go

@@ -18,4 +18,5 @@ const (
 	ConnectionIdLogField = "connectionID"
 	ConnectionDbLogField = "connectionDb"
 	ConnectTimeLogKey    = "connectTime"
+	QueryTimeLogKey      = "queryTime"
 )