Merge pull request #16249 from traceon/access-storage-added-log

Add a log message after an access storage is added

docker/test/testflows/runner/Dockerfile

@@ -35,7 +35,7 @@ RUN apt-get update \
 ENV TZ=Europe/Moscow
 RUN ln -snf /usr/share/zoneinfo/$TZ /etc/localtime && echo $TZ > /etc/timezone
 
-RUN pip3 install urllib3 testflows==1.6.48 docker-compose docker dicttoxml kazoo tzlocal
+RUN pip3 install urllib3 testflows==1.6.57 docker-compose docker dicttoxml kazoo tzlocal
 
 ENV DOCKER_CHANNEL stable
 ENV DOCKER_VERSION 17.09.1-ce
@@ -72,5 +72,5 @@ RUN set -x \
 VOLUME /var/lib/docker
 EXPOSE 2375
 ENTRYPOINT ["dockerd-entrypoint.sh"]
-CMD ["sh", "-c", "python3 regression.py --no-color --local --clickhouse-binary-path ${CLICKHOUSE_TESTS_SERVER_BIN_PATH} --log test.log ${TESTFLOWS_OPTS}; cat test.log | tfs report results --format json > results.json"]
+CMD ["sh", "-c", "python3 regression.py --no-color -o classic --local --clickhouse-binary-path ${CLICKHOUSE_TESTS_SERVER_BIN_PATH} --log test.log ${TESTFLOWS_OPTS}; cat test.log | tfs report results --format json > results.json"]
 

src/Access/AccessControlManager.cpp

@@ -137,7 +137,6 @@ AccessControlManager::AccessControlManager()
 
 AccessControlManager::~AccessControlManager() = default;
 
-
 void AccessControlManager::setUsersConfig(const Poco::Util::AbstractConfiguration & users_config_)
 {
     auto storages = getStoragesPtr();
@@ -163,6 +162,7 @@ void AccessControlManager::addUsersConfigStorage(const String & storage_name_, c
     auto new_storage = std::make_shared<UsersConfigAccessStorage>(storage_name_, check_setting_name_function);
     new_storage->setConfig(users_config_);
     addStorage(new_storage);
+    LOG_DEBUG(getLogger(), "Added {} access storage '{}', path: {}", String(new_storage->getStorageType()), new_storage->getStorageName(), new_storage->getPath());
 }
 
 void AccessControlManager::addUsersConfigStorage(
@@ -195,6 +195,7 @@ void AccessControlManager::addUsersConfigStorage(
     auto new_storage = std::make_shared<UsersConfigAccessStorage>(storage_name_, check_setting_name_function);
     new_storage->load(users_config_path_, include_from_path_, preprocessed_dir_, get_zookeeper_function_);
     addStorage(new_storage);
+    LOG_DEBUG(getLogger(), "Added {} access storage '{}', path: {}", String(new_storage->getStorageType()), new_storage->getStorageName(), new_storage->getPath());
 }
 
 void AccessControlManager::reloadUsersConfigs()
@@ -238,7 +239,9 @@ void AccessControlManager::addDiskStorage(const String & storage_name_, const St
             }
         }
     }
-    addStorage(std::make_shared<DiskAccessStorage>(storage_name_, directory_, readonly_));
+    auto new_storage = std::make_shared<DiskAccessStorage>(storage_name_, directory_, readonly_);
+    addStorage(new_storage);
+    LOG_DEBUG(getLogger(), "Added {} access storage '{}', path: {}", String(new_storage->getStorageType()), new_storage->getStorageName(), new_storage->getPath());
 }
 
 
@@ -250,13 +253,17 @@ void AccessControlManager::addMemoryStorage(const String & storage_name_)
         if (auto memory_storage = typeid_cast<std::shared_ptr<MemoryAccessStorage>>(storage))
             return;
     }
-    addStorage(std::make_shared<MemoryAccessStorage>(storage_name_));
+    auto new_storage = std::make_shared<MemoryAccessStorage>(storage_name_);
+    addStorage(new_storage);
+    LOG_DEBUG(getLogger(), "Added {} access storage '{}'", String(new_storage->getStorageType()), new_storage->getStorageName());
 }
 
 
 void AccessControlManager::addLDAPStorage(const String & storage_name_, const Poco::Util::AbstractConfiguration & config_, const String & prefix_)
 {
-    addStorage(std::make_shared<LDAPAccessStorage>(storage_name_, this, config_, prefix_));
+    auto new_storage = std::make_shared<LDAPAccessStorage>(storage_name_, this, config_, prefix_);
+    addStorage(new_storage);
+    LOG_DEBUG(getLogger(), "Added {} access storage '{}', LDAP server name: {}", String(new_storage->getStorageType()), new_storage->getStorageName(), new_storage->getLDAPServerName());
 }
 
 

