Upgrade OJS 3.1.1-2 to 3.1.2-1 failing on migrateUserAndAuthorNames

sarontt · September 26, 2019, 6:25pm

My upgrade of OJS 3.1.1-2 to 3.1.2-1 is failing on the section migrateUserAndAuthorNames. There are a variety of errors that I have seen. But unlike other posts in this forum (Upgrade database from 3.1.1.4 to stable-3.1.2, Problem updating OJS 2.4.5.0 to 3.1.2) it seems my data problem is more expansive. It seems the error isn’t pointing at an pkey violation in the middle of user_ids-- it is starting with the user_id = 1 or author_id = 1 and when I hack the database to delete the row in user_settings related to user_id = 1 and run the upgrade script-- it then complains about the next user_id = 2. The really bad hack that I have done is after I ran into the upgrade error – I truncated two tables authors_tmp and users_tmp and then re-ran the upgrade script and it completes the upgrade.

Some example logs referenced in description above:

[code: Installer Installer::migrateUserAndAuthorNames]
<h1>DB Error: Duplicate entry '11477-es_ES-preferredPublicName' for key 'author_settings_pkey'</h1>ojs2: DB Error: Duplicate entry '11477-es_ES-preferredPublicName' for key 'author_settings_pkey'

The above is similar to the posts which was resolved by auditing data results from this:

select author_id, count(author_id) from author_settings where setting_name = 'preferredPublicName' group by author_id having count(author_id) > 1;

we had one case of this.

After reading Problem updating OJS 2.4.5.0 to 3.1.2 which talked about orc ids being duplicated possibly I found one instance of this.

select setting_value, count(setting_value) from user_settings where setting_name='orcid' group by setting_value having count(*) > 1;

and so I deleted a row or two in the user_settings based off of the setting_value ord ids.

But none of the above seemed to fully resolve my data problems.

The error I get is:

[code: Installer Installer::migrateUserAndAuthorNames]
<h1>DB Error: Duplicate entry '1-en_US-givenName-0-0' for key 'user_settings_pkey'</h1>ojs2: DB Error: Duplicate entry '1-en_US-givenName-0-0' for key 'user_settings_pkey'

made me think hey maybe it’s a similar problem but it doesn’t seem to be:

mysql> select user_id, count(user_id) from user_settings where setting_name = 'givenName' group by user_id having count(user_id) > 1;
Empty set (0.02 sec)

So I try this hack:

delete from user_settings where setting_name = 'giveName' and user_id = 1;

and then I re-run the upgrade and then it complains about the next one:

[code: Installer Installer::migrateUserAndAuthorNames]
<h1>DB Error: Duplicate entry '2-en_US-givenName-0-0' for key 'user_settings_pkey'</h1>ojs2: DB Error: Duplicate entry '2-en_US-givenName-0-0' for key 'user_settings_pkey'

I hack on the database more deleting thousands of rows from user_settings where setting_name = ‘givenName’ and then the upgrade starts to complain about ‘familyName’ instead. I hack some more-- then start seeing similar problems but this time it’s the author_settings

[code: Installer Installer::migrateUserAndAuthorNames]
<h1>DB Error: Duplicate entry '1-en_US-givenName' for key 'author_settings_pkey'</h1>ojs2: DB Error: Duplicate entry '1-en_US-givenName' for key 'author_settings_pkey'

I then end up truncated the authors_tmp and users_tmp after a failed upgrade and then the upgrade runs successfully.

Thanks.
Saron

asmecher · September 26, 2019, 7:13pm

Hi @sarontt,

Do you have content in authors_tmp and users_tmp before you run the upgrade? I think that could only happen if you failed an upgrade and left those tables lying around afterward. If you fail an upgrade, make sure you restore your database to its state from before the upgrade was attempted – that database shouldn’t include those temporary tables. (Maybe you ran your database dump through mysql after failing an upgrade, but didn’t drop and recreate the database first?)

Regards,
Alec Smecher
Public Knowledge Project Team

