server icon indicating copy to clipboard operation
server copied to clipboard

Published 20 hours ago • verified publisher icon nextcloud

[Bug]: LDAP migration failing NC27->NC28 involving `ldap_group_members` table

Open elr3m opened this issue 1 year ago • 3 comments

⚠️ This issue respects the following points: ⚠️

Bug description

During the 27.1.6 to 28.0.2 upgrade, the process failed because of the user_ldap app.

I disabled user_ldap app with occ and was able to proceed with the rest of the upgrade.

After that I get the below error message when trying to re-enable user_ldap . Not sure what a boolean is returned there, my php knowledge is very limited so I am not sure what the query actually is (LDAP or MySQL?).

Any ideas? Please do let me know if I am missing something or if more specific logs needs to be uploaded to help. This is a staging instance of Nextcloud, production is untouched and working fine on 27.1.6.

Steps to reproduce

  1. Upgraded from 27.1.6 to 28.0.2
  2. Upgrade failed because of LDAP (see error below)
  3. isabled LDAP
  4. an occ upgrade manually successfully
  5. Running occ app:enable user_ldap throws the error below

Error:

An unhandled exception has been thrown:
TypeError: array_unique(): Argument #1 ($array) must be of type array, bool given in /var/www/html/nextcloud/apps/user_ldap/lib/Migration/Version1190Date20230706134108.php:102
Stack trace:
#0 /var/www/html/nextcloud/apps/user_ldap/lib/Migration/Version1190Date20230706134108.php(102): array_unique()
#1 /var/www/html/nextcloud/apps/user_ldap/lib/Migration/Version1190Date20230706134108.php(83): OCA\User_LDAP\Migration\Version1190Date20230706134108->copyGroupMembershipData()
#2 /var/www/html/nextcloud/lib/private/DB/MigrationService.php(527): OCA\User_LDAP\Migration\Version1190Date20230706134108->postSchemaChange()
#3 /var/www/html/nextcloud/lib/private/DB/MigrationService.php(402): OC\DB\MigrationService->executeStep()
#4 /var/www/html/nextcloud/lib/private/Installer.php(155): OC\DB\MigrationService->migrate()
#5 /var/www/html/nextcloud/core/Command/App/Enable.php(110): OC\Installer->installApp()
#6 /var/www/html/nextcloud/core/Command/App/Enable.php(80): OC\Core\Command\App\Enable->enableApp()
#7 /var/www/html/nextcloud/3rdparty/symfony/console/Command/Command.php(298): OC\Core\Command\App\Enable->execute()
#8 /var/www/html/nextcloud/3rdparty/symfony/console/Application.php(1040): Symfony\Component\Console\Command\Command->run()
#9 /var/www/html/nextcloud/3rdparty/symfony/console/Application.php(301): Symfony\Component\Console\Application->doRunCommand()
#10 /var/www/html/nextcloud/3rdparty/symfony/console/Application.php(171): Symfony\Component\Console\Application->doRun()
#11 /var/www/html/nextcloud/lib/private/Console/Application.php(206): Symfony\Component\Console\Application->run()
#12 /var/www/html/nextcloud/console.php(100): OC\Console\Application->run()
#13 /var/www/html/nextcloud/occ(11): require_once('...')
#14 {main}

Expected behavior

Ability to enable user_ldap

Installation method

Community Manual installation with Archive

Nextcloud Server version

28

Operating system

Debian/Ubuntu

PHP engine version

PHP 8.2

Web server

Apache (supported)

Database engine version

MariaDB

Is this bug present after an update or on a fresh install?

Upgraded to a MAJOR version (ex. 22 to 23)

Are you using the Nextcloud Server Encryption module?

Encryption is Disabled

What user-backends are you using?

  • [ ] Default user-backend (database)
  • [X] LDAP/ Active Directory
  • [X] SSO - SAML
  • [ ] Other

Configuration report

