Second node - operation not permitted

809 views
Skip to first unread message

Peto Michalak

unread,
Sep 26, 2013, 8:58:03 AM9/26/13
to codersh...@googlegroups.com
Hi Guys!

I am testing out galera replication, it was working nicely once, but when I came back to it and booted up my virtual machine I cannot make it work again. I have two nodes (I've read about split brain condition - I don't think that's the issue). FirstNode starts fine and it's synced (with itself), but the secondNode doesn't want to join...

SecondNode logs (controller-2 192.168.100.2):
130926 12:26:47 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
130926 12:26:47 mysqld_safe WSREP: Running position recovery with --log_error=/tmp/tmp.5cTTVDsS6q
130926 12:26:49 mysqld_safe WSREP: Recovered position 00000000-0000-0000-0000-000000000000:-1
130926 12:26:50 [Note] WSREP: wsrep_start_position var submitted: '00000000-0000-0000-0000-000000000000:-1'
130926 12:26:50 InnoDB: The InnoDB memory heap is disabled
130926 12:26:50 InnoDB: Mutexes and rw_locks use GCC atomic builtins
130926 12:26:50 InnoDB: Compressed tables use zlib 1.2.3.3
130926 12:26:50 InnoDB: Using Linux native AIO
130926 12:26:50 InnoDB: Initializing buffer pool, size = 128.0M
130926 12:26:50 InnoDB: Completed initialization of buffer pool
130926 12:26:50 InnoDB: highest supported file format is Barracuda.
130926 12:26:50  InnoDB: Waiting for the background threads to start
130926 12:26:51 InnoDB: 1.1.8 started; log sequence number 1595843
130926 12:26:51 [Note] Server hostname (bind-address): '192.168.100.2'; port: 3307
130926 12:26:51 [Note]   - '192.168.100.2' resolves to '192.168.100.2';
130926 12:26:51 [Note] Server socket created on IP: '192.168.100.2'.
130926 12:26:51 [Warning] 'user' entry 'root@controller-2' ignored in --skip-name-resolve mode.
130926 12:26:51 [Warning] 'user' entry '@controller-2' ignored in --skip-name-resolve mode.
130926 12:26:51 [Warning] 'proxies_priv' entry '@ root@controller-2' ignored in --skip-name-resolve mode.
130926 12:26:51 [Note] Event Scheduler: Loaded 0 events
130926 12:26:51 [Note] WSREP: Read nil XID from storage engines, skipping position init
130926 12:26:51 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'
130926 12:26:51 [Note] WSREP: wsrep_load(): Galera 23.2.4(r147) by Codership Oy <in...@codership.com> loaded succesfully.
130926 12:26:51 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1
130926 12:26:51 [Note] WSREP: Reusing existing '/var/lib/mysql//galera.cache'.
130926 12:26:51 [Note] WSREP: Passing config to GCS: base_host = 192.168.100.2; base_port = 4567; cert.log_conflicts = no; gcache.dir = /var/lib/mysql/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /var/lib/mysql//galera.cache; gcache.page_size = 128M; gcache.size = 128M; gcs.fc_debug = 0; gcs.fc_factor = 1; gcs.fc_limit = 16; gcs.fc_master_slave = NO; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = NO; gmcast.listen_addr = tcp://192.168.100.2:4567; ist.recv_addr = 192.168.100.2; pc.ignore_sb = no; replicator.causal_read_timeout = PT30S; replicator.commit_order = 3
130926 12:26:51 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1
130926 12:26:51 [Note] WSREP: Start replication
130926 12:26:51 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1
130926 12:26:51 [Note] WSREP: protonet asio version 0
130926 12:26:51 [Note] WSREP: backend: asio
130926 12:26:51 [Note] WSREP: GMCast version 0
130926 12:26:51 [Note] WSREP: (eb9d8fcd-26a6-11e3-0800-c0b3657652d1, 'tcp://192.168.100.2:4567') listening at tcp://192.168.100.2:4567
130926 12:26:51 [Note] WSREP: (eb9d8fcd-26a6-11e3-0800-c0b3657652d1, 'tcp://192.168.100.2:4567') multicast: , ttl: 1
130926 12:26:51 [Note] WSREP: EVS version 0
130926 12:26:51 [Note] WSREP: PC version 0
130926 12:26:51 [Note] WSREP: gcomm: connecting to group 'openstack', peer '192.168.100.1:4567'
130926 12:26:51 [Note] WSREP: gcomm: connected
130926 12:26:51 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
130926 12:26:51 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
130926 12:26:51 [Note] WSREP: Opened channel 'openstack'
130926 12:26:51 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.29'  socket: '/var/run/mysqld/mysqld.sock'  port: 3307  Source distribution, wsrep_23.7.3.r3853
130926 12:26:51 [Note] WSREP: declaring 1c71f1e7-26a1-11e3-0800-c5ced489d4ae stable
130926 12:26:51 [Note] WSREP: Node 1c71f1e7-26a1-11e3-0800-c5ced489d4ae state prim
130926 12:26:51 [Note] WSREP: view(view_id(PRIM,1c71f1e7-26a1-11e3-0800-c5ced489d4ae,8) memb {
        1c71f1e7-26a1-11e3-0800-c5ced489d4ae,
        eb9d8fcd-26a6-11e3-0800-c0b3657652d1,
} joined {
} left {
} partitioned {
})
130926 12:26:51 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 2
130926 12:26:51 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
130926 12:26:51 [Note] WSREP: STATE EXCHANGE: sent state msg: ebec9135-26a6-11e3-0800-6d8a20f415fa
130926 12:26:51 [Note] WSREP: STATE EXCHANGE: got state msg: ebec9135-26a6-11e3-0800-6d8a20f415fa from 0 (controller-1)
130926 12:26:51 [Note] WSREP: STATE EXCHANGE: got state msg: ebec9135-26a6-11e3-0800-6d8a20f415fa from 1 (controller-2)
130926 12:26:51 [Note] WSREP: Quorum results:
        version    = 2,
        component  = PRIMARY,
        conf_id    = 7,
        members    = 1/2 (joined/total),
        act_id     = 18588,
        last_appl. = -1,
        protocols  = 0/4/2 (gcs/repl/appl),
        group UUID = e3b83a53-2670-11e3-0800-a25e34e5a4ee
130926 12:26:51 [Note] WSREP: Flow-control interval: [23, 23]
130926 12:26:51 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 18588)
130926 12:26:51 [Note] WSREP: State transfer required:
        Group state: e3b83a53-2670-11e3-0800-a25e34e5a4ee:18588
        Local state: 00000000-0000-0000-0000-000000000000:-1
