Backends provided no user object for LDAP User

[cormite]

Steps to reproduce

1. Upgrade from 9.1.4 to 9.1.5 and finally to 10.0.1.5
2. No errors are shown during the update process so nothing else worth to be reported.

Expected behavior

If no errors are show during the update, the expected behavior would be a clean log file

Actual behavior

owncloud.log shows many errors of the type:

"{"reqId":"WS1xZ1KniSdmJ8jr-ICETgAAACU","level":3,"time":"2017-05-30T13:19:36+00:00","remoteAddr":"SENSITIVE_DATA","user":"SENSITIVE_DATA","app":"files","method":"PROPFIND","url":"\/remote.php\/webdav\/","message":" Backends provided no user object for SENSITIVE_DATA"}

This means some user cannot get shared files and receive a "Internal Server Error" message.

When making a occ files:scan on the user represented by SENSITIVE_DATA, the response is "Unknown user 1 SENSITIVE_DATA". This happens until the user logs in for the first time. Obviously the login triggers something so the user is no longer unknown.

Once the user logs in, then the person who received the "Internal Server Error" sees the Shared content again.

Server configuration

Operating system:
CentOS Linux release 7.3.1611 (Core)

Web server:
Apache 2.4.6

Database:
mysql Ver 15.1 Distrib 5.5.52-MariaDB, for Linux (x86_64) using readline 5.1

PHP version:
PHP 5.6.30

ownCloud version: (see ownCloud admin page)
ownCloud 10.0.1.5

Updated from an older ownCloud or fresh install:
Upgraded from 9.1.4 to 9.1.5 to 10.0.1.5

Where did you install ownCloud from:
Manual upgrade performed without any errors reported. The files where downloaded from owncloud.org.

Signing status (ownCloud 9.0 and above):
All good except .htaccess integrity due to modification of upload_max_size
https://gist.github.com/cormite/42c80455d3f300ff9c808853d56390ed

The content of config/config.php:
https://gist.github.com/cormite/a3de7da5a4bef885226ace36a82c55c2

List of activated apps:

Enabled:
  - activity: 2.3.4
  - comments: 0.3.0
  - configreport: 0.1.1
  - contacts: 1.5.2
  - dav: 0.2.9
  - federatedfilesharing: 0.3.0
  - federation: 0.1.0
  - files: 1.5.1
  - files_external: 0.7.0
  - files_pdfviewer: 0.8.2
  - files_sharing: 0.10.0
  - files_texteditor: 2.2
  - files_trashbin: 0.9.0
  - files_versions: 1.3.0
  - files_videoplayer: 0.9.8
  - firstrunwizard: 1.1
  - gallery: 16.0.2
  - market: 0.1.0
  - notifications: 0.3.0
  - provisioning_api: 0.5.0
  - systemtags: 0.3.0
  - templateeditor: 0.1
  - updatenotification: 0.2.1
  - user_ldap: 0.9.1
Disabled:
  - encryption
  - external
  - files_antivirus
  - theme-example
  - user_external

Are you using external storage, if yes which one: NFS

Are you using encryption: no

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

LDAP configuration (delete this part if not used)