src/Access/LDAPAccessStorage.cpp

@@ -29,6 +29,12 @@ LDAPAccessStorage::LDAPAccessStorage(const String & storage_name_, AccessControl
 }
 
 
+String LDAPAccessStorage::getLDAPServerName() const
+{
+    return ldap_server;
+}
+
+
 void LDAPAccessStorage::setConfiguration(AccessControlManager * access_control_manager_, const Poco::Util::AbstractConfiguration & config, const String & prefix)
 {
     std::scoped_lock lock(mutex);

src/Access/LDAPAccessStorage.h

@@ -32,6 +32,8 @@ public:
     explicit LDAPAccessStorage(const String & storage_name_, AccessControlManager * access_control_manager_, const Poco::Util::AbstractConfiguration & config, const String & prefix);
     virtual ~LDAPAccessStorage() override = default;
 
+    String getLDAPServerName() const;
+
 public: // IAccessStorage implementations.
     virtual const char * getStorageType() const override;
     virtual String getStorageParamsJSON() const override;

tests/testflows/ldap/authentication/tests/authentications.py

@@ -28,6 +28,8 @@ servers = {
 @TestStep(When)
 @Name("I login as {username} and execute query")
 def login_and_execute_query(self, username, password, exitcode=None, message=None, steps=True):
+    """Execute query as some user.
+    """
     self.context.node.query("SELECT 1",
         settings=[("user", username), ("password", password)],
         exitcode=exitcode or 0,
@@ -35,7 +37,8 @@ def login_and_execute_query(self, username, password, exitcode=None, message=Non
 
 @TestScenario
 def add_user_to_ldap_and_login(self, server, user=None, ch_user=None, login=None, exitcode=None, message=None, rbac=False):
-    """Add user to LDAP and ClickHouse and then try to login."""
+    """Add user to LDAP and ClickHouse and then try to login.
+    """
     self.context.ldap_node = self.context.cluster.node(server)
 
     if ch_user is None:
@@ -60,7 +63,8 @@ def add_user_to_ldap_and_login(self, server, user=None, ch_user=None, login=None
     RQ_SRS_007_LDAP_Authentication_Parallel_ValidAndInvalid("1.0")
 )
 def parallel_login(self, server, user_count=10, timeout=200, rbac=False):
-    """Check that login of valid and invalid LDAP authenticated users works in parallel."""
+    """Check that login of valid and invalid LDAP authenticated users works in parallel.
+    """
     self.context.ldap_node = self.context.cluster.node(server)
     user = None
 
@@ -114,7 +118,8 @@ def parallel_login(self, server, user_count=10, timeout=200, rbac=False):
     RQ_SRS_007_LDAP_Authentication_Invalid_DeletedUser("1.0")
 )
 def login_after_user_is_deleted_from_ldap(self, server, rbac=False):
-    """Check that login fails after user is deleted from LDAP."""
+    """Check that login fails after user is deleted from LDAP.
+    """
     self.context.ldap_node = self.context.cluster.node(server)
     user = None
 
@@ -146,7 +151,8 @@ def login_after_user_is_deleted_from_ldap(self, server, rbac=False):
     RQ_SRS_007_LDAP_Authentication_PasswordChanged("1.0")
 )
 def login_after_user_password_changed_in_ldap(self, server, rbac=False):
-    """Check that login fails after user password is changed in LDAP."""
+    """Check that login fails after user password is changed in LDAP.
+    """
     self.context.ldap_node = self.context.cluster.node(server)
     user = None
 
@@ -182,7 +188,8 @@ def login_after_user_password_changed_in_ldap(self, server, rbac=False):
     RQ_SRS_007_LDAP_Authentication_UsernameChanged("1.0")
 )
 def login_after_user_cn_changed_in_ldap(self, server, rbac=False):
-    """Check that login fails after user cn is changed in LDAP."""
+    """Check that login fails after user cn is changed in LDAP.
+    """
     self.context.ldap_node = self.context.cluster.node(server)
     user = None
     new_user = None
@@ -215,7 +222,8 @@ def login_after_user_cn_changed_in_ldap(self, server, rbac=False):
     RQ_SRS_007_LDAP_Authentication_LDAPServerRestart("1.0")
 )
 def login_after_ldap_server_is_restarted(self, server, timeout=60, rbac=False):
