Shared files, oC 9.1 adding "(2)" at the end #25718

Closed
Mysterycz opened this Issue Aug 8, 2016 · 180 comments

Projects

None yet

7 participants

@Mysterycz

Steps to reproduce (I don't know how to reproduce it, I need to investigate more)

  1. Use oC 9.1
  2. Share some files
  3. Wait untill some random magic happens and oC will add to all shared files some "(2)"

I found same issue here, but these steps to reproduce does not work:
#10736

Expected behaviour

oC should not rename shared files ...

Actual behaviour

oC adds "(2)" to all shared files (owner does not see renamed + "(2)" files

Server configuration

Ubuntu 14.04
Apache2
MySQL
PHP 5.6
oC 9.1
Updated from 9.04
Installed from official website manually

Integrity check: No errors have been found.

List of activated apps:

  - activity: 2.3.2
  - comments: 0.3.0
  - dav: 0.2.5
  - encryption: 1.3.0
  - external: 1.2
  - federatedfilesharing: 0.3.0
  - federation: 0.1.0
  - files: 1.5.1
  - files_pdfviewer: 0.8.1
  - files_sharing: 0.10.0
  - files_texteditor: 2.1
  - files_trashbin: 0.9.0
  - files_versions: 1.3.0
  - files_videoplayer: 0.9.8
  - firstrunwizard: 1.1
  - gallery: 15.0.0
  - notifications: 0.3.0
  - ownnote: 1.08
  - provisioning_api: 0.5.0
  - systemtags: 0.3.0
  - templateeditor: 0.1
  - updatenotification: 0.2.1
  - user_ldap: 0.9.0
Disabled:
  - files_antivirus
  - files_external
  - user_external

The content of config/config.php:

{
    "system": {
        "updatechecker": false,
        "instanceid": "***",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            ***
        ],
        "datadirectory": "\/home\/owncloud\/owncloud",
        "overwrite.cli.url": "*",
        "dbtype": "mysql",
        "version": "9.1.0.15",
        "default_language": "cz",
        "dbname": "ownCloud",
        "dbhost": "localhost",
        "dbtableprefix": "oc_",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "logtimezone": "UTC",
        "installed": true,
        "ldapIgnoreNamingRules": false,
        "loglevel": 2,
        "appstore.experimental.enabled": true,
        "theme": "HZS",
        "maintenance": false,
        "memcache.local": "\\OC\\Memcache\\APCu",
        "preview_libreoffice_path": "\/usr\/bin\/libreoffice",
        "mail_from_address": "owncloud",
        "mail_smtpmode": "php",
        "mail_domain": "**"
    }
}

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

Are you using encryption: yes

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

Client configuration

Browser: Opera 39
Operating system: Windows 10

@elektro-wolle

Have you shared the folder to a group? Then it might be a duplicate to #24575

@Mysterycz

Yes, some of files/folders were shared folders to groups. Some of them were shared files/folders to individual person account. It affects all of them. I don't think it is duplicate to #24575, because shared folders are only renamed not duplicated. It could be related to this issue ofcourse, i don't know.

@PVince81
Collaborator
PVince81 commented Aug 9, 2016

Without the exact sharing scenario it will be impossible to tell.

But I'm pretty confident that the fix for #24575 should cover most cases. The only exception is #25564

For #24575 a fix will be released with the upcoming 9.1.1. The fix is here #25534.

I'm going to close this for now. If you are able to find out the exact sharing scenario, you can first check if it is covered in the scenario list here https://github.com/owncloud/core/pull/25534/files#diff-b4888b15e6a7d80fe706602129494bfbR713

If it isn't, please reopen and I'll add it there for testing.

@PVince81 PVince81 closed this Aug 9, 2016
@ccheveaux
ccheveaux commented Sep 21, 2016 edited

Hi !

I have exactly the same problem since 9.1.0
I wait 9.1.1 to upgrade my cloud, but the result is the same.

This is my oc_share table on phpmyadmin :

oc_share

And an other screen of a user :

capture d ecran 2016-09-21 a 18 27 29

It's strange, the bug is only on ldap account, and not all ...
When i remove share, and share it again the bug back ...
After clean tables and when i stop app files_sharing, the database are correct on 'oc_share' ...

(sorry for my bad english ...)

`Enabled:

  • activity: 2.3.2
  • bookmarks: true
  • calendar: true
  • comments: 0.3.0
  • contacts: true
  • dav: 0.2.6
  • documents: true
  • external: 1.2
  • federatedfilesharing: 0.3.0
  • federation: 0.1.0
  • files: 1.5.1
  • files_pdfviewer: 0.8.1
  • files_sharing: 0.10.0
  • files_texteditor: 2.1
  • files_trashbin: 0.9.0
  • files_versions: 1.3.0
  • files_videoplayer: 0.9.8
  • firstrunwizard: 1.1
  • gallery: 15.0.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.0
    Disabled:
  • encryption
  • files_antivirus
  • files_external
  • user_external`

<?php $CONFIG = array ( 'updatechecker' => false, 'instanceid' => '***REMOVED SENSITIVE VALUE***', 'passwordsalt' => '***REMOVED SENSITIVE VALUE***', 'secret' => '***REMOVED SENSITIVE VALUE***', 'trusted_domains' => array ( 0 => '***REMOVED SENSITIVE VALUE***', ), 'datadirectory' => '/data/profs', 'overwrite.cli.url' => '***REMOVED SENSITIVE VALUE***', 'dbtype' => 'mysql', 'version' => '9.1.1.3', 'dbname' => 'owncloud', 'dbhost' => 'localhost', 'dbtableprefix' => 'oc_', 'dbuser' => 'owncloud', 'dbpassword' => '***REMOVED SENSITIVE VALUE***', 'logtimezone' => 'UTC', 'installed' => true, 'theme' => 'dgm', 'maintenance' => false, 'loglevel' => 0, );

Server configuration
Ubuntu 16.04
Apache 2.4.18
MySQL 5.7.15
PHP 7.0.8
oC 9.1.1
Updated from 9.1.0 <- 8.2.X

@PVince81
Collaborator

Please describe the sharing scenario, who shares what with who.

@PVince81 PVince81 reopened this Sep 22, 2016
@PVince81 PVince81 added this to the 9.1.2 milestone Sep 22, 2016
@ccheveaux
ccheveaux commented Sep 22, 2016 edited

Hello,

It's an LDAP user who shares a folder of its own owncloud another LDAP user or a local user.
We have not shared between several different cloud.
Just teachers of an educational department that shares them.

The user sees emits sharing the folder named correctly.
The '(2)' are only displayed for the user who receives the shares.

More use could not be simpler to owncloud sharing system to avoid using public clouds.
I hope you have provided enough information, I was not too used to report bugs.

Thx for your help ;)

@PVince81
Collaborator

Is it really just a simple case of "ldap_user1" shared folder with "ldap_user2" and when ldap_user2 views the file list it keeps adding a "(2)" ? I thought there was more complex sharing involved like group shares, reshares, etc.

@ccheveaux

Exactly !

No teacher uses sharing group because we are not much use this Cloud.
And for the reshares i disabled it in the settings.

@PVince81
Collaborator

Okay, thanks for the info. I'll see if I can reproduce it locally with this scenario.

@PVince81
Collaborator

My steps:

  1. Setup LDAP in OC (used the docker from https://github.com/owncloud/administration/tree/master/ldap-testing)
  2. Pick two users "user1" and "user2" from the LDAP
  3. Login as "user2" then "user1" to initialize their homes
  4. Create a folder "test"
  5. Share "test" with "user2" with default permissions
  6. Login as "user2"
  7. Look at the file list
  8. Access the file list with Webdav

The folder properly appears as "test" for me.

@ccheveaux

Thank you so much for your help.
In fact I do not understand why it does not affect everyone.
And above all I did not bug on another cloud that I use personal way with 2-3 users and certainly not a lot of sharing, but no LDAP users.

Another thing I noticed is that files_sharing a lot of mistakes when I made the command :
"sudo -u www-data occ php app: check code files_sharing"
This does not surrement prevents its operation, but this is the only app with much error ...

And I have the same errors on my personal ownCloud with this command.

check-code_files_sharing

check-code_files_sharing2

@PVince81
Collaborator

@ccheveaux your are using the wrong code checker, this is only to validate whether an app's code is clean (yes, the code of files_sharing isn't clean yet...). Try going to the admin page instead it will verify code integrity. Or on the CLI, the command you wanted is occ integrity:check-app

@PVince81
Collaborator

@ccheveaux I see in your oc_share table that not all folders received a "(2)". Are the ones without "(2)" from non-LDAP users ? Would be good to analyze the difference between the working ones and broken ones.

@ccheveaux

I also did the test to create shares with other users tests.
And I have no problem renaming.

My main problem is that I would find how to fix shares that have this bug.
Unfortunately I can not find the variable that causes it ...
And as soon as I tried to clean directly in table 'oc_share' them '(2)' back faster or slower, as if there was a cache or a script that was automatically ...

Ca become annoying, and I'm afraid that even with a clean reinstallation, when I will restore the database, the problem will come back ...

@PVince81
Collaborator

Are the users without "(2)" users who haven't logged in since a long time ? Because the logic that triggers duplicate detection is done when the filesystem for the share recipient is setup.

@elektro-wolle
elektro-wolle commented Sep 22, 2016 edited

Since I've had the same problem as @ccheveaux with LDAP-Users on 9.1:
The folder was shared by an LDAP User and some of the LDAP Users this folder is shared to, see the " (2)". After several reloads in the web-frontend, the " (2)" switches to " (2) (2)" and sometimes (maybe, if a third user accesses the page) to " (3)".
It doesn't matter if the folder is shared via a LDAP-group or directly to another user.

The main problem is the data-corruption on the client side if the owncloud-client is active. The client propagates the rename to the connected computer regardless of any open files, leaving sometime the original folder (without " (2)") due to the open file and the renamed folder.

A rename within the browser is only possible if the name is shorter then 512 chars. Sometimes this is not possible even after a few minutes due to the long " (2) (2) (2) (2) (2) ... (2) (2)" name.

@ccheveaux

Those with no (2) are on the screenshot is a sharing "user_ldap->public" or "user_ldap-> user_ldap".

I am currently doing a share with a teacher who is not connected for several weeks.

Yesterday, after cleaning (2) 'oc_sharing', this folder is incremented very quickly.
(Maybe because I had freshly to reinstall the owncloud package)
Today I clean and (2) do not come back yet, but they return to users connected at the moment with the owncloud desktop client.

@ccheveaux
ccheveaux commented Sep 22, 2016 edited

That could be an explanation indeed @elektro-wolle !
And how to you corrected the problem ?
You have to go on each client ?
And what manipulation you doing ?

@elektro-wolle

I've created a cronjob on the server, replacing the " (2)" in the name of the oc_share table and told the users to not use the desktop-client. This is not really a solution, I'm still waiting for 9.1.1 and currently evaluating other alternatives to owncloud.

@ccheveaux

So if I understand you well cleaned by the cron table.
There is no possibility to stop by each client to make a deletion of the account on the desktop client and then recreate it?
It seems to me that there is no data loss if one like this?
Naturally between deleting and recreating the account on the desktop client, a table cleaning should be done I think.

@ccheveaux
ccheveaux commented Sep 22, 2016 edited

Can you share me you're script to replacing the (2) please ?

@PVince81
Collaborator

I don't think this is related to the desktop client.
When the issue does happen, it might influence the desktop client.
But the cause of the problem is not created by the desktop client, because as @elektro-wolle said even refreshing the web UI already adds a "(2)".

I'm looking at the code that usually adds "(2)" to see if there is something that could make it mis-detect a duplicate.

@elektro-wolle

It's just an cronjob calling mysql with the following statement:
update oc_share set file_target = replace(file_target, ' (2)', '') where file_target like '%(2)%'; if I remember correctly.
But this should only run when no one is connected with the desktop-client.

@PVince81
Collaborator

Now trying to recreate a similar setup like @ccheveaux by enabling the same third party apps in case it's one of them messing with the FS setup.

@ccheveaux

Indeed there is no doubt these two actions that would generate this increment.

In waiting to find a solution i think will apply the same cron that @elektro-wolle
It will be cleaner for users.

I hope we will find the cause of this problem ...

A big thank you for your help in any two :)

@PVince81
Collaborator

To help debugging, here is a patch: https://github.com/owncloud/core/commit/fa5fe2b88e0892e842e63a76df9844094f269d6b.patch
You need to set "loglevel" to 0 and then grep for the word "DEBUG" or "SharedMount".

It will only log statements when it's about to add a "(2)". Maybe the extra information can help find out what kind of situation on your setup is creating these.

@PVince81
Collaborator

Instead of using cron another hack is to add return $path; here https://github.com/owncloud/core/blob/v9.1.1/apps/files_sharing/lib/SharedMount.php#L144
This would disable the logic altogether and should prevent a "(2)" to be added. (but I still hope we can debug this and find the root cause!)
With this hack if a user would receive two folders with the same name, the second folder would become invisible because it has the same name and won't be renamed to "folder (2)".

@ccheveaux

Ok i add it and i survey databases.
Thx ;)

@PVince81
Collaborator

I had an idea for a potential fix, but I am only guessing. I guess that maybe on your setup, for some unknown reason, the SharedMount is mounted twice and triggering the duplicate.
With this PR #26180 (patch https://github.com/owncloud/core/pull/26180.patch) it would make sure that the same folder isn't mounted twice for the same share id.

With a bit of luck this might fix the issue on your environments. If it doesn't, then it means that the root cause is different than what I guessed.

But ideal would be to first go the debug patch approach #25718 (comment) so I can find out more about what is happening on your envs.

@ccheveaux

Ok i remove this : #25718 (comment)
And add https://github.com/owncloud/core/pull/26180.patch

So for log with loglevel at 0 my 'owncloud.log' is so big and so quickly ... (2Go in 1 hours ...)
Would you that I sent you?
How do you find what you want in this mass of information ??

@ccheveaux
ccheveaux commented Sep 22, 2016 edited

Ok atm i have only 1 folder with (2) :
/Secretariat_EltsPartages JMR_2014 2015 (2) (2) (3) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2)

Strange there is a '(3)' now :/

Exception: {"Exception":"Doctrine\\DBAL\\Exception\\DriverException","Message":"An exception occurred while executing 'UPDATEoc_shareSETfile_target= ? WHEREid= ?' with params [\"\\\/Secretariat_EltsPartages JMR_2014 2015 (2) (2) (3) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2)\", \"396\"]:\n\nSQLSTATE[22001]: String data, right truncated: 1406 Data too long for column 'file_target' at row 1","Code":0,"Trace":"#0 \/var\/www\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/DBALException.php(116): Doctrine\\DBAL\\Driver\\AbstractMySQLDriver->convertException('An exception oc...', Object(Doctrine\\DBAL\\Driver\\PDOException))\n#1 \/var\/www\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Connection.php(996): Doctrine\\DBAL\\DBALException::driverExceptionDuringQuery(Object(Doctrine\\DBAL\\Driver\\PDOMySql\\Driver), Object(Doctrine\\DBAL\\Driver\\PDOException), 'UPDATEoc_shar...', Array)\n#2 /var/www/owncloud/lib/private/DB/Connection.php(209): Doctrine\DBAL\Connection->executeUpdate('UPDATE oc_shar...', Array, Array)\n#3 \/var\/www\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Query\/QueryBuilder.php(208): OC\\DB\\Connection->executeUpdate('UPDATEoc_shar...', Array, Array)\n#4 /var/www/owncloud/lib/private/DB/QueryBuilder/QueryBuilder.php(141): Doctrine\DBAL\Query\QueryBuilder->execute()\n#5 /var/www/owncloud/lib/private/Share20/DefaultShareProvider.php(405): OC\DB\QueryBuilder\QueryBuilder->execute()\n#6 /var/www/owncloud/lib/private/Share20/Manager.php(869): OC\Share20\DefaultShareProvider->move(Object(OC\Share20\Share), 'cbiache')\n#7 /var/www/owncloud/apps/files_sharing/lib/SharedMount.php(118): OC\Share20\Manager->moveShare(Object(OC\Share20\Share), 'cbiache')\n#8 /var/www/owncloud/apps/files_sharing/lib/SharedMount.php(100): OCA\Files_Sharing\SharedMount->updateFileTarget('/Secretariat_El...', Object(OC\Share20\Share))\n#9 /var/www/owncloud/apps/files_sharing/lib/SharedMount.php(71): OCA\Files_Sharing\SharedMount->verifyMountPoint(Object(OC\Share20\Share), Array)\n#10 /var/www/owncloud/apps/files_sharing/lib/MountProvider.php(89): OCA\Files_Sharing\SharedMount->__construct('\OC\Files\Stora...', Array, Array, Object(OC\Files\Storage\StorageFactory))\n#11 /var/www/owncloud/lib/private/Files/Config/MountProviderCollection.php(76): OCA\Files_Sharing\MountProvider->getMountsForUser(Object(OC\User\User), Object(OC\Files\Storage\StorageFactory))\n#12 [internal function]: OC\Files\Config\MountProviderCollection->OC\Files\Config{closure}(Object(OCA\Files_Sharing\MountProvider))\n#13 /var/www/owncloud/lib/private/Files/Config/MountProviderCollection.php(77): array_map(Object(Closure), Array)\n#14 /var/www/owncloud/lib/private/Files/Filesystem.php(422): OC\Files\Config\MountProviderCollection->getMountsForUser(Object(OC\User\User))\n#15 /var/www/owncloud/apps/files_sharing/lib/sharedstorage.php(99): OC\Files\Filesystem::initMountPoints('cbiache')\n#16 /var/www/owncloud/apps/files_sharing/lib/sharedstorage.php(448): OC\Files\Storage\Shared->init()\n#17 /var/www/owncloud/lib/private/Files/Storage/Wrapper/Wrapper.php(485): OC\Files\Storage\Shared->getWrapperStorage()\n#18 /var/www/owncloud/apps/files_sharing/lib/sharedstorage.php(122): OC\Files\Storage\Wrapper\Wrapper->instanceOfStorage('\OC\Files\Stora...')\n#19 /var/www/owncloud/lib/private/legacy/util.php(148): OC\Files\Storage\Shared->instanceOfStorage('\OC\Files\Stora...')\n#20 /var/www/owncloud/lib/private/Files/Storage/StorageFactory.php(100): OC_Util::{closure}('/jroussel/files...', Object(OC\Files\Storage\Shared), Object(OCA\Files_Sharing\SharedMount))\n#21 /var/www/owncloud/lib/private/Files/Storage/StorageFactory.php(82): OC\Files\Storage\StorageFactory->wrap(Object(OCA\Files_Sharing\SharedMount), Object(OC\Files\Storage\Shared))\n#22 /var/www/owncloud/lib/private/Files/Mount/MountPoint.php(137): OC\Files\Storage\StorageFactory->getInstance(Object(OCA\Files_Sharing\SharedMount), '\OC\Files\Stora...', Array)\n#23 /var/www/owncloud/lib/private/Files/Mount/MountPoint.php(160): OC\Files\Mount\MountPoint->createStorage()\n#24 /var/www/owncloud/lib/private/Files/View.php(1356): OC\Files\Mount\MountPoint->getStorage()\n#25 /var/www/owncloud/lib/private/Files/Node/Root.php(180): OC\Files\View->getFileInfo('/jroussel')\n#26 /var/www/owncloud/lib/private/AvatarManager.php(94): OC\Files\Node\Root->get('/jroussel')\n#27 /var/www/owncloud/lib/private/User/User.php(380): OC\AvatarManager->getAvatar('jroussel')\n#28 /var/www/owncloud/apps/dav/lib/CardDAV/Converter.php(164): OC\User\User->getAvatarImage(96)\n#29 /var/www/owncloud/apps/dav/lib/CardDAV/Converter.php(75): OCA\DAV\CardDAV\Converter->getAvatarImage(Object(OC\User\User))\n#30 /var/www/owncloud/apps/dav/lib/CardDAV/SyncService.php(228): OCA\DAV\CardDAV\Converter->updateCard(Object(Sabre\VObject\Component\VCard), Object(OC\User\User))\n#31 /var/www/owncloud/apps/dav/lib/HookManager.php(99): OCA\DAV\CardDAV\SyncService->updateUser(Object(OC\User\User))\n#32 /var/www/owncloud/lib/private/legacy/hook.php(105): OCA\DAV\HookManager->changeUser(Array)\n#33 /var/www/owncloud/lib/private/Server.php(275): OC_Hook::emit('OC_User', 'changeUser', Array)\n#34 [internal function]: OC\Server->OC{closure}(Object(OC\User\User), 'quota', '20 GB')\n#35 /var/www/owncloud/lib/private/Hooks/EmitterTrait.php(98): call_user_func_array(Object(Closure), Array)\n#36 /var/www/owncloud/lib/private/Hooks/PublicEmitter.php(32): OC\Hooks\BasicEmitter->emit('\OC\User', 'changeUser', Array)\n#37 /var/www/owncloud/lib/private/User/User.php(417): OC\Hooks\PublicEmitter->emit('\OC\User', 'changeUser', Array)\n#38 /var/www/owncloud/lib/private/User/User.php(364): OC\User\User->triggerChange('quota', '20 GB')\n#39 /var/www/owncloud/apps/user_ldap/lib/User/User.php(470): OC\User\User->setQuota('20 GB')\n#40 /var/www/owncloud/apps/user_ldap/lib/User/User.php(160): OCA\User_LDAP\User\User->updateQuota('20 GB')\n#41 /var/www/owncloud/apps/user_ldap/lib/Access.php(736): OCA\User_LDAP\User\User->processAttributes(Array)\n#42 /var/www/owncloud/apps/user_ldap/lib/Access.php(708): OCA\User_LDAP\Access->batchApplyUserAttributes(Array)\n#43 /var/www/owncloud/apps/user_ldap/lib/Access.php(681): OCA\User_LDAP\Access->fetchListOfUsers('(&(&(|(objectcl...', Array)\n#44 /var/www/owncloud/apps/user_ldap/lib/User_LDAP.php(102): OCA\User_LDAP\Access->fetchUsersByLoginName('jroussel', Array)\n#45 /var/www/owncloud/apps/user_ldap/lib/User_LDAP.php(81): OCA\User_LDAP\User_LDAP->getLDAPUserByLoginName('jroussel')\n#46 /var/www/owncloud/lib/private/User/Manager.php(160): OCA\User_LDAP\User_LDAP->loginName2UserName('jroussel')\n#47 /var/www/owncloud/lib/private/User/Manager.php(140): OC\User\Manager->getUserObject('jroussel', Object(OCA\User_LDAP\User_LDAP))\n#48 /var/www/owncloud/lib/private/User/Manager.php(183): OC\User\Manager->get('jroussel')\n#49 /var/www/owncloud/apps/files_versions/lib/Command/Expire.php(55): OC\User\Manager->userExists('jroussel')\n#50 /var/www/owncloud/lib/private/Command/CommandJob.php(34): OCA\Files_Versions\Command\Expire->handle()\n#51 /var/www/owncloud/lib/private/BackgroundJob/Job.php(52): OC\Command\CommandJob->run('O:33:"OCA\Files...')\n#52 /var/www/owncloud/lib/private/BackgroundJob/QueuedJob.php(42): OC\BackgroundJob\Job->execute(Object(OC\BackgroundJob\JobList), Object(OC\Log))\n#53 /var/www/owncloud/cron.php(144): OC\BackgroundJob\QueuedJob->execute(Object(OC\BackgroundJob\JobList), Object(OC\Log))\n#54 {main}","File":"/var/www/owncloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Driver/AbstractMySQLDriver.php","Line":115}`

@PVince81
Collaborator

@ccheveaux you didn't add the debug patch but simply disabled the code that might trigger the bug, so your log won't contain anything useful for me. I suggest you set your loglevel back to what it was before for now.

However it would be good if you could do the oc_share update to manually remove the (2) and then let the system run for an hour or two and tell me whether the (2) reappeared at all.

If they did NOT reappear, then revert #25718 (comment) to reenable the main code but keep the potential fix from https://github.com/owncloud/core/pull/26180.patch. Then let it run for another few hours and let me know whether the (2). Reappeared.

Thanks!

@ccheveaux
ccheveaux commented Sep 23, 2016 edited

Hello !

After 19 hours, i have only one folder with (2).
It's the same of #25718 (comment)

/Secretariat_EltsPartages JMR_2014 2015 (2) (2) (3) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2)