130926 12:26:51 [Note] WSREP: New cluster view: global state: e3b83a53-2670-11e3-0800-a25e34e5a4ee:18588, view# 8: Primary, number of nodes: 2, my index: 1, protocol version 2
130926 12:26:51 [Warning] WSREP: Gap in state sequence. Need state transfer.
130926 12:26:53 [Note] WSREP: Prepared SST request: mysqldump|192.168.100.2:3307
130926 12:26:53 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
130926 12:26:53 [Note] WSREP: Assign initial position for certification: 18588, protocol version: 2
130926 12:26:53 [Warning] WSREP: Failed to prepare for incremental state transfer: Local state UUID (00000000-0000-0000-0000-000000000000) does not match group state UUID (e3b83a53-2670-11e3-0800-a25e34e5a4ee): 1 (Operation not permitted)
         at galera/src/replicator_str.cpp:prepare_for_IST():442. IST will be unavailable.
130926 12:26:53 [Note] WSREP: Node 1 (controller-2) requested state transfer from '*any*'. Selected 0 (controller-1)(SYNCED) as donor.
130926 12:26:53 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 18588)
130926 12:26:53 [Note] WSREP: Requesting state transfer: success, donor: 0
130926 12:26:56 [Warning] WSREP: 0 (controller-1): State transfer to 1 (controller-2) failed: -1 (Operation not permitted)
130926 12:26:56 [ERROR] WSREP: gcs/src/gcs_group.c:gcs_group_handle_join_msg():719: Will never receive state. Need to abort.
130926 12:26:56 [Note] WSREP: gcomm: terminating thread
130926 12:26:56 [Note] WSREP: gcomm: joining thread
130926 12:26:56 [Note] WSREP: gcomm: closing backend
130926 12:26:57 [Note] WSREP: view(view_id(NON_PRIM,1c71f1e7-26a1-11e3-0800-c5ced489d4ae,8) memb {
        eb9d8fcd-26a6-11e3-0800-c0b3657652d1,
} joined {
} left {
} partitioned {
        1c71f1e7-26a1-11e3-0800-c5ced489d4ae,
})
130926 12:26:57 [Note] WSREP: view((empty))
130926 12:26:57 [Note] WSREP: gcomm: closed
130926 12:26:57 [Note] WSREP: /usr/sbin/mysqld: Terminated.
Aborted
130926 12:26:57 mysqld_safe Number of processes running now: 0
130926 12:26:57 mysqld_safe WSREP: not restarting wsrep node automatically
130926 12:26:57 mysqld_safe mysqld from pid file /var/lib/mysql/controller-2.pid ended