{
    "system": {
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "cloud-stg.kqed.org"
        ],
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "dbtype": "mysql",
        "version": "28.0.2.5",
        "overwrite.cli.url": "https:\/\/cloud-stg.kqed.org",
        "htaccess.RewriteBase": "\/",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbport": "",
        "dbtableprefix": "oc_",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "installed": true,
        "auth.webauthn.enabled": false,
        "ldapIgnoreNamingRules": false,
        "maintenance": false,
        "memcache.local": "\\OC\\Memcache\\APCu",
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "filelocking.enabled": "true",
        "redis": {
            "host": "***REMOVED SENSITIVE VALUE***",
            "port": 0,
            "timeout": 0
        },
        "lost_password_link": "disabled",
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpmode": "smtp",
        "mail_sendmailmode": "smtp",
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpport": "587",
        "twofactor_enforced": "true",
        "twofactor_enforced_groups": [
            "admin"
        ],
        "twofactor_enforced_excluded_groups": [],
        "theme": "",
        "loglevel": 0,
        "enabledPreviewProviders": [
            "OC\\Preview\\Image",
            "OC\\Preview\\Movie",
            "OC\\Preview\\TXT"
        ],
        "default_phone_region": "US",
        "updater.release.channel": "stable",
        "app_install_overwrite": [
            "twofactor_admin",
            "workflow_pdf_converter",
            "files_trackdownloads",
            "extract",
            "impersonate",
            "user_ldap"
        ],
        "mysql.utf8mb4": true,
        "mail_smtpauthtype": "LOGIN",
        "mail_smtpauth": 1,
        "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
        "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
        "updater.secret": "***REMOVED SENSITIVE VALUE***"
    }
}

List of activated Apps

Enabled:
  - activity: 2.20.0
  - admin_audit: 1.18.0
  - bruteforcesettings: 2.8.0
  - camerarawpreviews: 0.8.4
  - checksum: 1.2.3
  - circles: 28.0.0-dev
  - cloud_federation_api: 1.11.0
  - comments: 1.18.0
  - contactsinteraction: 1.9.0
  - dav: 1.29.1
  - federatedfilesharing: 1.18.0
  - federation: 1.18.0
  - files: 2.0.0
  - files_pdfviewer: 2.9.0
  - files_reminders: 1.1.0
  - files_sharing: 1.20.0
  - files_trashbin: 1.18.0
  - files_versions: 1.21.0
  - firstrunwizard: 2.17.0
  - impersonate: 1.15.0
  - logreader: 2.13.0
  - lookup_server_connector: 1.16.0
  - nextcloud_announcements: 1.17.0
  - notifications: 2.16.0
  - oauth2: 1.16.3
  - photos: 2.4.0
  - previewgenerator: 5.4.0
  - privacy: 1.12.0
  - provisioning_api: 1.18.0
  - quota_warning: 1.18.0
  - related_resources: 1.3.0
  - serverinfo: 1.18.0
  - settings: 1.10.1
  - sharebymail: 1.18.0
  - support: 1.11.0
  - survey_client: 1.16.0
  - systemtags: 1.18.0
  - text: 3.9.1
  - theming: 2.3.0
  - twofactor_admin: 4.4.0
  - twofactor_backupcodes: 1.17.0
  - twofactor_totp: 10.0.0-beta.2
  - updatenotification: 1.18.0
  - user_saml: 6.1.1
  - user_usage_report: 1.12.0
  - viewer: 2.2.0
  - weather_status: 1.8.0
  - workflow_pdf_converter: 1.13.0
  - workflowengine: 2.10.0
Disabled:
  - dashboard: 7.8.0 (installed 7.0.0)
  - encryption: 2.16.0
  - extract: 1.3.6 (installed 1.3.6)
  - files_downloadactivity: 1.16.0 (installed 1.16.0)
  - files_external: 1.20.0
  - files_trackdownloads: 1.11.0 (installed 1.11.0)
  - metadata: 0.19.0 (installed 0.19.0)
  - password_policy: 1.18.0 (installed 1.16.0)
  - recommendations: 2.0.0 (installed 0.6.0)
  - suspicious_login: 6.0.0
  - user_ldap: 1.19.0 (installed 1.17.0)
  - user_status: 1.8.1 (installed 1.4.0)

Nextcloud Signing status

No errors have been found.

Nextcloud Logs

Getting a lot of these:
# Seems unrelatd, but getting a lot of this:
[user_saml] Debug: /appinfo/app.php is deprecated, use \OCP\AppFramework\Bootstrap\IBootstrap on the application class instead.
	GET /apps/logreader/api/poll?lastReqId=SOMEID
	from IP.IP.IP.IP by SOMEADMIN at Feb 13, 2024, 11:56:50 AM

Additional info

I have tried taking a Database from the production environment and it fails all the same. SSO is used to authenticate and LDAP is used to permit create the NC account. Those 2 have been working along side for 2 or 3 major versions.

elr3m avatar Feb 14 '24 17:02 elr3m

Are background jobs disabled somehow in your staging environment by chance? Or maybe staging was off and just recently turned on so it hasn't had a chance to run before trying to update to v28?

There's an hourly upgradeGroups that comes to mind for this error (well not directly, but trying to figure out why that table would be empty at upgrade time?

