New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

New ldap-user get error-message when filelocking with redis is activated #20675

Closed
frankhoefling opened this Issue Nov 23, 2015 · 16 comments

Comments

Projects
None yet
5 participants
@frankhoefling

frankhoefling commented Nov 23, 2015

Steps to reproduce

  1. config.php without filelocking.enabled=true and 'memcache.locking' => '\OC\Memcache\Redis'
  2. Add new user in LDAP-Backend
  3. Login at owncloud with new user credentials okay - behaving as usual
  4. config.php with filelocking.enabled=true and 'memcache.locking' => '\OC\Memcache\Redis'
  5. Add another user in LDAP-Backend
  6. Login at owncloud with new user credentials fails with internal error
  7. Login to existing accounts works, but add/delete of files impossible

screenshot

Additional remark:
redis-server status is green (service redis-server status)

Server configuration

Operating system:
Raspbian GNU/Linux 8
Web server:
nginx/1.6.2
Database:
10.0.22-MariaDB-0+deb8u1
PHP version:
5.6.14-0+deb8u1
ownCloud version: (see ownCloud admin page)
8.2.1
Updated from an older ownCloud or fresh install:
fresh install
List of activated apps:
Enabled:

  • activity: 2.1.3
  • files: 1.2.0
  • files_pdfviewer: 0.7
  • files_sharing: 0.7.0
  • files_texteditor: 2.0
  • files_trashbin: 0.7.0
  • files_versions: 1.1.0
  • files_videoviewer: 0.1.3
  • firstrunwizard: 1.1
  • gallery: 14.2.0
  • notifications: 0.1.0
  • provisioning_api: 0.3.0
  • templateeditor: 0.1
  • updater: 0.6
  • user_ldap: 0.7.0

Disabled:

  • encryption
  • external
  • files_external
  • user_external

The content of config/config.php:
"system": { "instanceid": "ocvaq7ww8o9f", "passwordsalt": "***REMOVED SENSITIVE VALUE***", "secret": "***REMOVED SENSITIVE VALUE***", "trusted_domains": [ "localhost", "www.REMOVED:1024" ], "datadirectory": "\/mnt\/exthd1\/owncloudData", "overwrite.cli.url": "https:\/\/www.REMOVED:1024", "dbtype": "mysql", "version": "8.2.1.4", "dbname": "db_data_owncloud", "dbhost": "localhost", "dbtableprefix": "oc_", "dbuser": "***REMOVED SENSITIVE VALUE***", "dbpassword": "***REMOVED SENSITIVE VALUE***", "logtimezone": "UTC", "installed": true, "ldapIgnoreNamingRules": false, "filelocking.enabled": "true", "memcache.locking": "\\OC\\Memcache\\Redis", "memcache.local": "\\OC\\Memcache\\Redis", "redis": { "host": "\/var\/run\/redis\/redis.sock", "port": 0, "timeout": 0 }, "loglevel": 0 }
Are you using external storage, if yes which one:
yes: External USB HD permanently mounted at /mnt/exthd1
Are you using encryption:
no
Are you using an external user-backend, if yes which one:
LDAP

LDAP configuration

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

Client configuration

Browser:
Firefox 42.0 (OSX)
same result with Safari and Chrome - so no browser problem
Operating system:
OSX 10.10.5

Logs

ownCloud log

