[MDEV-15237] "Can't write; duplicate key in table" when updating some rows in a transaction - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Cannot Reproduce
Affects Version/s: 10.2.12, 10.3.4, 10.1.34, 10.2.14, 10.3.6, 10.3.7, 10.1.42
Fix Version/s: N/A
Component/s: Full-text Search, Storage Engine - InnoDB
Labels:
None
Environment:
Ubuntu Xenial

Description

CREATE TABLE `user` (

 `id` int(11) unsigned NOT NULL,

 `revision_date` int(14) NOT NULL,

 `revision_author` int(11) unsigned NOT NULL,

 `creation_date` int(14) NOT NULL,

 `creation_author` int(11) unsigned NOT NULL,

 `deleted` tinyint(1) NOT NULL,

 `user` varchar(250) NOT NULL,

 `password` varchar(255) NOT NULL,

 `name` varchar(250) NOT NULL,

 `surname` varchar(250) NOT NULL,

 `lastlogin` int(14) NOT NULL,

 `lastip` varchar(32) NOT NULL,

 `email` varchar(60) NOT NULL,

 PRIMARY KEY (`id`),

 KEY `id` (`id`,`deleted`),

 KEY `deleted` (`deleted`),

 FULLTEXT KEY `user` (`user`,`name`,`surname`)

) ENGINE=InnoDB DEFAULT CHARSET=utf8 TRANSACTIONAL=0

UPDATE user SET id = 275, revision_date = 1517476994, revision_author = 1, creation_date = 1475149574, creation_author = 1, user = "8502", name = "SOFIA", surname = "ORTONA - TEDESCO", email = "" WHERE id = 275

Can't write; duplicate key in table 'user'

I have an issue on InnoDB with both MariaDB versions 10.3.4 and 10.2.12
This problem is very difficult for me to reproduce since it doesn't always happen. As you can see, that error can't be true because the ID 275 is already set for that row, so I don't know why it is failing. Also, this is a pretty busy server, and this error pops up randomly on INSERTs and UPDATEs of various tables, but only 2-3 times a day (there are about 10.000 writes every day)

I don't even know how to debug it properly since that particular error message is associated with the creation of foreign keys. The table is referenced on other tables, but the error should occur on creation of them, not by writing rows.

The query is run inside a transaction. Please let me know if you need anything else to help diagnose the issue.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

custom.cnf
2 kB
2018-06-05 20:43
MDEV-15237.patch
1 kB
2018-06-21 11:58

Issue Links

relates to

MDEV-12676 InnoDB FTS duplicate key error

Closed

MDEV-14141 mysqld got exception 0xc0000005

Closed

MDEV-14970 MariaDB crashed with signal 11 and Aria table

Closed

MDEV-15304 Server crash in print_keydup_error / key_unpack or unexpected ER_DUP_KEY

Closed

MDEV-18868 FTS Breaking Replication

Closed