With this log :

root@midgar:~# tail -f /var/log/owncloud/owncloud.log | grep 'Secretariat_EltsPartages' {"reqId":"XVzthsCoYgl66zXjOefb","remoteAddr":"77.156.242.254","app":"no app in context","message":"Exception: {\"Exception\":\"Doctrine\\\\DBAL\\\\Exception\\\\DriverException\",\"Message\":\"An exception occurred while executing 'UPDATEoc_shareSETfile_target= ? WHEREid= ?' with params [\\\"\\\\\\\/Secretariat_EltsPartages JMR_2014 2015 (2) (2) (3) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2)\\\", \\\"396\\\"]:\\n\\nSQLSTATE[22001]: String data, right truncated: 1406 Data too long for column 'file_target' at row 1\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/DBALException.php(116): Doctrine\\\\DBAL\\\\Driver\\\\AbstractMySQLDriver->convertException('An exception oc...', Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOException))\\n#1 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/Connection.php(996): Doctrine\\\\DBAL\\\\DBALException::driverExceptionDuringQuery(Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOMySql\\\\Driver), Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOException), 'UPDATEoc_shar...', Array)\n#2 \/var\/www\/owncloud\/lib\/private\/DB\/Connection.php(209): Doctrine\DBAL\Connection->executeUpdate('UPDATE oc_shar...', Array, Array)\\n#3 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/Query\\\/QueryBuilder.php(208): OC\\\\DB\\\\Connection->executeUpdate('UPDATEoc_shar...', Array, Array)\n#4 \/var\/www\/owncloud\/lib\/private\/DB\/QueryBuilder\/QueryBuilder.php(141): Doctrine\DBAL\Query\QueryBuilder->execute()\n#5 \/var\/www\/owncloud\/lib\/private\/Share20\/DefaultShareProvider.php(405): OC\DB\QueryBuilder\QueryBuilder->execute()\n#6 \/var\/www\/owncloud\/lib\/private\/Share20\/Manager.php(869): OC\Share20\DefaultShareProvider->move(Object(OC\Share20\Share), 'cbiache')\n#7 \/var\/www\/owncloud\/apps\/files_sharing\/lib\/SharedMount.php(118): OC\Share20\Manager->moveShare(Object(OC\Share20\Share), 'cbiache')\n#8 \/var\/www\/owncloud\/apps\/files_sharing\/lib\/SharedMount.php(100): OCA\Files_Sharing\SharedMount->updateFileTarget('\/Secretariat_El...', Object(OC\Share20\Share))\n#9 \/var\/www\/owncloud\/apps\/files_sharing\/lib\/SharedMount.php(71): OCA\Files_Sharing\SharedMount->verifyMountPoint(Object(OC\Share20\Share), Array)\n#10 \/var\/www\/owncloud\/apps\/files_sharing\/lib\/MountProvider.php(89): OCA\Files_Sharing\SharedMount->__construct('\\OC\\Files\\Stora...', Array, Array, Object(OC\Files\Storage\StorageFactory))\n#11 \/var\/www\/owncloud\/lib\/private\/Files\/Config\/MountProviderCollection.php(76): OCA\Files_Sharing\MountProvider->getMountsForUser(Object(OC\User\User), Object(OC\Files\Storage\StorageFactory))\n#12 [internal function]: OC\Files\Config\MountProviderCollection->OC\Files\Config\{closure}(Object(OCA\Files_Sharing\MountProvider))\n#13 \/var\/www\/owncloud\/lib\/private\/Files\/Config\/MountProviderCollection.php(77): array_map(Object(Closure), Array)\n#14 \/var\/www\/owncloud\/lib\/private\/Files\/Filesystem.php(422): OC\Files\Config\MountProviderCollection->getMountsForUser(Object(OC\User\User))\n#15 \/var\/www\/owncloud\/apps\/files_sharing\/lib\/sharedstorage.php(99): OC\Files\Filesystem::initMountPoints('cbiache')\n#16 \/var\/www\/owncloud\/apps\/files_sharing\/lib\/sharedstorage.php(448): OC\Files\Storage\Shared->init()\n#17 \/var\/www\/owncloud\/lib\/private\/Files\/Storage\/Wrapper\/Wrapper.php(485): OC\Files\Storage\Shared->getWrapperStorage()\n#18 \/var\/www\/owncloud\/apps\/files_sharing\/lib\/sharedstorage.php(122): OC\Files\Storage\Wrapper\Wrapper->instanceOfStorage('\\OC\\Files\\Stora...')\n#19 \/var\/www\/owncloud\/lib\/private\/legacy\/util.php(148): OC\Files\Storage\Shared->instanceOfStorage('\\OC\\Files\\Stora...')\n#20 \/var\/www\/owncloud\/lib\/private\/Files\/Storage\/StorageFactory.php(100): OC_Util::{closure}('\/jroussel\/files...', Object(OC\Files\Storage\Shared), Object(OCA\Files_Sharing\SharedMount))\n#21 \/var\/www\/owncloud\/lib\/private\/Files\/Storage\/StorageFactory.php(82): OC\Files\Storage\StorageFactory->wrap(Object(OCA\Files_Sharing\SharedMount), Object(OC\Files\Storage\Shared))\n#22 \/var\/www\/owncloud\/lib\/private\/Files\/Mount\/MountPoint.php(137): OC\Files\Storage\StorageFactory->getInstance(Object(OCA\Files_Sharing\SharedMount), '\\OC\\Files\\Stora...', Array)\n#23 \/var\/www\/owncloud\/lib\/private\/Files\/Mount\/MountPoint.php(160): OC\Files\Mount\MountPoint->createStorage()\n#24 \/var\/www\/owncloud\/lib\/private\/Files\/View.php(1356): OC\Files\Mount\MountPoint->getStorage()\n#25 \/var\/www\/owncloud\/lib\/private\/Files\/Node\/Root.php(180): OC\Files\View->getFileInfo('\/jroussel')\n#26 \/var\/www\/owncloud\/lib\/private\/AvatarManager.php(94): OC\Files\Node\Root->get('\/jroussel')\n#27 \/var\/www\/owncloud\/lib\/private\/User\/User.php(380): OC\AvatarManager->getAvatar('jroussel')\n#28 \/var\/www\/owncloud\/apps\/dav\/lib\/CardDAV\/Converter.php(164): OC\User\User->getAvatarImage(96)\n#29 \/var\/www\/owncloud\/apps\/dav\/lib\/CardDAV\/Converter.php(75): OCA\DAV\CardDAV\Converter->getAvatarImage(Object(OC\User\User))\n#30 \/var\/www\/owncloud\/apps\/dav\/lib\/CardDAV\/SyncService.php(228): OCA\DAV\CardDAV\Converter->updateCard(Object(Sabre\VObject\Component\VCard), Object(OC\User\User))\n#31 \/var\/www\/owncloud\/apps\/dav\/lib\/HookManager.php(99): OCA\DAV\CardDAV\SyncService->updateUser(Object(OC\User\User))\n#32 \/var\/www\/owncloud\/lib\/private\/legacy\/hook.php(105): OCA\DAV\HookManager->changeUser(Array)\n#33 \/var\/www\/owncloud\/lib\/private\/Server.php(275): OC_Hook::emit('OC_User', 'changeUser', Array)\n#34 [internal function]: OC\Server->OC\{closure}(Object(OC\User\User), 'quota', '20 GB')\n#35 \/var\/www\/owncloud\/lib\/private\/Hooks\/EmitterTrait.php(98): call_user_func_array(Object(Closure), Array)\n#36 \/var\/www\/owncloud\/lib\/private\/Hooks\/PublicEmitter.php(32): OC\Hooks\BasicEmitter->emit('\\OC\\User', 'changeUser', Array)\n#37 \/var\/www\/owncloud\/lib\/private\/User\/User.php(417): OC\Hooks\PublicEmitter->emit('\\OC\\User', 'changeUser', Array)\n#38 \/var\/www\/owncloud\/lib\/private\/User\/User.php(364): OC\User\User->triggerChange('quota', '20 GB')\n#39 \/var\/www\/owncloud\/apps\/user_ldap\/lib\/User\/User.php(470): OC\User\User->setQuota('20 GB')\n#40 \/var\/www\/owncloud\/apps\/user_ldap\/lib\/User\/User.php(160): OCA\User_LDAP\User\User->updateQuota('20 GB')\n#41 \/var\/www\/owncloud\/apps\/user_ldap\/lib\/Access.php(736): OCA\User_LDAP\User\User->processAttributes(Array)\n#42 \/var\/www\/owncloud\/apps\/user_ldap\/lib\/Access.php(708): OCA\User_LDAP\Access->batchApplyUserAttributes(Array)\n#43 \/var\/www\/owncloud\/apps\/user_ldap\/lib\/Access.php(681): OCA\User_LDAP\Access->fetchListOfUsers('(&(&(|(objectcl...', Array)\n#44 \/var\/www\/owncloud\/apps\/user_ldap\/lib\/User_LDAP.php(102): OCA\User_LDAP\Access->fetchUsersByLoginName('jroussel', Array)\n#45 \/var\/www\/owncloud\/apps\/user_ldap\/lib\/User_LDAP.php(81): OCA\User_LDAP\User_LDAP->getLDAPUserByLoginName('jroussel')\n#46 \/var\/www\/owncloud\/lib\/private\/User\/Manager.php(160): OCA\User_LDAP\User_LDAP->loginName2UserName('jroussel')\n#47 \/var\/www\/owncloud\/lib\/private\/User\/Manager.php(140): OC\User\Manager->getUserObject('jroussel', Object(OCA\User_LDAP\User_LDAP))\n#48 \/var\/www\/owncloud\/lib\/private\/User\/Session.php(192): OC\User\Manager->get('jroussel')\n#49 \/var\/www\/owncloud\/lib\/private\/App\/AppManager.php(152): OC\User\Session->getUser()\n#50 \/var\/www\/owncloud\/lib\/private\/legacy\/app.php(313): OC\App\AppManager->isEnabledForUser('user_webdavauth')\n#51 \/var\/www\/owncloud\/lib\/public\/App.php(131): OC_App::isEnabled('user_webdavauth')\n#52 \/var\/www\/owncloud\/apps\/user_ldap\/appinfo\/app.php(72): OCP\App::isEnabled('user_webdavauth')\n#53 \/var\/www\/owncloud\/lib\/private\/legacy\/app.php(186): require_once('\/var\/www\/ownclo...')\n#54 \/var\/www\/owncloud\/lib\/private\/legacy\/app.php(149): OC_App::requireAppFile('user_ldap')\n#55 \/var\/www\/owncloud\/lib\/private\/legacy\/app.php(119): OC_App::loadApp('user_ldap')\n#56 \/var\/www\/owncloud\/remote.php(148): OC_App::loadApps(Array)\n#57 {main}","File":"\/var\/www\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Driver\/AbstractMySQLDriver.php","Line":115}","level":3,"time":"September 23, 2016 09:26:53","method":"PROPFIND","url":"/remote.php/webdav/","user":"jroussel"}`

@PVince81
Collaborator

@ccheveaux okay, and did you clean up this one specific share before 19 hours ? If the (2) was added even though we disabled the relevant code, then it means this one share "Secretariat_EltsPartages JMR_2014 2015" is different than the others and is maybe yet another additional case to look into.

@ccheveaux

Yes I "normally" cleaned.
But I can test again over an hour to confirm?

@PVince81
Collaborator

@ccheveaux sounds good.
Now with the disabled code I have no idea what other piece of code would be doing that.
Mind posting your SharedMount.php on http://pastebin.com/ to double check, just to be sure ?
Thanks

@ccheveaux
ccheveaux commented Sep 23, 2016 edited

This is my SharedMount.php

http://pastebin.com/cANJsY4Z

@PVince81
Collaborator

@ccheveaux it looks like you commented out all patches, so this basically is just like the original code.
So this means the original logic is now only affecting that one share ?

Can you then enable // if ($mountpoint->getShare()->getTarget() === $path && $mountpoint->getShare()->getId() !== $this->superShare->getId()) { alone and see if "Secretariat_EltsPartages JMR_2014 2015" is still receiving (2) ?

@ccheveaux

Ok let's go :)
I back in 1 hour ~

@ccheveaux
ccheveaux commented Sep 23, 2016 edited