sarontt · September 26, 2019, 7:26pm

There are no authors_tmp and users_tmp tables in my database before I run the upgrade. I haven’t dug too deep in to the upgrade scripts but it seemed like as part of the upgrade scripts-- it populated those tables? ← was going to be more of last resorts as my debugging of code isn’t very good. I have attached a debugger to my local dev environment before and will try to debug that way again but thought I’d ask around before I try that.

I usually follow that recommendation to start from a database state in which no upgrade was attempted yet (other than massaging of the data based off of previously seen attempts). The upgrade scripts do seem somewhat idempotent though typically?

asmecher · September 26, 2019, 11:06pm

Hi @sarontt,

The upgrade is not fully idempotent, so it’s always best to DROP DATABASE, CREATE DATABASE, and then reload a backup before trying again after a failed upgrade. Just make sure that you do DROP and CREATE – reloading a backup over top is not the same thing!

The upgrade process should take care of creating, using, then deleting the authors_tmp and users_tmp tables during the upgrade from 3.1.1 to 3.1.2.

Regards,
Alec Smecher
Public Knowledge Project Team

sarontt · September 27, 2019, 12:07am

Sorry my rant was kind of all over the place.

This is on my test environment (which is on 3.1.2-1): I drop the database. Then I import it from a backup from production (which is version 3.1.1-2). I run the upgrade and the upgrade fails on migrateUserAndAuthorNames with the following problem:

[code: Installer Installer::migrateUserAndAuthorNames]
<h1>DB Error: Duplicate entry '1-en_US-givenName-0-0' for key 'user_settings_pkey'</h1>ojs2: DB Error: Duplicate entry '1-en_US-givenName-0-0' for key 'user_settings_pkey'

asmecher · September 27, 2019, 12:53pm

Hi @sarontt,

Can you check in your OJS 3.1.1-2 (pre-upgrade) backup whether there are any rows matching the following query?

SELECT COUNT(*) FROM user_settings WHERE setting_name = 'givenName';

Regards,
Alec Smecher
Public Knowledge Project Team

sarontt · September 27, 2019, 2:16pm

0 count in production (3.1.1-2).

asmecher · September 27, 2019, 2:43pm

Hi @sarontt,

Hmm; do you by any chance have more than one entry in the site table?

Regards,
Alec Smecher
Public Knowledge Project Team

sarontt · September 27, 2019, 2:43pm

site table has 1 row returned.

asmecher · September 27, 2019, 2:47pm

Hi @sarontt,

Hmm, it’s hard to know what’s happening remotely. The query that appears to be choking is this, from Upgrade.inc.php in the migrateUserAndAuthorNames function:

INSERT INTO user_settings (user_id, locale, setting_name, setting_value, setting_type) SELECT DISTINCT u.user_id, s.primary_locale, 'givenName', u.first_name, 'string' FROM users_tmp u, site s;

However, the checks you’ve made on your production database don’t suggest that this would be a problem. I’d suggest making extra-sure that you’re running your upgrade on a clean reload, and that config.inc.php points to it correctly – it almost seems like you’re running checks/dumps/reloads on one database, while the upgrade script is running on another. (I only ask because this has happened to me before.)

Regards,
Alec Smecher
Public Knowledge Project Team

sarontt · September 27, 2019, 2:54pm

Yeah sorry, I am dropping my database and then I am importing the production database copy on my test environment to verify the same things you asked this morning but it takes about an hour to import into my docker test environment. Hopefully I haven’t been doing this the wrong way for several attempts haha. But yeah I think I have been starting from a fresh copy of production database (3.1.1-2) on my test environment (3.1.2-1) and then running the upgrade. It was just when it went awry that I would just try to run it again after some data massaging – just to see if I could get the upgrade script to finish (which I understand is not the right way and that it should be from fresh copy)

Yeah I was trying to read that part of the function to understand it and also looking at the sql backup file to see how it would work.

on test:

[sarontt@~]$ sudo su -
[root@~]# docker exec -it mysql bash
root@5a40a33d9d3c:/# mysql -h mysql -p
Enter password: 
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 479
Server version: 5.7.22 MySQL Community Server (GPL)

Copyright (c) 2000, 2018, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> drop database ojs;
Query OK, 147 rows affected (1.86 sec)

mysql> ^DBye
root@5a40a33d9d3c:/# exit
[root@~]# docker run -it --network ojs-docker_default -v /home/sarontt/20190910-0700.sql.gz/20190910-0700.sql.gz:/20190910-0700.sql.gz mysql bash
root@511c8c8845cb:/# zcat 20190910-0700.sql.gz | mysql -h mysql -p
Enter password: 
root@511c8c8845cb:/# exit
[root@libtstojsap02 ~]# docker exec -it mysql bash
root@5a40a33d9d3c:/# msyql -h mysql -p
bash: msyql: command not found
root@5a40a33d9d3c:/# mysql -h mysql -p
Enter password: 
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 481
Server version: 5.7.22 MySQL Community Server (GPL)

Copyright (c) 2000, 2018, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> use ojs;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> SELECT COUNT(*) FROM user_settings WHERE setting_name = 'givenName';
+----------+
| COUNT(*) |
+----------+
|        0 |
+----------+
1 row in set (0.01 sec)

mysql> select * from site;
+---------------------+----------------+-------------------------------------------+-------------------------------------------+--------------------------+----------+
| min_password_length | primary_locale | installed_locales                         | supported_locales                         | original_style_file_name | redirect |
+---------------------+----------------+-------------------------------------------+-------------------------------------------+--------------------------+----------+
|                   6 | en_US          | en_US:es_ES:pt_BR:fr_FR:de_DE:nb_NO:ru_RU | en_US:es_ES:pt_BR:fr_FR:de_DE:nb_NO:ru_RU | ojs-ku-site.css          |        0 |
+---------------------+----------------+-------------------------------------------+-------------------------------------------+--------------------------+----------+
1 row in set (0.00 sec)

mysql>

And here is output from the upgrade on the app’s container this morning:

[root@]# docker exec -it ojs bash
root@7053b7dc8fcb:/app# php tools/upgrade.php upgrade
[pre-install]
[load: upgrade.xml]
[version: 3.1.2.1]
[code: Installer Installer::checkPhpVersion]
[data: dbscripts/xml/upgrade/3.1.2_preupdate_user_author_names.xml]
[schema: lib/pkp/xml/schema/common.xml]
[schema: lib/pkp/xml/schema/log.xml]
[schema: lib/pkp/xml/schema/announcements.xml]
[schema: lib/pkp/xml/schema/scheduledTasks.xml]
[schema: lib/pkp/xml/schema/temporaryFiles.xml]
[schema: lib/pkp/xml/schema/metadata.xml]
[schema: lib/pkp/xml/schema/reviews.xml]
[schema: lib/pkp/xml/schema/reviewForms.xml]
[schema: lib/pkp/xml/schema/controlledVocab.xml]
[schema: lib/pkp/xml/schema/submissions.xml]
[schema: lib/pkp/xml/schema/submissionFiles.xml]
[schema: lib/pkp/xml/schema/categories.xml]
[schema: lib/pkp/xml/schema/notes.xml]
[schema: lib/pkp/xml/schema/genres.xml]
[schema: lib/pkp/xml/schema/tombstone.xml]
[schema: lib/pkp/xml/schema/rolesAndUserGroups.xml]
[schema: lib/pkp/xml/schema/metrics.xml]
[schema: lib/pkp/xml/schema/views.xml]
[schema: lib/pkp/xml/schema/libraryFiles.xml]
[schema: lib/pkp/xml/schema/navigationMenus.xml]
[schema: dbscripts/xml/ojs_schema.xml]
[data: dbscripts/xml/indexes.xml]
[code: Installer Installer::installDefaultNavigationMenus]
WARNING: The NavigationMenu (ContextId: 41, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 41, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 40, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 40, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 39, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 39, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 38, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 38, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 37, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 37, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 36, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 36, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 33, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 33, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 26, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 26, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 34, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 34, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 28, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 28, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 32, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 32, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 27, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 27, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 25, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 25, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 24, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 24, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 23, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 23, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 9, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 9, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 6, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 6, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 20, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 20, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 18, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 18, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 13, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 13, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 16, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 16, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 19, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 19, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 8, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 8, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 17, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 17, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 14, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 14, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 11, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 11, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 31, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 31, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 35, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 35, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 29, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 29, Title: Primary Navigation Menu, Area: primary) will be skipped because the specified area has already a NavigationMenu attached.
WARNING: The NavigationMenu (ContextId: 0, Title: User Navigation Menu, Area: user) will be skipped because the specified area has already a NavigationMenu attached.
[code: Installer Installer::migrateStaticPagesToNavigationMenuItems]
[code: Installer Installer::migrateSRLocale]
[code: Installer Installer::migrateUserAndAuthorNames]
<h1>DB Error: Duplicate entry '11477-es_ES-preferredPublicName' for key 'author_settings_pkey'</h1>ojs2: DB Error: Duplicate entry '11477-es_ES-preferredPublicName' for key 'author_settings_pkey'
root@7053b7dc8fcb:/app#