-    """Check that login succeeds after LDAP server is restarted."""
+    """Check that login succeeds after LDAP server is restarted.
+    """
     self.context.ldap_node = self.context.cluster.node(server)
     user = None
 
@@ -250,7 +258,8 @@ def login_after_ldap_server_is_restarted(self, server, timeout=60, rbac=False):
     RQ_SRS_007_LDAP_Authentication_ClickHouseServerRestart("1.0")
 )
 def login_after_clickhouse_server_is_restarted(self, server, timeout=60, rbac=False):
-    """Check that login succeeds after ClickHouse server is restarted."""
+    """Check that login succeeds after ClickHouse server is restarted.
+    """
     self.context.ldap_node = self.context.cluster.node(server)
     user = None
 
@@ -285,7 +294,8 @@ def login_after_clickhouse_server_is_restarted(self, server, timeout=60, rbac=Fa
     RQ_SRS_007_LDAP_Authentication_Password_Empty("1.0")
 )
 def valid_username_with_valid_empty_password(self, server, rbac=False):
-    """Check that we can't login using valid username that has empty password."""
+    """Check that we can't login using valid username that has empty password.
+    """
     user = {"cn": "empty_password", "userpassword": ""}
     exitcode = 4
     message = f"DB::Exception: {user['cn']}: Authentication failed: password is incorrect or there is no user with such name"
@@ -298,7 +308,8 @@ def valid_username_with_valid_empty_password(self, server, rbac=False):
     RQ_SRS_007_LDAP_Authentication_Password_Empty("1.0")
 )
 def valid_username_and_invalid_empty_password(self, server, rbac=False):
-    """Check that we can't login using valid username but invalid empty password."""
+    """Check that we can't login using valid username but invalid empty password.
+    """
     username = "user_non_empty_password"
     user = {"cn": username, "userpassword": username}
     login = {"password": ""}
@@ -313,7 +324,8 @@ def valid_username_and_invalid_empty_password(self, server, rbac=False):
     RQ_SRS_007_LDAP_Authentication_Valid("1.0")
 )
 def valid_username_and_password(self, server, rbac=False):
-    """Check that we can login using valid username and password."""
+    """Check that we can login using valid username and password.
+    """
     username = "valid_username_and_password"
     user = {"cn": username, "userpassword": username}
 
@@ -326,7 +338,8 @@ def valid_username_and_password(self, server, rbac=False):
 )
 def valid_username_and_password_invalid_server(self, server=None, rbac=False):
     """Check that we can't login using valid username and valid
-    password but for a different server."""
+    password but for a different server.
+    """
     self.context.ldap_node = self.context.cluster.node("openldap1")
 
     user = {"username": "user2", "userpassword": "user2", "server": "openldap1"}
@@ -344,7 +357,8 @@ def valid_username_and_password_invalid_server(self, server=None, rbac=False):
     RQ_SRS_007_LDAP_Configuration_User_Name_Long("1.0")
 )
 def valid_long_username_and_short_password(self, server, rbac=False):
-    """Check that we can login using valid very long username and short password."""
+    """Check that we can login using valid very long username and short password.
+    """
     username = "long_username_12345678901234567890123456789012345678901234567890123456789012345678901234567890"
     user = {"cn": username, "userpassword": "long_username"}
 
@@ -355,7 +369,8 @@ def valid_long_username_and_short_password(self, server, rbac=False):
     RQ_SRS_007_LDAP_Authentication_Invalid("1.0")
 )
 def invalid_long_username_and_valid_short_password(self, server, rbac=False):
-    """Check that we can't login using slightly invalid long username but valid password."""
+    """Check that we can't login using slightly invalid long username but valid password.
+    """
     username = "long_username_12345678901234567890123456789012345678901234567890123456789012345678901234567890"
     user = {"cn": username, "userpassword": "long_username"}
     login = {"username": f"{username}?"}
@@ -371,7 +386,8 @@ def invalid_long_username_and_valid_short_password(self, server, rbac=False):
     RQ_SRS_007_LDAP_Authentication_Password_Long("1.0")
 )
 def valid_short_username_and_long_password(self, server, rbac=False):
-    """Check that we can login using valid short username with very long password."""
+    """Check that we can login using valid short username with very long password.
+    """
     username = "long_password"
     user = {"cn": username, "userpassword": "long_password_12345678901234567890123456789012345678901234567890123456789012345678901234567890"}
     add_user_to_ldap_and_login(user=user, server=server, rbac=rbac)
@@ -381,7 +397,8 @@ def valid_short_username_and_long_password(self, server, rbac=False):
     RQ_SRS_007_LDAP_Authentication_Invalid("1.0")
 )
 def valid_short_username_and_invalid_long_password(self, server, rbac=False):