I'm assuming staging has it's own functioning ldap setup otherwise. :-)

joshtrichards avatar Feb 14 '24 19:02 joshtrichards

Thank you for your answer, I would like to do the 28 upgrade on Production and that issue worries me quite a bit :) . Also thank you for the labels and renaming of the bug report.

Are background jobs disabled somehow in your staging environment by chance? Or maybe staging was off and just recently turned on so it hasn't had a chance to run before trying to update to v28?

Background jobs were not disabled. Staging was used (even ran a php 8.1 to 8.2 upgrade a few days earlier with a bunch a standard test - login, sharing, desktop app...).

There's an hourly upgradeGroups that comes to mind for this error (well not directly, but trying to figure out why that table would be empty at upgrade time?

Is there a way to "fill the table" manually? FYI, I am not able to use occ ldap:* since the app is not enabled.

elr3m avatar Feb 15 '24 02:02 elr3m

Looks like some sort of interaction with the recent migration changes to the the group membership data from #39446 & #42576. I'm not particularly familiar with what's going on here.

Hey @come-nc: I'm kind of stabbing in the dark, but given the broad catch below should we also maybe be more accepting about silently failing if owncloudusers is already empty up above (before we make it into the try)?

https://github.com/nextcloud/server/blob/9c00d128f5fe4774c011e4a0936b2cf831fcd371/apps/user_ldap/lib/Migration/Version1190Date20230706134108.php#L111-L116

https://github.com/nextcloud/server/blob/9c00d128f5fe4774c011e4a0936b2cf831fcd371/apps/user_ldap/lib/Migration/Version1190Date20230706134108.php#L100-L104

Or is this a situation where this should never happen and you think something else is probably going on here?

joshtrichards avatar Feb 15 '24 13:02 joshtrichards

It’s quite unexpected for this unserialize call to return false. @elr3m What do you have in your oc_ldap_group_members table? Do you have rows where owncloudusers does not look like a serialized array (a:2:{i:0;s:3:"joe";i:1;s:5:"alice";})? Is it an empty string or NULL on some rows?

@joshtrichards I did not think it was possible for this column to not contain a serialized array, but yes I think we can ignore it and count on the background job to fill the new table later instead.

come-nc avatar Feb 19 '24 13:02 come-nc

@come-nc Thank you for your answer, here are a screenshot of the query: image And here is a redacted owncloudusers column: a:94:{i:0;s:7:"SomeUser";i:1;s:6:"SomeUser";i:2;s:17:"SomeUser";i:3;s:4:"SomeUser";i:4;s:7:"SomeUser";i:5;s:6:"SomeUser";i:6;s:8:"SomeUser";i:7;s:17:"SomeUser";i:8;s:11:"SomeUser";i:9;s:9:"SomeUser";i:10;s:8:"SomeUser";i:11;s:7:"SomeUser";i:12;s:6:"SomeUser";i:13;s:8:"SomeUser";i:14;s:6:"SomeUser";i:15;s:7:"SomeUser";i:16;s:8:"SomeUser";i:17;s:6:"SomeUser";i:18;s:6:"SomeUser";i:19;s:9:"SomeUser";i:20;s:8:"SomeUser";i:21;s:7:"SomeUser";i:22;s:7:"SomeUser";i:23;s:9:"SomeUser";i:24;s:6:"SomeUser";i:25;s:3:"SomeUser";i:26;s:7:"SomeUser";i:27;s:7:"SomeUser";i:28;s:4:"SomeUser";i:29;s:7:"SomeUser";i:30;s:8:"SomeUser";i:31;s:7:"SomeUser";i:32;s:7:"SomeUser";i:33;s:8:"SomeUser";i:34;s:13:"SomeUser";i:35;s:7:"SomeUser";i:36;s:8:"SomeUser";i:37;s:5:"SomeUser";i:38;s:6:"SomeUser";i:39;s:8:"SomeUser";i:40;s:11:"SomeUser";i:41;s:3:"SomeUser";i:42;s:7:"SomeUser";i:43;s:8:"SomeUser";i:44;s:8:"SomeUser";i:45;s:9:"SomeUser";i:46;s:7:"SomeUser";i:47;s:8:"SomeUser";i:48;s:6:"SomeUser";i:49;s:6:"SomeUser";i:50;s:7:"SomeUser";i:51;s:9:"SomeUser";i:52;s:8:"SomeUser";i:53;s:8:"SomeUser";i:54;s:9:"SomeUser";i:55;s:9:"SomeUser";i:56;s:8:"SomeUser";i:57;s:7:"SomeUser";i:58;s:8:"SomeUser";i:59;s:7:"SomeUser";i:60;s:10:"SomeUser";i:61;s:6:"SomeUser";i:62;s:6:"SomeUser";i:63;s:9:"SomeUser";i:64;s:5:"SomeUser";i:65;s:5:"SomeUser";i:66;s:6:"SomeUser";i:67;s:6:"SomeUser";i:68;s:7:"SomeUser";i:69;s:7:"SomeUser";i:70;s:8:"SomeUser";i:71;s:6:"SomeUser";i:72;s:6:"SomeUser";i:73;s:7:"SomeUser";i:74;s:7:"SomeUser";i:75;s:7:"SomeUser";i:76;s:8:"SomeUser";i:77;s:6:"SomeUser";i:78;s:4:"SomeUser";i:79;s:7:"SomeUser";i:80;s:6:"SomeUser";i:81;s:8:"SomeUser";i:82;s:7:"SomeUser";i:83;s:7:"SomeUser";i:84;s:7:"SomeUser";i:85;s:9:"SomeUser";i:86;s:6:"SomeUser";i:87;s:6:"SomeUser";i:88;s:9:"SomeUser";i:89;s:10:"SomeUser";i:90;s:7:"SomeUser";i:91;s:6:"SomeUser";i:92;s:9:"SomeUser";i:93;s:8:"SomeUser";}