mreedks · October 18, 2019, 8:10pm

Is there any additional information that you need to help troubleshoot this issue, Alec? Just let us know and we’ll get it for you. We could do a session where we share screens with you, if that would help.

asmecher · October 18, 2019, 8:29pm

Hi @mreedks,

I still think the likeliest cause is that your 3.1.1-2 database backup has some remnants of a failed upgrade to 3.1.2 already in it. What do you get in your 3.1.1-2 database for the following query?

SELECT COUNT(*) FROM author_settings WHERE setting_name='preferredPublicName';

Regards,
Alec Smecher
Public Knowledge Project Team

sarontt · October 19, 2019, 4:07pm

I don’t think that is the cause as I have been trying to explain that I am starting from a 3.1.1-2 database backup that has not been run through an upgrade once. (see comment on 2019.09.27@9:54AM where I drop the database then import it from a production backup (I then checked the queries you suggested before I run the upgrade script and they return no rows-- other than the site table) and then run the upgrade script).

There are no rows from that query.

asmecher · October 19, 2019, 5:33pm

Hi @sarontt,

Let’s try another tack. Can you identify the supported locales for the problem author? Like so:

SELECT js.setting_value FROM journal_settings js JOIN submissions s ON (s.context_id = js.journal_id) JOIN authors a ON (s.submission_id = a.submission_id) WHERE setting_name='supportedLocales' AND a.author_id = 11477;

I’m grasping at straws here, but perhaps the same locale is somehow listed twice?

Regards,
Alec Smecher
Public Knowledge Project Team

sarontt · October 19, 2019, 5:59pm

appreciate the help

mysql> SELECT js.setting_value FROM journal_settings js JOIN submissions s ON (s.context_id = js.journal_id) JOIN authors a ON (s.submission_id = a.submission_id) WHERE setting_name='supportedLocales' AND a.author_id = 11477;
+------------------------------------------------------------------------+
| setting_value                                                          |
+------------------------------------------------------------------------+
| a:4:{i:0;s:5:"en_US";i:1;s:5:"es_ES";i:2;s:5:"es_ES";i:3;s:5:"pt_BR";} |
+------------------------------------------------------------------------+
1 row in set (0.00 sec)

One row was expected? Or the duplicate of es_ES in that column is causing problems?

asmecher · October 20, 2019, 3:54pm

Hi @sarontt,

Yep, the duplicate Spanish is the problem. You might be able to fix it by visiting your OJS 2.x Languages form, double-checking the settings and saving. But I’m not sure what would have caused this – have there been any relevant modifications or interventions?

Regards,
Alec Smecher
Public Knowledge Project Team

sarontt · November 5, 2019, 5:20pm

Thank you very much. I have ran the upgrade on my local a few times and then repeated on test a couple times.