+-------------------------------+-------------------------------------------------------------------------------------------------+
| Configuration                 |                                                                                                 |
+-------------------------------+-------------------------------------------------------------------------------------------------+
| hasMemberOfFilterSupport      | 0                                                                                               |
| hasPagedResultSupport         |                                                                                                 |
| homeFolderNamingRule          |                                                                                                 |
| lastJpegPhotoLookup           | 0                                                                                               |
| ldapAgentName                 |                                                                                                 |
| ldapAgentPassword             | ***                                                                                             |
| ldapAttributesForGroupSearch  |                                                                                                 |
| ldapAttributesForUserSearch   |                                                                                                 |
| ldapBackupHost                |                                                                                                 |
| ldapBackupPort                |                                                                                                 |
| ldapBase                      |                                                                                                 |
| ldapBaseGroups                |                                                                                                 |
| ldapBaseUsers                 |                                                                                                 |
| ldapCacheTTL                  | 600                                                                                             |
| ldapConfigurationActive       | 1                                                                                               |
| ldapDynamicGroupMemberURL     |                                                                                                 |
| ldapEmailAttribute            |                                                                                                 |
| ldapExperiencedAdmin          | 0                                                                                               |
| ldapExpertUUIDGroupAttr       |                                                                                                 |
| ldapExpertUUIDUserAttr        |                                                                                                 |
| ldapExpertUsernameAttr        |                                                                                                 |
| ldapGroupDisplayName          |                                                                                                 |
| ldapGroupFilter               | (&(|(objectclass=top)))                                                                         |
| ldapGroupFilterGroups         |                                                                                                 |
| ldapGroupFilterMode           | 0                                                                                               |
| ldapGroupFilterObjectclass    | top                                                                                             |
| ldapGroupMemberAssocAttr      | uniqueMember                                                                                    |
| ldapHost                      |                                                                                                 |
| ldapIgnoreNamingRules         |                                                                                                 |
| ldapLoginFilter               | uid=%uid                                                                                        |
| ldapLoginFilterAttributes     |                                                                                                 |
| ldapLoginFilterEmail          | 0                                                                                               |
| ldapLoginFilterMode           | 1                                                                                               |
| ldapLoginFilterUsername       | 1                                                                                               |
| ldapNestedGroups              | 0                                                                                               |
| ldapOverrideMainServer        | 0                                                                                               |
| ldapPagingSize                | 500                                                                                             |
| ldapPort                      |                                                                                                 |
| ldapQuotaAttribute            |                                                                                                 |
| ldapQuotaDefault              |                                                                                                 |
| ldapTLS                       | 0                                                                                               |
| ldapUserDisplayName           | displayname                                                                                     |
| ldapUserDisplayName2          |                                                                                                 |
| ldapUserFilter                |                                                                                                 |
| ldapUserFilterGroups          |                                                                                                 |
| ldapUserFilterMode            | 1                                                                                               |
| ldapUserFilterObjectclass     |                                                                                                 |
| ldapUuidGroupAttribute        | auto                                                                                            |
| ldapUuidUserAttribute         | auto                                                                                            |
| turnOffCertCheck              | 0                                                                                               |
| useMemberOfToDetectMembership | 1                                                                                               |
+-------------------------------+-------------------------------------------------------------------------------------------------+

Client configuration

Browser:
Firefox, Chrome, Explorer (many different versions). We have > 1000 owncloud users.

Operating system:
Windows, Mac OS X, Linux

Logs

Web server error log

Many similar errors: PHP Fatal error: Call to a member function file_get_contents() on null in OWNCLOUD_DIR/lib/private/Files/Filesystem.php on line 753

ownCloud log (data/owncloud.log)

Repeated over and over again for many users:

"{"reqId":"WS1xZ1KniSdmJ8jr-ICETgAAACU","level":3,"time":"2017-05-30T13:19:36+00:00","remoteAddr":"SENSITIVE_DATA","user":"SENSITIVE_DATA","app":"files","method":"PROPFIND","url":"\/remote.php\/webdav\/","message":" Backends provided no user object for SENSITIVE_DATA"}

Browser log

Insert your browser log here, this could for example include:

a) The javascript console log