FirstNode logs (controller-1 192.168.100.1):
130926 12:26:51 [Note] WSREP: declaring eb9d8fcd-26a6-11e3-0800-c0b3657652d1 stable
130926 12:26:51 [Note] WSREP: Node 1c71f1e7-26a1-11e3-0800-c5ced489d4ae state prim
130926 12:26:51 [Note] WSREP: view(view_id(PRIM,1c71f1e7-26a1-11e3-0800-c5ced489d4ae,8) memb {
        1c71f1e7-26a1-11e3-0800-c5ced489d4ae,
        eb9d8fcd-26a6-11e3-0800-c0b3657652d1,
} joined {
} left {
} partitioned {
})
130926 12:26:51 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 2
130926 12:26:51 [Note] WSREP: STATE_EXCHANGE: sent state UUID: ebec9135-26a6-11e3-0800-6d8a20f415fa
130926 12:26:51 [Note] WSREP: STATE EXCHANGE: sent state msg: ebec9135-26a6-11e3-0800-6d8a20f415fa
130926 12:26:51 [Note] WSREP: STATE EXCHANGE: got state msg: ebec9135-26a6-11e3-0800-6d8a20f415fa from 0 (controller-1)
130926 12:26:51 [Note] WSREP: STATE EXCHANGE: got state msg: ebec9135-26a6-11e3-0800-6d8a20f415fa from 1 (controller-2)
130926 12:26:51 [Note] WSREP: Quorum results:
        version    = 2,
        component  = PRIMARY,
        conf_id    = 7,
        members    = 1/2 (joined/total),
        act_id     = 18588,
        last_appl. = 17638,
        protocols  = 0/4/2 (gcs/repl/appl),
        group UUID = e3b83a53-2670-11e3-0800-a25e34e5a4ee