{"reqId":"E\/IXLhKcYYk2gG32sN\/y","remoteAddr":"192.168.1.1","app":"user_ldap","message":"No DN found for on ldaps:\/\/REMOVED.bg","level":0,"time":"2015-11-23T09:19:40+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"eQbJpQAzqW27n\/RopF4S","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectClass=* base Array\n(\n [0] => cn=user3 test,ou=users,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => \n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"\/"} {"reqId":"eQbJpQAzqW27n\/RopF4S","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"\/"} {"reqId":"eQbJpQAzqW27n\/RopF4S","remoteAddr":"192.168.1.1","app":"user_ldap","message":"readAttribute: cn=user3 test,ou=users,dc=REMOVED,dc=bg found","level":0,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"\/"} {"reqId":"eQbJpQAzqW27n\/RopF4S","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectClass=* base Array\n(\n [0] => cn=user3 test,ou=users,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => mail\n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"\/"} {"reqId":"eQbJpQAzqW27n\/RopF4S","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"\/"} {"reqId":"eQbJpQAzqW27n\/RopF4S","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectClass=* base Array\n(\n [0] => cn=user3 test,ou=users,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => primaryGroupID\n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"\/"} {"reqId":"eQbJpQAzqW27n\/RopF4S","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"\/"} {"reqId":"eQbJpQAzqW27n\/RopF4S","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Requested attribute primarygroupid not found for cn=user3 test,ou=users,dc=REMOVED,dc=bg","level":0,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"\/"} {"reqId":"eQbJpQAzqW27n\/RopF4S","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectClass=* base Array\n(\n [0] => cn=user3 test,ou=users,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => memberOf\n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"\/"} {"reqId":"eQbJpQAzqW27n\/RopF4S","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"\/"} {"reqId":"eQbJpQAzqW27n\/RopF4S","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter (&(|(objectclass=groupOfNames))(|(cn=owncloudUser))) base Array\n(\n [0] => cn=ownclouduser,ou=groups,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => cn\n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"\/"} {"reqId":"eQbJpQAzqW27n\/RopF4S","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"\/"} {"reqId":"eQbJpQAzqW27n\/RopF4S","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectClass=* base Array\n(\n [0] => cn=ownclouduser,ou=groups,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => \n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"\/"} {"reqId":"eQbJpQAzqW27n\/RopF4S","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"\/"} {"reqId":"eQbJpQAzqW27n\/RopF4S","remoteAddr":"192.168.1.1","app":"user_ldap","message":"readAttribute: cn=ownclouduser,ou=groups,dc=REMOVED,dc=bg found","level":0,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"\/"} {"reqId":"eQbJpQAzqW27n\/RopF4S","remoteAddr":"192.168.1.1","app":"handleLogin","message":"Exception: {\"Exception\":\"InvalidArgumentException\",\"Message\":\"$absolutePath must be relative to \\\"files\\\"\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php(1807): OC\\\\Files\\\\View->getPathRelativeToFiles('\\\/test.user3@dok...')\\n#1 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php(1898): OC\\\\Files\\\\View->lockPath('\\\/test.user3@dok...', 1, false)\\n#2 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php(1196): OC\\\\Files\\\\View->lockFile('\\\/test.user3@dok...', 1)\\n#3 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/node\\\/node.php(80): OC\\\\Files\\\\View->getFileInfo('\\\/test.user3@dok...')\\n#4 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/node\\\/node.php(221): OC\\\\Files\\\\Node\\\\Node->getFileInfo()\\n#5 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/node\\\/node.php(104): OC\\\\Files\\\\Node\\\\Node->getPermissions()\\n#6 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/node\\\/folder.php(139): OC\\\\Files\\\\Node\\\\Node->checkPermissions(4)\\n#7 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/node\\\/root.php(346): OC\\\\Files\\\\Node\\\\Folder->newFolder('\\\/files')\\n#8 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/server.php(617): OC\\\\Files\\\\Node\\\\Root->getUserFolder('test.user3@doku...')\\n#9 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/user.php(254): OC\\\\Server->getUserFolder('test.user3@doku...')\\n#10 \\\/var\\\/www\\\/owncloud\\\/lib\\\/base.php(1051): OC_User::login(*** username and password replaced ***)\\n#11 \\\/var\\\/www\\\/owncloud\\\/lib\\\/base.php(947): OC::tryFormLogin()\\n#12 \\\/var\\\/www\\\/owncloud\\\/lib\\\/base.php(909): OC::handleLogin()\\n#13 \\\/var\\\/www\\\/owncloud\\\/index.php(39): OC::handleRequest()\\n#14 {main}\",\"File\":\"\\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php\",\"Line\":1969}","level":3,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"\/"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectClass=* base Array\n(\n [0] => cn=user3 test,ou=users,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => \n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"readAttribute: cn=user3 test,ou=users,dc=REMOVED,dc=bg found","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectClass=* base Array\n(\n [0] => cn=user3 test,ou=users,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => \n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"readAttribute: cn=user3 test,ou=users,dc=REMOVED,dc=bg found","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectClass=* base Array\n(\n [0] => cn=user3 test,ou=users,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => mail\n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectClass=* base Array\n(\n [0] => cn=user3 test,ou=users,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => primaryGroupID\n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Requested attribute primarygroupid not found for cn=user3 test,ou=users,dc=REMOVED,dc=bg","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectClass=* base Array\n(\n [0] => cn=user3 test,ou=users,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => memberOf\n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter (&(|(objectclass=groupOfNames))(|(cn=owncloudUser))) base Array\n(\n [0] => cn=ownclouduser,ou=groups,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => cn\n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectClass=* base Array\n(\n [0] => cn=ownclouduser,ou=groups,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => \n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"XM5L+oqR+RZFQwtNsB7c","remoteAddr":"192.168.1.1","app":"user_ldap","message":"readAttribute: cn=ownclouduser,ou=groups,dc=REMOVED,dc=bg found","level":0,"time":"2015-11-23T09:19:59+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectClass=* base Array\n(\n [0] => cn=user3 test,ou=users,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => \n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:20:00+00:00","method":"GET","url":"\/cron.php"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:20:00+00:00","method":"GET","url":"\/cron.php"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"readAttribute: cn=user3 test,ou=users,dc=REMOVED,dc=bg found","level":0,"time":"2015-11-23T09:20:00+00:00","method":"GET","url":"\/cron.php"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectClass=* base Array\n(\n [0] => cn=glugovskiy alexey,ou=users,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => \n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:20:01+00:00","method":"GET","url":"\/cron.php"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:20:01+00:00","method":"GET","url":"\/cron.php"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"readAttribute: cn=glugovskiy alexey,ou=users,dc=REMOVED,dc=bg found","level":0,"time":"2015-11-23T09:20:01+00:00","method":"GET","url":"\/cron.php"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectClass=* base Array\n(\n [0] => cn=hoefling frank,ou=users,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => \n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:20:01+00:00","method":"GET","url":"\/cron.php"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:20:01+00:00","method":"GET","url":"\/cron.php"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"readAttribute: cn=hoefling frank,ou=users,dc=REMOVED,dc=bg found","level":0,"time":"2015-11-23T09:20:01+00:00","method":"GET","url":"\/cron.php"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectClass=* base Array\n(\n [0] => cn=user2 test,ou=users,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => \n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:20:01+00:00","method":"GET","url":"\/cron.php"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:20:01+00:00","method":"GET","url":"\/cron.php"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"readAttribute: cn=user2 test,ou=users,dc=REMOVED,dc=bg found","level":0,"time":"2015-11-23T09:20:01+00:00","method":"GET","url":"\/cron.php"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectClass=* base Array\n(\n [0] => cn=user3 test,ou=users,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => \n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:20:01+00:00","method":"GET","url":"\/cron.php"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:20:01+00:00","method":"GET","url":"\/cron.php"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"readAttribute: cn=user3 test,ou=users,dc=REMOVED,dc=bg found","level":0,"time":"2015-11-23T09:20:01+00:00","method":"GET","url":"\/cron.php"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectClass=* base Array\n(\n [0] => cn=user test,ou=users,dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => \n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:20:01+00:00","method":"GET","url":"\/cron.php"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:20:01+00:00","method":"GET","url":"\/cron.php"} {"reqId":"oAL2Mq3dL70T60A4Jw9L","remoteAddr":"192.168.1.1","app":"user_ldap","message":"readAttribute: cn=user test,ou=users,dc=REMOVED,dc=bg found","level":0,"time":"2015-11-23T09:20:01+00:00","method":"GET","url":"\/cron.php"} {"reqId":"ja6cPH3+xNEEtErWJJiw","remoteAddr":"192.168.1.1","app":"user_ldap","message":"No DN found for on ldaps:\/\/REMOVED.bg","level":0,"time":"2015-11-23T09:24:18+00:00","method":"GET","url":"\/index.php\/core\/js\/oc.js?v=925443c2b043dc4b7106da9a08db4bd3"} {"reqId":"C7AVTrpl4TWB1sL2\/rXN","remoteAddr":"192.168.1.1","app":"DeleteOrphanedSharesJob","message":"0 orphaned share(s) deleted","level":0,"time":"2015-11-23T09:24:29+00:00","method":"GET","url":"\/cron.php"} {"reqId":"ZgL7yi368nn+OvzxIG+1","remoteAddr":"192.168.1.1","app":"PHP","message":"Module 'geoip' already loaded at Unknown#0","level":3,"time":"2015-11-23T09:24:29+00:00","method":"GET","url":"\/index.php\/apps\/notifications"} {"reqId":"7Ti4ONsBC\/Vm1\/wSyGkE","remoteAddr":"192.168.1.1","app":"PHP","message":"Array to string conversion at \/var\/www\/owncloud\/lib\/private\/template\/functions.php#36","level":3,"time":"2015-11-23T09:24:34+00:00","method":"GET","url":"\/index.php\/settings\/admin"} {"reqId":"I7btE8ivBY2tIbWqaU0N","remoteAddr":"192.168.1.1","app":"PHP","message":"Module 'geoip' already loaded at Unknown#0","level":3,"time":"2015-11-23T09:24:37+00:00","method":"GET","url":"\/index.php\/avatar\/ownCloud_Admin\/128"} {"reqId":"PzznJEA3ps4koBTzG5mq","remoteAddr":"192.168.1.1","app":"PHP","message":"ldap_read(): Search: Invalid DN syntax at \/var\/www\/owncloud\/apps\/user_ldap\/lib\/ldap.php#257","level":3,"time":"2015-11-23T09:24:38+00:00","method":"POST","url":"\/index.php\/apps\/user_ldap\/ajax\/testConfiguration.php"} {"reqId":"PzznJEA3ps4koBTzG5mq","remoteAddr":"192.168.1.1","app":"user_ldap","message":"LDAP error Invalid DN syntax (34) after calling ldap_read","level":0,"time":"2015-11-23T09:24:38+00:00","method":"POST","url":"\/index.php\/apps\/user_ldap\/ajax\/testConfiguration.php"} {"reqId":"zYc2S1K+ncn7ESBHtNFi","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Count filter: objectclass=*","level":0,"time":"2015-11-23T09:24:39+00:00","method":"POST","url":"\/index.php\/apps\/user_ldap\/ajax\/wizard.php"} {"reqId":"zYc2S1K+ncn7ESBHtNFi","remoteAddr":"192.168.1.1","app":"user_ldap","message":"initializing paged search for Filter objectclass=* base Array\n(\n [0] => dc=REMOVED,dc=bg\n)\n attr Array\n(\n [0] => dn\n)\n limit 500 offset 0","level":0,"time":"2015-11-23T09:24:39+00:00","method":"POST","url":"\/index.php\/apps\/user_ldap\/ajax\/wizard.php"} {"reqId":"zYc2S1K+ncn7ESBHtNFi","remoteAddr":"192.168.1.1","app":"user_ldap","message":"Ready for a paged search","level":0,"time":"2015-11-23T09:24:39+00:00","method":"POST","url":"\/index.php\/apps\/user_ldap\/ajax\/wizard.php"}

@PVince81

This comment has been minimized.

Show comment
Hide comment
@PVince81

PVince81 Nov 23, 2015

Member

@frankhoefling I'm surprised that there isn't any entry in your log related to "Internal Server Error". Can you check the Apache error_log too maybe ?

CC @blizzz @icewind1991

Member

PVince81 commented Nov 23, 2015

@frankhoefling I'm surprised that there isn't any entry in your log related to "Internal Server Error". Can you check the Apache error_log too maybe ?

CC @blizzz @icewind1991

@PVince81

This comment has been minimized.

Show comment
Hide comment
@PVince81

PVince81 Nov 23, 2015

Member

or nginx error log, not sure where that one is

Member

PVince81 commented Nov 23, 2015

or nginx error log, not sure where that one is

@frankhoefling

This comment has been minimized.

Show comment
Hide comment
@frankhoefling

frankhoefling Nov 23, 2015

nginx/error.log has only this entry
2015/11/23 09:25:08 [error] 1597#0: *1754 access forbidden by rule, client: 192.168.1.1, server: www.REMOVED.de:1024, request: "GET /data/htaccesstest.txt HTTP/1.1", host: "www.REMOVED.de:1024"

frankhoefling commented Nov 23, 2015

nginx/error.log has only this entry
2015/11/23 09:25:08 [error] 1597#0: *1754 access forbidden by rule, client: 192.168.1.1, server: www.REMOVED.de:1024, request: "GET /data/htaccesstest.txt HTTP/1.1", host: "www.REMOVED.de:1024"

@PVince81

This comment has been minimized.

Show comment
Hide comment
@PVince81

PVince81 Nov 23, 2015

Member

@blizzz are you able to reproduce this on 8.2.1 with redis locking ?

Member

PVince81 commented Nov 23, 2015

@blizzz are you able to reproduce this on 8.2.1 with redis locking ?

@frankhoefling

This comment has been minimized.

Show comment
Hide comment
@frankhoefling

frankhoefling Nov 23, 2015

Just to complete the logs…
redis-server.log:
[2377] 23 Nov 09:22:24.009 * 10 changes in 300 seconds. Saving... [2377] 23 Nov 09:22:24.010 * Background saving started by pid 2922 [2922] 23 Nov 09:22:24.025 * DB saved on disk [2922] 23 Nov 09:22:24.028 * RDB: 0 MB of memory used by copy-on-write [2377] 23 Nov 09:22:24.111 * Background saving terminated with success

php5-fpm.log:
nothing

mysql.err:
nothing

syslog:
Nov 23 09:19:58 dg-s02 slapd[7538]: <= mdb_equality_candidates: (memberOf) not indexed Nov 23 09:19:58 dg-s02 rsyslogd-2007: action 'action 17' suspended, next retry is Mon Nov 23 09:21:28 2015 [try http://www.rsyslog.com/e/2007 ] Nov 23 09:19:58 dg-s02 slapd[7538]: <= mdb_equality_candidates: (mail) not indexed

frankhoefling commented Nov 23, 2015

Just to complete the logs…
redis-server.log:
[2377] 23 Nov 09:22:24.009 * 10 changes in 300 seconds. Saving... [2377] 23 Nov 09:22:24.010 * Background saving started by pid 2922 [2922] 23 Nov 09:22:24.025 * DB saved on disk [2922] 23 Nov 09:22:24.028 * RDB: 0 MB of memory used by copy-on-write [2377] 23 Nov 09:22:24.111 * Background saving terminated with success

php5-fpm.log:
nothing

mysql.err:
nothing

syslog:
Nov 23 09:19:58 dg-s02 slapd[7538]: <= mdb_equality_candidates: (memberOf) not indexed Nov 23 09:19:58 dg-s02 rsyslogd-2007: action 'action 17' suspended, next retry is Mon Nov 23 09:21:28 2015 [try http://www.rsyslog.com/e/2007 ] Nov 23 09:19:58 dg-s02 slapd[7538]: <= mdb_equality_candidates: (mail) not indexed

@blizzz

This comment has been minimized.

Show comment
Hide comment
@blizzz

blizzz Nov 23, 2015

Contributor

@frankhoefling Does it work with (new) local users?

Contributor

blizzz commented Nov 23, 2015

@frankhoefling Does it work with (new) local users?

@blizzz

This comment has been minimized.

Show comment
Hide comment
@blizzz

blizzz Nov 23, 2015

Contributor

We have this backtrace in the log

{"reqId":"eQbJpQAzqW27n/RopF4S","remoteAddr":"192.168.1.1","app":"handleLogin","message":"Exception: {\"Exception\":\"InvalidArgumentException\",\"Message\":\"$absolutePath must be relative to \\"files\\"\",\"Code\":0,\"Trace\":\"#0 /var/www/owncloud/lib/private/files/view.php(1807): OC\\Files\\View->getPathRelativeToFiles('/test.user3@dok...')\
#1 /var/www/owncloud/lib/private/files/view.php(1898): OC\\Files\\View->lockPath('/test.user3@dok...', 1, false)\
#2 /var/www/owncloud/lib/private/files/view.php(1196): OC\\Files\\View->lockFile('/test.user3@dok...', 1)\
#3 /var/www/owncloud/lib/private/files/node/node.php(80): OC\\Files\\View->getFileInfo('/test.user3@dok...')\
#4 /var/www/owncloud/lib/private/files/node/node.php(221): OC\\Files\\Node\\Node->getFileInfo()\
#5 /var/www/owncloud/lib/private/files/node/node.php(104): OC\\Files\\Node\\Node->getPermissions()\
#6 /var/www/owncloud/lib/private/files/node/folder.php(139): OC\\Files\\Node\\Node->checkPermissions(4)\
#7 /var/www/owncloud/lib/private/files/node/root.php(346): OC\\Files\\Node\\Folder->newFolder('/files')\
#8 /var/www/owncloud/lib/private/server.php(617): OC\\Files\\Node\\Root->getUserFolder('test.user3@doku...')\
#9 /var/www/owncloud/lib/private/user.php(254): OC\\Server->getUserFolder('test.user3@doku...')\
#10 /var/www/owncloud/lib/base.php(1051): OC_User::login(*** username and password replaced ***)\
#11 /var/www/owncloud/lib/base.php(947): OC::tryFormLogin()\
#12 /var/www/owncloud/lib/base.php(909): OC::handleLogin()\
#13 /var/www/owncloud/index.php(39): OC::handleRequest()\
#14 {main}\",\"File\":\"/var/www/owncloud/lib/private/files/view.php\",\"Line\":1969}","level":3,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"/"} 
Contributor

blizzz commented Nov 23, 2015

We have this backtrace in the log

{"reqId":"eQbJpQAzqW27n/RopF4S","remoteAddr":"192.168.1.1","app":"handleLogin","message":"Exception: {\"Exception\":\"InvalidArgumentException\",\"Message\":\"$absolutePath must be relative to \\"files\\"\",\"Code\":0,\"Trace\":\"#0 /var/www/owncloud/lib/private/files/view.php(1807): OC\\Files\\View->getPathRelativeToFiles('/test.user3@dok...')\
#1 /var/www/owncloud/lib/private/files/view.php(1898): OC\\Files\\View->lockPath('/test.user3@dok...', 1, false)\
#2 /var/www/owncloud/lib/private/files/view.php(1196): OC\\Files\\View->lockFile('/test.user3@dok...', 1)\
#3 /var/www/owncloud/lib/private/files/node/node.php(80): OC\\Files\\View->getFileInfo('/test.user3@dok...')\
#4 /var/www/owncloud/lib/private/files/node/node.php(221): OC\\Files\\Node\\Node->getFileInfo()\
#5 /var/www/owncloud/lib/private/files/node/node.php(104): OC\\Files\\Node\\Node->getPermissions()\
#6 /var/www/owncloud/lib/private/files/node/folder.php(139): OC\\Files\\Node\\Node->checkPermissions(4)\
#7 /var/www/owncloud/lib/private/files/node/root.php(346): OC\\Files\\Node\\Folder->newFolder('/files')\
#8 /var/www/owncloud/lib/private/server.php(617): OC\\Files\\Node\\Root->getUserFolder('test.user3@doku...')\
#9 /var/www/owncloud/lib/private/user.php(254): OC\\Server->getUserFolder('test.user3@doku...')\
#10 /var/www/owncloud/lib/base.php(1051): OC_User::login(*** username and password replaced ***)\
#11 /var/www/owncloud/lib/base.php(947): OC::tryFormLogin()\
#12 /var/www/owncloud/lib/base.php(909): OC::handleLogin()\
#13 /var/www/owncloud/index.php(39): OC::handleRequest()\
#14 {main}\",\"File\":\"/var/www/owncloud/lib/private/files/view.php\",\"Line\":1969}","level":3,"time":"2015-11-23T09:19:58+00:00","method":"POST","url":"/"} 
@frankhoefling

This comment has been minimized.

Show comment
Hide comment
@frankhoefling

frankhoefling Nov 23, 2015

@blizzz same with new local user

frankhoefling commented Nov 23, 2015

@blizzz same with new local user

@blizzz blizzz removed the app:user_ldap label Nov 23, 2015

@blizzz

This comment has been minimized.

Show comment
Hide comment
@blizzz

blizzz Nov 23, 2015

Contributor

Creating the new folder structure fails obviously. I do not see Redis contributing here as well.

@frankhoefling can you confirm it happens also without Redis?

Rather it appears to be a pure locking issue in connection with users having not their home directory created yet.

I am not familiar with the locking code, only tried to undestand what's happening following the backtrace path.

Contributor

blizzz commented Nov 23, 2015

Creating the new folder structure fails obviously. I do not see Redis contributing here as well.

@frankhoefling can you confirm it happens also without Redis?

Rather it appears to be a pure locking issue in connection with users having not their home directory created yet.

I am not familiar with the locking code, only tried to undestand what's happening following the backtrace path.

@frankhoefling

This comment has been minimized.

Show comment
Hide comment
@frankhoefling

frankhoefling Nov 23, 2015

@blizzz I just tested 3 scenarios:

  1. Neither 'filelocking.enabled' => 'true' nor 'memcache.locking' => '\OC\Memcache\Redis'
    user-dirs & files are created => everything works as expected
  2. Both 'filelocking.enabled' => 'true' and 'memcache.locking' => '\OC\Memcache\Redis'
    no user-dir & file is created => error message as shown above
  3. Only `'filelocking.enabled' => 'true'‘
    user-dir & files are created => but browser gets HTTP Error 500

Additional information about folder-rights:
The Data-Directory has (as the original data created by the repository) 770
drwxrwx--- 11 www-data www-data 4096 Nov 23 17:22 owncloudData
The user-dirs are created as subfolders there with 755
drwxr-xr-x 4 www-data www-data 4096 Nov 23 07:22 test.user2@REMOVED.bg

frankhoefling commented Nov 23, 2015

@blizzz I just tested 3 scenarios:

  1. Neither 'filelocking.enabled' => 'true' nor 'memcache.locking' => '\OC\Memcache\Redis'
    user-dirs & files are created => everything works as expected
  2. Both 'filelocking.enabled' => 'true' and 'memcache.locking' => '\OC\Memcache\Redis'
    no user-dir & file is created => error message as shown above
  3. Only `'filelocking.enabled' => 'true'‘
    user-dir & files are created => but browser gets HTTP Error 500

Additional information about folder-rights:
The Data-Directory has (as the original data created by the repository) 770
drwxrwx--- 11 www-data www-data 4096 Nov 23 17:22 owncloudData
The user-dirs are created as subfolders there with 755
drwxr-xr-x 4 www-data www-data 4096 Nov 23 07:22 test.user2@REMOVED.bg

@frankhoefling

This comment has been minimized.

Show comment
Hide comment
@frankhoefling

frankhoefling Nov 23, 2015

@blizzz @PVince81 I found the reason for the problem!!!
The redis-server was configured according to the documentation WITH password-authorization (requirepass pass). THAT IS WRONG as OC 8.2.1 is unable to pass the auth-password to redis. The line 'password' => 'pass' in OCs config.php is simply ignored. see #20690 This is only a future feature of OC 8.2.2

SOLUTION

  1. Disable password authentication in /etc/redis/redis.conf
  2. Restart Redis with service redis-server restart
  3. add filelocking and memcache.locking in OC config.php
  4. OC works as intended

frankhoefling commented Nov 23, 2015

@blizzz @PVince81 I found the reason for the problem!!!
The redis-server was configured according to the documentation WITH password-authorization (requirepass pass). THAT IS WRONG as OC 8.2.1 is unable to pass the auth-password to redis. The line 'password' => 'pass' in OCs config.php is simply ignored. see #20690 This is only a future feature of OC 8.2.2

SOLUTION

  1. Disable password authentication in /etc/redis/redis.conf
  2. Restart Redis with service redis-server restart
  3. add filelocking and memcache.locking in OC config.php
  4. OC works as intended
@frankhoefling

This comment has been minimized.

Show comment
Hide comment
@frankhoefling

frankhoefling Nov 24, 2015

IMPORTANT FOR DEBIAN-JESSIE-USERS

If you configure redis for listining on unixsocket with
'host' => '/var/run/redis/redis.sock'
instead of
'host' => 'localhost'
in OC config.php (as recommended in the OC documentation) you run into the problem that the directory /var/run/redis is not created (and not recreated during boot). This results in redis-server red state and HTTP Error 500 when you call Owncloud with this recommended configuration.

SOLUTION

sudo nano /usr/lib/tmpfiles.d/redis-server.conf
fill it with
d /run/redis 2775 redis redis
save and reboot. Now the dir /var/run/redis is created automatically during boot/restart.

BACKGROUND

The currently by the stable-repository distributed version of redis (2.8.17) doesn't support systemd. So the mkdir command in the init script of redis is ignored during reboot/restart. Adding this file is a temporary fix recommended by Chris Lamb (https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=803233)
@blizzz @PVince81

frankhoefling commented Nov 24, 2015

IMPORTANT FOR DEBIAN-JESSIE-USERS

If you configure redis for listining on unixsocket with
'host' => '/var/run/redis/redis.sock'
instead of
'host' => 'localhost'
in OC config.php (as recommended in the OC documentation) you run into the problem that the directory /var/run/redis is not created (and not recreated during boot). This results in redis-server red state and HTTP Error 500 when you call Owncloud with this recommended configuration.

SOLUTION

sudo nano /usr/lib/tmpfiles.d/redis-server.conf
fill it with
d /run/redis 2775 redis redis
save and reboot. Now the dir /var/run/redis is created automatically during boot/restart.

BACKGROUND

The currently by the stable-repository distributed version of redis (2.8.17) doesn't support systemd. So the mkdir command in the init script of redis is ignored during reboot/restart. Adding this file is a temporary fix recommended by Chris Lamb (https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=803233)
@blizzz @PVince81

@PVince81

This comment has been minimized.

Show comment
Hide comment
@PVince81

PVince81 Nov 24, 2015

Member

@carlaschroder is this something we want added in our documentation or rather something to be raised upstream to the Debian maintainers ? (or both?)

Member

PVince81 commented Nov 24, 2015

@carlaschroder is this something we want added in our documentation or rather something to be raised upstream to the Debian maintainers ? (or both?)

@carlaschroder

This comment has been minimized.

Show comment
Hide comment
@carlaschroder

carlaschroder Nov 24, 2015

Thanks @PVince81, probably both. I'll add a doc note.

carlaschroder commented Nov 24, 2015

Thanks @PVince81, probably both. I'll add a doc note.

@carlaschroder

This comment has been minimized.

Show comment
Hide comment
@carlaschroder

carlaschroder Jan 7, 2016

Redis password auth is in 8.2 now #20690

carlaschroder commented Jan 7, 2016

Redis password auth is in 8.2 now #20690

@PVince81

This comment has been minimized.

Show comment
Hide comment
@PVince81

PVince81 Mar 7, 2016

Member

Cool, so it looks like this is solved, closing.

Feel free to reopen if you still have issues with 8.2.2

Member

PVince81 commented Mar 7, 2016

Cool, so it looks like this is solved, closing.

Feel free to reopen if you still have issues with 8.2.2

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