Remove false positive errors from logs #1 (#991)

Part of #4
We recently encountered some log spam on customer's panels, so I decided
to remove some false positive warnings/errors. Would also like to add
warn+ logging to all tests, but even if it's be possible, I'll do that
gradually.

This PR eliminates _a lot_ of log spam in our tests (vast majority of
it).

quesma/clickhouse/schema_test.go

@@ -16,10 +16,10 @@ func TestGetDateTimeType(t *testing.T) {
 		"timestamp64_1" DateTime64,
 		"timestamp64_2" DateTime64(3, 'UTC') ) ENGINE = Memory`, NewChTableConfigTimestampStringAttr())
 	assert.NoError(t, err)
-	assert.Equal(t, DateTime, table.GetDateTimeType(ctx, "timestamp1"))
-	assert.Equal(t, DateTime, table.GetDateTimeType(ctx, "timestamp2"))
-	assert.Equal(t, DateTime64, table.GetDateTimeType(ctx, "timestamp64_1"))
-	assert.Equal(t, DateTime64, table.GetDateTimeType(ctx, "timestamp64_2"))
-	assert.Equal(t, DateTime64, table.GetDateTimeType(ctx, timestampFieldName)) // default, created by us
-	assert.Equal(t, Invalid, table.GetDateTimeType(ctx, "non-existent"))
+	assert.Equal(t, DateTime, table.GetDateTimeType(ctx, "timestamp1", true))
+	assert.Equal(t, DateTime, table.GetDateTimeType(ctx, "timestamp2", true))
+	assert.Equal(t, DateTime64, table.GetDateTimeType(ctx, "timestamp64_1", true))
+	assert.Equal(t, DateTime64, table.GetDateTimeType(ctx, "timestamp64_2", true))
+	assert.Equal(t, DateTime64, table.GetDateTimeType(ctx, timestampFieldName, true)) // default, created by us
+	assert.Equal(t, Invalid, table.GetDateTimeType(ctx, "non-existent", false))
 }

quesma/clickhouse/table.go

@@ -85,7 +85,8 @@ func (t *Table) FullTableName() string {
 
 // GetDateTimeType returns type of a field (currently DateTime/DateTime64), if it's a DateTime type. Invalid otherwise.
 // Timestamp from config defaults to DateTime64.
-func (t *Table) GetDateTimeType(ctx context.Context, fieldName string) DateTimeType {
+// We don't warn the log message e.g. in e.g. in sum/avg/etc. aggregations, where date is (very) unexpected or impossible.
+func (t *Table) GetDateTimeType(ctx context.Context, fieldName string, dateInSchemaExpected bool) DateTimeType {
 	if col, ok := t.Cols[fieldName]; ok {
 		typeName := col.Type.String()
 		// hasPrefix, not equal, because we can have DateTime64(3) and we want to catch it
@@ -99,13 +100,16 @@ func (t *Table) GetDateTimeType(ctx context.Context, fieldName string) DateTimeT
 	if t.Config.HasTimestamp && fieldName == timestampFieldName {
 		return DateTime64
 	}
-	logger.WarnWithCtx(ctx).Msgf("datetime field '%s' not found in table '%s'", fieldName, t.Name)
+	if dateInSchemaExpected {
+		logger.WarnWithCtx(ctx).Msgf("datetime field '%s' not found in table '%s'", fieldName, t.Name)
+	}
 	return Invalid
 }
 
 func (t *Table) GetDateTimeTypeFromExpr(ctx context.Context, expr model.Expr) DateTimeType {
+	const dateInSchemaExpected = true
 	if ref, ok := expr.(model.ColumnRef); ok {
-		return t.GetDateTimeType(ctx, ref.ColumnName)
+		return t.GetDateTimeType(ctx, ref.ColumnName, dateInSchemaExpected)
 	}
 	logger.WarnWithCtx(ctx).Msgf("datetime field '%v' not found in table '%s'", expr, t.Name)
 	return Invalid

quesma/logger/logger.go

@@ -121,6 +121,22 @@ func InitSimpleLoggerForTests() {
 		Logger()
 }
 
+// InitSimpleLoggerForTestsWarnLevel initializes our global logger (level >= Warn) to the console output.
+// Useful e.g. in debugging failing tests: you can call this function at the beginning
+// of the test, and calls to the global logger will start appearing in the console.
+// Without it, they don't.
+func InitSimpleLoggerForTestsWarnLevel() {
+	logger = zerolog.New(
+		zerolog.ConsoleWriter{
+			Out:        os.Stderr,
+			TimeFormat: time.StampMilli,
+		}).
+		Level(zerolog.WarnLevel).
+		With().
+		Timestamp().
+		Logger()
+}
+
 func InitOnlyChannelLoggerForTests() <-chan LogWithLevel {
 	zerolog.TimeFieldFormat = time.RFC3339Nano   // without this we don't have milliseconds timestamp precision
 	logChannel := make(chan LogWithLevel, 50000) // small number like 5 or 10 made entire Quesma totally unresponsive during the few seconds where Kibana spams with messages

quesma/queryparser/aggregation_parser.go

@@ -38,6 +38,7 @@ func (cw *ClickhouseQueryTranslator) tryMetricsAggregation(queryMap QueryMap) (m
 	if len(queryMap) != 1 {
 		return metricsAggregation{}, false
 	}
+	const dateInSchemaExpected = false
 
 	// full list: https://www.elastic.co/guide/en/elasticsearch/reference/current/search-Aggregations-metrics.html
 	// shouldn't be hard to handle others, if necessary
@@ -50,7 +51,7 @@ func (cw *ClickhouseQueryTranslator) tryMetricsAggregation(queryMap QueryMap) (m
 			return metricsAggregation{
 				AggrType:            k,
 				Fields:              []model.Expr{field},
-				FieldType:           cw.GetDateTimeTypeFromSelectClause(cw.Ctx, field),
+				FieldType:           cw.GetDateTimeTypeFromSelectClause(cw.Ctx, field, dateInSchemaExpected),
 				IsFieldNameCompound: isFromScript,
 			}, true
 		}
@@ -66,7 +67,7 @@ func (cw *ClickhouseQueryTranslator) tryMetricsAggregation(queryMap QueryMap) (m
 		return metricsAggregation{
 			AggrType:    "quantile",
 			Fields:      []model.Expr{field},
-			FieldType:   cw.GetDateTimeTypeFromSelectClause(cw.Ctx, field),
+			FieldType:   cw.GetDateTimeTypeFromSelectClause(cw.Ctx, field, dateInSchemaExpected),
 			Percentiles: percentiles,
 			Keyed:       keyed,
 		}, true

quesma/queryparser/pancake_sql_query_generation_test.go

@@ -24,7 +24,7 @@ const TableName = model.SingleTableNamePlaceHolder
 
 func TestPancakeQueryGeneration(t *testing.T) {
 
-	// logger.InitSimpleLoggerForTests()
+	// logger.InitSimpleLoggerForTestsWarnLevel()
 	table := clickhouse.Table{
 		Cols: map[string]*clickhouse.Column{
 			"@timestamp":                     {Name: "@timestamp", Type: clickhouse.NewBaseType("DateTime64")},

quesma/queryparser/query_parser.go

@@ -785,9 +785,14 @@ func (cw *ClickhouseQueryTranslator) parseRange(queryMap QueryMap) model.SimpleQ
 		return model.NewSimpleQuery(nil, false)
 	}
 
+	// Maybe change to false if numeric fields exist.
+	// Even so, most likely >99% of ranges will be dates, as they come in (almost) every request.
+	const dateInSchemaExpected = true
+
 	for fieldName, v := range queryMap {
 		fieldName = cw.ResolveField(cw.Ctx, fieldName)
-		fieldType := cw.Table.GetDateTimeType(cw.Ctx, cw.ResolveField(cw.Ctx, fieldName))
+
+		fieldType := cw.Table.GetDateTimeType(cw.Ctx, cw.ResolveField(cw.Ctx, fieldName), dateInSchemaExpected)
 		stmts := make([]model.Expr, 0)
 		if _, ok := v.(QueryMap); !ok {
 			logger.WarnWithCtx(cw.Ctx).Msgf("invalid range type: %T, value: %v", v, v)
@@ -1269,9 +1274,10 @@ func (cw *ClickhouseQueryTranslator) parseSize(queryMap QueryMap, defaultSize in
 	}
 }
 
-func (cw *ClickhouseQueryTranslator) GetDateTimeTypeFromSelectClause(ctx context.Context, expr model.Expr) clickhouse.DateTimeType {
+func (cw *ClickhouseQueryTranslator) GetDateTimeTypeFromSelectClause(ctx context.Context, expr model.Expr,
+	dateInSchemaExpected bool) clickhouse.DateTimeType {
 	if ref, ok := expr.(model.ColumnRef); ok {
-		return cw.Table.GetDateTimeType(ctx, cw.ResolveField(ctx, ref.ColumnName))
+		return cw.Table.GetDateTimeType(ctx, cw.ResolveField(ctx, ref.ColumnName), dateInSchemaExpected)
 	}
 	return clickhouse.Invalid
 }