Unique constraint violation oc_authtoken

[Alex41160]

Hi,

With a fresh install of Owncloud I do have an issue with I believe OAuth2.

This always is the same user (mac user) that do provoque the following error:

{“reqId”:“ffa48ab4-7eb0-419c-b947-262eb08f2c65”,“level”:3,“time”:“2019-02-16T13:16:23+00:00”,“remoteAddr”:“192.168.1.1”,“user”:“46D3E531-855B-4458-B67A-39D5B47ECA50”,“app”:“OC\User\Session::createSessionToken”,“method”:“PROPFIND”,“url”:"/remote.php/dav/files/46D3E531-855B-4458-B67A-39D5B47ECA50/",“message”:“Exception: {“Exception”:“Doctrine\DBAL\Exception\UniqueConstraintViolationException”,“Message”:“An exception occurred while executing ‘INSERT INTO oc_authtoken(uid,login_name,name,token,type,last_activity,last_check) VALUES(?,?,?,?,?,?,?)’ with params [\“46D3E531-855B-4458-B67A-39D5B47ECA50\”, \“46D3E531-855B-4458-B67A-39D5B47ECA50\”, \“Mozilla/5.0 (Macintosh) mirall/2.5.2 (build 11198)”, \“f890299b609247757da477828576c915b2477bdc66adf9406799fd067f2edcc304840a280143ff90cf0a742ecc00a695b3f0bdbfc505cc527d2a71b812186b2a\”, 0, 1550322983, 1550322983]:

SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry ‘f890299b609247757da477828576c915b2477bdc66adf9406799fd067f2edcc3’ for key ‘authtoken_token_index’”,“Code”:0,“Trace”:”

#0 /var/www/html/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php(128): Doctrine\DBAL\Driver\AbstractMySQLDriver->convertException(‘An exception oc…’, Object(Doctrine\DBAL\Driver\PDOException))
#1 /var/www/html/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/Statement.php(177): Doctrine\DBAL\DBALException::driverExceptionDuringQuery(Object(Doctrine\DBAL\Driver\PDOMySql\Driver), Object(Doctrine\DBAL\Driver\PDOException), ‘INSERT INTO oc...', Array)
#2 /var/www/html/lib/public/AppFramework/Db/Mapper.php(241): Doctrine\DBAL\Statement->execute()
#3 /var/www/html/lib/public/AppFramework/Db/Mapper.php(119): OCP\AppFramework\Db\Mapper->execute('INSERT INTOP…’, Array)
#4 /var/www/html/lib/private/Authentication/Token/DefaultTokenProvider.php(101): OCP\AppFramework\Db\Mapper->insert(Object(OC\Authentication\Token\DefaultToken))
#5 /var/www/html/lib/private/User/Session.php(726): OC\Authentication\Token\DefaultTokenProvider->generateToken(** sensitive parameters replaced ***)
#6 /var/www/html/lib/private/User/Session.php(965): OC\User\Session->createSessionToken(Object(OC\AppFramework\Http\Request), ‘46D3E531-855B-4…’, ‘46D3E531-855B-4…’, NULL)
#7 /var/www/html/apps/oauth2/lib/Sabre/OAuth2.php(120): OC\User\Session->tryAuthModuleLogin(Object(OC\AppFramework\Http\Request))
#8 /var/www/html/apps/oauth2/lib/Sabre/AbstractBearer.php(99): OCA\OAuth2\Sabre\OAuth2->validateBearerToken(‘byRXmYzxr7xSJX7…’)
#9 /var/www/html/lib/composer/sabre/dav/lib/DAV/Auth/Plugin.php(201): OCA\OAuth2\Sabre\AbstractBearer->check(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))
#10 /var/www/html/lib/composer/sabre/dav/lib/DAV/Auth/Plugin.php(150): Sabre\DAV\Auth\Plugin->check(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))
#11 [internal function]: Sabre\DAV\Auth\Plugin->beforeMethod(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))
#12 /var/www/html/lib/composer/sabre/event/lib/EventEmitterTrait.php(105): call_user_func_array(Array, Array)
#13 /var/www/html/lib/composer/sabre/dav/lib/DAV/Server.php(466): Sabre\Event\EventEmitter->emit(‘beforeMethod’, Array)
#14 /var/www/html/lib/composer/sabre/dav/lib/DAV/Server.php(254): Sabre\DAV\Server->invokeMethod(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))
#15 /var/www/html/apps/dav/lib/Server.php(298): Sabre\DAV\Server->exec()
#16 /var/www/html/apps/dav/appinfo/v2/remote.php(31): OCA\DAV\Server->exec()
#17 /var/www/html/remote.php(165): require_once(’/var/www/html/a…’)
#18 {main}",“File”:"/var/www/html/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/Driver/AbstractMySQLDriver.php",“Line”:66}"}

What makes me think that it is due to the server is this line:

There are code paths that trigger the generation of an auth token for the same session twice. We log this to trace the code paths. Please send all log lines belonging to this request id.

If you have any ideas, AM.

[ownclouders]

GitMate.io thinks the contributors most likely able to help are @ownclouders, and @PVince81.

Possibly related issues are https://github.com/owncloud/core/issues/26192 (SQLSTATE[23000]: Integrity constraint violation: 19 UNIQUE constraint failed: oc_filecache.storage, oc_filecache.path_hash), https://github.com/owncloud/core/issues/19094 (oc_file_locks constraint violation), https://github.com/owncloud/core/issues/12519 (Integrity constraint violation: 1062 Duplicate entry), https://github.com/owncloud/core/issues/34185 (Integrity constraint violation [PRODUCTION CRASH]), and https://github.com/owncloud/core/issues/2566 (SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry ).

[davitol]

Hi @Alex41160 . i have just tried to log in using oauth2 in oC 10.1 and works for me. Can you please provide more feedback of your issue using the repo template?

https://github.com/owncloud/core/blob/master/.github/issue_template.md

Thanks for reporting!

[Alex41160]

I am not sure as well on how to reproduce it. I just know that it is spamming the logs. I do think that it is always due to the same user that is using the mac version of the client. He is able to connect though so he doesn't see this error.

Steps to reproduce

• Unknown

Expected behaviour

• The user can connect without any errors in the logs

Actual behaviour

• The user can connect but an error is written in the logs

Server configuration Operating system: Ubuntu 18.04 lts Web server: apache2 Database: mysql PHP version: 7.2 ownCloud version: 10.0.10.4

Updated from an older ownCloud or fresh install: fresh install Where did you install ownCloud from: The website, no appliance

Signing status (ownCloud 9.0 and above):

Login as admin user into your ownCloud and access http://example.com/index.php/settings/integrity/failed : no error

Are you using encryption: no Are you using an external user-backend, if yes which one: LDAP

Browser: Chrome Operating system: Windows 10

config_report_20190221.txt

owncloud (1).log

Hope it helps. Thanks, AM.

[PVince81]

@tomneedham @DeepDiver1975

[guimaluf]

We're getting around 40 events of that type per day. That error makes desktop client lose their session

Operating system: Ubuntu 14.04.5 LTS

Web server: Apache/2.4.33 (Ubuntu)

Database: mysqld Ver 5.5.54-1trusty for debian-linux-gnu on x86_64 ((Ubuntu), wsrep_25.20) galera-3 25.3.23+1trusty

PHP version: PHP 5.6.34-1+ubuntu14.04.1+deb.sury.org+1 (fpm-fcgi)

ownCloud version: (see ownCloud admin page) 10.0.10

Updated from an older ownCloud or fresh install: Updated from 7, then from 9

[daincredibleholg]

It is the same for me.

OwnCloud 10.2.1.4 CE Ubuntu 16.04.6 LTS MariaDB 10.2.27 Apache 2.4.18

Updated over the last years, I think from 6 or 7 onwards.

[cortho]

I can confirm this too. I am not sure how to reproduce it, but it keeps filling the logs.

ownCloud 10.3.2 oauth2 0.4.2

I don't think it depends on the clients, amongst them are

Mozilla/5.0 (Macintosh) mirall/2.5.1 (build 10818) Mozilla/5.0 (Macintosh) mirall/2.6.0 (build 12703) Mozilla/5.0 (Windows) mirall/2.5.4 (build 11415) Mozilla/5.0 (Windows) mirall/2.6.0 (build 12644)

Related? https://github.com/owncloud/oauth2/issues/227

[cdamken]

The solution is described in the release notes from 10.3.0 with OAuth: https://doc.owncloud.com/server/10.4/admin_manual/release_notes.html#oauth2-and-session-handling-improvements

if you are using the ownCloud-Docker it will be released with the solution in the next days.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 10 days if no further activity occurs. Thank you for your contributions.

[stale[bot]]

This issue has been automatically closed.

[butonic]

I will reopen this issue to debug the code paths that can cause this.

To be clear, the error in the log alone is not an indicator of any problem, other than us not cleaning up the code. We are actually catching the exception in https://github.com/owncloud/core/blob/8c5e5fb37b31b45c88275304c8033b57a04fbf1d/lib/private/User/Session.php#L757 and returning true. No client will ever see this exception.

We could change the default token mapper to insert if not exists to get rid of the error message. For now, we ignore that error.

Here is what else I know:

The OCA\DAV\Connector\Sabre\Auth::auth() seems to create a sessioen for shibboleth users. It will call -> public function loginWithApache(IApacheBackend $apacheBackend) -> calls $this->createSessionToken($request, $uid, $uid);

If the oauth2 app then is called as well we might see the duplicate key error?

There was a PR that removed token creation from loadApps(): https://github.com/owncloud/core/pull/31428 but it got reverted because we did not have time to properly QA it and instead we just settled with logging an exception and ignoring the duplicate insert.

There was a plan to bring it back: https://github.com/owncloud/core/issues/31731#issuecomment-396970001

But https://github.com/owncloud/core/pull/31782 was closed ...

Needs manual QA as the PR caused https://github.com/owncloud/core/issues/31731

Also if you want to dig into auth token creation add conditional logging as described in: https://github.com/owncloud/core/pull/31460#issue-323948177

[butonic]

I received another log:

ORA-00001: unique constraint (OCAUSER.AUTHTOKEN_TOKEN_INDEX) violated\",\"Code\":0,\"Trace\":\"
#0 /data/ocweb/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/Driver/OCI8/OCI8Statement.php(405): Doctrine\\DBAL\\Driver\\OCI8\\OCI8Exception::fromErrorInfo(Array)\
#1 /data/ocweb/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/Statement.php(155): Doctrine\\DBAL\\Driver\\OCI8\\OCI8Statement->execute(NULL)\
#2 /data/ocweb/lib/public/AppFramework/Db/Mapper.php(241): Doctrine\\DBAL\\Statement->execute()\
#3 /data/ocweb/lib/public/AppFramework/Db/Mapper.php(119): OCP\\AppFramework\\Db\\Mapper->execute('INSERT INTO `*P...', Array)\
#4 /data/ocweb/lib/private/Authentication/Token/DefaultTokenProvider.php(101): OCP\\AppFramework\\Db\\Mapper->insert(Object(OC\\Authentication\\Token\\DefaultToken))\
#5 /data/ocweb/lib/private/User/Session.php(732): OC\\Authentication\\Token\\DefaultTokenProvider->generateToken(*** sensitive parameters replaced ***)\
#6 /data/ocweb/lib/private/User/Session.php(981): OC\\User\\Session->createSessionToken(Object(OC\\AppFramework\\Http\\Request), 'uuuuu', 'uuuuu', NULL)\
#7 /data/ocweb/apps/oauth2/lib/Sabre/OAuth2.php(123): OC\\User\\Session->tryAuthModuleLogin(Object(OC\\AppFramework\\Http\\Request))\
#8 /data/ocweb/apps/oauth2/lib/Sabre/AbstractBearer.php(99): OCA\\OAuth2\\Sabre\\OAuth2->validateBearerToken('2Knnft85GbX4aQJ...')\
#9 /data/ocweb/lib/composer/sabre/dav/lib/DAV/Auth/Plugin.php(182): OCA\\OAuth2\\Sabre\\AbstractBearer->check(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\
#10 /data/ocweb/lib/composer/sabre/dav/lib/DAV/Auth/Plugin.php(137): Sabre\\DAV\\Auth\\Plugin->check(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\
#11 /data/ocweb/lib/composer/sabre/event/lib/WildcardEmitterTrait.php(89): Sabre\\DAV\\Auth\\Plugin->beforeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\
#12 /data/ocweb/lib/composer/sabre/dav/lib/DAV/Server.php(456): Sabre\\DAV\\Server->emit('beforeMethod:PR...', Array)\
#13 /data/ocweb/lib/composer/sabre/dav/lib/DAV/Server.php(253): Sabre\\DAV\\Server->invokeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\
#14 /data/ocweb/apps/dav/lib/Server.php(330): Sabre\\DAV\\Server->start()\
#15 /data/ocweb/apps/dav/appinfo/v2/remote.php(31): OCA\\DAV\\Server->exec()\
#16 /data/ocweb/remote.php(165): require_once('/data/ocweb/app...')\
#17 {main}\",\"File\":\"/data/ocweb/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/Driver/OCI8/OCI8Exception.php

In this trace as well as the TOP post I see the oauth2 app calling tryAuthModuleLogin

[butonic]

This is a related trace caused by a different unique constraint error

ORA-00001: unique constraint (OCAUSER.SYS_C0015122) violated\",\"Code\":0,\"Trace\":\"#0 /data/ocweb/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/Driver/OCI8/OCI8Statement.php(405): Doctrine\DBAL\Driver\OCI8\OCI8Exception::fromErrorInfo(Array)\
#1 /data/ocweb/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/Statement.php(155): Doctrine\DBAL\Driver\OCI8\OCI8Statement->execute(NULL)\
#2 /data/ocweb/lib/public/AppFramework/Db/Mapper.php(241): Doctrine\DBAL\Statement->execute()\
#3 /data/ocweb/lib/public/AppFramework/Db/Mapper.php(119): OCP\AppFramework\Db\Mapper->execute('INSERT INTO `*P...', Array)\
#4 /data/ocweb/lib/private/Authentication/Token/DefaultTokenProvider.php(101): OCP\AppFramework\Db\Mapper->insert(Object(OC\Authentication\Token\DefaultToken))\
#5 /data/ocweb/lib/private/User/Session.php(732): OC\Authentication\Token\DefaultTokenProvider->generateToken(*** sensitive parameters replaced ***)\
#6 /data/ocweb/core/Controller/LoginController.php(251): OC\User\Session->createSessionToken(*** sensitive parameters replaced ***)\
#7 /data/ocweb/lib/private/AppFramework/Http/Dispatcher.php(153): OC\Core\Controller\LoginController->tryLogin(*** sensitive parameters replaced ***)\
#8 /data/ocweb/lib/private/AppFramework/Http/Dispatcher.php(85): OC\AppFramework\Http\Dispatcher->executeController(Object(OC\Core\Controller\LoginController), 'tryLogin')\
#9 /data/ocweb/lib/private/AppFramework/App.php(100): OC\AppFramework\Http\Dispatcher->dispatch(Object(OC\Core\Controller\LoginController), 'tryLogin')\
#10 /data/ocweb/lib/private/AppFramework/Routing/RouteActionHandler.php(47): OC\AppFramework\App::main('LoginController', 'tryLogin', Object(OC\AppFramework\DependencyInjection\DIContainer), Array)\
#11 /data/ocweb/lib/private/Route/Router.php(341): OC\AppFramework\Routing\RouteActionHandler->__invoke(Array)\
#12 /data/ocweb/lib/base.php(915): OC\Route\Router->match('/login')\
#13 /data/ocweb/index.php(54): OC::handleRequest()\
#14 {main}\",\"File\":\"/data/ocweb/lib/composer/doctrine/dbal/lib/Doctrine/DBAL/Driver/OCI8/OCI8Exception.php

ba aware that this trace is not caused by a dublicate token, but actually a duplicate primary key which was caused by restoring an inconsistend oracle backup where sequence id and max table id no longer matched. But we can use it to compare the code paths.

This trace uses OC\Core\Controller\LoginController->tryLogin.

[butonic]

One code path for the user_shibboleth app is that in base php we find:

	/**
	 * Check login: apache auth, auth token, basic auth
	 *
	 * @param OCP\IRequest $request
	 * @return boolean
	 */
	public static function handleLogin(OCP\IRequest $request) {
		$userSession = self::$server->getUserSession();
		if (OC_User::handleApacheAuth()) {
			return true;
		}
		if ($userSession->tryTokenLogin($request)) {
			return true;
		}
		if ($userSession->tryAuthModuleLogin($request)) {
			return true;
		}
		if ($userSession->tryBasicAuthLogin($request)) {
			return true;
		}
		return false;
	}

OC_User::handleApacheAuth() finds the first active user backend (user_shibboleth) and then loads ALL apps:

	public static function handleApacheAuth() {
		$backend = self::findFirstActiveUsedBackend();
		if ($backend) {
			OC_App::loadApps();

			//setup extra user backends
			self::setupBackends();
			self::unsetMagicInCookie();

			return self::loginWithApache($backend);
		}

		return null;
	}

this method body leads to two calls to the createSessionToken:

1. OC_App::loadApps(); internally calls createSessionToken. This part was supposed to die a long time ago already: https://github.com/owncloud/core/pull/31782
2. self::loginWithApache($backend); is just a redirect:

	public static function loginWithApache(\OCP\Authentication\IApacheBackend $backend) {
		return self::getUserSession()->loginWithApache($backend);
	}

Now we are out of legacy land, and the UserSession first syncs the user metadata to the accounts table and then makes the second call to

			$request = OC::$server->getRequest();
			$this->createSessionToken($request, $uid, $uid);

That is how the createSessionToken code might get executed twice for user_shibboleth.

[cdamken]

Any news here?