Donor - Cannot assign requested address

[Jaykah]

Galera 25.3.5-wheezy(rXXXX)
Percona XtraDB 5.5.37-MariaDB-35.0
Built in Docker from https://github.com/neildunbar/mariadb55
Ubuntu trusty

1. Started first node in Donor mode
2. Connected node 2 and 3
3. They got in sync, everything was working fine

Until this happens to the donor:

140827 8:54:35 [Note] WSREP: (aaa04c84-2d4c-11e4-a1fe-c605ab19a328, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: tcp://10.0.1.5:4567
140827 8:54:35 [Warning] WSREP: last inactive check more than PT1.5S ago (PT5.52987S), skipping check
140827 8:54:35 [Note] WSREP: (aaa04c84-2d4c-11e4-a1fe-c605ab19a328, 'tcp://0.0.0.0:4567') turning message relay requesting off
140827 8:54:35 [Note] WSREP: view(view_id(NON_PRIM,1df53171-2d4d-11e4-829e-c29c0950cb7d,3) memb {
 aaa04c84-2d4c-11e4-a1fe-c605ab19a328,0
} joined {
} left {
} partitioned {
 1df53171-2d4d-11e4-829e-c29c0950cb7d,0
 d616fec0-2d4d-11e4-b768-d28e90659024,0
})
140827 8:54:35 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
140827 8:54:35 [Note] WSREP: Flow-control interval: [16, 16]
140827 8:54:35 [Note] WSREP: Received NON-PRIMARY.
140827 8:54:35 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 714927)
140827 8:54:35 [Note] WSREP: view(view_id(NON_PRIM,aaa04c84-2d4c-11e4-a1fe-c605ab19a328,4) memb {
 aaa04c84-2d4c-11e4-a1fe-c605ab19a328,0
} joined {
} left {
} partitioned {
 1df53171-2d4d-11e4-829e-c29c0950cb7d,0
 d616fec0-2d4d-11e4-b768-d28e90659024,0
})
140827 8:54:35 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
140827 8:54:35 [Note] WSREP: Flow-control interval: [16, 16]
140827 8:54:35 [Note] WSREP: Received NON-PRIMARY.
140827 8:54:36 [Note] WSREP: (aaa04c84-2d4c-11e4-a1fe-c605ab19a328, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: tcp://10.0.1.11:4567 tcp://10.0.1.5:4567
140827 8:54:37 [Note] WSREP: (aaa04c84-2d4c-11e4-a1fe-c605ab19a328, 'tcp://0.0.0.0:4567') reconnecting to d616fec0-2d4d-11e4-b768-d28e90659024 (tcp://10.0.1.11:4567), attempt 0
140827 8:54:37 [Note] WSREP: (aaa04c84-2d4c-11e4-a1fe-c605ab19a328, 'tcp://0.0.0.0:4567') reconnecting to 1df53171-2d4d-11e4-829e-c29c0950cb7d (tcp://10.0.1.5:4567), attempt 0
140827 8:54:38 [Note] WSREP: (aaa04c84-2d4c-11e4-a1fe-c605ab19a328, 'tcp://0.0.0.0:4567') reconnecting to d616fec0-2d4d-11e4-b768-d28e90659024 (tcp://10.0.1.11:4567), attempt 0
140827 8:54:38 [Note] WSREP: (aaa04c84-2d4c-11e4-a1fe-c605ab19a328, 'tcp://0.0.0.0:4567') reconnecting to 1df53171-2d4d-11e4-829e-c29c0950cb7d (tcp://10.0.1.5:4567), attempt 0
140827 8:54:40 [Note] WSREP: (aaa04c84-2d4c-11e4-a1fe-c605ab19a328, 'tcp://0.0.0.0:4567') reconnecting to d616fec0-2d4d-11e4-b768-d28e90659024 (tcp://10.0.1.11:4567), attempt 0
140827 8:54:40 [Note] WSREP: (aaa04c84-2d4c-11e4-a1fe-c605ab19a328, 'tcp://0.0.0.0:4567') reconnecting to 1df53171-2d4d-11e4-829e-c29c0950cb7d (tcp://10.0.1.5:4567), attempt 0
140827 8:54:40 [Warning] WSREP: Send action {(nil), 360, TORDERED} returned -107 (Transport endpoint is not connected)
140827 8:54:40 [Note] WSREP: evs::proto(aaa04c84-2d4c-11e4-a1fe-c605ab19a328, GATHER, view_id(REG,aaa04c84-2d4c-11e4-a1fe-c605ab19a328,4)) suspecting node: 1df53171-2d4d-11e4-829e-c29c0950cb7d
140827 8:54:40 [Note] WSREP: evs::proto(aaa04c84-2d4c-11e4-a1fe-c605ab19a328, GATHER, view_id(REG,aaa04c84-2d4c-11e4-a1fe-c605ab19a328,4)) suspecting node: d616fec0-2d4d-11e4-b768-d28e90659024
140827 8:54:41 [Note] WSREP: (aaa04c84-2d4c-11e4-a1fe-c605ab19a328, 'tcp://0.0.0.0:4567') reconnecting to d616fec0-2d4d-11e4-b768-d28e90659024 (tcp://10.0.1.11:4567), attempt 0
140827 8:54:41 [Note] WSREP: (aaa04c84-2d4c-11e4-a1fe-c605ab19a328, 'tcp://0.0.0.0:4567') reconnecting to 1df53171-2d4d-11e4-829e-c29c0950cb7d (tcp://10.0.1.5:4567), attempt 0
140827 8:54:41 [Note] WSREP: (aaa04c84-2d4c-11e4-a1fe-c605ab19a328, 'tcp://0.0.0.0:4567') turning message relay requesting off
140827 8:54:41 [Warning] WSREP: subsequent views have same members, prev view view(view_id(REG,aaa04c84-2d4c-11e4-a1fe-c605ab19a328,4) memb {
 aaa04c84-2d4c-11e4-a1fe-c605ab19a328,0
} joined {
} left {
} partitioned {
}) current view view(view_id(REG,aaa04c84-2d4c-11e4-a1fe-c605ab19a328,5) memb {
 aaa04c84-2d4c-11e4-a1fe-c605ab19a328,0
} joined {
} left {
} partitioned {
})
140827 8:54:41 [Note] WSREP: view(view_id(NON_PRIM,aaa04c84-2d4c-11e4-a1fe-c605ab19a328,5) memb {
 aaa04c84-2d4c-11e4-a1fe-c605ab19a328,0
} joined {
} left {
} partitioned {
 1df53171-2d4d-11e4-829e-c29c0950cb7d,0
 d616fec0-2d4d-11e4-b768-d28e90659024,0
})
140827 8:54:41 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
140827 8:54:41 [Note] WSREP: Flow-control interval: [16, 16]
140827 8:54:41 [Note] WSREP: Received NON-PRIMARY.
140827 8:54:41 [Note] WSREP: declaring 1df53171-2d4d-11e4-829e-c29c0950cb7d stable
140827 8:54:41 [Note] WSREP: declaring d616fec0-2d4d-11e4-b768-d28e90659024 stable
140827 8:54:41 [Note] WSREP: Node 1df53171-2d4d-11e4-829e-c29c0950cb7d state prim
140827 8:54:41 [Note] WSREP: view(view_id(PRIM,1df53171-2d4d-11e4-829e-c29c0950cb7d,6) memb {
 1df53171-2d4d-11e4-829e-c29c0950cb7d,0
 aaa04c84-2d4c-11e4-a1fe-c605ab19a328,0
 d616fec0-2d4d-11e4-b768-d28e90659024,0
} joined {
} left {
} partitioned {
})
140827 8:54:41 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 3
140827 8:54:41 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
140827 8:54:41 [Note] WSREP: STATE EXCHANGE: sent state msg: c87d2c4a-2dc7-11e4-97a4-16ee176669aa
140827 8:54:41 [Note] WSREP: STATE EXCHANGE: got state msg: c87d2c4a-2dc7-11e4-97a4-16ee176669aa from 0 ()
140827 8:54:41 [Note] WSREP: STATE EXCHANGE: got state msg: c87d2c4a-2dc7-11e4-97a4-16ee176669aa from 1 (283c4a3333ec)
140827 8:54:41 [Note] WSREP: STATE EXCHANGE: got state msg: c87d2c4a-2dc7-11e4-97a4-16ee176669aa from 2 ()
140827 8:54:41 [Note] WSREP: Quorum results:
 version = 3,
 component = PRIMARY,
 conf_id = 4,
 members = 2/3 (joined/total),
 act_id = 714953,
 last_appl. = 714853,
 protocols = 0/5/2 (gcs/repl/appl),
 group UUID = 40179a77-2bf4-11e4-b46a-a30695b570ce
140827 8:54:41 [Note] WSREP: Flow-control interval: [28, 28]
140827 8:54:41 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 714953)
140827 8:54:45 [Note] WSREP: New cluster view: global state: 40179a77-2bf4-11e4-b46a-a30695b570ce:714927, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 2
140827 8:54:45 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
140827 8:54:45 [Note] WSREP: New cluster view: global state: 40179a77-2bf4-11e4-b46a-a30695b570ce:714927, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 2
140827 8:54:45 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
140827 8:54:45 [Note] WSREP: New cluster view: global state: 40179a77-2bf4-11e4-b46a-a30695b570ce:714927, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 2
140827 8:54:45 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
140827 8:54:45 [Note] WSREP: State transfer required:
 Group state: 40179a77-2bf4-11e4-b46a-a30695b570ce:714953
 Local state: 40179a77-2bf4-11e4-b46a-a30695b570ce:714927
140827 8:54:45 [Note] WSREP: New cluster view: global state: 40179a77-2bf4-11e4-b46a-a30695b570ce:714953, view# 5: Primary, number of nodes: 3, my index: 1, protocol version 2
140827 8:54:45 [Warning] WSREP: Gap in state sequence. Need state transfer.
140827 8:54:47 [Note] WSREP: You have configured 'xtrabackup-v2' state snapshot transfer method which cannot be performed on a running server. Wsrep provider won't be able to fall back to it if other means of state transfer are unavailable. In that case you will need to restart the server.
140827 8:54:47 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
140827 8:54:47 [Note] WSREP: REPL Protocols: 5 (3, 1)
140827 8:54:47 [Note] WSREP: Service thread queue flushed.
140827 8:54:47 [Note] WSREP: Assign initial position for certification: 714953, protocol version: 3
140827 8:54:47 [Note] WSREP: Service thread queue flushed.
140827 8:54:47 [Warning] WSREP: Releasing seqno 714927 before 714928 was assigned.
140827 8:54:48 [Warning] WSREP: Failed to prepare for incremental state transfer: Failed to open IST listener at tcp://10.0.1.10:4568', asio error 'Cannot assign requested address': 99 (Cannot assign requested address)
  at galera/src/ist.cpp:prepare():334. IST will be unavailable.
140827 8:54:48 [Note] WSREP: Member 1.0 (283c4a3333ec) requested state transfer from '*any*'. Selected 0.0 ()(SYNCED) as donor.
140827 8:54:48 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 714955)
140827 8:54:48 [Note] WSREP: Requesting state transfer: success, donor: 0
140827 8:54:48 [Note] WSREP: GCache DEBUG: RingBuffer::seqno_reset(): discarded 0 bytes
140827 8:54:48 [Note] WSREP: GCache DEBUG: RingBuffer::seqno_reset(): found 1/2 locked buffers
140827 8:54:48 [Warning] WSREP: 0.0 (): State transfer to 1.0 (283c4a3333ec) failed: -125 (Operation canceled)
140827 8:54:48 [ERROR] WSREP: gcs/src/gcs_group.c:gcs_group_handle_join_msg():723: Will never receive state. Need to abort.
140827 8:54:48 [Note] WSREP: gcomm: terminating thread
140827 8:54:48 [Note] WSREP: gcomm: joining thread
140827 8:54:48 [Note] WSREP: gcomm: closing backend
140827 8:54:48 [Note] WSREP: view(view_id(NON_PRIM,1df53171-2d4d-11e4-829e-c29c0950cb7d,6) memb {
 aaa04c84-2d4c-11e4-a1fe-c605ab19a328,0
} joined {
} left {
} partitioned {
 1df53171-2d4d-11e4-829e-c29c0950cb7d,0
 d616fec0-2d4d-11e4-b768-d28e90659024,0
})
140827 8:54:48 [Note] WSREP: view((empty))
140827 8:54:48 [Note] WSREP: gcomm: closed
140827 8:54:48 [Note] WSREP: /usr/sbin/mysqld: Terminated.

This has happened multiple times, usually after 10 or so hours of operation.

[Jaykah (jaykah)]

Once again, the following day:

140902 7:16:30 [Note] WSREP: (451a0e59-3188-11e4-8945-026d25e51b59, 'tcp://0.0.0.0:4567') address 'tcp://10.0.1.10:4567' pointing to uuid 451a0e59-3188-11e4-8945-026d25e51b59 is blacklisted, skipping
140902 7:16:32 [Note] WSREP: (451a0e59-3188-11e4-8945-026d25e51b59, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: tcp://10.0.1.11:4567
140902 7:16:34 [Note] WSREP: (451a0e59-3188-11e4-8945-026d25e51b59, 'tcp://0.0.0.0:4567') reconnecting to 34535308-319d-11e4-962e-367c0d11956c (tcp://10.0.1.11:4567), attempt 0
140902 7:16:34 [Warning] WSREP: last inactive check more than PT1.5S ago (PT4.20089S), skipping check
140902 7:16:34 [Note] WSREP: (451a0e59-3188-11e4-8945-026d25e51b59, 'tcp://0.0.0.0:4567') cleaning up established 0x7fb69203d200 which is duplicate of 0x7fb652184400
140902 7:16:34 [Note] WSREP: (451a0e59-3188-11e4-8945-026d25e51b59, 'tcp://0.0.0.0:4567') address 'tcp://10.0.1.10:4567' pointing to uuid 451a0e59-3188-11e4-8945-026d25e51b59 is blacklisted, skipping
140902 7:16:34 [Note] WSREP: (451a0e59-3188-11e4-8945-026d25e51b59, 'tcp://0.0.0.0:4567') address 'tcp://10.0.1.10:4567' pointing to uuid 451a0e59-3188-11e4-8945-026d25e51b59 is blacklisted, skipping
140902 7:16:34 [Note] WSREP: (451a0e59-3188-11e4-8945-026d25e51b59, 'tcp://0.0.0.0:4567') address 'tcp://10.0.1.10:4567' pointing to uuid 451a0e59-3188-11e4-8945-026d25e51b59 is blacklisted, skipping
140902 7:16:34 [Note] WSREP: (451a0e59-3188-11e4-8945-026d25e51b59, 'tcp://0.0.0.0:4567') address 'tcp://10.0.1.10:4567' pointing to uuid 451a0e59-3188-11e4-8945-026d25e51b59 is blacklisted, skipping
140902 7:16:34 [Note] WSREP: (451a0e59-3188-11e4-8945-026d25e51b59, 'tcp://0.0.0.0:4567') turning message relay requesting off
140902 7:16:41 [Warning] WSREP: last inactive check more than PT1.5S ago (PT6.86932S), skipping check
140902 7:16:41 [Note] WSREP: (451a0e59-3188-11e4-8945-026d25e51b59, 'tcp://0.0.0.0:4567') address 'tcp://10.0.1.10:4567' pointing to uuid 451a0e59-3188-11e4-8945-026d25e51b59 is blacklisted, skipping
140902 7:16:42 [Note] WSREP: (451a0e59-3188-11e4-8945-026d25e51b59, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: tcp://10.0.1.11:4567 tcp://10.0.1.5:4567
140902 7:16:42 [Note] WSREP: (451a0e59-3188-11e4-8945-026d25e51b59, 'tcp://0.0.0.0:4567') reconnecting to 34535308-319d-11e4-962e-367c0d11956c (tcp://10.0.1.11:4567), attempt 0
140902 7:16:42 [Note] WSREP: (451a0e59-3188-11e4-8945-026d25e51b59, 'tcp://0.0.0.0:4567') reconnecting to 71da7145-3082-11e4-a9cb-d346363304ed (tcp://10.0.1.5:4567), attempt 0
140902 7:16:44 [Note] WSREP: (451a0e59-3188-11e4-8945-026d25e51b59, 'tcp://0.0.0.0:4567') reconnecting to 34535308-319d-11e4-962e-367c0d11956c (tcp://10.0.1.11:4567), attempt 0
140902 7:16:44 [Note] WSREP: (451a0e59-3188-11e4-8945-026d25e51b59, 'tcp://0.0.0.0:4567') reconnecting to 71da7145-3082-11e4-a9cb-d346363304ed (tcp://10.0.1.5:4567), attempt 0
140902 7:16:45 [Note] WSREP: (451a0e59-3188-11e4-8945-026d25e51b59, 'tcp://0.0.0.0:4567') reconnecting to 34535308-319d-11e4-962e-367c0d11956c (tcp://10.0.1.11:4567), attempt 0
140902 7:16:45 [Note] WSREP: (451a0e59-3188...

[Teemu Ollakka (teemu-ollakka)]

For some reason IST socked can't be bound to 10.0.1.10. Possible reason is that IST port is not published according to instructions in https://github.com/neildunbar/mariadb55. Adding option -p 4568:4568 to docker run command might help.

Marking as invalid as this is probably configuration problem. Also, Galera development has been moved to https://github.com/codership/galera. Please open a new issue there if problem persists after proper configuration.

[Jaykah (jaykah)]

The port is exposed, and mapped, so the issue is definitely not in configuration.

Have created an issue here: https://github.com/codership/galera/issues/103