diff --git a/ChangeLog.md b/ChangeLog.md index 33456baf..ecd22067 100644 --- a/ChangeLog.md +++ b/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) diff --git a/pkg/clickhouse/clickhouse.go b/pkg/clickhouse/clickhouse.go index d56ffa6c..ca011caf 100644 --- a/pkg/clickhouse/clickhouse.go +++ b/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 { diff --git a/pkg/clickhouse/log_query_test.go b/pkg/clickhouse/log_query_test.go new file mode 100644 index 00000000..ec87c535 --- /dev/null +++ b/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()) + }) +}