Let me know if you need more information!

elr3m avatar Feb 20 '24 02:02 elr3m

There is only one line? I do not understand how it could get false when unserializing in this case, unless the data is corrupted.

come-nc avatar Feb 20 '24 07:02 come-nc

Yes indeed, one line only, is there a way to re-generate the line? Or maybe there is a character in one of the username that breaks the serialization?

elr3m avatar Feb 20 '24 14:02 elr3m

Can you double-check the encoding on your database, @elr3m?

I can't unserialize your provided entree. Make sure it's not something like latin1_swedish_ci.

joshtrichards avatar Feb 20 '24 14:02 joshtrichards

I’d be surprised if PHP produced a serialization it’s not able to unserialize. Maybe an encoding thing indeed.

You can simply delete the line, the background job should recreate the info in the new table.

I guess I’ll edit the migration to ignore unserialization failures.

come-nc avatar Feb 20 '24 15:02 come-nc

Can you double-check the encoding on your database, @elr3m?

I can't unserialize your provided entree. Make sure it's not something like latin1_swedish_ci.

@joshtrichards It is currently utf8mb4_general_ci

I’d be surprised if PHP produced a serialization it’s not able to unserialize. Maybe an encoding thing indeed.

You can simply delete the line, the background job should recreate the info in the new table.

@come-nc , I will do that today (PT) and report back here.

Thank you both.

elr3m avatar Feb 20 '24 17:02 elr3m

FYI: we're regularly seeing errors originating from failed de-serialization, like the following, since at least NC 25:

"message":"Error while running background job (class: OCA\\User_LDAP\\Jobs\\UpdateGroups, arguments: )","userAgent":"--","version":"27.1.6.2","exception":{"Exception":"TypeError","Message":"array_diff(): Argument #1 ($array) must be of type array, bool given",

Our updates failed with the same errors. Emptying the oc_ldap_group_members table made the update work.

colpari avatar Feb 20 '24 17:02 colpari

Indeed, deleting the line seems to resolve the issue, as I was able to enable the user_ldap app and I have checked with a couple of users and their authentication and access to Staging was as expected.

I went and checked on the oc_ldap_group_members and it is still empty, not sure if normal or if I should wait longer. Cron job /var/www/html/nextcloud/cron.php is set to run every 5 minutes, so it might be triggered by another background job?

The solution being found, I am not sure what to do with this GitHub issue (change status, close...). Let me know what should I do with it, if anything.

elr3m avatar Feb 20 '24 20:02 elr3m

Indeed, deleting the line seems to resolve the issue, as I was able to enable the user_ldap app and I have checked with a couple of users and their authentication and access to Staging was as expected.

I went and checked on the oc_ldap_group_members and it is still empty, not sure if normal or if I should wait longer. Cron job /var/www/html/nextcloud/cron.php is set to run every 5 minutes, so it might be triggered by another background job?

The solution being found, I am not sure what to do with this GitHub issue (change status, close...). Let me know what should I do with it, if anything.

oc_ldap_group_members should not exist anymore after upgrading to 28, the new table used is oc_ldap_group_membership.

Leave this issue open, I will close after merging a PR for ignoring unserialize failure.

come-nc avatar Feb 22 '24 08:02 come-nc