Wow - OK, but I think the hardest part is done with that. Are you planning on running further upgrades now that you’re on 5.37.10?
Right?
Well we received output like this, not one hour ago. Also the db is no longer writing or doing anything at all. So I suspect the migration took even long than my last message:-
{"level":"info","ts":1681795337.2992396,"caller":"product_notices/worker.go:85","msg":"Worker: Job is complete","worker":"ProductNotices","job_id":"o7rgn9finjnaifkuheea76m4pr"}
We are planning on migrating to the very latest stable release.
Also…when attempting to start the service, for the first time, we are seeing these in journal:-
Apr 18 10:36:02 mm-clone multipathd[679]: sda: add missing path
Apr 18 10:36:02 mm-clone multipathd[679]: sda: failed to get udev uid: Invalid argument
Apr 18 10:36:02 mm-clone multipathd[679]: sda: failed to get sysfs uid: Invalid argument
Apr 18 10:36:02 mm-clone multipathd[679]: sda: failed to get sgio uid: No such file or directory
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"info","ts":1681814162.4018137,"caller":"app/server.go:269","msg":"Server is initializing...","go_version":"go1.16.7"}
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"info","ts":1681814162.4027097,"caller":"app/web_hub.go:93","msg":"Starting websocket hubs","number_of_hubs":8}
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"info","ts":1681814162.4035423,"caller":"i18n/i18n.go:93","msg":"Loaded system translations","for locale":"en","from locale":"/opt/ma>
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"info","ts":1681814162.4092457,"caller":"sqlstore/store.go:306","msg":"Pinging SQL","database":"master"}
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"info","ts":1681814162.4109106,"caller":"sqlstore/store.go:306","msg":"Pinging SQL","database":"migrations"}
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"warn","ts":1681814162.7015274,"caller":"sqlstore/store.go:1164","msg":"Could not create foreign key: Error 1826: Duplicate foreign k>
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"warn","ts":1681814162.702515,"caller":"sqlstore/store.go:1164","msg":"Could not create foreign key: Error 1826: Duplicate foreign ke>
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"info","ts":1681814162.8145804,"caller":"app/server.go:569","msg":"Current version is 5.37.10 (5.37.10/Wed Aug 31 08:32:32 UTC 2022/b>
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"info","ts":1681814162.8146672,"caller":"app/server.go:580","msg":"Team Edition Build","enterprise_build":false}
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"info","ts":1681814162.8146954,"caller":"app/server.go:584","msg":"Printing current working","directory":"/opt/mattermost"}
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"info","ts":1681814162.8147147,"caller":"app/server.go:585","msg":"Loaded config","source":"file:///opt/mattermost/config/config.json>
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"info","ts":1681814162.8296704,"caller":"jobs/workers.go:135","msg":"Starting workers"}
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"info","ts":1681814162.8318439,"caller":"jobs/schedulers.go:116","msg":"Starting schedulers."}
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"info","ts":1681814162.8401504,"caller":"app/license.go:88","msg":"License key from https://mattermost.com required to unlock enterpr>
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"info","ts":1681814162.8752697,"caller":"mlog/log.go:237","msg":"Starting up plugins"}
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"info","ts":1681814162.875358,"caller":"app/plugin.go:258","msg":"Syncing plugins from the file store"}
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"info","ts":1681814162.8928258,"caller":"app/plugin.go:318","msg":"Syncing plugin from file store","bundle":"plugins/com.mattermost.p>
Apr 18 10:36:02 mm-clone mattermost[95748]: {"level":"info","ts":1681814162.8931413,"caller":"app/plugin.go:318","msg":"Syncing plugin from file store","bundle":"plugins/com.github.matte>
Apr 18 10:36:03 mm-clone mattermost[95748]: {"level":"error","ts":1681814163.6105666,"caller":"app/plugin.go:320","msg":"Failed to sync plugin from file store","bundle":"plugins/com.matt>
lines 1283-1372/1372 (END)
The perms are all mattermost:mattermost
This message is not related to the migration, these are continuous worker jobs that do things inside the application server, so not related.
This message is problematic, because it means that there are some duplicate keys in your database, actually it is trying to create a foreign key but one is already there. The error message is truncated unfortunately, can you post the full message for all these SQL errors?
I also need to see the full message for this line, please.
Apologies, under the advice from our senior programmers, we have remade the test VM and are gonna run the DB commands separately to see what results this yields.
The query is running…here is the output of SHOW ENGINE INNODB STATUS;
| InnoDB | |
=====================================
2023-04-19 09:31:54 140288538412800 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 44 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1805 srv_active, 0 srv_shutdown, 7059 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 1044004
--Thread 140288535246592 has waited at buf0buf.cc line 5818 for 0 seconds the semaphore:
Mutex at 0x7f977c310880, Mutex BUF_POOL_LRU_LIST created buf0buf.cc:1230, locked by nobody
OS WAIT ARRAY INFO: signal count 524267
RW-shared spins 0, rounds 0, OS waits 0
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 133089316
Purge done for trx's n:o < 133086605 undo n:o < 0 state: running but idle
History list length 904
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421763667862312, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421763667859888, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421763667859080, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 133089315, ACTIVE 1 sec doing SYNC index
1 lock struct(s), heap size 1128, 0 row lock(s), undo log entries 1191
---TRANSACTION 133086529, ACTIVE 2622 sec inserting
mysql tables in use 2, locked 2
33463 lock struct(s), heap size 3547256, 1317758 row lock(s), undo log entries 264
MySQL thread id 113, OS thread handle 140288535246592, query id 882 localhost root copy to tmp table
ALTER TABLE Posts ADD RemoteId VARCHAR(26)
Trx read view will not see trx with id >= 133086595, sees < 133086595
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
ibuf aio reads:, log i/o's:
Pending flushes (fsync) log: 0; buffer pool: 27
1869177 OS file reads, 4240229 OS file writes, 2091947 OS fsyncs
653.28 reads/s, 16384 avg bytes/read, 1477.32 writes/s, 788.29 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1782, free list len 1312, seg size 3095, 303211 merges
merged operations:
insert 4204589, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 4 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
1362.06 hash searches/s, 4864.03 non-hash searches/s
---
LOG
---
Log sequence number 76634158485
Log buffer assigned up to 76634158485
Log buffer completed up to 76634158485
Log written up to 76634158485
Log flushed up to 76634158485
Added dirty pages up to 76634158485
Pages flushed up to 76606672823
Last checkpoint at 76602618838
Log minimum file id is 6721
Log maximum file id is 6740
1461247 log i/o's done, 421.75 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 0
Dictionary memory allocated 1352209
Buffer pool size 8192
Free buffers 4
Database pages 7961
Old database pages 2937
Modified db pages 7288
Pending reads 0
Pending writes: LRU 6, flush list 0, single page 1
Pages made young 999427, not young 3335576
38.21 youngs/s, 901.47 non-youngs/s
Pages read 1869172, created 98544, written 2065777
653.32 reads/s, 20.12 creates/s, 775.67 writes/s
Buffer pool hit rate 975 / 1000, young-making rate 1 / 1000 not 35 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 7961, unzip_LRU len: 0
I/O sum[65027]:cur[1027], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Process ID=910, Main thread ID=140288110614272 , state=sleeping
Number of rows inserted 1284321, updated 0, deleted 0, read 1459675
294.86 inserts/s, 0.00 updates/s, 0.00 deletes/s, 294.86 reads/s
Number of system rows inserted 208, updated 332, deleted 8, read 8528
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
I believe, as well, that nothing was being pushed to /tmp due to the size of the temp table not being bigger than tmp_table_size or max_heap_table_size
Here are the results of running the query in mysql:-
mysql> USE mattermost
Database changed
mysql> ALTER TABLE Posts ADD RemoteId VARCHAR(26);
Query OK, 8731735 rows affected (15 hours 21 min 27.45 sec)
Records: 8731735 Duplicates: 0 Warnings: 0
And here’s the error, again, in full:-
"sqlstore/store.go:1164","msg":"Could not create foreign key: Error 1826: Duplicate foreign key constraint name 'FK_RetentionPoliciesChannels_RetentionPolicies'"}
This can be closed. We spotted (in a gist) that this output can be ignored. Sure enough, the DB and app started up, fully upgraded.
The MM server is a VM (4 vCPUs, 8GB Memory, 2TB storage)