130926 12:26:51 [Note] WSREP: Flow-control interval: [23, 23]
130926 12:26:51 [Note] WSREP: New cluster view: global state: e3b83a53-2670-11e3-0800-a25e34e5a4ee:18588, view# 8: Primary, number of nodes: 2, my index: 0, protocol version 2
130926 12:26:51 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
130926 12:26:51 [Note] WSREP: Assign initial position for certification: 18588, protocol version: 2
130926 12:26:53 [Note] WSREP: Node 1 (controller-2) requested state transfer from '*any*'. Selected 0 (controller-1)(SYNCED) as donor.
130926 12:26:53 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 18588)
130926 12:26:53 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
ERROR 1130 (HY000): Host '192.168.100.1' is not allowed to connect to this MySQL server
130926 12:26:53 [ERROR] WSREP: Process completed with error: wsrep_sst_mysqldump --user 'wsrep_sst' --password 'password' --host '192.168.100.2' --port '3307' --local-port '3307' --socket '/var/run/mysqld/mysqld.sock' --gtid 'e3b83a53-2670-11e3-0800-a25e34e5a4ee:18588': 1 (Operation not permitted)
130926 12:26:53 [ERROR] WSREP: Try 1/3: 'wsrep_sst_mysqldump --user 'wsrep_sst' --password 'password' --host '192.168.100.2' --port '3307' --local-port '3307' --socket '/var/run/mysqld/mysqld.sock' --gtid 'e3b83a53-2670-11e3-0800-a25e34e5a4ee:18588'' failed: 1 (Operation not permitted)
ERROR 1130 (HY000): Host '192.168.100.1' is not allowed to connect to this MySQL server
130926 12:26:54 [ERROR] WSREP: Process completed with error: wsrep_sst_mysqldump --user 'wsrep_sst' --password 'password' --host '192.168.100.2' --port '3307' --local-port '3307' --socket '/var/run/mysqld/mysqld.sock' --gtid 'e3b83a53-2670-11e3-0800-a25e34e5a4ee:18588': 1 (Operation not permitted)
130926 12:26:54 [ERROR] WSREP: Try 2/3: 'wsrep_sst_mysqldump --user 'wsrep_sst' --password 'password' --host '192.168.100.2' --port '3307' --local-port '3307' --socket '/var/run/mysqld/mysqld.sock' --gtid 'e3b83a53-2670-11e3-0800-a25e34e5a4ee:18588'' failed: 1 (Operation not permitted)
ERROR 1130 (HY000): Host '192.168.100.1' is not allowed to connect to this MySQL server
130926 12:26:55 [ERROR] WSREP: Process completed with error: wsrep_sst_mysqldump --user 'wsrep_sst' --password 'password' --host '192.168.100.2' --port '3307' --local-port '3307' --socket '/var/run/mysqld/mysqld.sock' --gtid 'e3b83a53-2670-11e3-0800-a25e34e5a4ee:18588': 1 (Operation not permitted)
130926 12:26:55 [ERROR] WSREP: Try 3/3: 'wsrep_sst_mysqldump --user 'wsrep_sst' --password 'password' --host '192.168.100.2' --port '3307' --local-port '3307' --socket '/var/run/mysqld/mysqld.sock' --gtid 'e3b83a53-2670-11e3-0800-a25e34e5a4ee:18588'' failed: 1 (Operation not permitted)
130926 12:26:56 [Warning] WSREP: 0 (controller-1): State transfer to 1 (controller-2) failed: -1 (Operation not permitted)
130926 12:26:56 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 18596)
130926 12:26:57 [Note] WSREP: Member 0 (controller-1) synced with group.
130926 12:26:57 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 18596)
130926 12:26:57 [Note] WSREP: Synchronized with group, ready for connections
130926 12:26:57 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
130926 12:26:57 [Note] WSREP: Node 1c71f1e7-26a1-11e3-0800-c5ced489d4ae state prim
130926 12:26:57 [Note] WSREP: view(view_id(PRIM,1c71f1e7-26a1-11e3-0800-c5ced489d4ae,9) memb {
        1c71f1e7-26a1-11e3-0800-c5ced489d4ae,
} joined {
} left {
} partitioned {
        eb9d8fcd-26a6-11e3-0800-c0b3657652d1,
})
130926 12:26:57 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 1
130926 12:26:57 [Note] WSREP: forgetting eb9d8fcd-26a6-11e3-0800-c0b3657652d1 (tcp://192.168.100.2:4567)
130926 12:26:57 [Note] WSREP: STATE_EXCHANGE: sent state UUID: ef8cfc9e-26a6-11e3-0800-4d04f9603dc3
130926 12:26:57 [Note] WSREP: STATE EXCHANGE: sent state msg: ef8cfc9e-26a6-11e3-0800-4d04f9603dc3
130926 12:26:57 [Note] WSREP: STATE EXCHANGE: got state msg: ef8cfc9e-26a6-11e3-0800-4d04f9603dc3 from 0 (controller-1)
130926 12:26:57 [Note] WSREP: Quorum results:
        version    = 2,
        component  = PRIMARY,
        conf_id    = 8,
        members    = 1/1 (joined/total),
        act_id     = 18596,
        last_appl. = 17638,
        protocols  = 0/4/2 (gcs/repl/appl),
        group UUID = e3b83a53-2670-11e3-0800-a25e34e5a4ee
130926 12:26:57 [Note] WSREP: Flow-control interval: [16, 16]
130926 12:26:57 [Note] WSREP: New cluster view: global state: e3b83a53-2670-11e3-0800-a25e34e5a4ee:18596, view# 9: Primary, number of nodes: 1, my index: 0, protocol version 2
130926 12:26:57 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
130926 12:26:57 [Note] WSREP: Assign initial position for certification: 18596, protocol version: 2
130926 12:27:02 [Note] WSREP:  cleaning up eb9d8fcd-26a6-11e3-0800-c0b3657652d1 (tcp://192.168.100.2:4567)

Please tell me I forgot something silly. I've checked mysql.user wsrep_sst has only ONE match for '%' host.

Thank you!

Best Regards,
-Peter

Alex Yurchenko

unread,
Sep 26, 2013, 10:45:20 AM9/26/13
to codersh...@googlegroups.com
Nah, this is not Galera-related. Either make sure host 192.168.100.1 can
connect to both servers (how else do you expect to do mysqldump from one
to another?), or use rsync SST.

Regards,
Alex

On 2013-09-26 15:58, Peto Michalak wrote:
> Hi Guys!
>
> I am testing out galera replication, it was working nicely once, but
> when I
> came back to it and booted up my virtual machine I cannot make it work
> again. I have two nodes (I've read about split brain condition - I
> don't
> think that's the issue). FirstNode starts fine and it's synced (with
> itself), but the secondNode doesn't want to join...
>
> *SecondNode logs *(controller-2 192.168.100.2)*:*
> *FirstNode logs *(controller-1 192.168.100.1)*:*
> *ERROR 1130 (HY000): Host '192.168.100.1' is not allowed to connect to
> this
> MySQL server*
> *130926 12:26:53 [ERROR] WSREP: Process completed with error:
> wsrep_sst_mysqldump --user 'wsrep_sst' --password 'password' --host
> '192.168.100.2' --port '3307' --local-port '3307' --socket
> '/var/run/mysqld/mysqld.sock' --gtid
> 'e3b83a53-2670-11e3-0800-a25e34e5a4ee:18588': 1 (Operation not
> permitted)*
> *130926 12:26:53 [ERROR] WSREP: Try 1/3: 'wsrep_sst_mysqldump --user
> 'wsrep_sst' --password 'password' --host '192.168.100.2' --port '3307'
> --local-port '3307' --socket '/var/run/mysqld/mysqld.sock' --gtid
> 'e3b83a53-2670-11e3-0800-a25e34e5a4ee:18588'' failed: 1 (Operation not
> permitted)*
> *ERROR 1130 (HY000): Host '192.168.100.1' is not allowed to connect to
> this
> MySQL server*
> *130926 12:26:54 [ERROR] WSREP: Process completed with error:
> wsrep_sst_mysqldump --user 'wsrep_sst' --password 'password' --host
> '192.168.100.2' --port '3307' --local-port '3307' --socket
> '/var/run/mysqld/mysqld.sock' --gtid
> 'e3b83a53-2670-11e3-0800-a25e34e5a4ee:18588': 1 (Operation not
> permitted)*
> *130926 12:26:54 [ERROR] WSREP: Try 2/3: 'wsrep_sst_mysqldump --user
> 'wsrep_sst' --password 'password' --host '192.168.100.2' --port '3307'
> --local-port '3307' --socket '/var/run/mysqld/mysqld.sock' --gtid
> 'e3b83a53-2670-11e3-0800-a25e34e5a4ee:18588'' failed: 1 (Operation not
> permitted)*
> *ERROR 1130 (HY000): Host '192.168.100.1' is not allowed to connect to
> this
> MySQL server*
> *130926 12:26:55 [ERROR] WSREP: Process completed with error:
> wsrep_sst_mysqldump --user 'wsrep_sst' --password 'password' --host
> '192.168.100.2' --port '3307' --local-port '3307' --socket
> '/var/run/mysqld/mysqld.sock' --gtid
> 'e3b83a53-2670-11e3-0800-a25e34e5a4ee:18588': 1 (Operation not
> permitted)*
> *130926 12:26:55 [ERROR] WSREP: Try 3/3: 'wsrep_sst_mysqldump --user
> 'wsrep_sst' --password 'password' --host '192.168.100.2' --port '3307'
> --local-port '3307' --socket '/var/run/mysqld/mysqld.sock' --gtid
> 'e3b83a53-2670-11e3-0800-a25e34e5a4ee:18588'' failed: 1 (Operation not
> permitted)*
> *130926 12:26:56 [Warning] WSREP: 0 (controller-1): State transfer to 1
> (controller-2) failed: -1 (Operation not permitted)*
--
Alexey Yurchenko,
Codership Oy, www.codership.com
Skype: alexey.yurchenko, Phone: +358-400-516-011

Peto Michalak

unread,
Sep 27, 2013, 3:03:32 AM9/27/13
to codersh...@googlegroups.com
Hi Alexey,

oh thank you very much for pointing me in the right direction. I was so blind, looking at logs that there was initial communication between nodes, but mysql dump failed. If anyone has the same issue, check permissions in both nodes (mysql.user table). Second node mysql server shut down shortly after start so I had to run it as primary node, grant permissions shut it down and change it back to join with the first node. But I am replicating now! Great.

Best Regards,
-Peter

PS: Also this helped me to understand more and find the cause
http://dev.mysql.com/doc/refman/5.1/en/can-not-connect-to-server.html
Reply all
Reply to author
Forward
0 new messages