-    """Check that we can't login using valid short username and invalid long password."""
+    """Check that we can't login using valid short username and invalid long password.
+    """
     username = "long_password"
     user = {"cn": username, "userpassword": "long_password_12345678901234567890123456789012345678901234567890123456789012345678901234567890"}
     login = {"password": user["userpassword"] + "1"}
@@ -396,7 +413,8 @@ def valid_short_username_and_invalid_long_password(self, server, rbac=False):
     RQ_SRS_007_LDAP_Authentication_Invalid("1.0")
 )
 def valid_username_and_invalid_password(self, server, rbac=False):
-    """Check that we can't login using valid username and invalid password."""
+    """Check that we can't login using valid username and invalid password.
+    """
     username = "valid_username_and_invalid_password"
     user = {"cn": username, "userpassword": username}
     login = {"password": user["userpassword"] + "1"}
@@ -411,7 +429,8 @@ def valid_username_and_invalid_password(self, server, rbac=False):
     RQ_SRS_007_LDAP_Authentication_Invalid("1.0")
 )
 def invalid_username_and_valid_password(self, server, rbac=False):
-    """Check that we can't login using slightly invalid username but valid password."""
+    """Check that we can't login using slightly invalid username but valid password.
+    """
     username = "invalid_username_and_valid_password"
     user = {"cn": username, "userpassword": username}
     login = {"username": user["cn"] + "1"}
@@ -428,7 +447,8 @@ def invalid_username_and_valid_password(self, server, rbac=False):
     RQ_SRS_007_LDAP_Configuration_User_Name_UTF8("1.0")
 )
 def valid_utf8_username_and_ascii_password(self, server, rbac=False):
-    """Check that we can login using valid utf-8 username with ascii password."""
+    """Check that we can login using valid utf-8 username with ascii password.
+    """
     username = "utf8_username_Gãńdåłf_Thê_Gręât"
     user = {"cn": username, "userpassword": "utf8_username"}
 
@@ -440,7 +460,8 @@ def valid_utf8_username_and_ascii_password(self, server, rbac=False):
     RQ_SRS_007_LDAP_Authentication_Password_UTF8("1.0")
 )
 def valid_ascii_username_and_utf8_password(self, server, rbac=False):
-    """Check that we can login using valid ascii username with utf-8 password."""
+    """Check that we can login using valid ascii username with utf-8 password.
+    """
     username = "utf8_password"
     user = {"cn": username, "userpassword": "utf8_password_Gãńdåłf_Thê_Gręât"}
 
@@ -449,7 +470,8 @@ def valid_ascii_username_and_utf8_password(self, server, rbac=False):
 @TestScenario
 def empty_username_and_empty_password(self, server=None, rbac=False):
     """Check that we can login using empty username and empty password as
-    it will use the default user and that has an empty password."""
+    it will use the default user and that has an empty password.
+    """
     login_and_execute_query(username="", password="")
 
 @TestOutline(Feature)

tests/testflows/ldap/authentication/tests/common.py

@@ -95,6 +95,8 @@ def add_config(config, timeout=20, restart=False):
             if exitcode == 0:
                 break
             time.sleep(1)
+        if settings.debug:
+            node.command(f"cat /var/lib/clickhouse/preprocessed_configs/{config.preprocessed_name}")
         assert exitcode == 0, error()
 
     def wait_for_config_to_be_loaded():

tests/testflows/ldap/authentication/tests/connections.py

@@ -98,7 +98,8 @@ def starttls_with_custom_port(self):
     login(servers, *users)
 
 def tls_connection(enable_tls, tls_require_cert):
-    """Try to login using LDAP user authentication over a TLS connection."""
+    """Try to login using LDAP user authentication over a TLS connection.
+    """
     servers = {
         "openldap2": {
             "host": "openldap2",
@@ -152,7 +153,8 @@ def tls(self):
     RQ_SRS_007_LDAP_Configuration_Server_EnableTLS_Options_Default("1.0")
 )
 def tls_enable_tls_default_yes(self):
-    """Check that the default value for the `enable_tls` is set to `yes`."""
+    """Check that the default value for the `enable_tls` is set to `yes`.
+    """
     servers = {
         "openldap2": {
             "host": "openldap2",
@@ -171,7 +173,8 @@ def tls_enable_tls_default_yes(self):
     RQ_SRS_007_LDAP_Configuration_Server_TLSRequireCert_Options_Default("1.0")
 )
 def tls_require_cert_default_demand(self):
-    """Check that the default value for the `tls_require_cert` is set to `demand`."""
+    """Check that the default value for the `tls_require_cert` is set to `demand`.
+    """
     servers = {
         "openldap2": {
             "host": "openldap2",
@@ -210,7 +213,8 @@ def starttls(self):
     RQ_SRS_007_LDAP_Configuration_Server_TLSCipherSuite("1.0")
 )
 def tls_cipher_suite(self):
-    """Check that `tls_cipher_suite` parameter can be used specify allowed cipher suites."""
+    """Check that `tls_cipher_suite` parameter can be used specify allowed cipher suites.
+    """
     servers = {
         "openldap4": {
             "host": "openldap4",
@@ -241,7 +245,8 @@ def tls_cipher_suite(self):
 ])
 def tls_minimum_protocol_version(self, version, exitcode, message):
     """Check that `tls_minimum_protocol_version` parameter can be used specify
-    to specify the minimum protocol version of SSL/TLS."""
+    to specify the minimum protocol version of SSL/TLS.
+    """
 
     servers = {
         "openldap4": {
@@ -278,6 +283,8 @@ def tls_minimum_protocol_version(self, version, exitcode, message):
 @TestFeature
 @Name("connection protocols")
 def feature(self, node="clickhouse1"):
+    """Check different LDAP connection protocols.
+    """
     self.context.node = self.context.cluster.node(node)
 
     for scenario in loads(current_module(), Scenario):

tests/testflows/ldap/authentication/tests/multiple_servers.py

@@ -14,6 +14,7 @@ def scenario(self, node="clickhouse1"):
     authenticate users.
     """
     self.context.node = self.context.cluster.node(node)
+
     servers = {
         "openldap1": {
             "host": "openldap1",
@@ -35,4 +36,6 @@ def scenario(self, node="clickhouse1"):
         {"server": "openldap1", "username": "user1", "password": "user1", "login": True},
         {"server": "openldap2", "username": "user2", "password": "user2", "login": True}
     ]
-    login(servers, *users)
+
+    with When("I add multiple LDAP servers and users that use different servers and try to login"):
+        login(servers, *users)

tests/testflows/ldap/authentication/tests/server_config.py

@@ -267,5 +267,6 @@ def feature(self, node="clickhouse1"):
     """Check that LDAP server configuration.
     """
     self.context.node = self.context.cluster.node(node)
+
     for scenario in loads(current_module(), Scenario):
         scenario()

tests/testflows/ldap/external_user_directory/tests/common.py

@@ -70,6 +70,15 @@ def rbac_roles(*roles):
                 with By(f"dropping role {role}", flags=TE):
                     node.query(f"DROP ROLE IF EXISTS {role}")
 
+def verify_ldap_user_exists(server, username, password):
+    """Check that LDAP user is defined on the LDAP server.
+    """
+    with By("searching LDAP database"):
+        ldap_node = current().context.cluster.node(server)
+        r = ldap_node.command(
+            f"ldapwhoami -H ldap://localhost -D 'cn={username},ou=users,dc=company,dc=com' -w {password}")
+        assert r.exitcode == 0, error()
+
 def create_ldap_external_user_directory_config_content(server=None, roles=None, **kwargs):
     """Create LDAP external user directory configuration file content.
     """
@@ -197,8 +206,26 @@ def login(servers, directory_server, *users, config=None):
 
 @TestStep(When)
 @Name("I login as {username} and execute query")
-def login_and_execute_query(self, username, password, exitcode=None, message=None, steps=True, timeout=60):
-    self.context.node.query("SELECT 1",
-        settings=[("user", username), ("password", password)],
-        exitcode=exitcode or 0,
-        message=message, steps=steps, timeout=timeout)
+def login_and_execute_query(self, username, password, exitcode=None, message=None, steps=True, timeout=60, poll=False):
+    if poll:
+        start_time = time.time()
+        attempt = 0
+
+        with By("repeatedly trying to login until successful or timeout"):
+            while True:
+                with When(f"attempt #{attempt}"):
+                    r = self.context.node.query("SELECT 1", settings=[("user", username), ("password", password)],
+                        no_checks=True, steps=False, timeout=timeout)
+
+                if r.exitcode == (0 if exitcode is None else exitcode) and (message in r.output if message is not None else True):
+                    break
+
+                if time.time() - start_time > timeout:
+                    fail(f"timeout {timeout} trying to login")
+
+                attempt += 1
+    else:
+        self.context.node.query("SELECT 1",
+            settings=[("user", username), ("password", password)],
+            exitcode=(0 if exitcode is None else exitcode),
+            message=message, steps=steps, timeout=timeout)