Content Security Policy: Directive ‘frame-src’ has been deprecated. Please use directive ‘child-src’ instead. (unknown)
Content Security Policy: The page’s settings blocked the loading of a resource at self (“script-src https://OWNCLOUD_URL 'unsafe-eval'”). Source: onsubmit attribute on DIV element. files
Content Security Policy: The page’s settings blocked the loading of a resource at self (“script-src https://OWNCLOUD_URL 'unsafe-eval'”). Source: onchange attribute on DIV element. files
Content Security Policy: The page’s settings blocked the loading of a resource at self (“script-src https://OWNCLOUD_URL 'unsafe-eval'”). Source: onfocusin attribute on DIV element. files
JQMIGRATE: Migrate is installed, version 1.4.0 jquery-migrate.min.js:2:542
window.controllers is deprecated. Do not use it for UA detection. ace.js:1716

[PVince81]

@jvillafanez @butonic

Does the user_ldap app version in the list match the one release on the marketplace ? Or is that the old one ?

[cormite]

it is the one in the market place: user_ldap: 0.9.1
https://github.com/owncloud/user_ldap/blob/master/appinfo/info.xml

[jvillafanez]

@cormite did you run the occ user:sync command? The accounts for the users might not be created yet.

occ user:sync "OCA\User_LDAP\User_Proxy"

[cormite]

@jvillafanez, Yes I did ... Note that I have already > 1000 users but only 680 so far known (those who have logged in). However, in the logs I keep receiving the errors of unknown for those who have not yet logged in.

# occ user:sync "OCA\User_LDAP\User_Proxy"
If unknown users are found, what do you want to do with their accounts? (removing the account will also remove its data)
  [0] disable
  [1] remove
  [2] ask later
 > 2
Analyse unknown users ...
  681 [============================]

No unknown users have been detected.
Insert new and update existing users ...
 2133/2133 [============================] 100%

# occ user:report
+--------------------------+------+
| User Report              |      |
+--------------------------+------+
| OCA\User_LDAP\User_Proxy | 680  |
| OC\User\Database         | 2    |
|                          |      |
| total users              | 682  |
|                          |      |
| user directories         | 1183 |
+--------------------------+------+

[jvillafanez]

I need to know the filters and bases you're using and any other related configuration. The only thing I can say for now is that you're trying to load 2133 of something (not necessary users) from somewhere, so maybe you're not even trying to load users but other things.
If the so-called users aren't being loaded into the DB, they might have some critical fields missing (displayname, objectuuid or whatever attribute you've set as username, etc)

[cormite]

@jvillafanez The filters I am using are those which I have used since version 7 of ownCloud. Nothing has changed and it has always worked fine for us. The problem appear only after the migration from 9.1.4 to 10.0.1.5

We have custom attributes:
Filters:

(&(!(accountlockdate=*))(|(objectclass=owncloudallowed)(objectclass=personactive))(uid=*))

Bases:
dc=COMPANY_NAME,dc=org

[jvillafanez]

could you run the user:sync command as much isolated as possible and check the logs? There should be errors in the log file.

[cormite]

@jvillafanez do you mean in a per user level?

[cormite]

@PVince81 @jvillafanez I have run the user:sync command again in verbose mode. I have not received any information in the logs not in the console ... The only extra information I have received is about performance but no errors.

Any suggestion about how to gather better information to share should be appreciated.

So far this is what I get:

# occ user:sync "OCA\User_LDAP\User_Proxy" -vvv
If unknown users are found, what do you want to do with their accounts? (removing the account will also remove its data)
  [0] disable
  [1] remove
  [2] ask later
 > 2
Analyse unknown users ...
  692 [============================]  1 sec 28.0 MiB

No unknown users have been detected.
Insert new and update existing users ...
 2135/2135 [============================] 100% 2 mins/2 mins 60.2 MiB

[cormite]

I do not know if this brings any idea, or even if this is related to the issue or if on the other hand it is expected, but I thought it would be worth mention it and if it is not related we can delete this comment.

I am also consuming via python the owncloud API and for some users I do not receive a quota value. The XML response for quota is empty.

[jvillafanez]

Looks like we'll need to check the hard way...

Please add the following 2 lines in the "lib/private/User/SyncService.php", around line 111 of the file. Then run the "occ user:sync" command. You can remove the lines added afterwards.

					$a = $this->setupAccount($a, $uid);
					$this->mapper->update($a);
$this->logger->critical("Updated $uid account");  // <-- added
				} catch(DoesNotExistException $ex) {
					$a = $this->createNewAccount($uid);
					$this->setupAccount($a, $uid);
					$this->mapper->insert($a);
$this->logger->critical("Inserted $uid account");  // <-- added

You should see 680 log entries with "Updated ... account" and around 1450 entries with "Inserted ... account" in the owncloud.log file.

The other option is that you see 2135 entries with "Updated ... account", which would confirm that the exception isn't thrown and so the new accounts aren't being added.

[cormite]

@jvillafanez, I have followed your instructions but unfortunatelly I see nothing at all in the owncloud.log file after adding those two lines and running the occ users:sync command.

[jvillafanez]

Either ownCloud isn't writing there because you've set another location for the log file, or ownCloud can't write in the file for some reason. ownCloud should be yelling; the fact the there is no output shows that there is something wrong with your setup.

[cormite]

@jvillafanez I am tailing the file (realtime -f) and I see the errors contantly being written to owncloud.log so it seems to be accessible and writable. It is just that those lines are not in the owncloud.log file.

[cormite]

@jvillafanez I have modified the lines you mentioned for:
error_log("Updated $uid account");
error_log("Inserted $uid account");

I wanted to make sure that the problem does not come from owncloud.log nor being accessible/writtable.

Still I see nothing ...

[jvillafanez]

Let's try commenting those logs and add these ones (same file, around line 96):

		do {
			$users = $this->backend->getUsers('', $limit, $offset);

$userCount = count($users);  // <-- added
$this->logger->critical("Users fetched: $userCount");  // <-- added
			// update existing and insert new users
			foreach ($users as $uid) {

If somehow the backend isn't fetching the users, that could explain why you aren't seeing the other logs.

[cormite]

ok .. some improvement 👍

I see the following in owncloud.log:

{"reqId":"2MU6AucmlF8XxEakf8Bs","level":3,"time":"2017-06-02T09:32:39+00:00","remoteAddr":"","user":"--","app":"no app in context","method":"--","url":"--","message":"Users fetched: 498"}

The output of the occ user:sync command was:

sudo -u apache occ user:sync "OCA\User_LDAP\User_Proxy" -vvv
If unknown users are found, what do you want to do with their accounts? (removing the account will also remove its data)
  [0] disable
  [1] remove
  [2] ask later
 > 2
Analyse unknown users ...
  703 [============================]  1 sec 25.8 MiB

Following users are no longer known with the connected backend.
listing the unknown accounts
USER_ID
What do you want to do with their accounts? (removing the account will also remove its data)
  [0] disable
  [1] remove
 > 0
Proceeding to disable the accounts
Insert new and update existing users ...
 2134/2134 [============================] 100%  1 min/1 min  60.2 MiB

Still occ user:report shows:

occ user:report
+--------------------------+------+
| User Report              |      |
+--------------------------+------+
| OCA\User_LDAP\User_Proxy | 701  |
| OC\User\Database         | 2    |
|                          |      |
| total users              | 703  |
|                          |      |
| user directories         | 1187 |
+--------------------------+------+

[cormite]

@jvillafanez I have noticed that everytime I run the occ user:sync command the same userID pops up as unknown. If I disable the account it appears again as unknown in the next occ user:sync run.

[jvillafanez]

Ok, so somehow the users returned by the LDAP app are 498 and it stops there because it thinks there are no more users. That could explain why there isn't any new user.
Could you check what happens with the 2 missing users in the LDAP server? The 2 missing users should be in the first 500 entries of the result.

If I disable the account it appears again as unknown in the next occ user:sync run

That's kind of expected because the user is still in ownCloud but no longer in LDAP. It's expected that the account is removed by the admin at some point. You might want to open a new ticket for it for further discussion, but it isn't relevant for the current one.

[cormite]

@jvillafanez I agree with you I will open a new ticket for the non-relevant part of this issue.
Regarding the 2 users you mentioned ... excuse my clumsiness but, where did you get this information from? There are 2 users in the DB (different backend as LDAP) and 1 unknown user (which shows even after being disabled) as far I see. Where do you see 2 missing users?

[jvillafanez]

You've said there should be more than 1000 LDAP users. LDAP should be fetching the first 500, and then proceed with the next 500. Somehow LDAP is only returning 498 (I trust only the first 498 are being fetched, not 500 + 500 + 498 or something similar, please confirm this). Since the service asked for 500 users and only 498 have been returned, the service thinks there are no more users.

If this assumption is correct, there are 2 entries missing because LDAP should be returning 500 entries, not 498.

[jvillafanez]

You can also change the log level to debug and look for the following logs in the owncloud.log file after rerunning the "occ user:sync" command
https://github.com/owncloud/user_ldap/blob/master/lib/User_LDAP.php#L178
https://github.com/owncloud/user_ldap/blob/master/lib/User_LDAP.php#L186

The limit and the user count shoud match. If they don't match, add the following log there:

		$ldap_users = $this->access->fetchListOfUsers(
			$filter,
			$this->access->userManager->getAttributes(true),
			$limit, $offset);
\OCP\Util::writeLog('user_ldap', 'getUsers0: '.count($ldap_users). ' Users found', \OCP\Util::DEBUG);  // <-- line added
		$ldap_users = $this->access->ownCloudUserNames($ldap_users);
		\OCP\Util::writeLog('user_ldap', 'getUsers: '.count($ldap_users). ' Users found', \OCP\Util::DEBUG);

That will show where we're losing the users.

[cormite]

Changing the log level to debug and running the occ user:sync shows:

"getUsers: Options: search  limit 500 offset 0

and

"getUsers: 498 Users found"

Adding the new line and running the command again shows the following:

{"reqId":"uvt25nClX75Z6xC5bsBB","level":0,"time":"2017-06-02T12:23:04+00:00","remoteAddr":"","user":"--","app":"user_ldap","method":"--","url":"--","message":"getUsers: Options: search  limit 500 offset 0 Filter: (&(&(!(accountlockdate=*))(|(objectclass=owncloudallowed)(objectclass=personactive))(uid=*))(displayname=*)(displayname=*))"}
{"reqId":"uvt25nClX75Z6xC5bsBB","level":0,"time":"2017-06-02T12:25:10+00:00","remoteAddr":"","user":"--","app":"user_ldap","method":"--","url":"--","message":"getUsers0: 500 Users found"}
{"reqId":"uvt25nClX75Z6xC5bsBB","level":0,"time":"2017-06-02T12:25:10+00:00","remoteAddr":"","user":"--","app":"user_ldap","method":"--","url":"--","message":"getUsers: 498 Users found"}

So weird enough, the LDAP filter is not exactly the one I have defined in my admin settings:

(&(!(accountlockdate=*))(|(objectclass=owncloudallowed)(objectclass=personactive))(uid=*))

And also, two consecutive lines showing different number of users found: 500 and 498.

[cormite]

@jvillafanez Sorry ... I closed the case and reopen again ... (I pressed the wrong button).

[jvillafanez]

Ok, suspicious confirmed: somehow 2 users are left out, which is causing this weird behaviour.

Next logs in apps/user_ldap/lib/Access.php, around line 641

		$ownCloudNames = array();
\OCP\Util::writeLog('user_ldap', 'ldap2ownCloudNames count: ' . count($ldapObjects), \OCP\Util::ERROR);  // <-- added
		foreach($ldapObjects as $ldapObject) {
			$nameByLDAP = null;
			if(    isset($ldapObject[$nameAttribute])
				&& is_array($ldapObject[$nameAttribute])
				&& isset($ldapObject[$nameAttribute][0])
			) {
				// might be set, but not necessarily. if so, we use it.
				$nameByLDAP = $ldapObject[$nameAttribute][0];
			}

			$ocName = $this->dn2ocname($ldapObject['dn'][0], $nameByLDAP, $isUsers);
\OCP\Util::writeLog('user_ldap', 'dn2ocname: dn '.$ldapObject['dn'][0]. ' - ocName type ' .gettype($ocName). ' - ocName value ' .$ocName, \OCP\Util::ERROR);  // <-- added
			if($ocName) {
				$ownCloudNames[] = $ocName;
				if($isUsers) {
					//cache the user names so it does not need to be retrieved
					//again later (e.g. sharing dialogue).
					if(is_null($nameByLDAP)) {
						continue;
					}
					$sndName = isset($ldapObject[$sndAttribute][0])
						? $ldapObject[$sndAttribute][0] : '';
					$this->cacheUserDisplayName($ocName, $nameByLDAP, $sndName);
				}
			}
else {  // <-- added
\OCP\Util::writeLog('user_ldap', 'ldap2ownCloudNames: dn '.$ldapObject['dn'][0]. ' the ocName returned a falsy value', \OCP\Util::ERROR);  // <-- added
}  // <-- added
		}
		return $ownCloudNames;

The count there should be 500, but there should be 2 log entries with a weird "ocName" value. The "ocName" will likely be boolean for those.

[jvillafanez]

The goal is to verify if the dn2ocname function is returning false for some ldap entries, and what are those entries in order to fix it.

[cormite]

premio! 👍
I have located the two users with falsy ocName value. What I do not get is the returned ocName to really find out what the problem might be.

{"reqId":"UONqybnx3ZfWriDuCRj7","level":3,"time":"2017-06-02T14:47:30+00:00","remoteAddr":"","user":"--","app":"user_ldap","method":"--","url":"--","message":"ldap2ownCloudNames: dn cn=SENSITIVE_DATA the ocName returned a falsy value"}
{"reqId":"UONqybnx3ZfWriDuCRj7","level":3,"time":"2017-06-02T14:47:30+00:00","remoteAddr":"","user":"--","app":"user_ldap","method":"--","url":"--","message":"ldap2ownCloudNames: dn cn=SENSITIVE_DATA the ocName returned a falsy value"}

We are finally narrowing down the problem.

[cormite]

@jvillafanez, something I do not understand from the administration point of view is that if there are, like in my case, two problematic users (as far as we have found) why doesn't the code continue importing the rest of detected users? It is clear that occ user:scan detects >2000 LDAP users and occ user:report >1000 owncloud users. If it knows about >1000 why doesn't it continue with the rest and gets stuck at 498? why doesn't it report the admin about this problem and continues importing until the end? That would be the expected behavior from my point of view.

Anyway, for the time being, I would appreciate just a little hand further to fix overcome these two blocking users. Thanks!

[cormite]

@jvillafanez I have finally been able to fix the problem. I have slightly modified the LDAP filter to restrict a bit more and leave out the users whose condition was not meet in order to be considered ownCloud users. After this modification I was able to syn all the users again.

occ user:report
+--------------------------+------+
| User Report              |      |
+--------------------------+------+
| OCA\User_LDAP\User_Proxy | 2077 |
| OC\User\Database         | 2    |
|                          |      |
| total users              | 2079 |
|                          |      |
| user directories         | 1188 |
+--------------------------+------+

I really appreciate your effort, time spent, and support.
Thank you very much.

[jvillafanez]

If it knows about >1000 why doesn't it continue with the rest and gets stuck at 498? why doesn't it report the admin about this problem and continues importing until the end? That would be the expected behavior from my point of view.

The way it's coded doesn't involve knowing all the users: it asks for the first 500, if LDAP returns 500 users then it will ask for the next 500 because there could be more. The problem is that it ask for 500 user but LDAP returns 498, so it thinks there are no more users.

I'm glad you've fixed your problem. I'm reopening the issue because I'll have to take some action regarding this, probably adding some logs to detect this problem easier.

[cormite]

@jvillafanez yes, please take over the thread. If you want me to make more tests I will be glad to help.

[butonic]

more verbose logging in #28212

[ownclouders]

Hey, this issue has been closed because the label needs info is set and there were no updates for 14 days. Feel free to reopen this issue if you deem it appropriate.

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.