Or not 1 hour ...
'(2)' back immediately :(
Perhaps desktop client push the bad update with (2) ?

@PVince81
Collaborator

@ccheveaux okay, thanks. So that part is not enough.

Now uncomment return $path

@ccheveaux

with // if ($mountpoint->getShare()->getTarget() === $path && $mountpoint->getShare()->getId() !== $this->superShare->getId()) { uncomment ?

@PVince81
Collaborator

@ccheveaux in this case it doesn't matter, the return will skip that code anyway

@PVince81
Collaborator

@ccheveaux in past runs did you have some logs with the result from "INFO SUR LE BUG DES 2" ? Else we can try this later. I need to find out what is so special about this share.

@ccheveaux

For the moment the folder don't take (2).

For the log i don't know how i can filter for this bug :/
The file is so big :(

@PVince81
Collaborator

grep -re DEBUG owncloud.log 😄
or grep -re "SharedMount::" owncloud.log

@ccheveaux

Nothing is clear from these commands.
Words should not be in the file. :/

@PVince81
Collaborator

Ok, putting it on an extra line:

grep -re "SharedMount::" owncloud.log > output.txt

then check the file output.txt

@ccheveaux

I had only the contents in a log file that on 22 September at 11:40

output.txt

@PVince81
Collaborator

Oh wow, that is really suspicious:

{"reqId":"2kvfKR2SNJ\/sr7fTjep8","remoteAddr":"138.231.101.52","app":"PHP","message":"Argument 1 passed to OCA\\Files_Sharing\\SharedMount::verifyMountPoint() must implement interface OCP\\Share\\IShare, null given, called in \/var\/www\/owncloud\/apps\/files_sharing\/lib\/SharedMount.php on line 65 and defined at \/var\/www\/owncloud\/apps\/files_sharing\/lib\/SharedMount.php#78","level":3,"time":"September 09, 2016 14:18:57","method":"PROPFIND","url":"\/remote.php\/webdav\/","user":"xxxxxx"}

So there is a weird invalid share coming in.

And the debug log only appeared while ownCloud's cron.php was running so far. Usually it could happen as well if the users have a sync client running or they're browsing the UI. Maybe they didn't at this time:

{"reqId":"d4jYEv5DOpFozoZu2syd","remoteAddr":"138.231.101.143","app":"DEBUG","message":"SharedMount:: {\"user\":\"cbiache\",\"path\":\"\\\/Secretariat_EltsPartages JMR_2014 2015 (2) (2) (2) (2) (2) (2)\",\"file_exists\":true,\"mountpointExists\":false,\"targets\":[]}","level":0,"time":"September 22, 2016 11:40:02","method":"GET","url":"\/cron.php","user":"--"}

So "file_exists" but the mount point doesn't exist, hmmm.

I'll compare this with a normally functionning OC.
Thanks a lot for the info!

@ccheveaux

There's something strange since, but it has nothing to do can be.
My CPU usage is important ...

image

@PVince81
Collaborator

Mind providing the oc_share entry for "Secretariat_EltsPartages" ? select * from oc_share where file_target like '%Secretariat_EltsPartages%'.

From the log above it looks like there is a "null" share coming in and being mounted. Trying to find out where it comes from.

I've tested locally a legitimate duplicate folder, and in this case it's "mountPointexists" that is true, not file_exists. Now to find out what causes it...

@PVince81
Collaborator

Hmm, not sure what happened on your server on September 9th, but the server was likely unusable for all the users from #25718 (comment) that have the error about verifyMountPoint.

I tried simulating a null share and what I get is two message:

{"reqId":"Xl6kEK8\/XH9jJ07228jn","remoteAddr":"127.0.0.1","app":"PHP","message":"Argument 1 passed to OCA\\Files_Sharing\\SharedMount::verifyMountPoint() must be an instance of OCP\\Share\\IShare, null given, called in \/srv\/www\/htdocs\/owncloud\/apps\/files_sharing\/lib\/SharedMount.php on line 71 and defined at \/srv\/www\/htdocs\/owncloud\/apps\/files_sharing\/lib\/SharedMount.php#84","level":3,"time":"2016-09-23T11:59:03+00:00","method":"GET","url":"\/owncloud\/index.php\/apps\/files\/?dir=\/&fileid=20","user":"user2"}
{"reqId":"Xl6kEK8\/XH9jJ07228jn","remoteAddr":"127.0.0.1","app":"PHP","message":"Call to a member function getTarget() on null at \/srv\/www\/htdocs\/owncloud\/apps\/files_sharing\/lib\/SharedMount.php#86","level":3,"time":"2016-09-23T11:59:03+00:00","method":"GET","url":"\/owncloud\/index.php\/apps\/files\/?dir=\/&fileid=20","user":"user2"}

and the user's account is not usable at all.

(this is on ownCloud 9.1..1)

@PVince81
Collaborator
apps\/files_sharing\/lib\/SharedMount.php on line 65

on line 65. This is not the same line in 9.1.1 https://github.com/owncloud/core/blob/v9.1.1/apps/files_sharing/lib/SharedMount.php#L65. So likely you were still on the old version, it's from 9.1.0: https://github.com/owncloud/core/blob/v9.1.0/apps/files_sharing/lib/SharedMount.php#L65

Ok, let me see how it behaved on 9.1.0 and whether it can mess up the shares in a way that makes them break worse in 9.1.1

@ccheveaux

'filedid=20' is 'Paris.jpg' on 'files/Photos/', a default file on profile creation.
I never create a 'User' or 'User2' account ...
I check in database and list of user account in ownCloud.

@PVince81
Collaborator

user1 and user2 are only local users I used for my own testing. That was the debug log from my local instance.

@PVince81
Collaborator

@ccheveaux did you ever migrate your users from the local users to LDAP and then change the LDAP user id to be the same as before ?
I'm looking at the cron code and there could be a situation where this could cause the symptoms you observed. Still trying to reach that point.

@PVince81
Collaborator

let's find out:

select * from oc_ldap_user_mapping where ldap_dn like '%cbiache%';
select * from oc_users where uid='cbiache';
@ccheveaux

No, i never migrate users, i always use LDAP users since the beginning.

And empty result for this sql command :/

@PVince81
Collaborator

Hmm, you should at least get one result for "cbiache" which is the user name appearing in the debug log.
Maybe select * from oc_ldap_user_mapping where owncloud_name='cbiache'.

Anyway, it seems you don't have duplicate user names so the situation I thought about is unlikely to happen.

@ccheveaux
ccheveaux commented Sep 23, 2016 edited

Yes with this command i have an answer with ldap_dn, owncloud_name and directory_uuid.

And only one.

@PVince81
Collaborator

Hmm, had another idea: create a ghost folder with the same name. Basically a folder that exists on disk in the data folder but not in oc_filecache (for whatever reason).
This does trigger adding a "(2)" but it only does it once.

@PVince81
Collaborator

@ccheveaux and I guess you already tried running this before ?

./occ files:scan --all
@ccheveaux
ccheveaux commented Sep 23, 2016 edited

I never launch this command.

@PVince81
Collaborator

I checked the cron / background scan and it is not possible to have the same user id twice there. So my theory of "mount point mounted twice for the same user" is not valid.

@PVince81
Collaborator

Tried to deliberately create duplicate shares, doubly init the filesystem but still cannot find a situation in which this "(2)" would get added...

@PVince81
Collaborator

Hmm, if I deliberately duplicate the super share here https://github.com/owncloud/core/blob/v9.1.1/apps/files_sharing/lib/MountProvider.php#L76 it will automatically add a "(2)".
BUT it does it because $mountpointExists is true, but on your server it's $view->file_exists($path) that is true. So it means it's not a duplicate share but something mysterious that is making so as if the folder would already exist even though it doesn't.

But so far the only thing that could make it so is a shared mount with that name because there is surely no folder "name (2) (2) (2)" on-disk. So possibly a previous mount.

Maybe some situation where the mount providers are called twice, maybe with a missing clean-up in-between ?

@PVince81
Collaborator

calling initMountPoints twice doesn't make the problem happen because there is a built-in check.

So the bug must happen between somewhere between initMountsPoints and the SharedMount creation.

@PVince81
Collaborator

Now my next theory is that there is another background job (not the scan one) that sets up the FS and doesn't clear it properly, or only half clears it in a way that makes initMountPoint resetup the mount points.

@PVince81
Collaborator

My current findings: if we make the CardDAV\SyncJob it is not cleaning up the FS between users due to avatar fetching. Now I don't see how the job in itself would cause the issue about (2).
So the idea is that maybe there is a subsequent job that would re-init the FS without clearing.
It can't be the Background Scan job because that one always clears before init.

@ccheveaux mind posting your oc_jobs table ?

@PVince81
Collaborator

Could everyone here post their oc_jobs table ? The more data points we have, the more likely to find a solution soon. Thanks.

@ccheveaux
ccheveaux commented Sep 23, 2016 edited

Here's mine, by cons it is 44 MB ...
I hosted elsewhere but the link is valid until October 14, 2016.

https://filesender.renater.fr/?s=download&token=f4a4f874-015e-ee49-b66d-63589ab7e227

@PVince81
Collaborator

@ccheveaux ah, indeed I forgot about all those one-shot expire jobs.
I've filtered them out and it looks like this:

(2, 'OCA\\Activity\\BackgroundJob\\EmailNotification', 'null', 1473247787, 1473247786, 0),
(3, 'OCA\\Activity\\BackgroundJob\\ExpireActivities', 'null', 1473750228, 1473750227, 0),
(30554, 'OC\\Log\\Rotate', '"\\/var\\/log\\/owncloud.log"', 0, 0, 0),
(90422, 'OCA\\Files\\BackgroundJob\\ScanFiles', 'null', 1468918494, 0, 0),
(90423, 'OCA\\Files\\BackgroundJob\\DeleteOrphanedItems', 'null', 1468918481, 0, 0),
(90424, 'OCA\\Files\\BackgroundJob\\CleanupFileLocks', 'null', 1468918478, 0, 0),
(90426, 'OCA\\DAV\\CardDAV\\SyncJob', 'null', 1468918461, 0, 0),
(90427, 'OCA\\Federation\\SyncJob', 'null', 1468918447, 0, 0),
(90495, '\\OC\\Authentication\\Token\\DefaultTokenCleanupJob', 'null', 0, 1470037419, 0),
(90496, 'OCA\\UpdateNotification\\Notification\\BackgroundJob', 'null', 0, 1470037420, 0),
(90497, 'OCA\\User_LDAP\\Jobs\\UpdateGroups', 'null', 0, 1470037421, 0),
(90498, 'OCA\\User_LDAP\\Jobs\\CleanUp', 'null', 0, 1470037421, 0),
(90499, 'OC\\Migration\\BackgroundRepair', '{"app":"dav","step":"OCA\\\\DAV\\\\Migration\\\\GenerateBirthdays"}', 0, 1470037436, 0),
(90500, 'OCA\\DAV\\CardDAV\\Sync\\SyncJob', 'null', 0, 1470037436, 0),
(90501, 'OCA\\Files_Sharing\\DeleteOrphanedSharesJob', 'null', 0, 1470037575, 0),
(90502, 'OCA\\Files_Sharing\\ExpireSharesJob', 'null', 0, 1470037575, 0),
(90661, 'OC\\Log\\Rotate', '"\\/var\\/log\\/owncloud\\/owncloud.log"', 0, 1472636258, 0),

Hmm, so on your environment SyncJob runs after Background Sync job like on my env.

Ok, then the only remaining jobs to look at are DeleteOrphanedSharesJob and ExpireSharesJob. These are likely to setup the FS as well after the unclean SyncJob didn't clean up.

@gregoryR
gregoryR commented Sep 27, 2016 edited

I'm seeing the " (2)" appended to shares (ldap users only here) after an upgrade from 9.1.0.15 to 9.1.1.3
It happens to a limited number of files
Here is my oc_jobs table

"1029","OCA\Activity\BackgroundJob\ExpireActivities","null","1474913260","1474959072","0"
"2726","OCA\Activity\BackgroundJob\EmailNotification","null","1474958166","1474959002","0"
"2730","OC\BackgroundJob\Legacy\RegularJob","[""OCA\\Files_Antivirus\\Cron\\Task"",""run""]","1474959002","1474959002","0"
"40486","OCA\Files_Trashbin\BackgroundJob\ExpireTrash","null","1474959001","1474959001","0"
"40487","OCA\Files_Versions\BackgroundJob\ExpireVersions","null","1474958166","1474959001","0"
"42894","OC\Log\Rotate","""\/home\/cloud\/data\/owncloud.log""","1474959002","1474959002","0"
"43400","OCA\Files\BackgroundJob\ScanFiles","null","1474959002","1474959002","0"
"43401","OCA\Files\BackgroundJob\DeleteOrphanedItems","null","1474956379","1474959002","0"
"43402","OCA\Files\BackgroundJob\CleanupFileLocks","null","1474959002","1474959002","0"
"43404","OCA\Federation\SyncJob","null","1474902432","1474959002","0"
"43405","OCA\DAV\CardDAV\SyncJob","null","1474878183","1474959002","0"
"68960","OCA\Files_Antivirus\Cron\Task","null","1474958166","1474959002","0"
"70687","\OC\Authentication\Token\DefaultTokenCleanupJob","null","1474959001","1474959001","0"
"70688","OCA\UpdateNotification\Notification\BackgroundJob","null","1474881919","1474959001","0"
"70689","OCA\User_LDAP\Jobs\UpdateGroups","null","1474958165","1474959001","0"
"70690","OCA\User_LDAP\Jobs\CleanUp","null","1474958166","1474959001","0"
"70692","OCA\DAV\CardDAV\Sync\SyncJob","null","0","1474919405","1474919405"
"70693","OCA\Files_Sharing\DeleteOrphanedSharesJob","null","1474958166","1474959001","0"
"70694","OCA\Files_Sharing\ExpireSharesJob","null","1474882778","1474959001","0"
"73385","OC\Command\CommandJob","""O:33:\""OCA\\Files_Versions\\Command\\Expire\"":2:{s:43:\""\u0000OCA\\Files_Versions\\Command\\Expire\u0000fileName\"";s:69:\""\/mission-meeting\/201609-argo-tianjin\/document\/argo-gdac-cookbook.docx\"";s:39:\""\u0000OCA\\Files_Versions\\Command\\Expire\u0000user\"";s:7:\""tc01856\"";}""","0","1474959357","0"
"73386","OC\Command\CommandJob","""O:33:\""OCA\\Files_Trashbin\\Command\\Expire\"":1:{s:39:\""\u0000OCA\\Files_Trashbin\\Command\\Expire\u0000user\"";s:7:\""tc01856\"";}""","0","1474959361","0"
"73387","OC\Command\CommandJob","""O:33:\""OCA\\Files_Trashbin\\Command\\Expire\"":1:{s:39:\""\u0000OCA\\Files_Trashbin\\Command\\Expire\u0000user\"";s:7:\""dc05576\"";}""","0","1474959468","0"

Are there any other useful information that I can provide ?

@ccheveaux

It's crazy, I have many more page you two.
Do I clean something and how?
Is not this supposed to be automatic?

@PVince81
Collaborator

@ccheveaux are you using system cron ? From what I remember it doesn't always run all the jobs but just a subset of them until the next time. If you're often having too many jobs pending, you could try having several "cron.php" run in parallel (this is supported since 9.1).
Or you could manually run "cron.php" (as the web user) a few times to make it finish all the one-time jobs.

@ccheveaux

My crontab -l is empty.
And for ownCloud, in the administration panel, i have this but i don't know how configure it :/

image

@PVince81
Collaborator

@ccheveaux aha! Yes, ajax cron only runs every time a user loads the web page so it might not run often enough. For bigger setups it's best to use system cron. See https://doc.owncloud.org/server/9.1/admin_manual/configuration_server/background_jobs_configuration.html?highlight=cron#cron

@PVince81
Collaborator

Okay, more cases to examine:

  • Case 1: find out whether the jobs OCA\Files_Sharing\DeleteOrphanedSharesJob and 'OCA\Files_Sharing\ExpireSharesJob` would be affected by an uncleant FS setup
  • Case 2: check whether one-time jobs coming after this one would be affected by an uncleant FS setu
@ccheveaux

Ok I will study all ca.
I do not make manual cleaning in the database.

I also have another bug that has appeared since we work on the error (2) '.
Access to aministration panel is impossible if I did not manually put in the 'config.php' file the loglevel to 0 ...
If I put 2 or 4, the administration page will not load.
I do not know if this bug was present before our manipulations, or if this is another bug that is.

@PVince81
Collaborator

Access to aministration panel is impossible

Can you make a separate issue ? Could be similar to #25984 where the log file is too big and the code that extracts the last snippet is slow.

@PVince81
Collaborator

@ccheveaux "ca" in english is "that" 😉

@ccheveaux

Hahaha yes sorry ;)
I try your solution for admin panel.
I hope next update correct it 🤔

@PVince81 PVince81 referenced this issue Sep 27, 2016
Merged

[stable9.1] Tear down FS between cron jobs #26223

5 of 11 tasks complete
@PVince81
Collaborator

So I found that the job "Command\Version" doesn't do a tearDownFS at the beginning. However it still seems to work correctly. Maybe there's an additional condition required to trigger the error case.

Here is a potential fix for the issue: #26223 and in patch form https://github.com/owncloud/core/pull/26223.patch

Could you guys try to apply that one-line patch and see whether the replication of "(2)" continues to occur ? The result of this test will tell us in which direction to continue looking.

Thanks

@gregoryR
gregoryR commented Sep 27, 2016 edited

On my instance owncloud cronjobs are runs in the crontab of www-data

root@vextra3:~# crontab -l -u www-data
# m h  dom mon dow   command
05,20,35,50 * * * * php -f /export/home/cloud/cron.php

I've edited /export/home/cloud/cron.php with PR #26223 but (2) are still appended to oc_share.file_target

Maybe an app is causing the issue to occur ? I've de-enabled two experimental apps (gpxpod and contacts) and restarted apache. No effect. Error in an official app ? Here is the list of apps enabled

www-data@vextra3:/export/home/cloud$ php occ app:list
Enabled:
  - activity: 2.3.2
  - comments: 0.3.0
  - dav: 0.2.6
  - federatedfilesharing: 0.3.0
  - federation: 0.1.0
  - files: 1.5.1
  - files_antivirus: 0.9.0.0
  - files_pdfviewer: 0.8.1
  - files_sharing: 0.10.0
  - files_texteditor: 2.1
  - files_trashbin: 0.9.0
  - files_versions: 1.3.0
  - files_videoplayer: 0.9.8
  - firstrunwizard: 1.1
  - gallery: 15.0.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.0
Disabled:
  - contacts
  - encryption
  - external
  - files_external
  - gpxpod
  - user_external
@gregoryR

On my instance I've de-enabled cron tab of www-data

root@vextra3:~# crontab -l -u  www-data
# m h  dom mon dow   command
#05,20,35,50 * * * * php -f /export/home/cloud/cron.php

but (2) are still appended to oc_share.file_target. Seems not limited to cron.php

@PVince81
Collaborator

@gregoryR thanks a lot for the info. Ok, so either it's happening in cron job and somewhere else. Or not at all in cron.

At least I can stop looking there and look in other places.

@gregoryR

I have

  • applied patch fa5fe2b
  • set loglevel to 0
  • delete (2) (2)... form the corrupted share in oc_share.file_target

Here are lines from owncloud.log where the (2) are added to the share

{"reqId":"sOiVeSPQi7gTBsg8NZZS","remoteAddr":"134.246.167.184","app":"DEBUG","message":"SharedMount:: {\"user\":\"gr05542\",\"path\":\"\\\/ascig-photos\",\"file_exists\":true,\"mountpointExists\":false,\"targets\":[]}","level":0,"time":"2016-09-30T09:41:39+02:00","method":"PROPFIND","url":"\/remote.php\/webdav\/","user":"dl01780"}
{"reqId":"bA8Iz8SxZiLVZaBQAJx6","remoteAddr":"134.246.167.184","app":"DEBUG","message":"SharedMount:: {\"user\":\"gr05542\",\"path\":\"\\\/ascig-photos (2)\",\"file_exists\":true,\"mountpointExists\":false,\"targets\":[]}","level":0,"time":"2016-09-30T09:42:09+02:00","method":"PROPFIND","url":"\/remote.php\/webdav\/","user":"dl01780"}
{"reqId":"lqXcf4KTUES\/QUiPnkG6","remoteAddr":"134.246.167.184","app":"DEBUG","message":"SharedMount:: {\"user\":\"gr05542\",\"path\":\"\\\/ascig-photos (2) (2)\",\"file_exists\":true,\"mountpointExists\":false,\"targets\":[]}","level":0,"time":"2016-09-30T09:42:39+02:00","method":"PROPFIND","url":"\/remote.php\/webdav\/","user":"dl01780"}

It's strange here because I (gr05542) don't share directory /ascig-photos with dl01780
134.246.167.184 is the ip of desktop owncloud client of dl01780

It's user ab05850 that shares the directory with some users including me gr05542 and dl01780. Here are the two lines of oc_shares

"2379","0","gr05542","ab05850",NULL,"folder","428917",NULL,"428917","/ascig-photos (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2)","31","1475160265","0",NULL,NULL,"0","ab05850"
"1265","0","dl01780","ab05850",NULL,"folder","428917","/428917","428917","/ascig-photos","31","1449269515","0",NULL,NULL,"0","ab05850"

desktop owncloud client of dl01780 write in my share ?

@MorrisJobke MorrisJobke referenced this issue in nextcloud/server Sep 30, 2016
Closed

Appended (2) to received shares #1588

@MorrisJobke
Member

@PVince81 To make your life easier: I found the cause of this: if you set up a Android client but used capital usernames the avatar code seems to be the reason: see nextcloud/server#1588 (comment)

@gregoryR

@MorrisJobke @PVince81 I'm not sure we're hit by the same issue
I don't see any capitalized avatar request on my server
grep 'index.php/avatar/[A-Z]' /var/log/apache2/access-cloud.log returns nothing
grep 'index.php/avatar/[a-z]' /var/log/apache2/access-cloud.log returns a lot of lines

And with patch applied nextcloud/server#1595 (2) are still appended to shares

@MorrisJobke
Member

Then it seems to be yet another cause.

@gregoryR

I delete the share from ab05850 to dl01780
(2) are still appended to my share every time the desktop (windows) client hit the server through remote.php/webdav

I could disconnect the desktop client and I thought the (2) stopped appearing. But (2) keeps reappearing every time cron.php run.

{"reqId":"RtAFPI2RZkOe6zYSxw2u","remoteAddr":"","app":"DEBUG","message":"SharedMount:: {\"user\":\"gr05542\",\"path\":\"\\\/ascig-photos (2)\",\"file_exists\":true,\"mountpointExists\":false,\"targets\":[]}","level":0,"time":"2016-09-30T16:53:51+02:00","method":"--","url":"\/cron.php","user":"--"}

It happens both with cron.php and access to remote.php/webdav from this particular user. Other users who have the same share don't see the issue and seems not triggering the (2) for my view. Not sure about normal access through index.php

@gregoryR

Sorry doesn't seem to be the cron.php that trigger the (2)
After one hour, only two (2) were appended to my view
ascig-photos (2) (2)
My crontab run every 15 minutes

the log of the cron only show the (2) appended

@PVince81
Collaborator
PVince81 commented Oct 4, 2016

if related to avatars, one way to check would be to disable avatars in config.php:

"enable_avatars" => false
@PVince81
Collaborator
PVince81 commented Oct 4, 2016

@MorrisJobke thanks for the hints. At least with the avatar casing I can reproduce a similar issue locally with 9.1.1. (9.0.5 was fine)

Maybe it will show even more clues as to other scenarios where username casing messes up.

@PVince81
Collaborator
PVince81 commented Oct 4, 2016

From what I see, if someone calls \OCC::$server->getUserFolder($userId) with the wrong casing, it is also likely to happen.

Well, there would be a way to find out: add some code in initMountPoints that checks for casing mismatch then log the stack trace to find out where it's happening.

But I'm afraid that there could be many other locations where it could be happening.
And fixing the casing directly in initMountPoints might not be enough because some code paths might still be using the previous user id, expecting it to be correct.

@MorrisJobke
Member

But I'm afraid that there could be many other locations where it could be happening.
And fixing the casing directly in initMountPoints might not be enough because some code paths might still be using the previous user id, expecting it to be correct.

Correct. This needs to be fixed in the initMountPoints to avoid future pitfalls, but also in the calling code.

@PVince81 PVince81 referenced this issue Oct 4, 2016
Merged

[stable9.1] Fix user casing in initMountPoints #26271

12 of 16 tasks complete
@PVince81
Collaborator
PVince81 commented Oct 4, 2016

working but untested POC here: #26271
(will test later)

@PVince81
Collaborator
PVince81 commented Oct 6, 2016

I don't see any capitalized avatar request on my server

@gregoryR it's not about capitalized, it's about casing mismatch. So if the user id given in the request you see in the access log doesn't match the casing of the real user, then the issue would happen.

For example if you have a user "User1" but the avatar requests "user1" then the problem will happen.

@karamatos

I can confirm that I have the same problem of (2) being added to shares and I cannot find a pattern to explain it. Things were working fine with version 9.0 but when I upgraded to 9.1 it all broke.

We are using LDAP for user access. To try to fix the problem, I stopped sharing folders, then deleted the local (desktop) ownCloud folder. The then manually added the shares and they call came down to my desktop and things were fine for a few days. Then when I tried to share a new document, boom -- all of the folders shared with me got (2) added to them and the desktop sync broke again.

I tried turning off the avatar and applying some of the patches mentioned here, but nothing worked.

@PVince81
Collaborator
PVince81 commented Oct 6, 2016

Ok, thanks for the info. So if disabling avatars doesn't prevent the replication of "(2)" then it means there are other mechanisms causing this.

I think this fix #26271 might be able to cover more of these, but it's still in review and needs testing. And it's bigger than the other ones so I wouldn't recommend patching a productive instance with it.
Still, we need to find a way to find out whether it solves the problem. Maybe setup a mirrored test instance with the same database ? (but in the latter case whatever is triggering the issue might not appear any more if it's triggered by users using OC)

@PVince81
Collaborator

Have you guys been able to check whether you had user names with a certain casing and whether you found avatar GET calls in access log that use lower case version of these names ?

@gregoryR

@PVince81 all letters in my users in ldap are lowercase and ex : gr05542
but I don't see any uppercase requests in avatars GET see #25718 (comment)

grep 'index.php/avatar/[A-Z]' /var/log/apache2/access-cloud.log returns nothing
grep 'index.php/avatar/[a-z]' /var/log/apache2/access-cloud.log returns a lot of lines

FYI i've just duplicated my owncloud instance in order to test your patch #26271 Just need a little time to delete "patch" from your comment #25718 (comment) and see if '(2)' comes back on this instance

@gregoryR

@PVince81 my debug instance of owncloud is now up and running with copy of the database and owncloud data path
I have removed the return $path in apps/files_sharing/lib/SharedMount.php
loglevel is turned to debug (0 in config.php)
patch #26271 IS NOT applied

'(2)' doesn't appear with cron activated but I'm the only one to know the url of this instance.

So I've connected my desktop client with intentionally bad casing login Gr05542 instead of gr05542
Client synchronizes normally and I see this requests in apache access logs

xxx.xxx.xxx.xxx - Gr05542 [12/Oct/2016:11:51:57 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 992 "-" "Mozilla/5.0 (Linux) mirall/2.2.4"

I can login through web interface with bad casing login but again no (2) appears in my shares nor in oc_share.file_target

any advice ?

@PVince81
Collaborator

@gregoryR hmm, well... this shows that regular usage of OC doesn't seem to trigger it.

Can you run cron.php a few times manually ?
If that doesn't create it, then it means one or several of the users on the regular instance are triggering the issue somehow.

@PVince81
Collaborator

Ok, I've got another idea. I'll prepare another debugging patch that will log the request URL and stack trace from whichever code path is adding the "(2)". Then with a bit of luck we can trace it back to a web request / client / user and find out what is causing this.
Stay tuned.

@PVince81
Collaborator

Debugging patch: #26355 (patch version https://github.com/owncloud/core/pull/26355.patch)

What it does is whenever the logic that adds the "(2)" is triggered, it records the stack trace leading to it with a few additional information, then logs these in the debug loglevel. (needs "loglevel" 0 for it to appear in owncloud.log).

Hopefully this should help pinpoint what the exact code path is and where it's triggered on your setup.

@gregoryR

@PVince81 without manually running cron.php just after my comments (I was eating) regular cronjobs seems to finally have triggerred the bug. crontabs are running every 10,25,40,55

and here are their traces in syslog

grep clouddebug /var/log/syslog
Oct 12 08:40:01 vextra3 CRON[19575]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 08:55:01 vextra3 CRON[19750]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 09:10:01 vextra3 CRON[20054]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 09:25:01 vextra3 CRON[20314]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 09:40:01 vextra3 CRON[20582]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 09:55:01 vextra3 CRON[20740]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 10:10:01 vextra3 CRON[21071]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 10:25:01 vextra3 CRON[21272]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 10:40:01 vextra3 CRON[21512]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 10:55:01 vextra3 CRON[21832]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 11:10:01 vextra3 CRON[22111]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 11:25:01 vextra3 CRON[22326]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 11:40:01 vextra3 CRON[22595]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 11:55:01 vextra3 CRON[22840]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 12:10:01 vextra3 CRON[23107]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 12:25:01 vextra3 CRON[23338]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 12:40:01 vextra3 CRON[23643]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 12:55:01 vextra3 CRON[23843]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 13:10:01 vextra3 CRON[24064]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 13:25:01 vextra3 CRON[24173]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 13:40:01 vextra3 CRON[24382]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 13:55:01 vextra3 CRON[24514]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 14:10:01 vextra3 CRON[24730]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)
Oct 12 14:25:01 vextra3 CRON[24907]: (www-data) CMD (php -f /export/home/clouddebug/cron.php)

First occurrences of '(2)' in owncloud.log is 2016-10-12T13:56:15

grep '(2)' owncloud.log |more
{"reqId":"b1VRCysN1DmCexkvdVLw","remoteAddr":"","app":"DEBUG","message":"SharedMount:: {\"user\":\"ip0
5575\",\"path\":\"\\\/Test Partage avec Ingrid\",\"file_exists\":true,\"mountpointExists\":false,\"tar
gets\":[\"\\\/CPER_ROEC (2)\"]}","level":0,"time":"2016-10-12T13:56:15+02:00","method":"--","url":"\/c
ron.php","user":"--"}
{"reqId":"b1VRCysN1DmCexkvdVLw","remoteAddr":"","app":"DEBUG","message":"SharedMount:: {\"user\":\"to1
efa9\",\"path\":\"\\\/photosJourneeCaparmor\",\"file_exists\":true,\"mountpointExists\":false,\"target
s\":[\"\\\/MEMO\\\/Datarmor et web services (2)\"]}","level":0,"time":"2016-10-12T13:56:25+02:00","met
hod":"--","url":"\/cron.php","user":"--"}
{"reqId":"b1VRCysN1DmCexkvdVLw","remoteAddr":"","app":"DEBUG","message":"SharedMount:: {\"user\":\"lp0
5480\",\"path\":\"\\\/JERICO-Ifremer_shared\",\"file_exists\":true,\"mountpointExists\":false,\"target
s\":[\"\\\/Diffusion donn\\u00e9es Ifremer (2)\"]}","level":0,"time":"2016-10-12T13:57:12+02:00","meth
od":"--","url":"\/cron.php","user":"--"}
{"reqId":"b1VRCysN1DmCexkvdVLw","remoteAddr":"","app":"DEBUG","message":"SharedMount:: {\"user\":\"lp0
5480\",\"path\":\"\\\/WP7\",\"file_exists\":true,\"mountpointExists\":false,\"targets\":[\"\\\/Diffusi
on donn\\u00e9es Ifremer (2)\",\"\\\/JERICO-Ifremer_shared (2)\"]}","level":0,"time":"2016-10-12T13:57
:12+02:00","method":"--","url":"\/cron.php","user":"--"}
{"reqId":"b1VRCysN1DmCexkvdVLw","remoteAddr":"","app":"DEBUG","message":"SharedMount:: {\"user\":\"lp0
5480\",\"path\":\"\\\/coriolis-catalogue-sextant\",\"file_exists\":true,\"mountpointExists\":false,\"t
argets\":[\"\\\/Diffusion donn\\u00e9es Ifremer (2)\",\"\\\/JERICO-Ifremer_shared (2)\",\"\\\/WP7 (2)\
"]}","level":0,"time":"2016-10-12T13:57:12+02:00","method":"--","url":"\/cron.php","user":"--"}
{"reqId":"b1VRCysN1DmCexkvdVLw","remoteAddr":"","app":"DEBUG","message":"SharedMount:: {\"user\":\"lp0
5480\",\"path\":\"\\\/copernicus-wave-parameters\",\"file_exists\":true,\"mountpointExists\":false,\"t
argets\":[\"\\\/Diffusion donn\\u00e9es Ifremer (2)\",\"\\\/JERICO-Ifremer_shared (2)\",\"\\\/WP7 (2)\
",\"\\\/coriolis-catalogue-sextant (2)\"]}","level":0,"time":"2016-10-12T13:57:12+02:00","method":"--"
,"url":"\/cron.php","user":"--"}

but for /ascig-photos which is shared to meshare I had to connect the desktop client of a particular user for triggering the (2) on this particular share. It's the same user than comment #25718 (comment)

First occurrences of this user in apache access.log for this instance is 14:16:41

xxx.xxx.xxx.xxx - dl01780 [12/Oct/2016:14:16:41 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1155
 "-" "Mozilla/5.0 (Windows) mirall/2.2.4 (build 6408)"
xxx.xxx.xxx.xxx - dl01780 [12/Oct/2016:14:16:43 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 1748
 "-" "Mozilla/5.0 (Windows) mirall/2.2.4 (build 6408)"
xxx.xxx.xxx.xxx - dl01780 [12/Oct/2016:14:17:50 +0200] "HEAD /remote.php/webdav/ HTTP/1.1" 200 535 "-" 
"Mozilla/5.0 (Windows) mirall/2.2.4 (build 6408)"
xxx.xxx.xxx.xxx - dl01780 [12/Oct/2016:14:17:52 +0200] "GET /status.php HTTP/1.1" 200 827 "-" "Mozilla/
5.0 (Windows) mirall/2.2.4 (build 6408)"
xxx.xxx.xxx.xxx - dl01780 [12/Oct/2016:14:17:52 +0200] "PROPFIND /remote.php/webdav/ HTTP/1.1" 207 992 
"-" "Mozilla/5.0 (Windows) mirall/2.2.4 (build 6408)"
xxx.xxx.xxx.xxx - dl01780 [12/Oct/2016:14:17:52 +0200] "GET /ocs/v1.php/cloud/capabilities?format=json 
HTTP/1.1" 200 1369 "-" "Mozilla/5.0 (Windows) mirall/2.2.4 (build 6408)"

and bing (2) appear in my share of /ascig-photo at the same hour

grep 'ascig-photos (2)' owncloud.log |more
{"reqId":"JsohRrQqGcA6gaBH4NKA","remoteAddr":"134.246.167.184","app":"DEBUG","message":"SharedMount:: 
{\"user\":\"gr05542\",\"path\":\"\\\/ascig-photos (2)\",\"file_exists\":true,\"mountpointExists\":fals
e,\"targets\":[]}","level":0,"time":"2016-10-12T14:16:43+02:00","method":"PROPFIND","url":"\/remote.ph
p\/webdav\/","user":"dl01780"}
{"reqId":"MVU2SyOESfHvNF7INTf+","remoteAddr":"134.246.167.184","app":"DEBUG","message":"SharedMount:: 
{\"user\":\"gr05542\",\"path\":\"\\\/ascig-photos (2) (2)\",\"file_exists\":true,\"mountpointExists\":
false,\"targets\":[]}","level":0,"time":"2016-10-12T14:16:44+02:00","method":"PROPFIND","url":"\/remot
e.php\/webdav\/","user":"dl01780"}
{"reqId":"OoITorA8DZRdf2jQjdgt","remoteAddr":"134.246.167.184","app":"DEBUG","message":"SharedMount:: 
{\"user\":\"gr05542\",\"path\":\"\\\/ascig-photos (2) (2) (2)\",\"file_exists\":true,\"mountpointExist
s\":false,\"targets\":[]}","level":0,"time":"2016-10-12T14:17:51+02:00","method":"HEAD","url":"\/remot
e.php\/webdav\/","user":"dl01780"}
{"reqId":"T29a1gpe9LK0qL835ecm","remoteAddr":"134.246.167.184","app":"DEBUG","message":"SharedMount:: 
{\"user\":\"gr05542\",\"path\":\"\\\/ascig-photos (2) (2) (2) (2)\",\"file_exists\":true,\"mountpointE
xists\":false,\"targets\":[]}","level":0,"time":"2016-10-12T14:17:52+02:00","method":"PROPFIND","url":
"\/remote.php\/webdav\/","user":"dl01780"}
{"reqId":"B3flUDegc5Jppi2k20vy","remoteAddr":"134.246.167.184","app":"DEBUG","message":"SharedMount:: 
{\"user\":\"gr05542\",\"path\":\"\\\/ascig-photos (2) (2) (2) (2) (2)\",\"file_exists\":true,\"mountpo
intExists\":false,\"targets\":[]}","level":0,"time":"2016-10-12T14:17:55+02:00","method":"GET","url":"
\/ocs\/v1.php\/cloud\/activity?page=0&pagesize=100&format=json","user":"dl01780"}
{"reqId":"f9ozEmRsLgpLISBxTXrB","remoteAddr":"134.246.167.184","app":"DEBUG","message":"SharedMount:: 
{\"user\":\"gr05542\",\"path\":\"\\\/ascig-photos (2) (2) (2) (2) (2) (2)\",\"file_exists\":true,\"mou
ntpointExists\":false,\"targets\":[]}","level":0,"time":"2016-10-12T14:17:57+02:00","method":"PROPFIND
","url":"\/remote.php\/webdav\/","user":"dl01780"}
{"reqId":"O5hFJZEaHSqznHkf48iC","remoteAddr":"134.246.167.184","app":"DEBUG","message":"SharedMount:: 
{\"user\":\"gr05542\",\"path\":\"\\\/ascig-photos (2) (2) (2) (2) (2) (2) (2)\",\"file_exists\":true,\
"mountpointExists\":false,\"targets\":[]}","level":0,"time":"2016-10-12T14:17:58+02:00","method":"PROP
FIND","url":"\/remote.php\/webdav\/documents","user":"dl01780"}
@PVince81
Collaborator

Hmm, all these calls are different URLs but internally would set up the user's filesystem.

In all cases I see that file_exists is true, so for some reason the code believes that the share exists already even though it doesn't. This is what was observed before already on @ccheveaux's system. So at least we know the issue on @gregoryR's system is the same and not related to avatars.

Just in case, can you try the following:
select * from oc_filecache where path like '%ascig-photos%'.
There should be only a single result linking to the storage of the folder owner, but no entries for the recipients. (this is to rule out that maybe there is a folder with this name, but shouldn't)

@PVince81
Collaborator

I'm going to add even more information to the last debug patch above to find out about the whole current mount table. There is something fishy in there.

@gregoryR

here are first 25 (of 520) of select * from oc_filecache where path like '%ascig-photos%' ordered by path ASC. Do you need all ? (lot of files in here)

"428917","414","files/ascig-photos","626e7cfc957558283888d11e88dd1229","428910","ascig-photos","2","1","1848887294","1467177171","1465988580","0","0","577358d3e7516","31",NULL
"455285","414","files/ascig-photos/Coordonnees_membres.ods","95ab9a35f99af91520c22cd00cb60483","428917","Coordonnees_membres.ods","17","3","108","1453975311","1453975311","0","0","9c1e83b91e664b58a1fd3bc6371d53c0","27",NULL
"455262","414","files/ascig-photos/Photos_Sections","b8ed987847072e430374750ade1178fa","428917","Photos_Sections","2","1","192800323","1467177171","1465478616","0","0","577358d3e1902","31",NULL
"503978","414","files/ascig-photos/Photos_Sections/Art_Floral","955d49da9fe708e40372f3007ff98ad6","455262","Art_Floral","2","1","91648042","1461152174","1461152174","0","0","571769ae1b22d","31",NULL
"511499","414","files/ascig-photos/Photos_Sections/Art_Floral/ASCIG_ArtFloral_FG_9431.JPG","d53505cd23527c6206a5229ffee47b6d","503978","ASCIG_ArtFloral_FG_9431.JPG","6","5","6652018","1459526209","1459526209","0","0","97a938afcef9258b0415a01e43567102","27",NULL
"511500","414","files/ascig-photos/Photos_Sections/Art_Floral/ASCIG_ArtFloral_FG_9435.JPG","39ce6c62fca81a6760d088215887c952","503978","ASCIG_ArtFloral_FG_9435.JPG","6","5","6373083","1459526211","1459526211","0","0","7f188e21e61eb3d0f3ecd58e40f9c6e2","27",NULL
"511504","414","files/ascig-photos/Photos_Sections/Art_Floral/ASCIG_ArtFloral_FG_9448.JPG","cfe5419c5fca94a0c54b02118e22c9a0","503978","ASCIG_ArtFloral_FG_9448.JPG","6","5","6377484","1459526212","1459526212","0","0","dd426d59ae2862c562b7ba693cb369be","27",NULL
"511508","414","files/ascig-photos/Photos_Sections/Art_Floral/ASCIG_ArtFloral_FG_9450.JPG","2ee11029b10c2e8b3c70338e8325098b","503978","ASCIG_ArtFloral_FG_9450.JPG","6","5","6856637","1459526214","1459526214","0","0","5a72d6e6bc67d6191f7d71fe6b78ec1b","27",NULL
"511512","414","files/ascig-photos/Photos_Sections/Art_Floral/ASCIG_ArtFloral_FG_9466.JPG","04caa7c76c5d3373bf9661d593df57d3","503978","ASCIG_ArtFloral_FG_9466.JPG","6","5","6577818","1459526215","1459526215","0","0","5655e797ffa7954d63f5725fa5502b8b","27",NULL
"511516","414","files/ascig-photos/Photos_Sections/Art_Floral/ASCIG_ArtFloral_FG_9474.JPG","a9bd4b986784ffdec38268d14c8cf677","503978","ASCIG_ArtFloral_FG_9474.JPG","6","5","5484322","1459526217","1459526217","0","0","8146a4f29fede71447f641412f39f2e6","27",NULL
"511520","414","files/ascig-photos/Photos_Sections/Art_Floral/ASCIG_ArtFloral_FG_9495.JPG","7729575826eac0f3456aabeefd071439","503978","ASCIG_ArtFloral_FG_9495.JPG","6","5","5964370","1459526218","1459526218","0","0","db01d4a805e44fb92513cb09a614472b","27",NULL
"511524","414","files/ascig-photos/Photos_Sections/Art_Floral/ASCIG_ArtFloral_FG_9513.JPG","f5cc74599a5d81204de064ca29f5cb8b","503978","ASCIG_ArtFloral_FG_9513.JPG","6","5","6078691","1459526219","1459526219","0","0","ed5d83da6ae792e0919a0bf5762159d1","27",NULL
"511528","414","files/ascig-photos/Photos_Sections/Art_Floral/ASCIG_ArtFloral_FG_9517.JPG","508fe2dfbaec9619f0c3aaa60403fb27","503978","ASCIG_ArtFloral_FG_9517.JPG","6","5","6318711","1461152160","1461152160","0","0","a82998240633113b35be6287ccd7b57e","27",NULL
"511532","414","files/ascig-photos/Photos_Sections/Art_Floral/ASCIG_ArtFloral_FG_9529.JPG","50689e1e9b1c52acf81d0c0e3cc83d2e","503978","ASCIG_ArtFloral_FG_9529.JPG","6","5","6125969","1461152163","1461152163","0","0","df83247c6abdb5473983237d38192095","27",NULL
"511536","414","files/ascig-photos/Photos_Sections/Art_Floral/ASCIG_ArtFloral_FG_9532.JPG","caf4d6555b33cb8366d7c2142a289a6f","503978","ASCIG_ArtFloral_FG_9532.JPG","6","5","6240928","1461152166","1461152166","0","0","d57bab779b5028554987fb13ebda243c","27",NULL
"511540","414","files/ascig-photos/Photos_Sections/Art_Floral/ASCIG_ArtFloral_FG_9534.JPG","cc41ce4f2bf2ddce9b04b8c63adb6f0a","503978","ASCIG_ArtFloral_FG_9534.JPG","6","5","6649675","1459526225","1459526225","0","0","958900354f7a636b3b924ca7d0704f79","27",NULL
"511544","414","files/ascig-photos/Photos_Sections/Art_Floral/ASCIG_ArtFloral_FG_9536.JPG","152499387d42e2c9eb24c251ef6f1694","503978","ASCIG_ArtFloral_FG_9536.JPG","6","5","6405200","1459526227","1459526227","0","0","a25aa50fb8eb0952e176d92328d26305","27",NULL
"503719","414","files/ascig-photos/Photos_Sections/Art_Floral/AscigArtFloral_ND_058.JPG","faa784cd39e1065dd73a5b1d16481da3","503978","AscigArtFloral_ND_058.JPG","6","5","2247440","1458718076","1458718076","0","0","49433d11eb197c28641dc5a9bbccc614","27",NULL
"503720","414","files/ascig-photos/Photos_Sections/Art_Floral/AscigArtFloral_ND_077.JPG","629c8febf36abb221a7210b53fa57cb1","503978","AscigArtFloral_ND_077.JPG","6","5","2375560","1458718127","1458718127","0","0","11b5b563c20d248f0077d090533cdf01","27",NULL
"503721","414","files/ascig-photos/Photos_Sections/Art_Floral/AscigArtFloral_ND_084.JPG","bd8f252c5143de1671f301ced0670f9f","503978","AscigArtFloral_ND_084.JPG","6","5","2321746","1458718154","1458718154","0","0","07f5fa7273d70bb5c487c653513e68af","27",NULL
"503722","414","files/ascig-photos/Photos_Sections/Art_Floral/AscigArtFloral_ND_088.JPG","bbc1152e4b65446d7d5e4c08542590f8","503978","AscigArtFloral_ND_088.JPG","6","5","2427030","1458718168","1458718168","0","0","7e772ee61c53f50f0a9070068a5034e8","27",NULL
"504894","414","files/ascig-photos/Photos_Sections/Art_Floral/Compo_Art_Floral_ND.jpg","5ec322d160ced851c68c58378c4ae202","503978","Compo_Art_Floral_ND.jpg","6","5","171360","1458727441","1458727441","0","0","e6dd86908f22199a350aad8473373751","27",NULL
"503980","414","files/ascig-photos/Photos_Sections/Breton","7b08be21f364fec1ae7495b7f1048539","455262","Breton","2","1","155966","1458725613","1458725613","0","0","56f262ed5a208","31",NULL
"455265","414","files/ascig-photos/Photos_Sections/Breton/Proposition_Breton_K.jpeg","12cc23a09131867457df2e73c09edb0f","503980","Proposition_Breton_K.jpeg","6","5","155966","1453966369","1453966369","0","0","c68e42676716f5de14501cf98e0f572a","27",NULL
"655752","414","files/ascig-photos/Photos_Sections/Chorale","e03eab52e125e2ee3435b2281bd0e199","455262","Chorale","2","1","6745902","1467177171","1467177171","0","0","577358d3ce2e2","31",

patch #26355 is applied here but will wait for the corrected version

@PVince81
Collaborator

I added a commit to the patch. So now the debug patch becomes: https://github.com/owncloud/core/pull/26355.patch

Did some local test and debugged as well, purposefully creating duplicates to observe what the normal behavior is. But the normal behavior doesn't match what we observe on your systems. Normal behavior is "if there is already another file or received share with the same name, then append a (2)". In case of an existing file the "file_exists($path)" would return true, else the $mountpointExists($path) would return true. But the debug info so far on your servers shows that there is no other mount point.

@PVince81
Collaborator

@gregoryR thanks for the output. Actually I only wanted the one entry. This query select * from oc_filecache where path like '%ascig-photos' (remove trailing '%').

Now also in case of oc_filecache integrity problems, running this command would fix them:

% ./occ files:scan --all
@PVince81
Collaborator

another thing to try, mostly because I'm out of ideas, in case of oc_filecache corruption:

  • path hash check: select * from oc_filecache where path_hash != md5(path); => must return 0 results
  • parent-child relationship check: select fc.fileid, fc.path, fc2.fileid, fc2.path from oc_filecache fc, oc_filecache fc2 where fc.parent = fc2.fileid and CONCAT(fc2.path, '/', fc.name) != fc.path and fc2.path != ''; => must return 0 results
@PVince81
Collaborator

Just saw your comment from #25718 (comment) again with the strangely "share in two directions case". I tried to create this locally by fiddling with the DB (the UI doesn't allow that), but it doesn't case any nasty side effects not adds a "(2)", so possibly unrelated.

@PVince81
Collaborator

It's strange here because I (gr05542) don't share directory /ascig-photos with dl01780

Indeed strange... so it means that dl01789 has a shared mount belonging to gr05542...

I'll adjust the patch again to also log the share id, so we can at least map to oc_share entries.

@PVince81
Collaborator

Updated debug patch to also include share info: https://github.com//owncloud/core/pull/26355

Goal is also to understand the strange non-matching sharing scenario observed here #25718 (comment) which could hopefully be a clue.

@gregoryR

Applied modified version of #26355, here is the first log

{"reqId":"G\/SPP1HxYmSBQPIu2stb","remoteAddr":"134.246.167.184","app":"DEBUG","message":"Share two DEBUG: {\"stack\":[{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/files_sharing\\\/lib\\\/SharedMount.php\",\"line\":97,\"function\":\"generateUniqueTarget\",\"class\":\"OCA\\\\Files_Sharing\\\\SharedMount\",\"object\":{},\"type\":\"->\",\"args\":[\"\\\/MEMO\\\/Datarmor et web services (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (\",{},[]]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/files_sharing\\\/lib\\\/SharedMount.php\",\"line\":71,\"function\":\"verifyMountPoint\",\"class\":\"OCA\\\\Files_Sharing\\\\SharedMount\",\"object\":{},\"type\":\"->\",\"args\":[{},[]]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/files_sharing\\\/lib\\\/MountProvider.php\",\"line\":92,\"function\":\"__construct\",\"class\":\"OCA\\\\Files_Sharing\\\\SharedMount\",\"object\":{},\"type\":\"->\",\"args\":[\"\\\\OC\\\\Files\\\\Storage\\\\Shared\",[],{\"user\":\"to1efa9\",\"superShare\":{},\"groupedShares\":[{}]},{}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Config\\\/MountProviderCollection.php\",\"line\":76,\"function\":\"getMountsForUser\",\"class\":\"OCA\\\\Files_Sharing\\\\MountProvider\",\"object\":{},\"type\":\"->\",\"args\":[{},{}]},{\"function\":\"OC\\\\Files\\\\Config\\\\{closure}\",\"class\":\"OC\\\\Files\\\\Config\\\\MountProviderCollection\",\"object\":{},\"type\":\"->\",\"args\":[{}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Config\\\/MountProviderCollection.php\",\"line\":77,\"function\":\"array_map\",\"args\":[{},[{},{},{}]]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Filesystem.php\",\"line\":422,\"function\":\"getMountsForUser\",\"class\":\"OC\\\\Files\\\\Config\\\\MountProviderCollection\",\"object\":{},\"type\":\"->\",\"args\":[{}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/files_sharing\\\/lib\\\/sharedstorage.php\",\"line\":99,\"function\":\"initMountPoints\",\"class\":\"OC\\\\Files\\\\Filesystem\",\"type\":\"::\",\"args\":[\"to1efa9\"]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/files_sharing\\\/lib\\\/sharedstorage.php\",\"line\":448,\"function\":\"init\",\"class\":\"OC\\\\Files\\\\Storage\\\\Shared\",\"object\":{\"cache\":null,\"scanner\":null,\"watcher\":null,\"propagator\":null,\"updater\":null},\"type\":\"->\",\"args\":[]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Storage\\\/Wrapper\\\/Wrapper.php\",\"line\":485,\"function\":\"getWrapperStorage\",\"class\":\"OC\\\\Files\\\\Storage\\\\Shared\",\"object\":{\"cache\":null,\"scanner\":null,\"watcher\":null,\"propagator\":null,\"updater\":null},\"type\":\"->\",\"args\":[]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/files_sharing\\\/lib\\\/sharedstorage.php\",\"line\":122,\"function\":\"instanceOfStorage\",\"class\":\"OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper\",\"object\":{\"cache\":null,\"scanner\":null,\"watcher\":null,\"propagator\":null,\"updater\":null},\"type\":\"->\",\"args\":[\"\\\\OC\\\\Files\\\\Storage\\\\Common\"]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/legacy\\\/util.php\",\"line\":148,\"function\":\"instanceOfStorage\",\"class\":\"OC\\\\Files\\\\Storage\\\\Shared\",\"object\":{\"cache\":null,\"scanner\":null,\"watcher\":null,\"propagator\":null,\"updater\":null},\"type\":\"->\",\"args\":[\"\\\\OC\\\\Files\\\\Storage\\\\Common\"]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Storage\\\/StorageFactory.php\",\"line\":100,\"function\":\"{closure}\",\"class\":\"OC_Util\",\"type\":\"::\",\"args\":[\"\\\/dl01780\\\/files\\\/DATARMOR-install\\\/\",{\"cache\":null,\"scanner\":null,\"watcher\":null,\"propagator\":null,\"updater\":null},{}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Storage\\\/StorageFactory.php\",\"line\":82,\"function\":\"wrap\",\"class\":\"OC\\\\Files\\\\Storage\\\\StorageFactory\",\"object\":{},\"type\":\"->\",\"args\":[{},{\"cache\":null,\"scanner\":null,\"watcher\":null,\"propagator\":null,\"updater\":null}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Mount\\\/MountPoint.php\",\"line\":137,\"function\":\"getInstance\",\"class\":\"OC\\\\Files\\\\Storage\\\\StorageFactory\",\"object\":{},\"type\":\"->\",\"args\":[{},\"\\\\OC\\\\Files\\\\Storage\\\\Shared\",{\"user\":\"dl01780\",\"superShare\":{},\"groupedShares\":[{}],\"ownerView\":{}}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Mount\\\/MountPoint.php\",\"line\":160,\"function\":\"createStorage\",\"class\":\"OC\\\\Files\\\\Mount\\\\MountPoint\",\"object\":{},\"type\":\"->\",\"args\":[]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/View.php\",\"line\":1356,\"function\":\"getStorage\",\"class\":\"OC\\\\Files\\\\Mount\\\\MountPoint\",\"object\":{},\"type\":\"->\",\"args\":[]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Node\\\/Root.php\",\"line\":180,\"function\":\"getFileInfo\",\"class\":\"OC\\\\Files\\\\View\",\"object\":{},\"type\":\"->\",\"args\":[\"\\\/dl01780\"]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Node\\\/Root.php\",\"line\":342,\"function\":\"get\",\"class\":\"OC\\\\Files\\\\Node\\\\Root\",\"object\":{},\"type\":\"->\",\"args\":[\"\\\/dl01780\"]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Server.php\",\"line\":809,\"function\":\"getUserFolder\",\"class\":\"OC\\\\Files\\\\Node\\\\Root\",\"object\":{},\"type\":\"->\",\"args\":[\"dl01780\"]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/ServerFactory.php\",\"line\":127,\"function\":\"getUserFolder\",\"class\":\"OC\\\\Server\",\"object\":{},\"type\":\"->\",\"args\":[]},{\"function\":\"OCA\\\\DAV\\\\Connector\\\\Sabre\\\\{closure}\",\"class\":\"OCA\\\\DAV\\\\Connector\\\\Sabre\\\\ServerFactory\",\"object\":{},\"type\":\"->\",\"args\":[{\"absoluteUrl\":\"http:\\\/\\\/clouddebug.ifremer.fr\\\/remote.php\\\/webdav\\\/\"},{}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php\",\"line\":105,\"function\":\"call_user_func_array\",\"args\":[{},[{\"absoluteUrl\":\"http:\\\/\\\/clouddebug.ifremer.fr\\\/remote.php\\\/webdav\\\/\"},{}]]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php\",\"line\":446,\"function\":\"emit\",\"class\":\"Sabre\\\\Event\\\\EventEmitter\",\"object\":{\"tree\":{},\"httpResponse\":{},\"httpRequest\":{\"absoluteUrl\":\"http:\\\/\\\/clouddebug.ifremer.fr\\\/remote.php\\\/webdav\\\/\"},\"sapi\":{},\"transactionType\":null,\"protectedProperties\":[\"{DAV:}getcontentlength\",\"{DAV:}getetag\",\"{DAV:}getlastmodified\",\"{DAV:}lockdiscovery\",\"{DAV:}supportedlock\",\"{DAV:}quota-available-bytes\",\"{DAV:}quota-used-bytes\",\"{DAV:}supported-privilege-set\",\"{DAV:}current-user-privilege-set\",\"{DAV:}acl\",\"{DAV:}acl-restrictions\",\"{DAV:}inherited-acl-set\",\"{DAV:}supported-method-set\",\"{DAV:}supported-report-set\",\"{DAV:}sync-token\",\"{http:\\\/\\\/calendarserver.org\\\/ns\\\/}ctag\",\"{http:\\\/\\\/sabredav.org\\\/ns}sync-token\"],\"debugExceptions\":false,\"resourceTypeMapping\":{\"Sabre\\\\DAV\\\\ICollection\":\"{DAV:}collection\"},\"enablePropfindDepthInfinity\":true,\"xml\":{\"elementMap\":{\"{DAV:}multistatus\":\"Sabre\\\\DAV\\\\Xml\\\\Response\\\\MultiStatus\",\"{DAV:}response\":\"Sabre\\\\DAV\\\\Xml\\\\Element\\\\Response\",\"{DAV:}propfind\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\PropFind\",\"{DAV:}propertyupdate\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\PropPatch\",\"{DAV:}mkcol\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\MkCol\",\"{DAV:}resourcetype\":\"Sabre\\\\DAV\\\\Xml\\\\Property\\\\ResourceType\"},\"namespaceMap\":{\"DAV:\":\"d\",\"http:\\\/\\\/sabredav.org\\\/ns\":\"s\"},\"classMap\":[]}},\"type\":\"->\",\"args\":[\"beforeMethod\",[{\"absoluteUrl\":\"http:\\\/\\\/clouddebug.ifremer.fr\\\/remote.php\\\/webdav\\\/\"},{}]]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php\",\"line\":248,\"function\":\"invokeMethod\",\"class\":\"Sabre\\\\DAV\\\\Server\",\"object\":{\"tree\":{},\"httpResponse\":{},\"httpRequest\":{\"absoluteUrl\":\"http:\\\/\\\/clouddebug.ifremer.fr\\\/remote.php\\\/webdav\\\/\"},\"sapi\":{},\"transactionType\":null,\"protectedProperties\":[\"{DAV:}getcontentlength\",\"{DAV:}getetag\",\"{DAV:}getlastmodified\",\"{DAV:}lockdiscovery\",\"{DAV:}supportedlock\",\"{DAV:}quota-available-bytes\",\"{DAV:}quota-used-bytes\",\"{DAV:}supported-privilege-set\",\"{DAV:}current-user-privilege-set\",\"{DAV:}acl\",\"{DAV:}acl-restrictions\",\"{DAV:}inherited-acl-set\",\"{DAV:}supported-method-set\",\"{DAV:}supported-report-set\",\"{DAV:}sync-token\",\"{http:\\\/\\\/calendarserver.org\\\/ns\\\/}ctag\",\"{http:\\\/\\\/sabredav.org\\\/ns}sync-token\"],\"debugExceptions\":false,\"resourceTypeMapping\":{\"Sabre\\\\DAV\\\\ICollection\":\"{DAV:}collection\"},\"enablePropfindDepthInfinity\":true,\"xml\":{\"elementMap\":{\"{DAV:}multistatus\":\"Sabre\\\\DAV\\\\Xml\\\\Response\\\\MultiStatus\",\"{DAV:}response\":\"Sabre\\\\DAV\\\\Xml\\\\Element\\\\Response\",\"{DAV:}propfind\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\PropFind\",\"{DAV:}propertyupdate\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\PropPatch\",\"{DAV:}mkcol\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\MkCol\",\"{DAV:}resourcetype\":\"Sabre\\\\DAV\\\\Xml\\\\Property\\\\ResourceType\"},\"namespaceMap\":{\"DAV:\":\"d\",\"http:\\\/\\\/sabredav.org\\\/ns\":\"s\"},\"classMap\":[]}},\"type\":\"->\",\"args\":[{\"absoluteUrl\":\"http:\\\/\\\/clouddebug.ifremer.fr\\\/remote.php\\\/webdav\\\/\"},{}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/dav\\\/appinfo\\\/v1\\\/webdav.php\",\"line\":56,\"function\":\"exec\",\"class\":\"Sabre\\\\DAV\\\\Server\",\"object\":{\"tree\":{},\"httpResponse\":{},\"httpRequest\":{\"absoluteUrl\":\"http:\\\/\\\/clouddebug.ifremer.fr\\\/remote.php\\\/webdav\\\/\"},\"sapi\":{},\"transactionType\":null,\"protectedProperties\":[\"{DAV:}getcontentlength\",\"{DAV:}getetag\",\"{DAV:}getlastmodified\",\"{DAV:}lockdiscovery\",\"{DAV:}supportedlock\",\"{DAV:}quota-available-bytes\",\"{DAV:}quota-used-bytes\",\"{DAV:}supported-privilege-set\",\"{DAV:}current-user-privilege-set\",\"{DAV:}acl\",\"{DAV:}acl-restrictions\",\"{DAV:}inherited-acl-set\",\"{DAV:}supported-method-set\",\"{DAV:}supported-report-set\",\"{DAV:}sync-token\",\"{http:\\\/\\\/calendarserver.org\\\/ns\\\/}ctag\",\"{http:\\\/\\\/sabredav.org\\\/ns}sync-token\"],\"debugExceptions\":false,\"resourceTypeMapping\":{\"Sabre\\\\DAV\\\\ICollection\":\"{DAV:}collection\"},\"enablePropfindDepthInfinity\":true,\"xml\":{\"elementMap\":{\"{DAV:}multistatus\":\"Sabre\\\\DAV\\\\Xml\\\\Response\\\\MultiStatus\",\"{DAV:}response\":\"Sabre\\\\DAV\\\\Xml\\\\Element\\\\Response\",\"{DAV:}propfind\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\PropFind\",\"{DAV:}propertyupdate\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\PropPatch\",\"{DAV:}mkcol\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\MkCol\",\"{DAV:}resourcetype\":\"Sabre\\\\DAV\\\\Xml\\\\Property\\\\ResourceType\"},\"namespaceMap\":{\"DAV:\":\"d\",\"http:\\\/\\\/sabredav.org\\\/ns\":\"s\"},\"classMap\":[]}},\"type\":\"->\",\"args\":[]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/remote.php\",\"line\":164,\"args\":[\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/dav\\\/appinfo\\\/v1\\\/webdav.php\"],\"function\":\"require_once\"}],\"user\":\"to1efa9\",\"original_path\":\"\\\/MEMO\\\/Datarmor et web services (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (\",\"renamed_path\":\"\\\/MEMO\\\/Datarmor et web services (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) ( (2)\",\"url\":\"\\\/remote.php\\\/webdav\\\/\",\"already_mounted_storageId\":\"shared::\\\/MEMO\\\/Datarmor et web services (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (\",\"already_mounted_internal_path\":\"\",\"all_mounts\":{\"\\\/\":{},\"\\\/dl01780\\\/\":{},\"\\\/dl01780\\\/files\\\/1061409.jpg\\\/\":{},\"\\\/dl01780\\\/files\\\/DATARMOR-install\\\/\":{},\"\\\/dl01780\\\/files\\\/Datarmor et web services.xlsx\\\/\":{},\"\\\/dl01780\\\/files\\\/2016-Dossier-de-promotion-TA-grocher.doc\\\/\":{},\"\\\/dl01780\\\/files\\\/ascig-photos\\\/\":{},\"\\\/el05cfc\\\/\":{},\"\\\/to1efa9\\\/\":{},\"\\\/to1efa9\\\/files\\\/MEMO\\\/Datarmor et web services (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (\\\/\":{},\"\\\/to1efa9\\\/files\\\/photosJourneeCaparmor (2) (2) (2) (2) (2) (2) (2) (2) (2) (3) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (\\\/\":{},\"\\\/tl0569f\\\/\":{},\"\\\/tl0569f\\\/files\\\/BDD-Capteurs\\\/\":{},\"\\\/tl0569f\\\/files\\\/WP7.1_WP7.2\\\/\":{},\"\\\/tl0569f\\\/files\\\/CoriolisBigData\\\/\":{},\"\\\/tl0569f\\\/files\\\/004 Doc Developpement Info \\\/\":{},\"\\\/sl05415\\\/\":{},\"\\\/sl05415\\\/files\\\/datarmo-photo\\\/\":{}},\"superShare\":{\"id\":\"2115\",\"nodeid\":760660,\"shared_with\":null,\"share_owner\":\"tl0569f\",\"share_type\":null,\"shared_by\":null},\"groupedShares\":[{\"id\":\"2115\",\"nodeid\":760660,\"shared_with\":\"to1efa9\",\"share_owner\":\"tl0569f\",\"share_type\":0,\"shared_by\":\"tl0569f\"}]}","level":0,"time":"2016-10-12T16:05:39+02:00","method":"PROPFIND","url":"\/remote.php\/webdav\/","user":"dl01780"}

with a warning concerning encodeShare() just after

{"reqId":"G\/SPP1HxYmSBQPIu2stb","remoteAddr":"134.246.167.184","app":"PHP","message":"Cannot redeclare OCA\\Files_Sharing\\encodeShare() (previously declared in \/export\/home\/clouddebug\/apps\/files_sharing\/lib\/SharedMount.php:161) at \/export\/home\/clouddebug\/apps\/files_sharing\/lib\/SharedMount.php#161","level":3,"time":"2016-10-12T16:05:39+02:00","method":"PROPFIND","url":"\/remote.php\/webdav\/","user":"dl01780"}
@PVince81
Collaborator

@gregoryR thanks a lot. What I see doesn't match the regular use case and seems to contain potential clues.

At first look I see that there are many mount points already setup.

This is the share that triggers the (2) logic:

      "id": "2115",
      "nodeid": 760660,
      "shared_with": "to1efa9",
      "share_owner": "tl0569f",
      "share_type": 0,
      "shared_by": "tl0569f"

@gregoryR select * from oc_share where id=2115

@PVince81
Collaborator

from what I see at this stage there are mount points for at least 5 users set up at the same time. This is usually normal in some resharing situations.

The request is a normal Webdav PROPFIND on the root by the user "dl01780".
The SharedMount in question however is being mounted for the user "to1efa9", so potentially some kind of reshare.

@PVince81
Collaborator

@gregoryR let's find out about the share in question:

  • select * from oc_share where id=2115 or file_source=760660
  • select * from oc_storages s, oc_filecache fc where s.numeric_id=fc.storage and fc.fileid=760660

Goal is to find out who shares what with who, it seems it might be a bit complex.

Following the stack trace, I see that it is setting up the mount "/dl01780/files/DATAARMOR-install" and this results in a later initialization of the mount points for the user "to1efa9", which itself will setup the mount "/MEMO/Dataarmor et web services (2) (2) ..." for the user "to1efa9".

So it is likely that the user "to1efa9" is sharing "DATAARMOR-install" somehow with "dl01780". Maybe it's the same, maybe not.

@gregoryR

path hash check: select * from oc_filecache where path_hash != md5(path); => must return 0 results

returns 0 lines in my instance

parent-child relationship check: select fc.fileid, fc.path, fc2.fileid, fc2.path from oc_filecache fc, oc_filecache fc2 where fc.parent = fc2.fileid and CONCAT(fc2.path, '/', fc.name) != fc.path and fc2.path != '';

returns 7 lines on my instance

 fileid     path    fileid  path    
508632  files/CPER-ROEC/dossierFEDER/formulaire/001-Plan_d...   508631  files_trashbin/files/Dossier_demande_FEDER.d147428...
508633  files/CPER-ROEC/dossierFEDER/formulaire/003-Formul...   508631  files_trashbin/files/Dossier_demande_FEDER.d147428...
508634  files/CPER-ROEC/dossierFEDER/formulaire/002-guide ...   508631  files_trashbin/files/Dossier_demande_FEDER.d147428...
508635  files/CPER-ROEC/dossierFEDER/formulaire/004-Formul...   508631  files_trashbin/files/Dossier_demande_FEDER.d147428...
508636  files/CPER-ROEC/dossierFEDER/formulaire/005-Annexe...   508631  files_trashbin/files/Dossier_demande_FEDER.d147428...
508637  files/CPER-ROEC/dossierFEDER/formulaire/006-Annexe...   508631  files_trashbin/files/Dossier_demande_FEDER.d147428...
510085  files/CPER-ROEC/dossierFEDER/formulaire/004-Formul...   508631  files_trashbin/files/Dossier_demande_FEDER.d147428...
@gregoryR

Here is the result of select * from oc_share where id=2115

"2115","0","to1efa9","tl0569f",NULL,"file","760660",NULL,"760660","/MEMO/Datarmor et web services (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (","19","1468246436","0",NULL,NULL,"0","tl0569f"
@PVince81
Collaborator

At least there is one clear clue: at the time the SharedMount for user "to1efa9" is being processed, there is already a mount point for the same name for that user:

    "/to1efa9/": {},
    "/to1efa9/files/MEMO/Datarmor et web services (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (/": {},
    "/to1efa9/files/photosJourneeCaparmor (2) (2) (2) (2) (2) (2) (2) (2) (2) (3) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (/": {},

so this is what is causing the duplication.

Now the question is why the mount point already exists at this point.

@PVince81
Collaborator

Just in case, let's check if any of the involved users is receiving the same share twice, this query will retrieve all shares that target any of the users for which mounts points exist at the time of the bug:

select oc_share sh where share_with in ('dl01780', 'el05cfc', 'to1efa9', 'tl0569f', 'sl05415');
@PVince81
Collaborator

here are all mounts, for readability:

     "/": {},
    "/dl01780/": {},
    "/dl01780/files/1061409.jpg/": {},
    "/dl01780/files/DATARMOR-install/": {},
    "/dl01780/files/Datarmor et web services.xlsx/": {},
    "/dl01780/files/2016-Dossier-de-promotion-TA-grocher.doc/": {},
    "/dl01780/files/ascig-photos/": {},
    "/el05cfc/": {},
    "/to1efa9/": {},
    "/to1efa9/files/MEMO/Datarmor et web services (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (/": {},
    "/to1efa9/files/photosJourneeCaparmor (2) (2) (2) (2) (2) (2) (2) (2) (2) (3) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (/": {},
    "/tl0569f/": {},
    "/tl0569f/files/BDD-Capteurs/": {},
    "/tl0569f/files/WP7.1_WP7.2/": {},
    "/tl0569f/files/CoriolisBigData/": {},
    "/tl0569f/files/004 Doc Developpement Info /": {},
    "/sl05415/": {},
    "/sl05415/files/datarmo-photo/": {}

interestingly the user "dl01780" already received a file "Dataarmor et web services.xlsx".
I assume that "Dataarmor et web services (2) (2) ..." of user "to1efa9" is the same file.

Maybe the same file is shared to the same user "to1efa9" using different sharing paths ?

@karamatos

I don't have much to add now but I was trying to experiment with restoring a backup version of oc. I restored my 9.0 installation but after a while, the same thing happened with the share names. I don't think it is related to my 9.1 upgrade -- this problem may have started in 9.0. Everything was OK with 9.1 until I created a new share -- then all my existing shares started to get (2) (2) added to the end. It also seems to get worse over time as now my desktop sync is broken and CPU usage as gone up quite a bit.

@PVince81
Collaborator

@karamatos thanks. Desktop sync will go crazy because for every Webdav access to the server, a folder gets renamed, so it means perpetual changes to sync.

@PVince81
Collaborator

I tried going super-crazy and created a chain of shares where subfolders from shares were reshared. I did this on v8.2 in a way to have user1 see one of the shared subfolders coming back as a received mount point. After upgrading to v9.0 it disappeared due to the flattening of reshares. Upgrading to v9.1.1 didn't cause any issues either.

Then I tried again going crazy and moving subfolder reshares in and out, etc. I could not reproduce the issue with the "(2)", however I managed to find a different issue... #26357

@PVince81
Collaborator

Tried to create ghost shares using the technique from #26357 in the hope to have overlapping ghost shares, but it didn't cause any extra "(2)" to appear, but rather iterated to "(3)", "(4)" ...

@gregoryR

Here are the results of queries

select * from oc_share where id=2115 or file_source=760660

"2106","3",NULL,"tl0569f",NULL,"file","760660",NULL,"760660","/Datarmor et web services.xlsx","1","1468246078","0",NULL,"JTGxfgFzgpvJjeq","0","tl0569f"
"2107","0","ww1fc52","tl0569f",NULL,"file","760660",NULL,"760660","/Datarmor et web services.xlsx","19","1468246106","0",NULL,NULL,"0","tl0569f"
"2108","0","ag0601d","tl0569f",NULL,"file","760660",NULL,"760660","/Datarmor et web services.xlsx","19","1468246287","0",NULL,NULL,"0","tl0569f"
"2109","0","fp05b47","tl0569f",NULL,"file","760660",NULL,"760660","/Datarmor et web services.xlsx","19","1468246326","0",NULL,NULL,"0","tl0569f"
"2110","0","sh05e75","tl0569f",NULL,"file","760660",NULL,"760660","/Datarmor et web services.xlsx","19","1468246343","0",NULL,NULL,"0","tl0569f"
"2111","0","tc01856","tl0569f",NULL,"file","760660",NULL,"760660","/Datarmor et web services.xlsx","19","1468246365","0",NULL,NULL,"0","tl0569f"
"2112","0","eb05e11","tl0569f",NULL,"file","760660",NULL,"760660","/Datarmor et web services.xlsx","19","1468246383","0",NULL,NULL,"0","tl0569f"
"2113","0","gm018cc","tl0569f",NULL,"file","760660",NULL,"760660","/Datarmor et web services.xlsx","19","1468246397","0",NULL,NULL,"0","tl0569f"
"2114","0","dl01780","tl0569f",NULL,"file","760660",NULL,"760660","/Datarmor et web services.xlsx","19","1468246423","0",NULL,NULL,"0","tl0569f"
"2115","0","to1efa9","tl0569f",NULL,"file","760660",NULL,"760660","/MEMO/Datarmor et web services (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (","19","1468246436","0",NULL,NULL,"0","tl0569f"
"2116","0","dc05576","tl0569f",NULL,"file","760660",NULL,"760660","/Datarmor et web services.xlsx","19","1468246448","0",NULL,NULL,"0","tl0569f"
"2117","0","pc00588","tl0569f",NULL,"file","760660",NULL,"760660","/Datarmor et web services.xlsx","19","1468246515","0",NULL,NULL,"0","tl0569f"

select * from oc_storages s, oc_filecache fc where s.numeric_id=fc.storage and fc.fileid=760660

"home::tl0569f","90","1",NULL,"760660","90","files/documents/datarmor/Datarmor et web services.xlsx","6f91a26d2932c14372f642c70657e759","760647","Datarmor et web services.xlsx","18","3","17798","1474884460","1474884460","0","0","4a2c2fb8d7d99bd6009fa234331f9440","27",

select oc_share sh where share_with in ('dl01780', 'el05cfc', 'to1efa9', 'tl0569f', 'sl05415');

"1018","0","dl01780","el05cfc",NULL,"file","143691","/143691","143691","/1061409.jpg","19","1443179969","0",NULL,NULL,"0","el05cfc"
"1148","0","tl0569f","ld019cd",NULL,"folder","393224","/393224","393224","/BDD-Capteurs","31","1446483420","0",NULL,NULL,"1","ld019cd"
"1483","0","tl0569f","vh01867",NULL,"folder","482896","/482896","482896","/WP7.1_WP7.2","15","1455098542","0",NULL,NULL,"0","vh01867"
"1647","0","tl0569f","tc01856",NULL,"folder","502958",NULL,"502958","/CoriolisBigData","31","1460375669","0",NULL,NULL,"1","jd06304"
"1925","0","dl01780","to1efa9",NULL,"folder","679560",NULL,"679560","/DATARMOR-install","31","1466150979","0",NULL,NULL,"0","to1efa9"
"1997","0","tl0569f","ld019cd",NULL,"folder","724595",NULL,"724595","/004 Doc Developpement Info ","31","1467214499","0",NULL,NULL,"1","ld019cd"
"2114","0","dl01780","tl0569f",NULL,"file","760660",NULL,"760660","/Datarmor et web services.xlsx","19","1468246423","0",NULL,NULL,"0","tl0569f"
"2115","0","to1efa9","tl0569f",NULL,"file","760660",NULL,"760660","/MEMO/Datarmor et web services (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (","19","1468246436","0",NULL,NULL,"0","tl0569f"
"2220","0","dl01780","gr05542",NULL,"file","792676",NULL,"792676","/2016-Dossier-de-promotion-TA-grocher.doc","17","1472189867","0",NULL,NULL,"0","gr05542"
"2363","0","sl05415","to1efa9",NULL,"folder","812322",NULL,"812322","/datarmo-photo","15","1474988088","0",NULL,NULL,"0","to1efa9"
"2391","0","dl01780","ab05850",NULL,"folder","428917",NULL,"428917","/ascig-photos","31","1475494811","0",NULL,NULL,"0","ab05850"
"2392","0","to1efa9","sl05415",NULL,"folder","817882",NULL,"817882","/photosJourneeCaparmor (2) (2) (2) (2) (2) (2) (2) (2) (2) (3) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (","15","1475495853","0",NULL,NULL,"0","sl05415"
@gregoryR

@PVince81 what I think is happening

  • user tl0569f share ./tl0569f/files/documents/datarmor/Datarmor et web services.xlsx to a bunch of users including to1efa9 and dl01780
  • when to1efa9 receiving share of Datarmor et web services.xlsx he moves it to his MEMO/ folder using the owncloud sync client

is such a scenario trigger the bug on your instance ?

@PVince81
Collaborator

Thanks for the info! I'll have a retry soon. I remember trying this already and it worked fine.

Looking at the oc_share entries, note that the last column on the right is the "uid_initiator". When that value is different than "uid_owner" it means the entry was reshared by someone else. Not sure if it matters but something to try.

With this list of entries I'll try and recreate the whole scenario locally in its entirety in case of side effects.

@PVince81
Collaborator

No luck so far, my oc_share now contains the same entries, I even used the same file names and user names. 😦

@PVince81
Collaborator

I debugged in the code with my local scenario and I noticed a difference in mount points:
Here is what I see at the end of the Webdav request:

  "/": {},
  "/dl01780/": {},
  "/dl01780/files/1061409.jpg/": {},
  "/dl01780/files/DATARMOR-install/": {},
  "/dl01780/files/Datarmor et web services.xlsx/": {},
  "/dl01780/files/2016-Dossier-de-promotion-TA-grocher.doc/": {},
  "/dl01780/files/ascig-photos/": {},
  "/el05cfc/": {},
  "/to1efa9/": {},
  "/to1efa9/files/MEMO/Datarmor et web services.xlsx/": {},
  "/to1efa9/files/photosJourneeCaparmor/": {},
  "/tl0569f/": {},
  "/tl0569f/files/BDD-Capteurs/": {},
  "/tl0569f/files/WP7.1_WP7.2/": {},
  "/tl0569f/files/CoriolisBigData/": {},
  "/tl0569f/files/004 Doc Developpement Info /": {},
  "/gr05542/": {},
  "/ab05850/": {}

however in the mount list from your setup, there are two additional entries missing above:

    "/sl05415/": {},
    "/sl05415/files/datarmo-photo/": {}

so I might be missing one more share connection to get closer to your sharing scenario

@PVince81
Collaborator

Did a bit more research and actually "sl05415" should NOT be mounted here because sl05415 doesn't share anything directly with the current PROPFIND user "dl01780".
So when setting up the FS of "dl01780" only the users from direct shares will have their homes mounted. But any share affected these other users should not be mounted. (no recursion)

Maybe there's a clue there and it could lead us to the reason of the bug.

@PVince81
Collaborator

I recreated this sharing structure in OC 8.2.6 then updated to 9.0.4 then 9.1.1.
Still no issues, same mount list result.

There must be a piece missing.

@PVince81
Collaborator

Just in case it contains more clues, @gregoryR: select * from oc_share where uid_owner='sl05415' maybe contains the missing connection.

@gregoryR

Yes something seems weird with a share of user sl05415. Here is what I see in filesystem

ls -l sl05415/files/
total 3976
drwxr-xr-x 2 www-data www-data    4096 Sep 27 16:57 Documents
-rw-r--r-- 1 www-data www-data 4039431 Sep 27 16:57 ownCloud Manual.pdf
drwxr-xr-x 2 www-data www-data    4096 Sep 27 16:57 Photos
drwxr-xr-x 2 www-data www-data    4096 Oct  3 10:26 photosJourneeCaparmor

His shares select * from oc_share where uid_owner='sl05415'

"2392","0","to1efa9","sl05415",NULL,"folder","817882",NULL,"817882","/photosJourneeCaparmor (2) (2) (2) (2) (2) (2) (2) (2) (2) (3) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (","15","1475495853","0",NULL,NULL,"0","sl05415"

What user to1efa9 is seeing in web interface
to1efa9

What I see in filesystem for user to1efa9

ls -l to1efa9/files
total 96
[...]
drwxr-xr-x  2 www-data www-data  4096 Oct  3 11:48 photosJourneeCaparmor (2) (2) (2) (2) (2) (2) (2) (2) (2) (2)
[...]

User to1efa9 tells me that he hadn't created folder photosJourneeCaparmor (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) , the one wich isn't a share from sl05415, himself

@PVince81
Collaborator

Hmmm, received shares aren't supposed to create actual filesystem entries. This could explain why file_exists returned true for that entry. But also, even if there was some buggy code that would create the entry, it seems that after adding a "(2)" the entry is renamed to the new name instead of recreating a new one, which itself is already quite complex logic.

Maybe it's also a coincidence. From what I see in the screenshot the number of "(2)" for the filesystem folder is less than the received share. So at that stage it shoulnd't conflict any more.

On a related note: when trying to reproduce the issue I tried to create a similar situation where the FS does have a conflicting but unscanned folder name, but could not reproduce the issue.

@gregoryR can you check the filesystem also for the other broken shares like "ascig-photos" to see whether there is also a bogus local folder for them ?

@PVince81
Collaborator

Okay, one theory for that extra folder: if a sync client is running and has downloaded the bogus incoming share with the "(2)" and later on it turns out that on the server this folder has been renamed or doesn't exist due to rename, it is likely that the sync client might in some cases have recreated/reuploaded that folder. It doesn't necessarily mean that the extra FS folder is the cause of the original issue 😦

@elektro-wolle

@PVince81 the differences between the oc_shares and the synced filesystem at the desktop client probably caused the data-loss mentioned in [https://github.com/owncloud/core/issues/25718#issuecomment-248846553]
It seems that the " (2)" was added between the transfer of the files to sync and the actual sync.

@PVince81
Collaborator

My next theory, based on the observation from above that the storage of the user "sl05415" got setup even if it shouldn't. There was an other bug in 9.1.0 #25557 related to recursions and a flag has been put in place to prevent such recursion. The recursion only occurred when dealing with deleted file/folders the were still shared.
So for now, am looking at what happens when:

  1. a user has deleted a file/folder that was shared with the current user => this would, before the fix from #25557 cause some nasty recursions
  2. because of the fix from #25557 the recursion cannot happen any more. However there might be other code paths that do not exclude the recursion.

So far, even with this I haven't been able to reproduce the original issue.
Still, I've pushed a change on #26355 that will remove the potential recursion from acquireLock and releaseLock: 6389bb4.

I'm not sure if it can really help, but you could still try applying it and let me know.

@PVince81
Collaborator

This query will show which share entries are connected to deleted files from trash:
select * from oc_share sh, oc_filecache fc where sh.file_source=fc.fileid and fc.path like 'files_trashbin/%';

@gregoryR

@PVince81 I don't see any bogus "ascig-photos" directory in the filesystem

# find . -name 'ascig-photos*'
./ab05850/files/ascig-photos
./ab05850/files_versions/ascig-photos

The result of select * from oc_share sh, oc_filecache fc where sh.file_source=fc.fileid and fc.path like 'files_trashbin/%';

"1346","3",NULL,"vh01867","739","folder","426788","/426788","426788","/RTQC","1","1451294655","0",NULL,"RlcIexhzdjW6nfH","0","sp01951","426788","266","files_trashbin/files/RTQC.d1473844220","3dc8e0581fc898470581afc7bb559b2e","802779","RTQC.d1473844220","2","1","472436","1448875887","1473844220","0","0","565c176fc2a22","31",NULL
"1488","0","pm00991","js054fa",NULL,"file","483358","/483358","483358","/Qualite_sensibilisation_2015_Bretagne.pptx","19","1455203099","0",NULL,NULL,"0","js054fa","483358","136","files_trashbin/files/Qualite_sensibilisation_2016.pptx.d1473674328","894c34b0c65c77a57b90013c03266acf","801763","Qualite_sensibilisation_2016.pptx.d1473674328","13","3","6942388","1458903742","1458903742","0","0","2abc4a524ac63fa9486e821aee45aae6","27",NULL
"1489","3",NULL,"js054fa",NULL,"file","483358","/483358","483358","/Qualite_sensibilisation_2015_Bretagne.pptx","1","1455203117","0",NULL,"iqKdSyfZJfnGpZC","0","js054fa","483358","136","files_trashbin/files/Qualite_sensibilisation_2016.pptx.d1473674328","894c34b0c65c77a57b90013c03266acf","801763","Qualite_sensibilisation_2016.pptx.d1473674328","13","3","6942388","1458903742","1458903742","0","0","2abc4a524ac63fa9486e821aee45aae6","27",NULL
"1613","3",NULL,"bc063f4",NULL,"folder","507395",NULL,"507395","/SubCtech","1","1459196194","0",NULL,"3N0c88SfSeFccuH","0","bc063f4","507395","78","files_trashbin/files/SubCtech.d1475065256","48edad0d1ed84d9f27e21174a1c5fd8d","813134","SubCtech.d1475065256","2","1","0","1459196161","1475065256","0","0","56f99101b31c0","31",NULL
"1704","0","cl007b2","dj05812",NULL,"folder","535319",NULL,"535319","/GM","31","1461680821","0",NULL,NULL,"0","dj05812","535319","3","files_trashbin/files/GM.d1473679685","6f23991d855dbfacbe9c6ab90f5f57d8","801884","GM.d1473679685","2","1","0","1466433944","1473679685","0","0","5768019840f65","31",NULL
"1705","0","ns05347","dj05812",NULL,"folder","535319",NULL,"535319","/GM","31","1461680834","0",NULL,NULL,"0","dj05812","535319","3","files_trashbin/files/GM.d1473679685","6f23991d855dbfacbe9c6ab90f5f57d8","801884","GM.d1473679685","2","1","0","1466433944","1473679685","0","0","5768019840f65","31",NULL
"1751","3",NULL,"rc1e8aa",NULL,"file","572096",NULL,"572096","/NORDIC_DEPL2016.pdf","1","1463062118","0",NULL,"uzEbb4i304P4Nzg","0","rc1e8aa","572096","1450","files_trashbin/files/NORDIC_DEPL2016.pdf.d1475135012","742dc8aab168e97157c77f1bd85b8716","814744","NORDIC_DEPL2016.pdf.d1475135012","13","3","28770902","1463062113","1463062113","0","0","cd5782215a7703f455ab20a47a978044","27",NULL
"2000","3",NULL,"js054fa",NULL,"file","744589",NULL,"744589","/medits16_modif.zip","1","1467298109","0",NULL,"DbGoOoZc3rxqrzt","0","js054fa","744589","136","files_trashbin/files/medits16_modif.zip.d1473674361","6a6d5bf00e6990ad94a17ae7cb765329","801763","medits16_modif.zip.d1473674361","13","3","32890363","1467293380","1467293380","0","0","04dbc4eeacb2fb5580a713545dc00a47","27",
"2174","3",NULL,"bc063f4",NULL,"file","772883",NULL,"772883","/Modernisation du N O  thalassa  regulé.pdf","1","1469624404","0",NULL,"IgJ9ZoL7gjqSJfw","0","bc063f4","772883","78","files_trashbin/files/Modernisation du N O  thalassa  regulé.pdf.d1475065264","fe9f88a909fd7573883bfe0f369e999d","813134","Modernisation du N O  thalassa  regulé.pdf.d1475065264","13","3","28053239","1469624398","1469624398","0","0","a24eb6f05bc52c1e6f65d0ffb6fae3bd","27",
"2177","3",NULL,"bc063f4",NULL,"file","778530",NULL,"778530","/JERICO_REPORTS.zip","1","1469721308","0",NULL,"woKxHBFSPVfRsc6","0","bc063f4","778530","78","files_trashbin/files/JERICO_REPORTS.zip.d1475065256","55d21eb7c24061060b2edb7a8ce9aa37","813134","JERICO_REPORTS.zip.d1475065256","13","3","18673762","1469721292","1469721292","0","0","19d79712a42aa1bfbb96fc1a28c7e986","27",
"2256","3",NULL,"rc1e8aa",NULL,"folder","795524",NULL,"795524","/Justin","1","1472644510","0",NULL,"4jl9mZncN5Dt7wn","0","rc1e8aa","795524","1450","files_trashbin/files/Justin.d1475135012","23e7d5f764232d95b1e3504f1dff62cb","814744","Justin.d1475135012","2","1","10205351","1472644501","1475135012","0","0","57c6c59619d1a","31",
"2266","3",NULL,"pm0789a","2038","file","795801",NULL,"795801","/HYSCORES_Rapport_final_V1r03.docx","1","1472723468","0",NULL,"kzd8bxwyYPoi5vm","0","mr0ea9a","795801","81","files_trashbin/files/HYSCORES_Rapport_final_V1r03.docx.d1475044904","85dca100f3df2b221ee739d6de40b294","802354","HYSCORES_Rapport_final_V1r03.docx.d1475044904","13","3","44858071","1472723252","1472723252","0","0","e1546cf2bdfa1c178e72c01199fc3aad","27",
"2287","3",NULL,"bc063f4",NULL,"folder","799747",NULL,"799747","/marport_juillet2016","1","1473320263","0",NULL,"j1zI5l6Vcx0VcUq","0","bc063f4","799747","78","files_trashbin/files/marport_juillet2016.d1475065278","cabb7ca998d4deec356640109116ae77","813134","marport_juillet2016.d1475065278","2","1","24439264","1473320250","1475065278","0","0","57d1153a2e379","31",
"2305","0","gr05542","md7a437",NULL,"folder","802818",NULL,"802818","/pour Greg","31","1473845525","0",NULL,NULL,"0","md7a437","802818","409","files_trashbin/files/pour Greg.d1473845650","5c85a0c45ba179fd93658a638fff5a55","802825","pour Greg.d1473845650","2","1","0","1473845642","1473845650","0","0","57d9198a7d5af","31",
"2306","0","gd15fb1","jb0279d",NULL,"folder","802842",NULL,"802842","/SBTAG_PARTAGE","31","1473848931","0",NULL,NULL,"0","jb0279d","802842","514","files_trashbin/files/SBTAG_PARTAGE.d1473849563","0d931097eabd9f47e9f679f147038fac","802727","SBTAG_PARTAGE.d1473849563","2","1","13618683","1473849425","1473849563","0","0","57d9285249422","31",
"2323","3",NULL,"rc1e8aa",NULL,"file","806628",NULL,"806628","/Mickael.zip","1","1474362050","0",NULL,"NAo7O4vr5FgxXVq","0","rc1e8aa","806628","1450","files_trashbin/files/Mickael.zip.d1475135013","eff564239315741070354103cd4a3610","814744","Mickael.zip.d1475135013","13","3","9627169","1474361937","1474361937","0","0","4b44c10f5233acc095a633fbe2ad9add","27",
"2414","3","1|$2y$10$8bq9TNFzYVanumFaHj7KjeMyk3jozT.xWC/laz.P208r9/RgwsjuW","cb0c4f7",NULL,"folder","820537",NULL,"820537","/temporaire","1","1475745395","0",NULL,"9MSUoeY2o4NuVS0","0","cb0c4f7","820537","828","files_trashbin/files/temporaire.d1475745573","1fc490953549b98e43a42cd7d7db4742","816272","temporaire.d1475745573","2","1","0","1475745380","1475745573","0","0","57f616644fb29","31",

Will try to apply 6389bb4 and clean my oc_share table to see if (2) re-appear

@PVince81
Collaborator

Thanks. Ok, so none of the trashed files are linked in any way to the sharing above. 😢

Another try: finding orphaned shares:

  • where fileid has no matching entry: select s.* from oc_share s left join oc_filecache fc on fc.fileid=s.file_source where fc.fileid is null;;
  • where fileid points to a deleted storage: select sh.* from oc_share sh, oc_filecache fc left join oc_storages s on fc.storage=s.numeric_id where sh.file_source=fc.fileid and s.numeric_id is NULL:

Note: such shares would usually get cleant up by cron at some point.

@PVince81
Collaborator

ok, there is only a single one in trash actually, shared with you:

"2305","0","gr05542","md7a437",NULL,"folder","802818",NULL,"802818","/pour Greg","31","1473845525","0",NULL,NULL,"0","md7a437","802818","409","files_trashbin/files/pour Greg.d1473845650","5c85a0c45ba179fd93658a638fff5a55","802825","pour Greg.d1473845650","2","1","0","1473845642","1473845650","0","0","57d9198a7d5af","31",

I'll add this to my test case and hope the issue will happen.

@PVince81
Collaborator

Just tried with the extra trashed entry, same result as before: cannot reproduce.

@gregoryR

Results of the two queries

select s.* from oc_share s left join oc_filecache fc on fc.fileid=s.file_source where fc.fileid is null;
=> 0 line

select sh.* from oc_share sh, oc_filecache fc left join oc_storages s on fc.storage=s.numeric_id where sh.file_source=fc.fileid and s.numeric_id is NULL;
=> 0 line

@PVince81
Collaborator

If the patch doesn't work then maybe it would be best if someone sends me a database dump, at least of the following tables:

  • oc_share
  • oc_filecache
  • oc_mounts
  • oc_storages
  • oc_users

Then based on oc_filecache entries I can recreate the data folder structure locally with dummy files and hopefully trigger the bug...

Send to pvince81 at owncloud dot com (gpg key available).

I assume that you are all running an unpatched v9.1.1, except the patches mentionned in this ticket.

Thanks

@PVince81
Collaborator

ah, and are you all also running LDAP ? I wonder if that is causing side effects as well...

@PVince81
Collaborator

Trying one last time, this time with LDAP...

@gregoryR

Applied patch 6389bb4 and whashed (deleted the (2) (2)...) my oc_share table.

After several minutes the (2) came back but seems un-related because I reverted the change (6389bb4) rewashed oc_share and the (2) came back again.

Lines affected are different : there is only one line affected

"2115","0","to1efa9","tl0569f",NULL,"file","760660",NULL,"760660","/MEMO/Datarmor et web services (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (","19","1468246436","0",NULL,NULL,"0","tl0569f"

Last relevant line of owncloud.log is

{"reqId":"2Lt3KfE4WlpjBnM2YkIb","remoteAddr":"134.246.167.184","app":"DEBUG","message":"Share two DEBUG: {\"stack\":[{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/files_sharing\\\/lib\\\/SharedMount.php\",\"line\":97,\"function\":\"generateUniqueTarget\",\"class\":\"OCA\\\\Files_Sharing\\\\SharedMount\",\"object\":{},\"type\":\"->\",\"args\":[\"\\\/MEMO\\\/Datarmor et web services (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (\",{},[]]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/files_sharing\\\/lib\\\/SharedMount.php\",\"line\":71,\"function\":\"verifyMountPoint\",\"class\":\"OCA\\\\Files_Sharing\\\\SharedMount\",\"object\":{},\"type\":\"->\",\"args\":[{},[]]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/files_sharing\\\/lib\\\/MountProvider.php\",\"line\":92,\"function\":\"__construct\",\"class\":\"OCA\\\\Files_Sharing\\\\SharedMount\",\"object\":{},\"type\":\"->\",\"args\":[\"\\\\OC\\\\Files\\\\Storage\\\\Shared\",[],{\"user\":\"to1efa9\",\"superShare\":{},\"groupedShares\":[{}]},{}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Config\\\/MountProviderCollection.php\",\"line\":76,\"function\":\"getMountsForUser\",\"class\":\"OCA\\\\Files_Sharing\\\\MountProvider\",\"object\":{},\"type\":\"->\",\"args\":[{},{}]},{\"function\":\"OC\\\\Files\\\\Config\\\\{closure}\",\"class\":\"OC\\\\Files\\\\Config\\\\MountProviderCollection\",\"object\":{},\"type\":\"->\",\"args\":[{}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Config\\\/MountProviderCollection.php\",\"line\":77,\"function\":\"array_map\",\"args\":[{},[{},{},{}]]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Filesystem.php\",\"line\":422,\"function\":\"getMountsForUser\",\"class\":\"OC\\\\Files\\\\Config\\\\MountProviderCollection\",\"object\":{},\"type\":\"->\",\"args\":[{}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/files_sharing\\\/lib\\\/sharedstorage.php\",\"line\":99,\"function\":\"initMountPoints\",\"class\":\"OC\\\\Files\\\\Filesystem\",\"type\":\"::\",\"args\":[\"to1efa9\"]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/files_sharing\\\/lib\\\/sharedstorage.php\",\"line\":446,\"function\":\"init\",\"class\":\"OC\\\\Files\\\\Storage\\\\Shared\",\"object\":{\"cache\":null,\"scanner\":null,\"watcher\":null,\"propagator\":null,\"updater\":null},\"type\":\"->\",\"args\":[]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Storage\\\/Wrapper\\\/Wrapper.php\",\"line\":485,\"function\":\"getWrapperStorage\",\"class\":\"OC\\\\Files\\\\Storage\\\\Shared\",\"object\":{\"cache\":null,\"scanner\":null,\"watcher\":null,\"propagator\":null,\"updater\":null},\"type\":\"->\",\"args\":[]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/files_sharing\\\/lib\\\/sharedstorage.php\",\"line\":122,\"function\":\"instanceOfStorage\",\"class\":\"OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper\",\"object\":{\"cache\":null,\"scanner\":null,\"watcher\":null,\"propagator\":null,\"updater\":null},\"type\":\"->\",\"args\":[\"\\\\OC\\\\Files\\\\Storage\\\\Common\"]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/legacy\\\/util.php\",\"line\":148,\"function\":\"instanceOfStorage\",\"class\":\"OC\\\\Files\\\\Storage\\\\Shared\",\"object\":{\"cache\":null,\"scanner\":null,\"watcher\":null,\"propagator\":null,\"updater\":null},\"type\":\"->\",\"args\":[\"\\\\OC\\\\Files\\\\Storage\\\\Common\"]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Storage\\\/StorageFactory.php\",\"line\":100,\"function\":\"{closure}\",\"class\":\"OC_Util\",\"type\":\"::\",\"args\":[\"\\\/dl01780\\\/files\\\/DATARMOR-install\\\/\",{\"cache\":null,\"scanner\":null,\"watcher\":null,\"propagator\":null,\"updater\":null},{}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Storage\\\/StorageFactory.php\",\"line\":82,\"function\":\"wrap\",\"class\":\"OC\\\\Files\\\\Storage\\\\StorageFactory\",\"object\":{},\"type\":\"->\",\"args\":[{},{\"cache\":null,\"scanner\":null,\"watcher\":null,\"propagator\":null,\"updater\":null}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Mount\\\/MountPoint.php\",\"line\":137,\"function\":\"getInstance\",\"class\":\"OC\\\\Files\\\\Storage\\\\StorageFactory\",\"object\":{},\"type\":\"->\",\"args\":[{},\"\\\\OC\\\\Files\\\\Storage\\\\Shared\",{\"user\":\"dl01780\",\"superShare\":{},\"groupedShares\":[{}],\"ownerView\":{}}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Mount\\\/MountPoint.php\",\"line\":160,\"function\":\"createStorage\",\"class\":\"OC\\\\Files\\\\Mount\\\\MountPoint\",\"object\":{},\"type\":\"->\",\"args\":[]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/View.php\",\"line\":1356,\"function\":\"getStorage\",\"class\":\"OC\\\\Files\\\\Mount\\\\MountPoint\",\"object\":{},\"type\":\"->\",\"args\":[]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Node\\\/Root.php\",\"line\":180,\"function\":\"getFileInfo\",\"class\":\"OC\\\\Files\\\\View\",\"object\":{},\"type\":\"->\",\"args\":[\"\\\/dl01780\"]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Files\\\/Node\\\/Root.php\",\"line\":342,\"function\":\"get\",\"class\":\"OC\\\\Files\\\\Node\\\\Root\",\"object\":{},\"type\":\"->\",\"args\":[\"\\\/dl01780\"]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/Server.php\",\"line\":809,\"function\":\"getUserFolder\",\"class\":\"OC\\\\Files\\\\Node\\\\Root\",\"object\":{},\"type\":\"->\",\"args\":[\"dl01780\"]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/User\\\/Session.php\",\"line\":384,\"function\":\"getUserFolder\",\"class\":\"OC\\\\Server\",\"object\":{},\"type\":\"->\",\"args\":[\"dl01780\"]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/User\\\/Session.php\",\"line\":438,\"function\":\"prepareUserLogin\",\"class\":\"OC\\\\User\\\\Session\",\"object\":{},\"type\":\"->\",\"args\":[]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/User\\\/Session.php\",\"line\":287,\"function\":\"loginWithPassword\",\"class\":\"OC\\\\User\\\\Session\",\"object\":{},\"type\":\"->\",\"args\":[\"dl01780\",\"c!est64!\"]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/lib\\\/private\\\/User\\\/Session.php\",\"line\":313,\"function\":\"login\",\"class\":\"OC\\\\User\\\\Session\",\"object\":{},\"type\":\"->\",\"args\":[\"dl01780\",\"c!est64!\"]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Auth.php\",\"line\":121,\"function\":\"logClientIn\",\"class\":\"OC\\\\User\\\\Session\",\"object\":{},\"type\":\"->\",\"args\":[\"dl01780\",\"c!est64!\",{}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Backend\\\/AbstractBasic.php\",\"line\":105,\"function\":\"validateUserPass\",\"class\":\"OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Auth\",\"object\":{},\"type\":\"->\",\"args\":[\"dl01780\",\"c!est64!\"]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Auth.php\",\"line\":242,\"function\":\"check\",\"class\":\"Sabre\\\\DAV\\\\Auth\\\\Backend\\\\AbstractBasic\",\"object\":{},\"type\":\"->\",\"args\":[{\"absoluteUrl\":\"http:\\\/\\\/clouddebug.ifremer.fr\\\/remote.php\\\/webdav\\\/\"},{}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Auth.php\",\"line\":146,\"function\":\"auth\",\"class\":\"OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Auth\",\"object\":{},\"type\":\"->\",\"args\":[{\"absoluteUrl\":\"http:\\\/\\\/clouddebug.ifremer.fr\\\/remote.php\\\/webdav\\\/\"},{}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Plugin.php\",\"line\":166,\"function\":\"check\",\"class\":\"OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Auth\",\"object\":{},\"type\":\"->\",\"args\":[{\"absoluteUrl\":\"http:\\\/\\\/clouddebug.ifremer.fr\\\/remote.php\\\/webdav\\\/\"},{}]},{\"function\":\"beforeMethod\",\"class\":\"Sabre\\\\DAV\\\\Auth\\\\Plugin\",\"object\":{},\"type\":\"->\",\"args\":[{\"absoluteUrl\":\"http:\\\/\\\/clouddebug.ifremer.fr\\\/remote.php\\\/webdav\\\/\"},{}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php\",\"line\":105,\"function\":\"call_user_func_array\",\"args\":[[{},\"beforeMethod\"],[{\"absoluteUrl\":\"http:\\\/\\\/clouddebug.ifremer.fr\\\/remote.php\\\/webdav\\\/\"},{}]]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php\",\"line\":446,\"function\":\"emit\",\"class\":\"Sabre\\\\Event\\\\EventEmitter\",\"object\":{\"tree\":{},\"httpResponse\":{},\"httpRequest\":{\"absoluteUrl\":\"http:\\\/\\\/clouddebug.ifremer.fr\\\/remote.php\\\/webdav\\\/\"},\"sapi\":{},\"transactionType\":null,\"protectedProperties\":[\"{DAV:}getcontentlength\",\"{DAV:}getetag\",\"{DAV:}getlastmodified\",\"{DAV:}lockdiscovery\",\"{DAV:}supportedlock\",\"{DAV:}quota-available-bytes\",\"{DAV:}quota-used-bytes\",\"{DAV:}supported-privilege-set\",\"{DAV:}current-user-privilege-set\",\"{DAV:}acl\",\"{DAV:}acl-restrictions\",\"{DAV:}inherited-acl-set\",\"{DAV:}supported-method-set\",\"{DAV:}supported-report-set\",\"{DAV:}sync-token\",\"{http:\\\/\\\/calendarserver.org\\\/ns\\\/}ctag\",\"{http:\\\/\\\/sabredav.org\\\/ns}sync-token\"],\"debugExceptions\":false,\"resourceTypeMapping\":{\"Sabre\\\\DAV\\\\ICollection\":\"{DAV:}collection\"},\"enablePropfindDepthInfinity\":true,\"xml\":{\"elementMap\":{\"{DAV:}multistatus\":\"Sabre\\\\DAV\\\\Xml\\\\Response\\\\MultiStatus\",\"{DAV:}response\":\"Sabre\\\\DAV\\\\Xml\\\\Element\\\\Response\",\"{DAV:}propfind\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\PropFind\",\"{DAV:}propertyupdate\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\PropPatch\",\"{DAV:}mkcol\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\MkCol\",\"{DAV:}resourcetype\":\"Sabre\\\\DAV\\\\Xml\\\\Property\\\\ResourceType\"},\"namespaceMap\":{\"DAV:\":\"d\",\"http:\\\/\\\/sabredav.org\\\/ns\":\"s\"},\"classMap\":[]}},\"type\":\"->\",\"args\":[\"beforeMethod\",[{\"absoluteUrl\":\"http:\\\/\\\/clouddebug.ifremer.fr\\\/remote.php\\\/webdav\\\/\"},{}]]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php\",\"line\":248,\"function\":\"invokeMethod\",\"class\":\"Sabre\\\\DAV\\\\Server\",\"object\":{\"tree\":{},\"httpResponse\":{},\"httpRequest\":{\"absoluteUrl\":\"http:\\\/\\\/clouddebug.ifremer.fr\\\/remote.php\\\/webdav\\\/\"},\"sapi\":{},\"transactionType\":null,\"protectedProperties\":[\"{DAV:}getcontentlength\",\"{DAV:}getetag\",\"{DAV:}getlastmodified\",\"{DAV:}lockdiscovery\",\"{DAV:}supportedlock\",\"{DAV:}quota-available-bytes\",\"{DAV:}quota-used-bytes\",\"{DAV:}supported-privilege-set\",\"{DAV:}current-user-privilege-set\",\"{DAV:}acl\",\"{DAV:}acl-restrictions\",\"{DAV:}inherited-acl-set\",\"{DAV:}supported-method-set\",\"{DAV:}supported-report-set\",\"{DAV:}sync-token\",\"{http:\\\/\\\/calendarserver.org\\\/ns\\\/}ctag\",\"{http:\\\/\\\/sabredav.org\\\/ns}sync-token\"],\"debugExceptions\":false,\"resourceTypeMapping\":{\"Sabre\\\\DAV\\\\ICollection\":\"{DAV:}collection\"},\"enablePropfindDepthInfinity\":true,\"xml\":{\"elementMap\":{\"{DAV:}multistatus\":\"Sabre\\\\DAV\\\\Xml\\\\Response\\\\MultiStatus\",\"{DAV:}response\":\"Sabre\\\\DAV\\\\Xml\\\\Element\\\\Response\",\"{DAV:}propfind\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\PropFind\",\"{DAV:}propertyupdate\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\PropPatch\",\"{DAV:}mkcol\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\MkCol\",\"{DAV:}resourcetype\":\"Sabre\\\\DAV\\\\Xml\\\\Property\\\\ResourceType\"},\"namespaceMap\":{\"DAV:\":\"d\",\"http:\\\/\\\/sabredav.org\\\/ns\":\"s\"},\"classMap\":[]}},\"type\":\"->\",\"args\":[{\"absoluteUrl\":\"http:\\\/\\\/clouddebug.ifremer.fr\\\/remote.php\\\/webdav\\\/\"},{}]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/dav\\\/appinfo\\\/v1\\\/webdav.php\",\"line\":56,\"function\":\"exec\",\"class\":\"Sabre\\\\DAV\\\\Server\",\"object\":{\"tree\":{},\"httpResponse\":{},\"httpRequest\":{\"absoluteUrl\":\"http:\\\/\\\/clouddebug.ifremer.fr\\\/remote.php\\\/webdav\\\/\"},\"sapi\":{},\"transactionType\":null,\"protectedProperties\":[\"{DAV:}getcontentlength\",\"{DAV:}getetag\",\"{DAV:}getlastmodified\",\"{DAV:}lockdiscovery\",\"{DAV:}supportedlock\",\"{DAV:}quota-available-bytes\",\"{DAV:}quota-used-bytes\",\"{DAV:}supported-privilege-set\",\"{DAV:}current-user-privilege-set\",\"{DAV:}acl\",\"{DAV:}acl-restrictions\",\"{DAV:}inherited-acl-set\",\"{DAV:}supported-method-set\",\"{DAV:}supported-report-set\",\"{DAV:}sync-token\",\"{http:\\\/\\\/calendarserver.org\\\/ns\\\/}ctag\",\"{http:\\\/\\\/sabredav.org\\\/ns}sync-token\"],\"debugExceptions\":false,\"resourceTypeMapping\":{\"Sabre\\\\DAV\\\\ICollection\":\"{DAV:}collection\"},\"enablePropfindDepthInfinity\":true,\"xml\":{\"elementMap\":{\"{DAV:}multistatus\":\"Sabre\\\\DAV\\\\Xml\\\\Response\\\\MultiStatus\",\"{DAV:}response\":\"Sabre\\\\DAV\\\\Xml\\\\Element\\\\Response\",\"{DAV:}propfind\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\PropFind\",\"{DAV:}propertyupdate\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\PropPatch\",\"{DAV:}mkcol\":\"Sabre\\\\DAV\\\\Xml\\\\Request\\\\MkCol\",\"{DAV:}resourcetype\":\"Sabre\\\\DAV\\\\Xml\\\\Property\\\\ResourceType\"},\"namespaceMap\":{\"DAV:\":\"d\",\"http:\\\/\\\/sabredav.org\\\/ns\":\"s\"},\"classMap\":[]}},\"type\":\"->\",\"args\":[]},{\"file\":\"\\\/export\\\/home\\\/clouddebug\\\/remote.php\",\"line\":164,\"args\":[\"\\\/export\\\/home\\\/clouddebug\\\/apps\\\/dav\\\/appinfo\\\/v1\\\/webdav.php\"],\"function\":\"require_once\"}],\"user\":\"to1efa9\",\"original_path\":\"\\\/MEMO\\\/Datarmor et web services (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (\",\"renamed_path\":\"\\\/MEMO\\\/Datarmor et web services (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) ( (2)\",\"url\":\"\\\/remote.php\\\/webdav\\\/\",\"already_mounted_storageId\":\"shared::\\\/MEMO\\\/Datarmor et web services (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (\",\"already_mounted_internal_path\":\"\",\"all_mounts\":{\"\\\/\":{},\"\\\/dl01780\\\/\":{},\"\\\/dl01780\\\/files\\\/1061409.jpg\\\/\":{},\"\\\/dl01780\\\/files\\\/DATARMOR-install\\\/\":{},\"\\\/dl01780\\\/files\\\/Datarmor et web services.xlsx\\\/\":{},\"\\\/dl01780\\\/files\\\/2016-Dossier-de-promotion-TA-grocher.doc\\\/\":{},\"\\\/dl01780\\\/files\\\/ascig-photos\\\/\":{},\"\\\/el05cfc\\\/\":{},\"\\\/to1efa9\\\/\":{},\"\\\/to1efa9\\\/files\\\/MEMO\\\/Datarmor et web services (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (2) (\\\/\":{},\"\\\/to1efa9\\\/files\\\/photosJourneeCaparmor\\\/\":{},\"\\\/tl0569f\\\/\":{},\"\\\/tl0569f\\\/files\\\/BDD-Capteurs\\\/\":{},\"\\\/tl0569f\\\/files\\\/WP7.1_WP7.2\\\/\":{},\"\\\/tl0569f\\\/files\\\/CoriolisBigData\\\/\":{},\"\\\/tl0569f\\\/files\\\/004 Doc Developpement Info \\\/\":{},\"\\\/sl05415\\\/\":{},\"\\\/sl05415\\\/files\\\/datarmo-photo\\\/\":{}},\"superShare\":{\"id\":\"2115\",\"nodeid\":760660,\"shared_with\":null,\"share_owner\":\"tl0569f\",\"share_type\":null,\"shared_by\":null},\"groupedShares\":[{\"id\":\"2115\",\"nodeid\":760660,\"shared_with\":\"to1efa9\",\"share_owner\":\"tl0569f\",\"share_type\":0,\"shared_by\":\"tl0569f\"}]}","level":0,"time":"2016-10-17T13:24:23+02:00","method":"PROPFIND","url":"\/remote.php\/webdav\/","user":"dl01780"}
@PVince81
Collaborator

Got a dump from @gregoryR, thanks a lot.
I've imported the tables and created dummy data.

Am now syncing some of the users from the sharing scenario above.

So far it started happening, two file_targets got a "(2)" but it is not clear yet what is triggering it.

At least now I should be able to debug.

@PVince81
Collaborator

@gregoryR how are you actually triggering the error ?
Do you have a system cron running on the test instance ?
Are you running the sync client for some users ?

I have three users setup for sync currently: "tl0569f", "to1efa9" and "dl01780".
The sync client takes a while because there are LOTs of folders to discover and sync.

So far the problem only appeared once, am now waiting for the next occurence.

@PVince81
Collaborator

I wrote a script that would simulate scrolling through the users page, which itself triggers loading the avatar of every user. That itself does setup the FS of every LDAP user and also creates a LDAP mapping if there was none already.

While this is running, it stopped at my breakpoint in SharedMount. A closer look shows that the addition of a "(2)" in these cases are legitimate: the recipient already has a folder called "XYZ" in oc_filecache (and likely on disk, I only have the DB dump). And someone shared a folder called "XYZ" with that user, so as soon as the user logs in or the user's storage is setup, it will detect the duplicate and append a "(2)" to the share. So the received share becomes "(2)".

Normally this kind of situation would happen if a user never logged in before, so their FS was never setup. BUT I see in oc_filecache that this user already has data in their homes.

So the question is, how come we find ourselves in a situation where a user already has a folder "XYZ" and only later on oc_share contains a share with that name, and only after that the deduplication code runs. This situation is not really possible.

However, we do know that @gregoryR and others in this thread have been "washing" this table automatically. So what I'm observing is only a legitimate "(2)" that got cleant away, and gets readded when that user's FS is setup. In these cases, I expect that it won't be added again since the duplication was resolved already.

Now I'm letting the users page script and sync client continue to run and hope to catch the real 🐛

@PVince81
Collaborator

@gregoryR side note, I see that your oc_storages table contains old entries "local::/export/home1/owncloud/data/". I assume that your data dir is not "/export/home1/owncloud/data/" any more.
There seem to be a lot of obsolete storage entries.

I checked and these are not connected to any shares, so ownCloud should already ignore these and they are likely unrelated to this issue.

@PVince81
Collaborator

Ohhhh, there's a ghost here.
Not sure yet how it happened, I left the sync client running for "tl0569f" together with the LDAP users page loader.

This is oc_filecache from the dump:

+--------+---------+-----------------------------------------------------------------------------+----------------------------------+--------+-------------------------------------------+----------+----------+-------+------------+---------------+-----------+------------------+----------------------------------+-------------+----------+
| fileid | storage | path                                                                        | path_hash                        | parent | name                                      | mimetype | mimepart | size  | mtime      | storage_mtime | encrypted | unencrypted_size | etag                             | permissions | checksum |
+--------+---------+-----------------------------------------------------------------------------+----------------------------------+--------+-------------------------------------------+----------+----------+-------+------------+---------------+-----------+------------------+----------------------------------+-------------+----------+
| 760660 |      90 | files/documents/datarmor/Datarmor et web services.xlsx                      | 6f91a26d2932c14372f642c70657e759 | 760647 | Datarmor et web services.xlsx             |       18 |        3 | 17798 | 1474884460 |    1474884460 |         0 |                0 | 4a2c2fb8d7d99bd6009fa234331f9440 |          27 |          |
| 810626 |      90 | files_versions/documents/datarmor/Datarmor et web services.xlsx.v1468246070 | f1efbd2df991f3a1110f599728c18e99 | 810625 | Datarmor et web services.xlsx.v1468246070 |       13 |        3 | 12198 | 1474884460 |    1474884460 |         0 |                0 | 7394e06611021da28195e01d73f50c3e |          27 |          |
+--------+---------+-----------------------------------------------------------------------------+----------------------------------+--------+-------------------------------------------+----------+----------+-------+------------+---------------+-----------+------------------+----------------------------------+-------------+----------+

and this is after:

+--------+---------+-----------------------------------------------------------------------------+----------------------------------+--------+-------------------------------------------+----------+----------+------+------------+---------------+-----------+------------------+----------------------------------+-------------+----------+
| fileid | storage | path                                                                        | path_hash                        | parent | name                                      | mimetype | mimepart | size | mtime      | storage_mtime | encrypted | unencrypted_size | etag                             | permissions | checksum |
+--------+---------+-----------------------------------------------------------------------------+----------------------------------+--------+-------------------------------------------+----------+----------+------+------------+---------------+-----------+------------------+----------------------------------+-------------+----------+
| 760660 |      90 | files/documents/datarmor/Datarmor et web services.xlsx                      | 6f91a26d2932c14372f642c70657e759 | 760647 | Datarmor et web services.xlsx             |       18 |        3 |    0 | 1474884460 |    1474884460 |         0 |                0 | 4a2c2fb8d7d99bd6009fa234331f9440 |          27 |          |
| 810626 |      90 | files_versions/documents/datarmor/Datarmor et web services.xlsx.v1468246070 | f1efbd2df991f3a1110f599728c18e99 | 810625 | Datarmor et web services.xlsx.v1468246070 |       13 |        3 |    0 | 1474884460 |    1474884460 |         0 |                0 | 7394e06611021da28195e01d73f50c3e |          27 |          |
| 824522 |      90 | files/Datarmor et web services.xlsx                                         | 17f79ce1b7d6fbf5a5cad32a07abbe96 |  39351 | Datarmor et web services.xlsx             |        9 |        3 | 4454 | 1476360589 |    1476360589 |         0 |                0 | c7d1b51428efe51ae75f8369a8e45fba |          27 |          |
+--------+---------+-----------------------------------------------------------------------------+----------------------------------+--------+-------------------------------------------+----------+----------+------+------------+---------------+-----------+------------------+----------------------------------+-------------+----------+

A new entry has appeared in "oc_filecache" in the user's home: "files/Datarmor et web services.xlsx".
This user is NOT a received of any share with this name.
Also, the local folder of the sync client for this user does NOT contain such file. So it's not the sync client that created it.
Also, in the data folder I don't see any such file.

This might be a bit far away from share duplication but it is likely that such ghost entries makes OC believe that an entry already exists, and as such it will add a "(2)" to incoming shares with the same name.

Now to the tricky part: make it happen again and find out why it happens...

@PVince81
Collaborator

also quite weird: all my test files have a size of 0, but the ghost entry reports a size of "4454" bytes. There is no such file with this size in the data folder.

@PVince81
Collaborator

I reran cron and also the users script. The breakpoints didn't stop any more, no more "(2)" added.
Re-ran the sync from scratch for "dl01780", "tl0569f", "to1efa9" but the problem didn't happen. Well, I stopped earlier with "to1efa9"'s account as there are more than 12k files.

If the problem doesn't appear any more, then maybe I need to run all this in parallel to have some kind of race condition kick in... Now also trying to delete all the "lastFeatureRefresh" keys in oc_preferences to make sure the LDAP stuff gets resynced, just in case...

The only insert statements I received so far were for avatars, but none approach the size observed above.

@PVince81
Collaborator

No more luck today apparently. Tomorrow hopefully.

@gregoryR please tell me what processes are running against the test system:

  • cron ?
  • sync clients with which accounts ? are they syncing all the time or just pinging ?

also how high is the TTL in the LDAP config of OC ?

@PVince81
Collaborator

FINALLY, I got something.

What I did:

  1. delete from oc_preferences where configkey='lastFeatureRefresh'; => this will force the LDAP code to refresh the info of all users
  2. update oc_jobs set last_run=0,last_checked=0,reserved_at=0; => reset cron jobs

Then in parallel:

  1. Run curl command to simulate fetching all pages in the users page => this will trigger LDAP user refresh
  2. Run cron.php
  3. I also have an idle sync client for users "dl01780", "tl0569f", "to1efa9"

Shortly after running cron + the users page thing, I got this stack trace from the LDAP refresh:

0  OCA\Files_Sharing\SharedMount->generateUniqueTarget() /srv/www/htdocs/owncloudtest/apps/files_sharing/lib/SharedMount.php:149
1  OCA\Files_Sharing\SharedMount->verifyMountPoint() /srv/www/htdocs/owncloudtest/apps/files_sharing/lib/SharedMount.php:97
2  OCA\Files_Sharing\SharedMount->__construct() /srv/www/htdocs/owncloudtest/apps/files_sharing/lib/SharedMount.php:71
3  OCA\Files_Sharing\MountProvider->getMountsForUser() /srv/www/htdocs/owncloudtest/apps/files_sharing/lib/MountProvider.php:92
4  OC\Files\Config\MountProviderCollection->OC\Files\Config\{closure}() /srv/www/htdocs/owncloudtest/lib/private/Files/Config/MountProviderCollection.php:76
5  array_map()     /srv/www/htdocs/owncloudtest/lib/private/Files/Config/MountProviderCollection.php:77
6  OC\Files\Config\MountProviderCollection->getMountsForUser() /srv/www/htdocs/owncloudtest/lib/private/Files/Config/MountProviderCollection.php:77
7  OC\Files\Filesystem::initMountPoints() /srv/www/htdocs/owncloudtest/lib/private/Files/Filesystem.php:422
8  OC\Files\Storage\Shared->init() /srv/www/htdocs/owncloudtest/apps/files_sharing/lib/sharedstorage.php:99
9  OC\Files\Storage\Shared->getWrapperStorage() /srv/www/htdocs/owncloudtest/apps/files_sharing/lib/sharedstorage.php:448
10 OC\Files\Storage\Wrapper\Wrapper->instanceOfStorage() /srv/www/htdocs/owncloudtest/lib/private/Files/Storage/Wrapper/Wrapper.php:485
11 OC\Files\Storage\Shared->instanceOfStorage() /srv/www/htdocs/owncloudtest/apps/files_sharing/lib/sharedstorage.php:122
12 OC_Util::{closure:/srv/www/htdocs/owncloudtest/lib/private/legacy/util.php:147-153}() /srv/www/htdocs/owncloudtest/lib/private/legacy/util.php:148
13 OC\Files\Storage\StorageFactory->wrap() /srv/www/htdocs/owncloudtest/lib/private/Files/Storage/StorageFactory.php:100
14 OC\Files\Storage\StorageFactory->getInstance() /srv/www/htdocs/owncloudtest/lib/private/Files/Storage/StorageFactory.php:82
15 OC\Files\Mount\MountPoint->createStorage() /srv/www/htdocs/owncloudtest/lib/private/Files/Mount/MountPoint.php:137
16 OC\Files\Mount\MountPoint->getStorage() /srv/www/htdocs/owncloudtest/lib/private/Files/Mount/MountPoint.php:160
17 OC\Files\View->getFileInfo() /srv/www/htdocs/owncloudtest/lib/private/Files/View.php:1356
18 OC\Files\Node\Root->get() /srv/www/htdocs/owncloudtest/lib/private/Files/Node/Root.php:180
19 OC\AvatarManager->getAvatar() /srv/www/htdocs/owncloudtest/lib/private/AvatarManager.php:94
20 OCA\User_LDAP\User\User->setOwnCloudAvatar() /srv/www/htdocs/owncloudtest/apps/user_ldap/lib/User/User.php:523
21 OCA\User_LDAP\User\User->updateAvatar() /srv/www/htdocs/owncloudtest/apps/user_ldap/lib/User/User.php:499
22 OCA\User_LDAP\User\User->update() /srv/www/htdocs/owncloudtest/apps/user_ldap/lib/User/User.php:143
23 OCA\User_LDAP\User_LDAP->userExists() /srv/www/htdocs/owncloudtest/apps/user_ldap/lib/User_LDAP.php:277
24 OC\User\Manager->get() /srv/www/htdocs/owncloudtest/lib/private/User/Manager.php:139
25 OC\User\Session->getUser() /srv/www/htdocs/owncloudtest/lib/private/User/Session.php:192
26 OC\App\AppManager->isEnabledForUser() /srv/www/htdocs/owncloudtest/lib/private/App/AppManager.php:152
27 OC_App::isEnabled() /srv/www/htdocs/owncloudtest/lib/private/legacy/app.php:313
28 OCP\App::isEnabled() /srv/www/htdocs/owncloudtest/lib/public/App.php:131
29 require_once()  /srv/www/htdocs/owncloudtest/apps/user_ldap/appinfo/app.php:72
30 OC_App::requireAppFile() /srv/www/htdocs/owncloudtest/lib/private/legacy/app.php:186
31 OC_App::loadApp() /srv/www/htdocs/owncloudtest/lib/private/legacy/app.php:149
32 OC_App::loadApps() /srv/www/htdocs/owncloudtest/lib/private/legacy/app.php:119
33 {main}          /srv/www/htdocs/owncloudtest/remote.php:148

It is trying to add "(2)" for "/BDD-Capteurs" for user "tl0569f":

  $this->user                    = (string[7]) 'tl0569f';
  $this->superShare              = (object|OC\Share20\Share[19]);
    $this->superShare->id        = (string[4]) '1148';
    $this->superShare->fileId    = (int) '393224';
    $this->superShare->shareOwner = (string[7]) 'ld019cd';
    $this->superShare->permissions = (int) '31';
    $this->superShare->target    = (string[13]) '/BDD-Capteurs';
    $this->superShare->rootFolder = (object|OC\Files\Node\LazyRoot[2])+;

Now from what I see in the mounts list, this share is already mounted for that user:

$evalResult                      = (object|OCA\Files_Sharing\SharedMount[12]);
  $evalResult->storage           = (object|OCA\Files_Trashbin\Storage[10])+;
  $evalResult->recipientView     = (object|OC\Files\View[5])+;
  $evalResult->user              = (string[7]) 'tl0569f';
  $evalResult->superShare        = (object|OC\Share20\Share[19])+;
  $evalResult->groupedShares     = (array[1])+;
  $evalResult->class             = (string[24]) '\OC\Files\Storage\Shared';
  $evalResult->storageId         = (null);
  $evalResult->arguments         = (array[4])+;
  $evalResult->mountPoint        = (string[28]) '/tl0569f/files/BDD-Capteurs/';
  $evalResult->mountOptions      = (array[0]);
  $evalResult->*OC\Files\Mount\MountPoint*loader = (object|OC\Files\Storage\StorageFactory[1])+;
  $evalResult->*OC\Files\Mount\MountPoint*invalidStorage = (bool) '0';

so next step is to find out why the FS setup for user "tl0569f" is running twice through this code path instead of detecting that we already have it. In initMountPoints there's code that tracks which FS was already setup.

@gregoryR

@PVince81 I'll try to answer questions in order

@gregoryR how are you actually triggering the error ?
Do you have a system cron running on the test instance ?
Are you running the sync client for some users ?

Just wait and (2) begins to appear in oc_share.file_target

Yes cron is running for www-data in test instance

crontab -l -u www-data
# m h  dom mon dow   command
10,25,40,55 * * * * php -f /export/home/clouddebug/cron.php

Since #26355 crontab occasionally (one or two time a day, crontab runs every 15 minutes) output a Fatal Error

PHP Fatal error:  Cannot redeclare OCA\Files_Sharing\encodeShare() (previously declared in /export/home/clouddebug/apps/files_sharing/lib/SharedMount.php:161) in /export/home/clouddebug/apps/files_sharing/lib/SharedMount.php on line 161

Sync client is running for user dl01780 and me gr05542. Sync client isn't just pinging. Running continuously

I see that your oc_storages table contains old entries "local::/export/home1/owncloud/data/". I assume that your data dir is not "/export/home1/owncloud/data/" any more.
There seem to be a lot of obsolete storage entries.

Yes /export/home1/owncloud/data/ was the old data directory, on the local filesystem of the webserver. Data is now on an NFS share. Migration have been done by

  • put owncloud in maintenance mode (or stop the webserver I don't remember precisely)
  • rsync data folder from local storage to nfs storage
  • change datadirectory config/config.php
  • restart owncloud

Ohhhh, there's a ghost here.

When I run find in fs I only see the first two entries

find . -name 'Datarmor et web services*'
./files/documents/datarmor/Datarmor et web services.xlsx
./files_versions/documents/datarmor/Datarmor et web services.xlsx.v1468246070

In oc_filecache

SELECT * FROM `oc_filecache` WHERE `path` LIKE '%Datarmor et web services%'
"760660","90","files/documents/datarmor/Datarmor et web services.xlsx","6f91a26d2932c14372f642c70657e759","760647","Datarmor et web services.xlsx","18","3","17798","1474884460","1474884460","0","0","4a2c2fb8d7d99bd6009fa234331f9440","27",
"810626","90","files_versions/documents/datarmor/Datarmor et web services.xlsx.v1468246070","f1efbd2df991f3a1110f599728c18e99","810625","Datarmor et web services.xlsx.v1468246070","13","3","12198","1474884460","1474884460","0","0","7394e06611021da28195e01d73f50c3e","27",

Well, I stopped earlier with "to1efa9"'s account as there are more than 12k files.

I'm seeing just 90 files in tl0569f filesystem

find files/ -type f -ls |wc -l
90

but I remember that this user had loaded a lot of files in his account.

also how high is the TTL in the LDAP config of OC ?

TTL is 600

@PVince81
Collaborator

So far all I know is that initMountPoints has already run for a user X, and somehow it runs again for that user. I'm trying to find the proof.

So far, looking at initMountPoints, I see one potential code path that could bypass the usersSetup check. The check is here: https://github.com/owncloud/core/blob/v9.1.1/lib/private/Files/Filesystem.php#L396

and later we set the value to say "we already processed this user": https://github.com/owncloud/core/blob/v9.1.1/lib/private/Files/Filesystem.php#L408

But in-between there are calls to the user manager to get the user: https://github.com/owncloud/core/blob/v9.1.1/lib/private/Files/Filesystem.php#L401

From what I observe in the stack trace posted previously, a call to $userManager->get() can trigger an avatar update when using LDAP with avatars. This is likely to happen only when a feature refresh is due (see lastFeatureRefresh in oc_preferences). Whenever avatar refresh is due, the AvatarManager itself will also trigger an initMountPoints for the user whose avatar will be setup.

Since at this stage we haven't yet set usersSetup, it is likely that initMountPoints will run a second time for the same user.

Still looking for proof of this, but will also look into ways to prevent this so we can test.

@PVince81
Collaborator

Side note: starting with 9.2 the avatar manager will be decoupled from FS setup, so this kind of crazy issues shouldn't happen any more: #26124 (not backportable as it changes the FS structure)

@PVince81
Collaborator

@ccheveaux @gregoryR could you guys try with this new patch: #26396 (https://github.com/owncloud/core/pull/26396.patch). This should solve the problem by preventing duplicate setup FS of users with LDAP.

In my local test env the problem didn't appear any more after this change after several retries.

@gregoryR

@PVince81 patch #26396 is applied to my test instance. I've cleaned my oc_share table.
I'm off for a few days, will give feed back on monday

@PVince81
Collaborator

Thanks. Now regardless whether this patch fixes this specific issue or not, I think it should be merged because it would prevent any other potential similar issues.

@ccheveaux

Sorry @PVince81 i don't have test instance to try this patch :/
And lot of work atm.
My product instance is "stable" for this moment with this #25718 (comment)
I hope my next upgrade of ownCloud don't break it or fix it correctly :/

@PVince81
Collaborator

Based on all the information found so far, I managed to find steps to reproduce this issue:

Steps:

  1. Setup LDAP with at least two users "user1" and "user2"
  2. Setup LDAP in OC
  3. Login as "user1"
  4. Share a folder "test" with "user2"
  5. Login as "user2"
  6. Share a folder "abc" with "user1"
  7. delete from oc_preferences where configkey='lastFeatureRefresh' <= this was the missing bit which made it random!
  8. curl -X PROPFIND -H "Depth: 1" http://user1:test@localhost/owncloud/remote.php/webdav
  9. select * from oc_share

Then repeat the last three steps several times.
You'll see that the file_target of "test" will receive further "(2)" appended.

@ccheveaux

What I also noticed but may be an isolated problem.
A ten users (using lots of shares) no longer able to connect to ownCloud.
I had to delete their account to recreate itself.
He has mounted the data and i scanned with a "occ file:scan username" for each users.
But unfortunately i lost the shares of these people who have been forced to recreate them. (I have not found anything to save them).

For several weeks my body production works again correctly, but if I remove your patch then (2) back.

@PVince81
Collaborator

no longer able to connect to ownCloud.

Any error messages ? Was it web UI or desktop client ?
Not sure if related with this "(2)" issue, except maybe that a recursive replication of these could cause memory errors I guess.

@ccheveaux

image

And desktop client can't connect.

Following our patches and tests, I had a period or my ownCloud instance was enormously slow in terms of connection and access the files through Web UI.
Ditto for synchronizing the desktop client.

It became extremely chaotic so I completely reinstalled distribution and ownCloud, because just install ownCloud was not enough.

After this and re-import the database, ownCloud was responsive but (2) was still present and active.
I apply your patch again and that stopped these (2).

Finally I delete and recreate the blocked user accounts and I noticed that it was those sharing much.

Since I did not touch anything to await a future last days I would do during the school holidays.
The server has been reinstalled on a virtual machine that will allow me to go back very quickly in case of problems.

@PVince81
Collaborator

@ccheveaux was that on v9.1.0 or v9.1.1 ? Because on v9.1.0 there was a memory issue which could cause users to not be able to log in any more.

@PVince81 PVince81 added the regression label Oct 19, 2016
@ccheveaux

image

v9.1.1

But after deleting account and create again the problem disappeared.

@PVince81
Collaborator

closing as fixed through #26399 which willl be in 9.1.2.

@ccheveaux if you have old logs about the users who couldn't login we could have a look in a separate issue.

@PVince81 PVince81 closed this Oct 19, 2016
@karamatos

I have applied patch 26396 and did everything as before that caused the (2) (2) ... problem. The problem has not reappeared. It has been about 24 hours and I have been running various sync clients without issue.

I did notice a strange thing with avatars. Even though I had avatars turned off in config.php, the system was still trying to update the database with avatar information. I think it was coming from the LDAP system and the mysql error was: The total blob data length (10067609) is greater than 10% of the total redo log size. It was trying to update a record in oc_cards.

The query was large and it slowed down every ownCloud access for the user with the avatar. The solution was to turn avatars back on and upload a new avatar. That seemed to fix the avatar database problem. I turned avatars off again and applied patch 26396 and the main problem is gone. I am keeping avatars off as I read that the next version will change the way avatars are handled.

Will patch 26396 be in the next release?

@PVince81
Collaborator

Will patch 26396 be in the next release?

Yes, in 9.1.2 but it had to be adjusted due to further code changes: #26399
The effect will be the same.

Regarding the avatars + LDAP issue, can you make a new ticket ? I find it suspicious that LDAP tries to sync avatars even when disabled.

@gregoryR

@PVince81 I'm back
I can confirm that patch #26396 solve the (2) problem on both test and production instance.
Thanks for all your work

@PVince81
Collaborator

Also thanks everyone here who helped debug the issue !

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment