search

tine-groupware / tine

tine groupware main repository
https://www.tine-groupware.de
GNU Affero General Public License v3.0
11 stars 2 forks source link

Login with TOTP denied after some time #26

Closed zud222 closed 2 months ago

zud222 commented 4 months ago

I'm trying to set up MFA with Tine but am consistently running into a weird problem:

When I register TOTP, I can initially use it for logging in. However, after some time, all generated codes are denied.

My setup:

I am generating codes with both hardware token and local app - both come out identical. Also, time on all devices is in sync. Fortunately, the Fido stick that's also registered keeps working flawlessly...

What am I doing wrong?

pschuele commented 4 months ago

my initial thought was that the time is not in sync ... :wink: do you see anything in the tine logs (DEBUG level)?

zud222 commented 4 months ago

That would pretty well explain it... 😉... but unfortunately, both client and server are very much in sync (ntp'ing the same time server).

I had, however, some other strange behaviour lately, which I could pin down to insufficient access permissions in the tine data directory (probably caused by running setup.php as root). So I just registered my token once again and will report in a couple of days if this issue is solved...

zud222 commented 4 months ago

Strange. It worked until this morning... now all MFA codes are rejected again... however, the log shows some error at the end but I can't figure out what's going wrong...

Log:

3b04aa - -- none -- - 2024-03-24T16:28:52+00:00 INFO (6): Tinebase_Core::setupLogger::891 Logger initialized.
3b04aa - -- none -- - 2024-03-24T16:28:52+00:00 INFO (6): index.php (20) Start processing request (PID: 11853)
3b04aa - -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_Core::setExecutionLifeTime::1462 setting execution life time to: 0
3b04aa - -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_Core::createAndConfigureDbAdapter::1232 DB connection id: 16311
3b04aa - -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_Core::dispatchRequest::259 Client transaction a5e594fa387bf91272ccad939a2a37f8c34e78dc
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_Session_Abstract::setSessionOptions::361 Session options: Array
(
    [name] => TINE20SESSID
    [hash_function] => 1
    [cookie_httponly] => 1
    [cookie_path] => /
    [cookie_secure] => 1
    [cookie_samesite] => none
)

3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_Session_Abstract::getSessionDir::194 Using session dir: /var/lib/php/sessions/tine20_sessions
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 INFO (6): Tinebase_Session_Abstract::setSessionBackend::316 Session of backend type 'File' configured.
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 INFO (6): Tinebase_Core::initFramework::483 initializing framework (PID: 11853)
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_Translation::getLocale::205 given localeString 'en_US'
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_Translation::getLocale::218 'en_US' is not supported, checking fallback
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_Translation::getLocale::244 selected locale: 'en'
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_Core::setupUserLocale::1329 given localeString 'auto'
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_Core::setupUserLocale::1339 Got locale from session : de
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 INFO (6): Tinebase_Core::setupUserLocale::1380 Setting user locale: de
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_Core::setupUserLocale::1389 Setting CTYPE locale from "C" to "en_US.UTF8".
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_Server_Json::_logRequests::241 is JSON request. rawdata: array (
  0 => 
  array (
    'jsonrpc' => '2.0',
    'method' => 'Tinebase.login',
    'params' => 
    array (
      'username' => 'xXXx',
      'password' => '*******',
    ),
    'id' => 6,
  ),
)
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 INFO (6): Tinebase_Server_Json::_handle::400 is JSON request. method: Tinebase.login
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_Server_Json::_getServer::337 Get server from cache
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_Server_Json::_handle::425 handle request ...
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_License::getInstance::59 License class used: Tinebase_License_BusinessEdition
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_Auth::setBackend::309 authentication backend: Sql
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_Auth::authenticate::207 Trying to authenticate xXXx
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_User::setBackendType::326 Setting backend type to Sql
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Addressbook_Controller_Contact::__construct::71 Geolocation service disabled with config option.
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_User_Abstract::registerPlugin::127 Registering Addressbook_Controller_Contact plugin.
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_User_Sql::registerPlugin::117 Registering Addressbook_Controller_Contact SQL plugin.
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_User_Abstract::registerPlugin::127 Registering Tinebase_EmailUser_Imap_Standard plugin.
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_User_Sql::registerPlugin::117 Registering Tinebase_EmailUser_Imap_Standard SQL plugin.
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_User_Abstract::registerPlugin::127 Registering Tinebase_EmailUser_Smtp_Standard plugin.
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_User_Sql::registerPlugin::117 Registering Tinebase_EmailUser_Smtp_Standard SQL plugin.
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_User::factory::287 Created user backend of type Tinebase_User_Sql
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 INFO (6): Tinebase_Core::setUser::1728 Setting user xXXx
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 NOTICE (5): Tinebase_Server_Json::_handleException::457 Tinebase_Exception_AreaLocked -> mfa required
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 DEBUG (7): Tinebase_Server_Json::_getServer::351 setting up json server ...
3b04aa a5e59 -- none -- - 2024-03-24T16:28:52+00:00 INFO (6): Tinebase_Log::logUsageAndMethod::299 {"file":"index.php","method":"Tinebase_Server_Json::Tinebase.login","time":"14ms","memory":" Memory usage: 14 MB","cache":" Real patch cache size: 219576","pid":11853}
fbd180 - -- none -- - 2024-03-24T16:29:00+00:00 INFO (6): Tinebase_Core::setupLogger::891 Logger initialized.
fbd180 - -- none -- - 2024-03-24T16:29:00+00:00 INFO (6): index.php (20) Start processing request (PID: 16367)
fbd180 - -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Core::setExecutionLifeTime::1462 setting execution life time to: 0
fbd180 - -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Core::createAndConfigureDbAdapter::1232 DB connection id: 16312
fbd180 - -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Core::dispatchRequest::259 Client transaction eac177ec1cedd88d9e5557fa9f7eba8edaf5edd4
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Session_Abstract::setSessionOptions::361 Session options: Array
(
    [name] => TINE20SESSID
    [hash_function] => 1
    [cookie_httponly] => 1
    [cookie_path] => /
    [cookie_secure] => 1
    [cookie_samesite] => none
)

fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Session_Abstract::getSessionDir::194 Using session dir: /var/lib/php/sessions/tine20_sessions
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 INFO (6): Tinebase_Session_Abstract::setSessionBackend::316 Session of backend type 'File' configured.
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 INFO (6): Tinebase_Core::initFramework::483 initializing framework (PID: 16367)
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Translation::getLocale::205 given localeString 'en_US'
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Translation::getLocale::218 'en_US' is not supported, checking fallback
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Translation::getLocale::244 selected locale: 'en'
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Core::setupUserLocale::1329 given localeString 'auto'
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Core::setupUserLocale::1339 Got locale from session : de
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 INFO (6): Tinebase_Core::setupUserLocale::1380 Setting user locale: de
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Core::setupUserLocale::1389 Setting CTYPE locale from "C" to "en_US.UTF8".
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Server_Json::_logRequests::241 is JSON request. rawdata: array (
  0 => 
  array (
    'jsonrpc' => '2.0',
    'method' => 'Tinebase.login',
    'params' => 
    array (
      'username' => 'xXXx',
      'password' => '*******',
      'MFAUserConfigId' => '[...]',
      'MFAPassword' => '[...]',
    ),
    'id' => 7,
  ),
)
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 INFO (6): Tinebase_Server_Json::_handle::400 is JSON request. method: Tinebase.login
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Server_Json::_getServer::337 Get server from cache
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Server_Json::_getServer::351 setting up json server ...
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Server_Json::_handle::425 handle request ...
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_License::getInstance::59 License class used: Tinebase_License_BusinessEdition
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Auth::setBackend::309 authentication backend: Sql
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Auth::authenticate::207 Trying to authenticate xXXx
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_User::setBackendType::326 Setting backend type to Sql
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Addressbook_Controller_Contact::__construct::71 Geolocation service disabled with config option.
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_User_Abstract::registerPlugin::127 Registering Addressbook_Controller_Contact plugin.
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_User_Sql::registerPlugin::117 Registering Addressbook_Controller_Contact SQL plugin.
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_User_Abstract::registerPlugin::127 Registering Tinebase_EmailUser_Imap_Standard plugin.
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_User_Sql::registerPlugin::117 Registering Tinebase_EmailUser_Imap_Standard SQL plugin.
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_User_Abstract::registerPlugin::127 Registering Tinebase_EmailUser_Smtp_Standard plugin.
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_User_Sql::registerPlugin::117 Registering Tinebase_EmailUser_Smtp_Standard SQL plugin.
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_User::factory::287 Created user backend of type Tinebase_User_Sql
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 INFO (6): Tinebase_Core::setUser::1728 Setting user xXXx
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Auth_CredentialCache::setCacheAdapter::110 Using credential cache adapter: Tinebase_Auth_CredentialCache_Adapter_Cookie
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 NOTICE (5): Tinebase_Exception::logExceptionToLogger::135 Tinebase_Exception_NotFound -> Tinebase_Model_CredentialCache record with id = 831ee2c82bbd3db9ed93c38e89eb167d3d0a7a75 not found!
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 NOTICE (5): Tinebase_Exception::logExceptionToLogger::157 #0 .../Tinebase/Backend/Sql/Abstract.php(288): Tinebase_Backend_Sql_Abstract->getRawDataByProperty()
#1 .../Tinebase/Backend/Sql/Abstract.php(257): Tinebase_Backend_Sql_Abstract->getByProperty()
#2 .../Tinebase/Auth/MFA/HTOTPAdapter.php(50): Tinebase_Backend_Sql_Abstract->get()
#3 .../Tinebase/Auth/MFA.php(64): Tinebase_Auth_MFA_HTOTPAdapter->validate()
#4 .../Tinebase/AreaLock.php(183): Tinebase_Auth_MFA->validate()
#5 .../Tinebase/Controller.php(971): Tinebase_AreaLock->unlock()
#6 .../Tinebase/Controller.php(885): Tinebase_Controller->_validateSecondFactor()
#7 .../Tinebase/Controller.php(127): Tinebase_Controller->_validateAuthResult()
#8 .../Tinebase/Frontend/Json.php(619): Tinebase_Controller->login()
#9 .../vendor/zendframework/zendframework1/library/Zend/Server/Abstract.php(231): Tinebase_Frontend_Json->login()
#10 .../vendor/zendframework/zendframework1/library/Zend/Json/Server.php(603): Zend_Server_Abstract->_dispatch()
#11 .../vendor/zendframework/zendframework1/library/Zend/Json/Server.php(206): Zend_Json_Server->_handle()
#12 .../Tinebase/Server/Json.php(427): Zend_Json_Server->handle()
#13 .../Tinebase/Server/Json.php(181): Tinebase_Server_Json->_handle()
#14 .../Tinebase/Core.php(270): Tinebase_Server_Json->handle()
#15 .../index.php(24): Tinebase_Core::dispatchRequest()
#16 {main}
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 NOTICE (5): Tinebase_Server_Json::_handleException::457 Tinebase_Exception_SystemGeneric -> MFA validation failed, please try again or check with your system administrator
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 DEBUG (7): Tinebase_Server_Json::_getServer::351 setting up json server ...
fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 INFO (6): Tinebase_Log::logUsageAndMethod::299 {"file":"index.php","method":"Tinebase_Server_Json::Tinebase.login","time":"16ms","memory":" Memory usage: 20 MB","cache":" Real patch cache size: 229086","pid":16367}
ignoreigor commented 3 months ago

Obviously, when truncation table tine20_credential_cache MFA is no longer working ([weekly-2024.12.1]).

fbd180 eac17 -- none -- - 2024-03-24T16:29:00+00:00 NOTICE (5): Tinebase_Exception::logExceptionToLogger::135 Tinebase_Exception_NotFound -> Tinebase_Model_CredentialCache record with id = 831ee2c82bbd3db9ed93c38e89eb167d3d0a7a75 not found!

Did you run some tidy up-crons on your own?

There's a daily task Tinebase_CredentialCacheCleanup in the scheduler, but it should only remove invalid credentials. Maybe you got a backup and can have a look at the time limits (creation_time, valid_until) of credential-cache entry 831ee2c82bbd3db9ed93c38e89eb167d3d0a7a75.

zud222 commented 3 months ago

Yes, there are actually two cron jobs cleaning up caches:

/usr/bin/php /var/html/tine/tine20.php --method Tinebase.clearTable credential_cache access_log async_job -- date=$(date -d -1day +%Y-%m-%d)
/usr/bin/php /var/html/tine/tine20.php --method Tinebase.purgeDeletedRecords -- date=$(date -d -7days +%Y-%m-%d)

The first should clear entries which are older than 24h. I set this up ages ago to avoid bloating the database and had completely forgotten about it. Are you saying that I could get rid of this completely because now tine takes care of this anyway?

ignoreigor commented 3 months ago

Don't saying that. But maybe yes. Have a look at the scheduler in your admin-app. There are several tasks installed by default. The scheduler is started by running triggerAsyncEvents.

https://tine-docu.s3web.rz1.metaways.net/operators/howto/tine20AdminScheduler/

Maybe just remove table credentialsCache from your own crons and see whether MFA will not fail for longer time. It seems that MFA is using credentials cache (why not) but updating is at least done after successful login, which won't be possible if credential caches are deleted. So my first and dirty guess, which may be wrong.

zud222 commented 3 months ago

Thank you very much! I replaced my cron jobs with the one proposed in the documentation and set up MFA once again. Will report back in a few days if this solved the issue.

zud222 commented 3 months ago

I can gladly report that not clearing credentials_cache appears to have solved my problem. I replaced my cron jobs with the scheduler job as pointed out above and now mfa works consistently.

Thanks to @ignoreigor for helping me out on this!

pschuele commented 2 months ago

hi, thanks for reporting and debugging this issue! I had a look into the code and think that it's problematic, that the MFA CC records are removed by Tinebase.clearTable when a date is given. I'll change that, so that only invalid/obsolete records are removed from the credential cache table.

A fix is incoming, re-opened the issue until the fix is in the repo...