Mask URL passwords in the SQL query log, fix #1630

ChangeLog.md

@@ -5,6 +5,7 @@ NEW FEATURES
 - add `azblob.chunk_size` (env `AZBLOB_CHUNK_SIZE`, default `0`), a fixed upload block size used when `ceil(file size / chunk_size) <= max_parts_count`, clamped to [2MiB, 4000MiB], `0` keeps the automatic `file size / max_parts_count` clamped to [2MiB, 10MiB], brings back the explicit size removed together with `AZBLOB_BUFFER_SIZE` in v2.6.6, fix [#1142](https://github.com/Altinity/clickhouse-backup/issues/1142)
 
 BUG FIXES
+- the SQL query log no longer prints passwords embedded in URLs: `pass=` / `password=` query string parameters and `user:password@` are written as `[MASKED]`, with `api.create_integration_tables: true` and `api.password` set every `server` start logged the DDL of `system.backup_actions`, `system.backup_list` and `system.backup_version` with the API password in plain text inside the `URL()` engine argument, at `info` level with the default `clickhouse.log_sql_queries: true`, the query sent to ClickHouse is unchanged, fix [#1630](https://github.com/Altinity/clickhouse-backup/issues/1630)
 - `s3.chunk_size` is now also used when `ceil(file size / chunk_size)` is exactly `s3.max_parts_count`, previously it fell back to `file size / max_parts_count`, ReadMe.md now shows the real default `5242880` and the semantics of `s3.chunk_size`, raise it to upload big files as fewer bigger parts instead of `max_parts_count=1` workaround, each multipart upload allocates about `(s3.concurrency + 2) * chunk_size` bytes, `s3.chunk_size` and `azblob.chunk_size` also apply to uploads into object disks during restore, fix [#1142](https://github.com/Altinity/clickhouse-backup/issues/1142)
 - `watch` no longer treats a failed `backups_to_keep_remote` / `backups_to_keep_local` retention or `--delete-source` after a completely uploaded backup as a failed upload: the new backup becomes the base of the next increment (previously the next increment was diffed from a stale base) and the failure is not counted towards `too many errors ... abort watching`, so a permanently failing post-upload step no longer stops `watch`, it is reported only by the error log, `/backup/status`, `system.backup_actions` and the callback, with `api.enable_metrics` the `failed_create_remotes` counter keeps growing and `last_create_remote_status` stays `0` while new backups are uploaded; all post-upload steps now run even when a previous one failed and their errors are reported together; with `--schedule` the `full_type: rebase` and `delete_previous_cycle` steps also proceed, a failed rebase is reported together with the post-upload error and the backup is not used as the base; `use_embedded_backup_restore_cluster` initiator waits for the worker nodes before the backup is used as the base, a post-upload failure on a worker node is still counted as a failed upload; `create_remote --streaming` no longer reports such a complete backup as partial; one-shot `create_remote` and `upload` still exit with a non-zero code, fix [#1535](https://github.com/Altinity/clickhouse-backup/issues/1535)
 - `restore --schema --rm` without `restore_schema_on_cluster` on a replica of `ENGINE=Replicated` database, when the database schema was already restored from another replica (ACM restore sequence and `How to back up / restore a sharded cluster` in Examples.md), no longer fails with `code: 529 ... Cannot enqueue query on this replica, because it has replication lag`, `code: 36 ... It's not allowed to specify explicit zookeeper_path and replica_name` or `Table ... already exists`: local `DROP DATABASE` of a Replicated database is skipped (it removed only the current replica, which then recovered from the database DDL log concurrently with the following DROP/CREATE TABLE, tables are still dropped and their DROP TABLE is replicated), `SYSTEM SYNC DATABASE REPLICA` is executed before and after dropping tables (ClickHouse 22.5+), and `{uuid}` macro of `Replicated*MergeTree` path is no longer replaced with the backup table UUID and the replication path is no longer rebound to `default_replica_path` inside a Replicated database, fix [#1611](https://github.com/Altinity/clickhouse-backup/issues/1611)

pkg/clickhouse/clickhouse.go

@@ -1493,14 +1493,33 @@ func (ch *ClickHouse) LogQuery(query string, args ...interface{}) string {
 	if !ch.Config.LogSQLQueries {
 		level = zerolog.DebugLevel
 	}
+	event := log.WithLevel(level)
+	if !event.Enabled() {
+		return query
+	}
+	msg := query
 	if len(args) > 0 {
-		log.WithLevel(level).Msg(strings.NewReplacer("\n", " ", "\r", " ", "\t", " ").Replace(fmt.Sprintf("%s with args %#v", query, args)))
-	} else {
-		log.WithLevel(level).Msg(strings.NewReplacer("\n", " ", "\r", " ", "\t", " ").Replace(query))
+		msg = fmt.Sprintf("%s with args %#v", query, args)
 	}
+	event.Msg(maskURLCredentials(strings.NewReplacer("\n", " ", "\r", " ", "\t", " ").Replace(msg)))
 	return query
 }
 
+// urlPassParamRe matches the value of a `pass` / `password` query string parameter, the `system.backup_*` integration tables carry `api.password` as `pass=`
+var urlPassParamRe = regexp.MustCompile(`(?i)([?&](?:pass|password)=)[^&'"\s]*`)
+
+// urlUserInfoPassRe matches the password of `scheme://user:password@host`
+var urlUserInfoPassRe = regexp.MustCompile(`(://[^:/?#@'"\s]*:)[^@/?#'"\s]*@`)
+
+// maskURLCredentials replaces passwords inside URLs, such as the URL() table engine argument, before the query is logged
+func maskURLCredentials(s string) string {
+	if !strings.Contains(s, "://") {
+		return s
+	}
+	s = urlPassParamRe.ReplaceAllString(s, "${1}[MASKED]")
+	return urlUserInfoPassRe.ReplaceAllString(s, "${1}[MASKED]@")
+}
+
 func (ch *ClickHouse) IsDbAtomicOrReplicated(database string) (bool, error) {
 	dbEngine, err := ch.GetDatabaseEngine(database)
 	if err != nil {

pkg/clickhouse/log_query_test.go

@@ -0,0 +1,90 @@
+package clickhouse
+
+import (
+	"bytes"
+	"encoding/json"
+	"net/url"
+	"testing"
+
+	"github.com/Altinity/clickhouse-backup/v2/pkg/config"
+	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/log"
+	"github.com/stretchr/testify/assert"
+)
+
+func TestLogQueryMasksURLCredentials(t *testing.T) {
+	const password = "s3cr&t'p@ss word"
+	params := url.Values{}
+	params.Add("user", "backup")
+	params.Add("pass", password)
+	encodedPassword := url.QueryEscape(password)
+
+	testCases := []struct {
+		Name     string
+		Query    string
+		Args     []interface{}
+		Expected string
+	}{
+		{
+			Name:     "integration table URL engine",
+			Query:    "CREATE TABLE system.backup_actions (command String) ENGINE=URL('http://127.0.0.1:7171/backup/actions?" + params.Encode() + "', JSONEachRow) SETTINGS input_format_skip_unknown_fields=1",
+			Expected: "CREATE TABLE system.backup_actions (command String) ENGINE=URL('http://127.0.0.1:7171/backup/actions?pass=[MASKED]&user=backup', JSONEachRow) SETTINGS input_format_skip_unknown_fields=1",
+		},
+		{
+			Name:     "password parameter after another parameter",
+			Query:    "CREATE TABLE db.t (x String) ENGINE=URL('https://host:8443/data?user=u&password=" + encodedPassword + "', JSONEachRow)",
+			Expected: "CREATE TABLE db.t (x String) ENGINE=URL('https://host:8443/data?user=u&password=[MASKED]', JSONEachRow)",
+		},
+		{
+			Name:     "password in URL userinfo",
+			Query:    "CREATE TABLE db.t (x String) ENGINE=URL('https://u:" + encodedPassword + "@host:8443/data', JSONEachRow)",
+			Expected: "CREATE TABLE db.t (x String) ENGINE=URL('https://u:[MASKED]@host:8443/data', JSONEachRow)",
+		},
+		{
+			Name:     "query with args",
+			Query:    "CREATE TABLE db.t (x String) ENGINE=URL('http://host/data?pass=" + encodedPassword + "', JSONEachRow) COMMENT ?",
+			Args:     []interface{}{"c"},
+			Expected: `CREATE TABLE db.t (x String) ENGINE=URL('http://host/data?pass=[MASKED]', JSONEachRow) COMMENT ? with args []interface {}{"c"}`,
+		},
+		{
+			Name:     "query without credentials is unchanged",
+			Query:    "SELECT name FROM system.tables WHERE database = 'default' AND engine_full LIKE '%://host:9000/%'",
+			Expected: "SELECT name FROM system.tables WHERE database = 'default' AND engine_full LIKE '%://host:9000/%'",
+		},
+	}
+
+	originalLogger := log.Logger
+	originalGlobalLevel := zerolog.GlobalLevel()
+	t.Cleanup(func() {
+		log.Logger = originalLogger
+		zerolog.SetGlobalLevel(originalGlobalLevel)
+	})
+	zerolog.SetGlobalLevel(zerolog.InfoLevel)
+	ch := ClickHouse{Config: &config.ClickHouseConfig{LogSQLQueries: true}}
+
+	for _, tc := range testCases {
+		t.Run(tc.Name, func(t *testing.T) {
+			var buf bytes.Buffer
+			log.Logger = zerolog.New(&buf)
+
+			assert.Equal(t, tc.Query, ch.LogQuery(tc.Query, tc.Args...), "the executed query must keep the credentials")
+			output := buf.String()
+			assert.NotContains(t, output, password)
+			assert.NotContains(t, output, encodedPassword)
+			var entry struct {
+				Message string `json:"message"`
+			}
+			assert.NoError(t, json.Unmarshal(buf.Bytes(), &entry))
+			assert.Equal(t, tc.Expected, entry.Message)
+		})
+	}
+
+	t.Run("disabled level writes nothing", func(t *testing.T) {
+		var buf bytes.Buffer
+		log.Logger = zerolog.New(&buf)
+		debugCh := ClickHouse{Config: &config.ClickHouseConfig{LogSQLQueries: false}}
+		query := testCases[0].Query
+		assert.Equal(t, query, debugCh.LogQuery(query))
+		assert.Empty(t, buf.String())
+	})
+}