MDEV-24608 Failing assertion: error == DB_SUCCESS || error == DB_DUPLICATE_KEY OR Assertion `error == DB_DUPLICATE_KEY || error == DB_LOCK_WAIT_TIMEOUT' failed IN trx_t::commit_low

Open

MDEV-25581 MS FTS Bug 103523 also applicable to MariaDB Server (Was: Test MS Bug 103523 against MD010521-bb-10.5-thiru)

Closed

MDEV-29335 Crash after Duplicate Key error

Closed

(3 relates to)

Activity

Ascending order - Click to sort in descending order

View 35 older comments

Marko Mäkelä added a comment - 2022-08-22 08:54

It seems that ~~MDEV-25581~~ would convert the error message to a server crash, as reported in ~~MDEV-29335~~.

johnkiller or jrioux or anyone who can reproduce this error, we would greatly appreciate something that would allow us to reproduce and fix this bug.

Marko Mäkelä added a comment - 2022-08-22 08:54 It seems that MDEV-25581 would convert the error message to a server crash, as reported in MDEV-29335 . johnkiller or jrioux or anyone who can reproduce this error, we would greatly appreciate something that would allow us to reproduce and fix this bug.

Jérémie Rioux added a comment - 2022-08-29 13:32

We unfortunately had to move to another engine because of this issue. I cannot reproduce it anymore.

Jérémie Rioux added a comment - 2022-08-29 13:32 We unfortunately had to move to another engine because of this issue. I cannot reproduce it anymore.

Marko Mäkelä added a comment - 2022-08-29 14:41

There now is a test case in ~~MDEV-29342~~.

Marko Mäkelä added a comment - 2022-08-29 14:41 There now is a test case in MDEV-29342 .

Marko Mäkelä added a comment - 2022-09-14 12:33 - edited

It is possible that this bug was fixed in ~~MDEV-29342~~. Given that this bug has been open so long, with relatively few votes and watchers, I think that we must wait several months for any feedback.

An unscheduled release of MariaDB Server 10.6.10, 10.7.6, 10.8.5, 10.9.3 is expected to be available soon. For older major versions, releases including the fix of ~~MDEV-29342~~ should become available in the next scheduled quarterly release (October or November 2022).

Marko Mäkelä added a comment - 2022-09-14 12:33 - edited It is possible that this bug was fixed in MDEV-29342 . Given that this bug has been open so long, with relatively few votes and watchers, I think that we must wait several months for any feedback. An unscheduled release of MariaDB Server 10.6.10, 10.7.6, 10.8.5, 10.9.3 is expected to be available soon. For older major versions, releases including the fix of MDEV-29342 should become available in the next scheduled quarterly release (October or November 2022).

Khai Ping added a comment - 2024-07-19 01:27 - edited

i am still seeing this error in 10.6.12 in a 3 node galera cluster. When duplicate key happens, the galera cluster will slow down and eventually unable to serve.

240716 14:05:11 mysqld_safe mysqld from pid file /var/lib/mysql/mysql.pid ended

240716 14:05:37 mysqld_safe Starting mariadbd daemon with databases from /var/lib/mysql

240716 14:05:37 mysqld_safe WSREP: Running position recovery with --disable-log-error  --pid-file='/var/lib/mysql/server-h3-recover.pid'

240716 14:05:39 mysqld_safe WSREP: Recovered position 67210f6b-52bc-11ed-8997-d697d3148f87:88711849

2024-07-16 14:05:39 0 [Note] Starting MariaDB 10.6.12-MariaDB source revision 4c79e15cc3716f69c044d4287ad2160da8101cdc as process 28412

2024-07-16 14:05:39 0 [Note] WSREP: Loading provider /usr/lib64/galera/libgalera_smm.so initial position: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849

2024-07-16 14:05:39 0 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib64/galera/libgalera_smm.so'

2024-07-16 14:05:39 0 [Note] WSREP: wsrep_load(): Galera 26.4.14(rf27da2a) by Codership Oy <info@codership.com> loaded successfully.

2024-07-16 14:05:39 0 [Note] WSREP: CRC-32C: using 64-bit x86 acceleration.

2024-07-16 14:05:39 0 [Warning] WSREP: SSL compression is not effective. The option socket.ssl_compression is deprecated and will be removed in future releases.

2024-07-16 14:05:39 0 [Note] WSREP: Found saved state: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849, safe_to_bootstrap: 0

2024-07-16 14:05:39 0 [Note] WSREP: GCache DEBUG: opened preamble:

Version: 2

UUID: 67210f6b-52bc-11ed-8997-d697d3148f87

Seqno: 87943436 - 88711849

Offset: 1749575000

Synced: 1

2024-07-16 14:05:39 0 [Note] WSREP: Recovering GCache ring buffer: version: 2, UUID: 67210f6b-52bc-11ed-8997-d697d3148f87, offset: 1749575000

2024-07-16 14:05:39 0 [Note] WSREP: GCache::RingBuffer initial scan...  0.0% (         0/2147483672 bytes) complete.

2024-07-16 14:05:42 0 [Note] WSREP: GCache::RingBuffer initial scan...100.0% (2147483672/2147483672 bytes) complete.

2024-07-16 14:05:42 0 [Note] WSREP: Recovering GCache ring buffer: found gapless sequence 87943436-88711849

2024-07-16 14:05:42 0 [Note] WSREP: GCache::RingBuffer unused buffers scan...  0.0% (         0/2147055560 bytes) complete.

2024-07-16 14:05:42 0 [Note] WSREP: Recovering GCache ring buffer: found 1/768415 locked buffers

2024-07-16 14:05:42 0 [Note] WSREP: Recovering GCache ring buffer: free space: 428280/2147483648

2024-07-16 14:05:42 0 [Note] WSREP: GCache::RingBuffer unused buffers scan...100.0% (2147055560/2147055560 bytes) complete.

2024-07-16 14:05:42 0 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql/; base_host = tdmint-h3; base_port = 4567; cert.log_conflicts = no; cert.optimistic_pa = yes; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT10S; evs.inactive_timeout = PT60S; evs.install_timeout = PT60S; evs.join_retrans_period = PT1S; evs.keepalive_period = PT3S; evs.max_install_timeouts = 3; evs.send_window = 512; evs.stats_report_period = PT1M; evs.suspect_timeout = PT30S; evs.user_send_window = 512; evs.view_forget_timeout = PT24H; gcache.dir = /var/lib/mysql/; gcache.keep_pages_size = 0; gcache.keep_plaintext_size = 1G; gcache.mem_size = 0; gcache.name = galera.cache; gcache.page_size = 1G; gcache.recover = yes; gcache.size = 2G; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 16; gcs.fc_master_slave = no; gcs.fc_single_primary = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_l

2024-07-16 14:05:42 0 [Note] WSREP: Service thread queue flushed.

2024-07-16 14:05:42 0 [Note] WSREP: ####### Assign initial position for certification: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849, protocol version: -1

2024-07-16 14:05:42 0 [Note] WSREP: Start replication

2024-07-16 14:05:42 0 [Note] WSREP: Connecting with bootstrap option: 0

2024-07-16 14:05:42 0 [Note] WSREP: Setting GCS initial position to 67210f6b-52bc-11ed-8997-d697d3148f87:88711849

2024-07-16 14:05:42 0 [Note] WSREP: Using CRC-32 (backward-compatible) for message checksums.

2024-07-16 14:05:42 0 [Note] WSREP: backend: asio

2024-07-16 14:05:42 0 [Note] WSREP: gcomm thread scheduling priority set to other:0

2024-07-16 14:05:42 0 [Note] WSREP: access file(/var/lib/mysql//gvwstate.dat) failed(No such file or directory)

2024-07-16 14:05:42 0 [Note] WSREP: restore pc from disk failed

2024-07-16 14:05:42 0 [Note] WSREP: GMCast version 0

2024-07-16 14:05:42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567') listening at ssl://0.0.0.0:4567

2024-07-16 14:05:42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567') multicast: , ttl: 1

2024-07-16 14:05:42 0 [Note] WSREP: EVS version 1

2024-07-16 14:05:42 0 [Note] WSREP: gcomm: connecting to group 'accdbcluster', peer '57.3.12.100:,57.3.12.101:,57.3.12.107:'

2024-07-16 14:05:42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567') Found matching local endpoint for a connection, blacklisting address ssl://57.3.12.107:4567

2024-07-16 14:05:42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567') connection established to 29aeda1c-8bc1 ssl://57.3.12.101:4567

2024-07-16 14:05:42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567') turning message relay requesting on, nonlive peers:

2024-07-16 14:05:42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567') connection established to 49695eda-b162 ssl://57.3.12.100:4567

2024-07-16 14:05:43 0 [Note] WSREP: EVS version upgrade 0 -> 1

2024-07-16 14:05:43 0 [Note] WSREP: declaring 29aeda1c-8bc1 at ssl://57.3.12.101:4567 stable

2024-07-16 14:05:43 0 [Note] WSREP: declaring 49695eda-b162 at ssl://57.3.12.100:4567 stable

2024-07-16 14:05:43 0 [Note] WSREP: PC protocol upgrade 0 -> 1

2024-07-16 14:05:43 0 [Note] WSREP: Node 29aeda1c-8bc1 state prim

2024-07-16 14:05:43 0 [Note] WSREP: view(view_id(PRIM,29aeda1c-8bc1,14) memb {

	29aeda1c-8bc1,4

	49695eda-b162,3

	7d3f1c69-bd93,7

} joined {

} left {

} partitioned {

})

2024-07-16 14:05:43 0 [Note] WSREP: save pc into disk

2024-07-16 14:05:43 0 [Note] WSREP: gcomm: connected

2024-07-16 14:05:43 0 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636

2024-07-16 14:05:43 0 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)

2024-07-16 14:05:43 0 [Note] WSREP: Opened channel 'accdbcluster'

2024-07-16 14:05:43 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 2, memb_num = 3

2024-07-16 14:05:43 0 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.

2024-07-16 14:05:43 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 7d8e3f95-437c-11ef-a8ec-bb1b8da382a8

2024-07-16 14:05:43 0 [Note] WSREP: STATE EXCHANGE: got state msg: 7d8e3f95-437c-11ef-a8ec-bb1b8da382a8 from 0 (tdmint-h2)

2024-07-16 14:05:43 0 [Note] WSREP: STATE EXCHANGE: got state msg: 7d8e3f95-437c-11ef-a8ec-bb1b8da382a8 from 1 (tdmint-h1)

2024-07-16 14:05:43 1 [Note] WSREP: Starting rollbacker thread 1

2024-07-16 14:05:43 2 [Note] WSREP: Starting applier thread 2

2024-07-16 14:05:43 0 [Note] WSREP: STATE EXCHANGE: got state msg: 7d8e3f95-437c-11ef-a8ec-bb1b8da382a8 from 2 (tdmint-h3)

2024-07-16 14:05:43 0 [Note] WSREP: Quorum results:

	version    = 6,

	component  = PRIMARY,

	conf_id    = 11,

	members    = 2/3 (joined/total),

	act_id     = 88711850,

	last_appl. = 88711807,

	protocols  = 2/10/4 (gcs/repl/appl),

	vote policy= 0,

	group UUID = 67210f6b-52bc-11ed-8997-d697d3148f87

2024-07-16 14:05:43 0 [Note] WSREP: Flow-control interval: [28, 28]

2024-07-16 14:05:43 0 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 88711851)

2024-07-16 14:05:43 2 [Note] WSREP: ####### processing CC 88711851, local, ordered

2024-07-16 14:05:43 2 [Note] WSREP: Process first view: 67210f6b-52bc-11ed-8997-d697d3148f87 my uuid: 7d3f1c69-437c-11ef-bd93-1be78d6491dc

2024-07-16 14:05:43 2 [Note] WSREP: Server tdmint-h3 connected to cluster at position 67210f6b-52bc-11ed-8997-d697d3148f87:88711851 with ID 7d3f1c69-437c-11ef-bd93-1be78d6491dc

2024-07-16 14:05:43 2 [Note] WSREP: Server status change disconnected -> connected

2024-07-16 14:05:43 2 [Note] WSREP: ####### My UUID: 7d3f1c69-437c-11ef-bd93-1be78d6491dc

2024-07-16 14:05:43 2 [Note] WSREP: Cert index reset to 00000000-0000-0000-0000-000000000000:-1 (proto: 10), state transfer needed: yes

2024-07-16 14:05:43 0 [Note] WSREP: Service thread queue flushed.

2024-07-16 14:05:43 2 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:-1, protocol version: -1

2024-07-16 14:05:43 2 [Note] WSREP: State transfer required:

	Group state: 67210f6b-52bc-11ed-8997-d697d3148f87:88711851

	Local state: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849

2024-07-16 14:05:43 2 [Note] WSREP: Server status change connected -> joiner

2024-07-16 14:05:43 0 [Note] WSREP: Joiner monitor thread started to monitor

2024-07-16 14:05:43 0 [Note] WSREP: Running: 'wsrep_sst_mariabackup --role 'joiner' --address 'tdmint-h3' --datadir '/var/lib/mysql/' --parent 28412 --progress 0 --mysqld-args --basedir=/opt --datadir=/var/lib/mysql --plugin-dir=/opt/lib64/mysql/plugin --user=mysql --wsrep_provider=/usr/lib64/galera/libgalera_smm.so --wsrep_on=ON --log-error=/var/lib/mysql/mysql.err --pid-file=/var/lib/mysql/mysql.pid --wsrep_start_position=67210f6b-52bc-11ed-8997-d697d3148f87:88711849'

WSREP_SST: [INFO] mariabackup SST started on joiner (20240716 14:05:44.005)

WSREP_SST: [INFO] SSL configuration: CA='', CAPATH='', CERT='/var/lib/mysql/galera_cert.pem', KEY='/var/lib/mysql/galera_key.pem', MODE='DISABLED', encrypt='3' (20240716 14:05:44.127)

WSREP_SST: [INFO] Streaming with mbstream (20240716 14:05:44.278)

WSREP_SST: [INFO] Using socat as streamer (20240716 14:05:44.280)

WSREP_SST: [INFO] Using openssl based encryption with socat: with key and crt (20240716 14:05:44.294)

WSREP_SST: [INFO] Decrypting with cert='/var/lib/mysql/galera_cert.pem', key='/var/lib/mysql/galera_key.pem', verify=0 (20240716 14:05:44.324)

WSREP_SST: [INFO] Evaluating timeout -k 310 300 socat -u openssl-listen:4444,reuseaddr,cert='/var/lib/mysql/galera_cert.pem',key='/var/lib/mysql/galera_key.pem',verify=0 stdio | '/opt//bin/mbstream' -x; RC=( ${PIPESTATUS[@]} ) (20240716 14:05:44.366)

2024-07-16 14:05:44 2 [Note] WSREP: ####### IST uuid:67210f6b-52bc-11ed-8997-d697d3148f87 f: 88711850, l: 88711851, STRv: 3

2024-07-16 14:05:44 2 [Note] WSREP: IST receiver addr using ssl://h3-tdmint:4568

2024-07-16 14:05:44 2 [Note] WSREP: IST receiver using ssl

2024-07-16 14:05:44 2 [Note] WSREP: Prepared IST receiver for 88711850-88711851, listening at: ssl://57.3.12.107:4568

2024-07-16 14:05:44 0 [Note] WSREP: Member 2.7 (tdmint-h3) requested state transfer from '*any*'. Selected 1.3 (tdmint-h1)(SYNCED) as donor.

2024-07-16 14:05:44 0 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 88711851)

2024-07-16 14:05:44 2 [Note] WSREP: Requesting state transfer: success, donor: 1

WSREP_SST: [INFO] 'xtrabackup_ist' received from donor: Running IST (20240716 14:05:45.351)

WSREP_SST: [INFO] Galera co-ords from recovery: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849 0 (20240716 14:05:45.356)

WSREP_SST: [INFO] Total time on joiner: 0 seconds (20240716 14:05:45.358)

WSREP_SST: [INFO] mariabackup IST completed on joiner (20240716 14:05:45.361)

WSREP_SST: [INFO] Removing the sst_in_progress file (20240716 14:05:45.364)

WSREP_SST: [INFO] Cleaning up temporary directories (20240716 14:05:45.368)

2024-07-16 14:05:45 0 [Note] WSREP: 1.3 (tdmint-h1): State transfer to 2.7 (tdmint-h3) complete.

2024-07-16 14:05:45 0 [Note] WSREP: Member 1.3 (tdmint-h1) synced with group.

2024-07-16 14:05:45 3 [Note] WSREP: SST received

2024-07-16 14:05:45 3 [Note] WSREP: Server status change joiner -> initializing

2024-07-16 14:05:45 0 [Note] InnoDB: Compressed tables use zlib 1.2.7

2024-07-16 14:05:45 0 [Note] InnoDB: Number of pools: 1

2024-07-16 14:05:45 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions

2024-07-16 14:05:45 0 [Note] InnoDB: Using Linux native AIO

2024-07-16 14:05:45 0 [Note] InnoDB: Initializing buffer pool, total size = 3221225472, chunk size = 134217728

2024-07-16 14:05:45 0 [Note] InnoDB: Completed initialization of buffer pool

2024-07-16 14:05:45 0 [Note] InnoDB: 128 rollback segments are active.

2024-07-16 14:05:45 0 [Note] InnoDB: Creating shared tablespace for temporary tables

2024-07-16 14:05:45 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...

2024-07-16 14:05:45 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.

2024-07-16 14:05:45 0 [Note] InnoDB: 10.6.12 started; log sequence number 201028063150; transaction id 210746763

2024-07-16 14:05:45 0 [Note] InnoDB: Loading buffer pool(s) from /db/mysql/ib_buffer_pool

2024-07-16 14:05:45 0 [Note] Plugin 'FEEDBACK' is disabled.

2024-07-16 14:05:45 0 [Note] Server socket created on IP: '0.0.0.0'.

2024-07-16 14:05:45 0 [Note] Server socket created on IP: '::'.

2024-07-16 14:05:45 0 [Note] WSREP: wsrep_init_schema_and_SR (nil)

2024-07-16 14:05:46 0 [Note] WSREP: Server initialized

2024-07-16 14:05:46 0 [Note] WSREP: Server status change initializing -> initialized

2024-07-16 14:05:46 3 [Note] WSREP: Recovered position from storage: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849

2024-07-16 14:05:46 3 [Note] WSREP: Recovered view from SST:

  id: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849

  status: primary

  protocol_version: 4

  capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO

  final: no

  own_index: -1

  members(3):

	0: 29aeda1c-437c-11ef-8bc1-6eceee2419ad, tdmint-h2

	1: 49695eda-437b-11ef-b162-a6a2c1a29b12, tdmint-h1

	2: 63a42fae-8953-11ee-adad-56d15056d25c, tdmint-h3

2024-07-16 14:05:46 0 [Note] /opt/sbin/mariadbd: ready for connections.

Version: '10.6.12-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server

2024-07-16 14:05:46 7 [Note] WSREP: Recovered cluster id 67210f6b-52bc-11ed-8997-d697d3148f87

2024-07-16 14:05:46 3 [Note] WSREP: SST received: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849

2024-07-16 14:05:46 3 [Note] WSREP: SST succeeded for position 67210f6b-52bc-11ed-8997-d697d3148f87:88711849

2024-07-16 14:05:46 0 [Note] WSREP: Joiner monitor thread ended with total time 3 sec

2024-07-16 14:05:46 2 [Note] WSREP: Installed new state from SST: 67210f6b-52bc-11ed-8997-d697d3148f87:88711849

2024-07-16 14:05:46 2 [Note] WSREP: Receiving IST: 2 writesets, seqnos 88711850-88711851

2024-07-16 14:05:46 0 [Note] WSREP: ####### IST applying starts with 88711850

2024-07-16 14:05:46 0 [Note] WSREP: ####### IST current seqno initialized to 88711808

2024-07-16 14:05:46 0 [Note] WSREP: Receiving IST...  0.0% ( 0/44 events) complete.

2024-07-16 14:05:46 0 [Note] WSREP: IST preload starting at 88711808

2024-07-16 14:05:46 0 [Note] WSREP: Service thread queue flushed.

2024-07-16 14:05:46 0 [Note] WSREP: ####### Assign initial position for certification: 00000000-0000-0000-0000-000000000000:88711807, protocol version: 5

2024-07-16 14:05:46 0 [Note] WSREP: REPL Protocols: 10 (5)

2024-07-16 14:05:46 0 [Note] WSREP: ####### Adjusting cert position: 88711838 -> 88711839

2024-07-16 14:05:46 0 [Note] WSREP: Service thread queue flushed.

2024-07-16 14:05:46 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 88711808

2024-07-16 14:05:46 0 [Note] WSREP: Min available from gcache for CC from preload: 87943436

2024-07-16 14:05:46 0 [Note] WSREP: REPL Protocols: 10 (5)

2024-07-16 14:05:46 0 [Note] WSREP: ####### Adjusting cert position: 88711839 -> 88711840

2024-07-16 14:05:46 0 [Note] WSREP: Service thread queue flushed.

2024-07-16 14:05:46 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 88711808

2024-07-16 14:05:46 0 [Note] WSREP: Min available from gcache for CC from preload: 87943436

2024-07-16 14:05:46 0 [Note] WSREP: REPL Protocols: 10 (5)

2024-07-16 14:05:46 0 [Note] WSREP: ####### Adjusting cert position: 88711840 -> 88711841

2024-07-16 14:05:46 0 [Note] WSREP: Service thread queue flushed.

2024-07-16 14:05:46 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 88711808

2024-07-16 14:05:46 0 [Note] WSREP: Min available from gcache for CC from preload: 87943436

2024-07-16 14:05:46 0 [Note] WSREP: REPL Protocols: 10 (5)

2024-07-16 14:05:46 0 [Note] WSREP: ####### Adjusting cert position: 88711848 -> 88711849

2024-07-16 14:05:46 0 [Note] WSREP: Service thread queue flushed.

2024-07-16 14:05:46 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 88711808

2024-07-16 14:05:46 0 [Note] WSREP: Min available from gcache for CC from preload: 87943436

2024-07-16 14:05:46 0 [Note] WSREP: REPL Protocols: 10 (5)

2024-07-16 14:05:46 0 [Note] WSREP: ####### Adjusting cert position: 88711849 -> 88711850

2024-07-16 14:05:46 0 [Note] WSREP: Service thread queue flushed.

2024-07-16 14:05:46 0 [Note] WSREP: Lowest cert index boundary for CC from ist: 88711808

2024-07-16 14:05:46 0 [Note] WSREP: Min available from gcache for CC from ist: 87943437

2024-07-16 14:05:46 2 [Note] WSREP: ================================================

View:

  id: 67210f6b-52bc-11ed-8997-d697d3148f87:88711850

  status: primary

  protocol_version: 4

  capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO

  final: no

  own_index: -1

  members(2):

	0: 29aeda1c-437c-11ef-8bc1-6eceee2419ad, tdmint-h2

	1: 49695eda-437b-11ef-b162-a6a2c1a29b12, tdmint-h1

=================================================

2024-07-16 14:05:46 0 [Note] WSREP: REPL Protocols: 10 (5)

2024-07-16 14:05:46 0 [Note] WSREP: ####### Adjusting cert position: 88711850 -> 88711851

2024-07-16 14:05:46 0 [Note] WSREP: Service thread queue flushed.

2024-07-16 14:05:46 0 [Note] WSREP: Lowest cert index boundary for CC from ist: 88711808

2024-07-16 14:05:46 0 [Note] WSREP: Min available from gcache for CC from ist: 87943437

2024-07-16 14:05:46 2 [Note] WSREP: ================================================

View:

  id: 67210f6b-52bc-11ed-8997-d697d3148f87:88711851

  status: primary

  protocol_version: 4

  capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO

  final: no

  own_index: 2

  members(3):

	0: 29aeda1c-437c-11ef-8bc1-6eceee2419ad, tdmint-h2

	1: 49695eda-437b-11ef-b162-a6a2c1a29b12, tdmint-h1

	2: 7d3f1c69-437c-11ef-bd93-1be78d6491dc, tdmint-h3

=================================================

2024-07-16 14:05:46 0 [Note] WSREP: Receiving IST...100.0% (44/44 events) complete.

2024-07-16 14:05:46 2 [Note] WSREP: Server status change initialized -> joined

2024-07-16 14:05:46 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567') turning message relay requesting off

2024-07-16 14:05:46 2 [Note] WSREP: Draining apply monitors after IST up to 88711851

2024-07-16 14:05:46 2 [Note] WSREP: IST received: 67210f6b-52bc-11ed-8997-d697d3148f87:88711851

2024-07-16 14:05:46 2 [Note] WSREP: Lowest cert index boundary for CC from sst: 88711808

2024-07-16 14:05:46 2 [Note] WSREP: Min available from gcache for CC from sst: 87943437

2024-07-16 14:05:46 0 [Note] WSREP: 2.7 (tdmint-h3): State transfer from 1.3 (tdmint-h1) complete.

2024-07-16 14:05:46 0 [Note] WSREP: Shifting JOINER -> JOINED (TO: 88711851)

2024-07-16 14:05:46 0 [Note] WSREP: Processing event queue:... -nan% (0/0 events) complete.

2024-07-16 14:05:46 0 [Note] WSREP: Member 2.7 (tdmint-h3) synced with group.

2024-07-16 14:05:46 0 [Note] WSREP: Processing event queue:...100.0% (1/1 events) complete.

2024-07-16 14:05:46 0 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 88711851)

2024-07-16 14:05:46 2 [Note] WSREP: Server tdmint-h3 synced with group

2024-07-16 14:05:46 2 [Note] WSREP: Server status change joined -> synced

2024-07-16 14:05:46 2 [Note] WSREP: Synchronized with group, ready for connections

2024-07-16 14:05:48 0 [Note] InnoDB: Buffer pool(s) load completed at 240716 14:05:48

2024-07-16 14:07:09 105 [Warning] Access denied for user 'monitor'@'localhost' (using password: YES)

2024-07-16 14:08:57 143 [Warning] Aborted connection 143 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets)

2024-07-16 14:08:57 144 [Warning] Aborted connection 144 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets)

2024-07-16 14:08:58 65 [Warning] Aborted connection 65 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets)

2024-07-16 14:08:58 64 [Warning] Aborted connection 64 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets)

2024-07-16 14:08:58 63 [Warning] Aborted connection 63 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets)

2024-07-16 14:08:58 66 [Warning] Aborted connection 66 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets)

2024-07-16 14:08:58 98 [Warning] Aborted connection 98 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets)

2024-07-16 14:08:58 99 [Warning] Aborted connection 99 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets)

2024-07-16 14:08:58 100 [Warning] Aborted connection 100 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets)

2024-07-16 14:08:58 101 [Warning] Aborted connection 101 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets)

2024-07-16 14:08:58 208 [Warning] Aborted connection 208 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets)

2024-07-16 14:08:58 209 [Warning] Aborted connection 209 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets)

2024-07-16 14:17:01 400 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */

2024-07-16 14:17:04 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */

2024-07-16 14:17:04 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */

2024-07-16 14:17:08 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */

2024-07-16 14:17:08 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */

2024-07-16 14:17:08 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */

2024-07-16 14:17:09 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */

2024-07-16 14:17:09 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */

2024-07-16 14:17:09 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */

2024-07-16 14:17:09 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */

2024-07-16 14:17:09 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */

2024-07-16 14:17:10 390 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */

2024-07-16 14:17:10 392 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */

2024-07-16 14:17:10 392 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */

2024-07-16 14:17:11 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */

Khai Ping added a comment - 2024-07-19 01:27 - edited i am still seeing this error in 10.6.12 in a 3 node galera cluster. When duplicate key happens, the galera cluster will slow down and eventually unable to serve. 240716 14 : 05 : 11 mysqld_safe mysqld from pid file /var/lib/mysql/mysql.pid ended 240716 14 : 05 : 37 mysqld_safe Starting mariadbd daemon with databases from /var/lib/mysql 240716 14 : 05 : 37 mysqld_safe WSREP: Running position recovery with --disable-log-error --pid-file= '/var/lib/mysql/server-h3-recover.pid' 240716 14 : 05 : 39 mysqld_safe WSREP: Recovered position 67210f6b-52bc-11ed- 8997 -d697d3148f87: 88711849 2024 - 07 - 16 14 : 05 : 39 0 [Note] Starting MariaDB 10.6 . 12 -MariaDB source revision 4c79e15cc3716f69c044d4287ad2160da8101cdc as process 28412 2024 - 07 - 16 14 : 05 : 39 0 [Note] WSREP: Loading provider /usr/lib64/galera/libgalera_smm.so initial position: 67210f6b-52bc-11ed- 8997 -d697d3148f87: 88711849 2024 - 07 - 16 14 : 05 : 39 0 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib64/galera/libgalera_smm.so' 2024 - 07 - 16 14 : 05 : 39 0 [Note] WSREP: wsrep_load(): Galera 26.4 . 14 (rf27da2a) by Codership Oy <info @codership .com> loaded successfully. 2024 - 07 - 16 14 : 05 : 39 0 [Note] WSREP: CRC-32C: using 64 -bit x86 acceleration. 2024 - 07 - 16 14 : 05 : 39 0 [Warning] WSREP: SSL compression is not effective. The option socket.ssl_compression is deprecated and will be removed in future releases. 2024 - 07 - 16 14 : 05 : 39 0 [Note] WSREP: Found saved state: 67210f6b-52bc-11ed- 8997 -d697d3148f87: 88711849 , safe_to_bootstrap: 0 2024 - 07 - 16 14 : 05 : 39 0 [Note] WSREP: GCache DEBUG: opened preamble: Version: 2 UUID: 67210f6b-52bc-11ed- 8997 -d697d3148f87 Seqno: 87943436 - 88711849 Offset: 1749575000 Synced: 1 2024 - 07 - 16 14 : 05 : 39 0 [Note] WSREP: Recovering GCache ring buffer: version: 2 , UUID: 67210f6b-52bc-11ed- 8997 -d697d3148f87, offset: 1749575000 2024 - 07 - 16 14 : 05 : 39 0 [Note] WSREP: GCache::RingBuffer initial scan... 0.0 % ( 0 / 2147483672 bytes) complete. 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: GCache::RingBuffer initial scan... 100.0 % ( 2147483672 / 2147483672 bytes) complete. 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: Recovering GCache ring buffer: found gapless sequence 87943436 - 88711849 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: GCache::RingBuffer unused buffers scan... 0.0 % ( 0 / 2147055560 bytes) complete. 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: Recovering GCache ring buffer: found 1 / 768415 locked buffers 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: Recovering GCache ring buffer: free space: 428280 / 2147483648 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: GCache::RingBuffer unused buffers scan... 100.0 % ( 2147055560 / 2147055560 bytes) complete. 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql/; base_host = tdmint-h3; base_port = 4567 ; cert.log_conflicts = no; cert.optimistic_pa = yes; debug = no; evs.auto_evict = 0 ; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT10S; evs.inactive_timeout = PT60S; evs.install_timeout = PT60S; evs.join_retrans_period = PT1S; evs.keepalive_period = PT3S; evs.max_install_timeouts = 3 ; evs.send_window = 512 ; evs.stats_report_period = PT1M; evs.suspect_timeout = PT30S; evs.user_send_window = 512 ; evs.view_forget_timeout = PT24H; gcache.dir = /var/lib/mysql/; gcache.keep_pages_size = 0 ; gcache.keep_plaintext_size = 1G; gcache.mem_size = 0 ; gcache.name = galera.cache; gcache.page_size = 1G; gcache.recover = yes; gcache.size = 2G; gcomm.thread_prio = ; gcs.fc_debug = 0 ; gcs.fc_factor = 1.0 ; gcs.fc_limit = 16 ; gcs.fc_master_slave = no; gcs.fc_single_primary = no; gcs.max_packet_size = 64500 ; gcs.max_throttle = 0.25 ; gcs.recv_q_hard_limit = 9223372036854775807 ; gcs.recv_q_soft_l 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: Service thread queue flushed. 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: ####### Assign initial position for certification: 67210f6b-52bc-11ed- 8997 -d697d3148f87: 88711849 , protocol version: - 1 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: Start replication 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: Connecting with bootstrap option: 0 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: Setting GCS initial position to 67210f6b-52bc-11ed- 8997 -d697d3148f87: 88711849 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: Using CRC- 32 (backward-compatible) for message checksums. 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: backend: asio 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: gcomm thread scheduling priority set to other: 0 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: access file(/var/lib/mysql //gvwstate.dat) failed(No such file or directory) 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: restore pc from disk failed 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: GMCast version 0 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567' ) listening at ssl:// 0.0 . 0.0 : 4567 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567' ) multicast: , ttl: 1 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: EVS version 1 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: gcomm: connecting to group 'accdbcluster' , peer '57.3.12.100:,57.3.12.101:,57.3.12.107:' 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567' ) Found matching local endpoint for a connection, blacklisting address ssl:// 57.3 . 12.107 : 4567 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567' ) connection established to 29aeda1c-8bc1 ssl:// 57.3 . 12.101 : 4567 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567' ) turning message relay requesting on, nonlive peers: 2024 - 07 - 16 14 : 05 : 42 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567' ) connection established to 49695eda-b162 ssl:// 57.3 . 12.100 : 4567 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: EVS version upgrade 0 -> 1 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: declaring 29aeda1c-8bc1 at ssl: //57.3.12.101:4567 stable 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: declaring 49695eda-b162 at ssl: //57.3.12.100:4567 stable 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: PC protocol upgrade 0 -> 1 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: Node 29aeda1c-8bc1 state prim 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: view(view_id(PRIM,29aeda1c-8bc1, 14 ) memb { 29aeda1c-8bc1, 4 49695eda-b162, 3 7d3f1c69-bd93, 7 } joined { } left { } partitioned { }) 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: save pc into disk 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: gcomm: connected 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: Changing maximum packet size to 64500 , resulting msg size: 32636 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0 ) 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: Opened channel 'accdbcluster' 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 2 , memb_num = 3 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID. 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: STATE EXCHANGE: sent state msg: 7d8e3f95-437c-11ef-a8ec-bb1b8da382a8 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: STATE EXCHANGE: got state msg: 7d8e3f95-437c-11ef-a8ec-bb1b8da382a8 from 0 (tdmint-h2) 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: STATE EXCHANGE: got state msg: 7d8e3f95-437c-11ef-a8ec-bb1b8da382a8 from 1 (tdmint-h1) 2024 - 07 - 16 14 : 05 : 43 1 [Note] WSREP: Starting rollbacker thread 1 2024 - 07 - 16 14 : 05 : 43 2 [Note] WSREP: Starting applier thread 2 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: STATE EXCHANGE: got state msg: 7d8e3f95-437c-11ef-a8ec-bb1b8da382a8 from 2 (tdmint-h3) 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: Quorum results: version = 6 , component = PRIMARY, conf_id = 11 , members = 2 / 3 (joined/total), act_id = 88711850 , last_appl. = 88711807 , protocols = 2 / 10 / 4 (gcs/repl/appl), vote policy= 0 , group UUID = 67210f6b-52bc-11ed- 8997 -d697d3148f87 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: Flow-control interval: [ 28 , 28 ] 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 88711851 ) 2024 - 07 - 16 14 : 05 : 43 2 [Note] WSREP: ####### processing CC 88711851 , local, ordered 2024 - 07 - 16 14 : 05 : 43 2 [Note] WSREP: Process first view: 67210f6b-52bc-11ed- 8997 -d697d3148f87 my uuid: 7d3f1c69-437c-11ef-bd93-1be78d6491dc 2024 - 07 - 16 14 : 05 : 43 2 [Note] WSREP: Server tdmint-h3 connected to cluster at position 67210f6b-52bc-11ed- 8997 -d697d3148f87: 88711851 with ID 7d3f1c69-437c-11ef-bd93-1be78d6491dc 2024 - 07 - 16 14 : 05 : 43 2 [Note] WSREP: Server status change disconnected -> connected 2024 - 07 - 16 14 : 05 : 43 2 [Note] WSREP: ####### My UUID: 7d3f1c69-437c-11ef-bd93-1be78d6491dc 2024 - 07 - 16 14 : 05 : 43 2 [Note] WSREP: Cert index reset to 00000000 - 0000 - 0000 - 0000 - 000000000000 :- 1 (proto: 10 ), state transfer needed: yes 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: Service thread queue flushed. 2024 - 07 - 16 14 : 05 : 43 2 [Note] WSREP: ####### Assign initial position for certification: 00000000 - 0000 - 0000 - 0000 - 000000000000 :- 1 , protocol version: - 1 2024 - 07 - 16 14 : 05 : 43 2 [Note] WSREP: State transfer required: Group state: 67210f6b-52bc-11ed- 8997 -d697d3148f87: 88711851 Local state: 67210f6b-52bc-11ed- 8997 -d697d3148f87: 88711849 2024 - 07 - 16 14 : 05 : 43 2 [Note] WSREP: Server status change connected -> joiner 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: Joiner monitor thread started to monitor 2024 - 07 - 16 14 : 05 : 43 0 [Note] WSREP: Running: 'wsrep_sst_mariabackup --role ' joiner ' --address ' tdmint-h3 ' --datadir ' /var/lib/mysql/ ' --parent 28412 --progress 0 --mysqld-args --basedir=/opt --datadir=/var/lib/mysql --plugin-dir=/opt/lib64/mysql/plugin --user=mysql --wsrep_provider=/usr/lib64/galera/libgalera_smm.so --wsrep_on=ON --log-error=/var/lib/mysql/mysql.err --pid-file=/var/lib/mysql/mysql.pid --wsrep_start_position=67210f6b-52bc-11ed-8997-d697d3148f87:88711849' WSREP_SST: [INFO] mariabackup SST started on joiner ( 20240716 14 : 05 : 44.005 ) WSREP_SST: [INFO] SSL configuration: CA= '' , CAPATH= '' , CERT= '/var/lib/mysql/galera_cert.pem' , KEY= '/var/lib/mysql/galera_key.pem' , MODE= 'DISABLED' , encrypt= '3' ( 20240716 14 : 05 : 44.127 ) WSREP_SST: [INFO] Streaming with mbstream ( 20240716 14 : 05 : 44.278 ) WSREP_SST: [INFO] Using socat as streamer ( 20240716 14 : 05 : 44.280 ) WSREP_SST: [INFO] Using openssl based encryption with socat: with key and crt ( 20240716 14 : 05 : 44.294 ) WSREP_SST: [INFO] Decrypting with cert= '/var/lib/mysql/galera_cert.pem' , key= '/var/lib/mysql/galera_key.pem' , verify= 0 ( 20240716 14 : 05 : 44.324 ) WSREP_SST: [INFO] Evaluating timeout -k 310 300 socat -u openssl-listen: 4444 ,reuseaddr,cert= '/var/lib/mysql/galera_cert.pem' ,key= '/var/lib/mysql/galera_key.pem' ,verify= 0 stdio | '/opt//bin/mbstream' -x; RC=( ${PIPESTATUS[@]} ) ( 20240716 14 : 05 : 44.366 ) 2024 - 07 - 16 14 : 05 : 44 2 [Note] WSREP: ####### IST uuid:67210f6b-52bc-11ed- 8997 -d697d3148f87 f: 88711850 , l: 88711851 , STRv: 3 2024 - 07 - 16 14 : 05 : 44 2 [Note] WSREP: IST receiver addr using ssl: //h3-tdmint:4568 2024 - 07 - 16 14 : 05 : 44 2 [Note] WSREP: IST receiver using ssl 2024 - 07 - 16 14 : 05 : 44 2 [Note] WSREP: Prepared IST receiver for 88711850 - 88711851 , listening at: ssl: //57.3.12.107:4568 2024 - 07 - 16 14 : 05 : 44 0 [Note] WSREP: Member 2.7 (tdmint-h3) requested state transfer from '*any*' . Selected 1.3 (tdmint-h1)(SYNCED) as donor. 2024 - 07 - 16 14 : 05 : 44 0 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 88711851 ) 2024 - 07 - 16 14 : 05 : 44 2 [Note] WSREP: Requesting state transfer: success, donor: 1 WSREP_SST: [INFO] 'xtrabackup_ist' received from donor: Running IST ( 20240716 14 : 05 : 45.351 ) WSREP_SST: [INFO] Galera co-ords from recovery: 67210f6b-52bc-11ed- 8997 -d697d3148f87: 88711849 0 ( 20240716 14 : 05 : 45.356 ) WSREP_SST: [INFO] Total time on joiner: 0 seconds ( 20240716 14 : 05 : 45.358 ) WSREP_SST: [INFO] mariabackup IST completed on joiner ( 20240716 14 : 05 : 45.361 ) WSREP_SST: [INFO] Removing the sst_in_progress file ( 20240716 14 : 05 : 45.364 ) WSREP_SST: [INFO] Cleaning up temporary directories ( 20240716 14 : 05 : 45.368 ) 2024 - 07 - 16 14 : 05 : 45 0 [Note] WSREP: 1.3 (tdmint-h1): State transfer to 2.7 (tdmint-h3) complete. 2024 - 07 - 16 14 : 05 : 45 0 [Note] WSREP: Member 1.3 (tdmint-h1) synced with group. 2024 - 07 - 16 14 : 05 : 45 3 [Note] WSREP: SST received 2024 - 07 - 16 14 : 05 : 45 3 [Note] WSREP: Server status change joiner -> initializing 2024 - 07 - 16 14 : 05 : 45 0 [Note] InnoDB: Compressed tables use zlib 1.2 . 7 2024 - 07 - 16 14 : 05 : 45 0 [Note] InnoDB: Number of pools: 1 2024 - 07 - 16 14 : 05 : 45 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions 2024 - 07 - 16 14 : 05 : 45 0 [Note] InnoDB: Using Linux native AIO 2024 - 07 - 16 14 : 05 : 45 0 [Note] InnoDB: Initializing buffer pool, total size = 3221225472 , chunk size = 134217728 2024 - 07 - 16 14 : 05 : 45 0 [Note] InnoDB: Completed initialization of buffer pool 2024 - 07 - 16 14 : 05 : 45 0 [Note] InnoDB: 128 rollback segments are active. 2024 - 07 - 16 14 : 05 : 45 0 [Note] InnoDB: Creating shared tablespace for temporary tables 2024 - 07 - 16 14 : 05 : 45 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 2024 - 07 - 16 14 : 05 : 45 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. 2024 - 07 - 16 14 : 05 : 45 0 [Note] InnoDB: 10.6 . 12 started; log sequence number 201028063150 ; transaction id 210746763 2024 - 07 - 16 14 : 05 : 45 0 [Note] InnoDB: Loading buffer pool(s) from /db/mysql/ib_buffer_pool 2024 - 07 - 16 14 : 05 : 45 0 [Note] Plugin 'FEEDBACK' is disabled. 2024 - 07 - 16 14 : 05 : 45 0 [Note] Server socket created on IP: '0.0.0.0' . 2024 - 07 - 16 14 : 05 : 45 0 [Note] Server socket created on IP: '::' . 2024 - 07 - 16 14 : 05 : 45 0 [Note] WSREP: wsrep_init_schema_and_SR (nil) 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Server initialized 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Server status change initializing -> initialized 2024 - 07 - 16 14 : 05 : 46 3 [Note] WSREP: Recovered position from storage: 67210f6b-52bc-11ed- 8997 -d697d3148f87: 88711849 2024 - 07 - 16 14 : 05 : 46 3 [Note] WSREP: Recovered view from SST: id: 67210f6b-52bc-11ed- 8997 -d697d3148f87: 88711849 status: primary protocol_version: 4 capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO final : no own_index: - 1 members( 3 ): 0 : 29aeda1c-437c-11ef-8bc1-6eceee2419ad, tdmint-h2 1 : 49695eda-437b-11ef-b162-a6a2c1a29b12, tdmint-h1 2 : 63a42fae- 8953 -11ee-adad-56d15056d25c, tdmint-h3 2024 - 07 - 16 14 : 05 : 46 0 [Note] /opt/sbin/mariadbd: ready for connections. Version: '10.6.12-MariaDB' socket: '/var/lib/mysql/mysql.sock' port: 3306 MariaDB Server 2024 - 07 - 16 14 : 05 : 46 7 [Note] WSREP: Recovered cluster id 67210f6b-52bc-11ed- 8997 -d697d3148f87 2024 - 07 - 16 14 : 05 : 46 3 [Note] WSREP: SST received: 67210f6b-52bc-11ed- 8997 -d697d3148f87: 88711849 2024 - 07 - 16 14 : 05 : 46 3 [Note] WSREP: SST succeeded for position 67210f6b-52bc-11ed- 8997 -d697d3148f87: 88711849 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Joiner monitor thread ended with total time 3 sec 2024 - 07 - 16 14 : 05 : 46 2 [Note] WSREP: Installed new state from SST: 67210f6b-52bc-11ed- 8997 -d697d3148f87: 88711849 2024 - 07 - 16 14 : 05 : 46 2 [Note] WSREP: Receiving IST: 2 writesets, seqnos 88711850 - 88711851 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: ####### IST applying starts with 88711850 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: ####### IST current seqno initialized to 88711808 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Receiving IST... 0.0 % ( 0 / 44 events) complete. 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: IST preload starting at 88711808 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Service thread queue flushed. 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: ####### Assign initial position for certification: 00000000 - 0000 - 0000 - 0000 - 000000000000 : 88711807 , protocol version: 5 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: REPL Protocols: 10 ( 5 ) 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: ####### Adjusting cert position: 88711838 -> 88711839 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Service thread queue flushed. 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 88711808 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Min available from gcache for CC from preload: 87943436 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: REPL Protocols: 10 ( 5 ) 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: ####### Adjusting cert position: 88711839 -> 88711840 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Service thread queue flushed. 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 88711808 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Min available from gcache for CC from preload: 87943436 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: REPL Protocols: 10 ( 5 ) 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: ####### Adjusting cert position: 88711840 -> 88711841 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Service thread queue flushed. 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 88711808 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Min available from gcache for CC from preload: 87943436 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: REPL Protocols: 10 ( 5 ) 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: ####### Adjusting cert position: 88711848 -> 88711849 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Service thread queue flushed. 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Lowest cert index boundary for CC from preload: 88711808 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Min available from gcache for CC from preload: 87943436 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: REPL Protocols: 10 ( 5 ) 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: ####### Adjusting cert position: 88711849 -> 88711850 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Service thread queue flushed. 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Lowest cert index boundary for CC from ist: 88711808 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Min available from gcache for CC from ist: 87943437 2024 - 07 - 16 14 : 05 : 46 2 [Note] WSREP: ================================================ View: id: 67210f6b-52bc-11ed- 8997 -d697d3148f87: 88711850 status: primary protocol_version: 4 capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO final : no own_index: - 1 members( 2 ): 0 : 29aeda1c-437c-11ef-8bc1-6eceee2419ad, tdmint-h2 1 : 49695eda-437b-11ef-b162-a6a2c1a29b12, tdmint-h1 ================================================= 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: REPL Protocols: 10 ( 5 ) 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: ####### Adjusting cert position: 88711850 -> 88711851 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Service thread queue flushed. 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Lowest cert index boundary for CC from ist: 88711808 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Min available from gcache for CC from ist: 87943437 2024 - 07 - 16 14 : 05 : 46 2 [Note] WSREP: ================================================ View: id: 67210f6b-52bc-11ed- 8997 -d697d3148f87: 88711851 status: primary protocol_version: 4 capabilities: MULTI-MASTER, CERTIFICATION, PARALLEL_APPLYING, REPLAY, ISOLATION, PAUSE, CAUSAL_READ, INCREMENTAL_WS, UNORDERED, PREORDERED, STREAMING, NBO final : no own_index: 2 members( 3 ): 0 : 29aeda1c-437c-11ef-8bc1-6eceee2419ad, tdmint-h2 1 : 49695eda-437b-11ef-b162-a6a2c1a29b12, tdmint-h1 2 : 7d3f1c69-437c-11ef-bd93-1be78d6491dc, tdmint-h3 ================================================= 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Receiving IST... 100.0 % ( 44 / 44 events) complete. 2024 - 07 - 16 14 : 05 : 46 2 [Note] WSREP: Server status change initialized -> joined 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: (7d3f1c69-bd93, 'ssl://0.0.0.0:4567' ) turning message relay requesting off 2024 - 07 - 16 14 : 05 : 46 2 [Note] WSREP: Draining apply monitors after IST up to 88711851 2024 - 07 - 16 14 : 05 : 46 2 [Note] WSREP: IST received: 67210f6b-52bc-11ed- 8997 -d697d3148f87: 88711851 2024 - 07 - 16 14 : 05 : 46 2 [Note] WSREP: Lowest cert index boundary for CC from sst: 88711808 2024 - 07 - 16 14 : 05 : 46 2 [Note] WSREP: Min available from gcache for CC from sst: 87943437 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: 2.7 (tdmint-h3): State transfer from 1.3 (tdmint-h1) complete. 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Shifting JOINER -> JOINED (TO: 88711851 ) 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Processing event queue:... -nan% ( 0 / 0 events) complete. 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Member 2.7 (tdmint-h3) synced with group. 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Processing event queue:... 100.0 % ( 1 / 1 events) complete. 2024 - 07 - 16 14 : 05 : 46 0 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 88711851 ) 2024 - 07 - 16 14 : 05 : 46 2 [Note] WSREP: Server tdmint-h3 synced with group 2024 - 07 - 16 14 : 05 : 46 2 [Note] WSREP: Server status change joined -> synced 2024 - 07 - 16 14 : 05 : 46 2 [Note] WSREP: Synchronized with group, ready for connections 2024 - 07 - 16 14 : 05 : 48 0 [Note] InnoDB: Buffer pool(s) load completed at 240716 14 : 05 : 48 2024 - 07 - 16 14 : 07 : 09 105 [Warning] Access denied for user 'monitor' @ 'localhost' (using password: YES) 2024 - 07 - 16 14 : 08 : 57 143 [Warning] Aborted connection 143 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets) 2024 - 07 - 16 14 : 08 : 57 144 [Warning] Aborted connection 144 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets) 2024 - 07 - 16 14 : 08 : 58 65 [Warning] Aborted connection 65 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets) 2024 - 07 - 16 14 : 08 : 58 64 [Warning] Aborted connection 64 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets) 2024 - 07 - 16 14 : 08 : 58 63 [Warning] Aborted connection 63 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets) 2024 - 07 - 16 14 : 08 : 58 66 [Warning] Aborted connection 66 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets) 2024 - 07 - 16 14 : 08 : 58 98 [Warning] Aborted connection 98 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets) 2024 - 07 - 16 14 : 08 : 58 99 [Warning] Aborted connection 99 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets) 2024 - 07 - 16 14 : 08 : 58 100 [Warning] Aborted connection 100 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets) 2024 - 07 - 16 14 : 08 : 58 101 [Warning] Aborted connection 101 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets) 2024 - 07 - 16 14 : 08 : 58 208 [Warning] Aborted connection 208 to db: 'configurationDB' user: 'app_user' host: 'localhost' (Got an error reading communication packets) 2024 - 07 - 16 14 : 08 : 58 209 [Warning] Aborted connection 209 to db: 'database_users' user: 'app_user' host: 'localhost' (Got an error reading communication packets) 2024 - 07 - 16 14 : 17 : 01 400 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ 2024 - 07 - 16 14 : 17 : 04 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ 2024 - 07 - 16 14 : 17 : 04 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ 2024 - 07 - 16 14 : 17 : 08 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ 2024 - 07 - 16 14 : 17 : 08 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ 2024 - 07 - 16 14 : 17 : 08 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ 2024 - 07 - 16 14 : 17 : 09 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ 2024 - 07 - 16 14 : 17 : 09 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ 2024 - 07 - 16 14 : 17 : 09 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ 2024 - 07 - 16 14 : 17 : 09 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ 2024 - 07 - 16 14 : 17 : 09 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ 2024 - 07 - 16 14 : 17 : 10 390 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ 2024 - 07 - 16 14 : 17 : 10 392 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ 2024 - 07 - 16 14 : 17 : 10 392 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */ 2024 - 07 - 16 14 : 17 : 11 2 [ERROR] InnoDB: (Duplicate key) writing word node to FTS auxiliary index table `database_users`.`events` /* Partition `for20240716` */

People

Assignee:: Thirunarayanan Balathandayuthapani

Reporter:: Gianni Angelozzi

Votes:: 7 Vote for this issue

Watchers:: 19 Start watching this issue

Dates

Created:: 2018-02-07 15:56

Updated:: 2024-07-19 01:30

Resolved:: 2022-10-17 18:48

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.