Hi,
On Sep 14, 2007, at 10:07 , Gérard BUNEL wrote:
Hello,
Setting up a Raid-b1 configuration, my 2 controllers can't see each
other
Looking at the logs I can see messages exchanged between the 2
controllers but for some reason I don't know
the 2 controllers can't add the other in the group. I've set all
log messages to DEBUG level
to be able to analyze. Can someone give some help on this problem ?
Looking at Appia, they can see each other. This is the start of the
view change process, when this group member detects that there is
another member to join:
2007-09-14 11:02:36,716 DEBUG group.intra.IntraSession Started view
change due to ViewChange
2007-09-14 11:02:36,717 DEBUG group.sync.VSyncSession Started blocking
2007-09-14 11:02:36,717 DEBUG group.bottom.GroupBottomSession
Trying to send to somenone but i'm the only one. Discarding Event
2007-09-14 11:02:36,717 DEBUG continuent.hedera.gms Appia reported
block()
This is the new view, with 2 members in the group:
2007-09-14 11:02:38,227 DEBUG continuent.hedera.appia Received new
view:
version: 1
group: [Group:MATISSEDB]
id: [ViewID:1;[AppiaHedera@/192.168.87.54:32768]]
previous: [[ViewID:0;[AppiaHedera@/192.168.87.54:32768]],[ViewID:0;
[AppiaHedera@/192.168.87.64:32768]],]
view: [[AppiaHedera@/192.168.87.54:32768],[AppiaHedera@/
192.168.87.64:32768],]
addresses: [/192.168.87.54:32768,/192.168.87.64:32768,]
2007-09-14 11:02:38,228 DEBUG group.heal.GossipOutSession placing
my address /192.168.87.54:32768 on message to /224.1.1.5:45566
2007-09-14 11:02:38,228 DEBUG continuent.hedera.gms Appia reported
new view:
version: 1
group: [Group:MATISSEDB]
id: [ViewID:1;[AppiaHedera@/192.168.87.54:32768]]
previous: [[ViewID:0;[AppiaHedera@/192.168.87.54:32768]],[ViewID:0;
[AppiaHedera@/192.168.87.64:32768]],]
view: [[AppiaHedera@/192.168.87.54:32768],[AppiaHedera@/
192.168.87.64:32768],]
addresses: [/192.168.87.54:32768,/192.168.87.64:32768,]
2007-09-14 11:02:38,229 DEBUG continuent.hedera.gms Member(address=/
192.168.87.64:32768, uid=192.168.87.64:32768) joins Group
(gid=MATISSEDB).
And then we can see a lot of control messages on Appia.
After a while, we can see some messages in the from the Sequoia
controller being exchanged. The AppiaGroupEvent is a message produced
by Sequoia.
2007-09-14 11:03:37,284 DEBUG protocols.udpsimple.UdpSimpleSession
$UdpSimpleReader :run: PtP datagram received. Size = 1661
2007-09-14 11:03:37,285 DEBUG protocols.udpsimple.UdpSimpleSession
$UdpSimpleReader :receiveAndFormat: Reader, creating
org.continuent.hedera.appia.AppiaGroupEvent event.
2007-09-14 11:03:37,285 DEBUG protocols.udpsimple.UdpSimpleSession
$UdpSimpleReader :receiveAndFormat: UDP p2p TOKEN Channel (1135015211)
2007-09-14 11:03:37,285 DEBUG
protocols.udpsimple.UdpSimpleSession :handleSendable:
[EMAIL PROTECTED]
2007-09-14 11:03:37,285 DEBUG group.bottom.GroupBottomSession
Received message
[EMAIL PROTECTED] from 1
And then you see a message from Sequoia like this:
2007-09-14 11:03:37,305 DEBUG controller.virtualdatabase.MATISSEDB
handleMessageSingleThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.SuspendActi
vity):
org.continuent.sequoia.controller.virtualdatabase.protocol.SuspendActi
[EMAIL PROTECTED]
2007-09-14 11:03:37,309 DEBUG controller.virtualdatabase.MATISSEDB
handleMessageMultiThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.SuspendActi
vity):
org.continuent.sequoia.controller.virtualdatabase.protocol.SuspendActi
[EMAIL PROTECTED]
2007-09-14 11:03:37,309 DEBUG sequoia.controller.scheduler
Suspending new persistent connections
2007-09-14 11:03:37,309 DEBUG sequoia.controller.scheduler
Suspending new transactions and writes
2007-09-14 11:03:37,309 DEBUG sequoia.controller.scheduler All
writes suspended
2007-09-14 11:03:37,309 DEBUG sequoia.controller.scheduler All
transactions suspended
2007-09-14 11:03:37,309 DEBUG sequoia.controller.scheduler All
persistent connections closed
2007-09-14 11:03:37,310 DEBUG continuent.hedera.adapters Replying
to Member(address=/192.168.87.64:32768, uid=192.168.87.64:32768)
for message 0
(...)
2007-09-14 11:03:37,813 DEBUG sequoia.controller.loadbalancer
Removed
org.continuent.sequoia.controller.virtualdatabase.protocol.SuspendWrit
[EMAIL PROTECTED] from total order queue
2007-09-14 11:03:37,816 INFO controller.virtualdatabase.MATISSEDB
Checkpoint disable all
backends-192.168.87.64:25322-20070914031034930+0200 was stored
2007-09-14 11:03:37,816 WARN controller.virtualdatabase.MATISSEDB
No information has been found for remote controller Member(address=/
192.168.87.64:32768, uid=192.168.87.64:32768)
2007-09-14 11:03:37,817 WARN controller.virtualdatabase.MATISSEDB
Updating backend list with unknown backend sd01 disabled on
controller Member(address=/192.168.87.64:32768,
uid=192.168.87.64:32768)
2007-09-14 11:03:37,817 DEBUG continuent.hedera.adapters Replying
to Member(address=/192.168.87.64:32768, uid=192.168.87.64:32768)
for message 1
2007-09-14 11:03:37,819 DEBUG sequoia.controller.recoverylog
Storing checkpoint disable all
backends-192.168.87.64:25322-20070914031034930+0200 at request id 0
After a while, this group member receives a LeaveEvent from the other
controller. This somehow was forced by the other controller and will
cause this one leave the group:
2007-09-14 11:03:40,374 DEBUG protocols.udpsimple.UdpSimpleSession
$UdpSimpleReader :receiveAndFormat: Reader, creating
org.continuent.appia.protocols.group.leave.LeaveEvent event.
2007-09-14 11:03:40,375 DEBUG protocols.udpsimple.UdpSimpleSession
$UdpSimpleReader :receiveAndFormat: UDP p2p TOKEN Channel (1135015211)
2007-09-14 11:03:40,375 DEBUG
protocols.udpsimple.UdpSimpleSession :handleSendable:
[EMAIL PROTECTED]
2007-09-14 11:03:40,375 DEBUG group.bottom.GroupBottomSession
Received message
[EMAIL PROTECTED] from 1
2007-09-14 11:03:40,375 DEBUG group.stable.StableSession Received
147 from 1
2007-09-14 11:03:40,376 DEBUG total.token.TotalTokenSession My rank
= 0 hasToken = 1
2007-09-14 11:03:40,376 DEBUG total.token.TotalTokenSession
Received Group Sendable from the network with seq = 294 token = true
2007-09-14 11:03:40,376 DEBUG total.token.TotalTokenSession
Delivering message with seq = 294
2007-09-14 11:03:40,376 DEBUG total.token.TotalTokenSession I'll
try to send some messages
2007-09-14 11:03:40,376 DEBUG total.token.TotalTokenSession I do
not have any messages. Rotanting token. My rank is 0
2007-09-14 11:03:40,376 DEBUG group.intra.IntraSession Started view
change due to ViewChange
2007-09-14 11:03:40,376 DEBUG group.bottom.GroupBottomSession
Sending message (isSend=false)
[EMAIL PROTECTED]
2007-09-14 11:03:40,376 DEBUG
protocols.udpsimple.UdpSimpleSession :handleSendable:
[EMAIL PROTECTED]
2007-09-14 11:03:40,377 DEBUG
protocols.udpsimple.UdpSimpleSession :formatAndSend: 106 bytes
datagram sent to 192.168.87.64 (port 32768)
2007-09-14 11:03:40,377 DEBUG group.sync.VSyncSession Started blocking
2007-09-14 11:03:40,377 DEBUG group.bottom.GroupBottomSession
Sending message (isSend=true)
[EMAIL PROTECTED]
2007-09-14 11:03:40,377 DEBUG
protocols.udpsimple.UdpSimpleSession :handleSendable:
[EMAIL PROTECTED]
2007-09-14 11:03:40,377 DEBUG
protocols.udpsimple.UdpSimpleSession :formatAndSend: 89 bytes
datagram sent to 192.168.87.64 (port 32768)
2007-09-14 11:03:40,378 DEBUG continuent.hedera.gms Appia reported
block()
2007-09-14 11:03:40,378 DEBUG group.sync.VSyncSession {0} Sending
my_casts and my_sends_sent to coordinator
2007-09-14 11:03:40,378 DEBUG group.sync.VSyncSession my_casts=[,,]
2007-09-14 11:03:40,378 DEBUG group.sync.VSyncSession my_sends_sent=
[,,]
2007-09-14 11:03:40,379 DEBUG protocols.udpsimple.UdpSimpleSession
$UdpSimpleReader :run: PtP datagram received. Size = 110
2007-09-14 11:03:40,379 DEBUG protocols.udpsimple.UdpSimpleSession
$UdpSimpleReader :receiveAndFormat: Reader, creating
org.continuent.appia.protocols.total.token.TokenEvent event.
2007-09-14 11:03:40,379 DEBUG protocols.udpsimple.UdpSimpleSession
$UdpSimpleReader :receiveAndFormat: UDP p2p TOKEN Channel (1135015211)
2007-09-14 11:03:40,380 DEBUG
protocols.udpsimple.UdpSimpleSession :handleSendable:
[EMAIL PROTECTED]
2007-09-14 11:03:40,380 DEBUG group.bottom.GroupBottomSession
Received message
[EMAIL PROTECTED] from 1
2007-09-14 11:03:40,380 DEBUG group.stable.StableSession Received
gossip information from 1 (doClean=true)
2007-09-14 11:03:40,380 DEBUG group.stable.StableSession Received
148 from 1
2007-09-14 11:03:40,380 DEBUG group.stable.StableStorage Cleaned
116 from 1
2007-09-14 11:03:40,380 DEBUG group.stable.StableStorage Cleaned
117 from 1
2007-09-14 11:03:40,380 DEBUG group.stable.StableStorage Cleaned
118 from 1
2007-09-14 11:03:40,380 DEBUG group.stable.StableStorage Cleaned
119 from 1
2007-09-14 11:03:40,380 DEBUG group.stable.StableStorage Cleaned
120 from 1
2007-09-14 11:03:40,381 DEBUG group.stable.StableStorage Cleaned
121 from 1
2007-09-14 11:03:40,381 DEBUG group.stable.StableStorage Cleaned
122 from 1
2007-09-14 11:03:40,381 DEBUG group.stable.StableStorage Cleaned
123 from 1
2007-09-14 11:03:40,381 DEBUG group.stable.StableStorage Cleaned
124 from 1
2007-09-14 11:03:40,381 DEBUG protocols.udpsimple.UdpSimpleSession
$UdpSimpleReader :run: PtP datagram received. Size = 129
2007-09-14 11:03:40,381 DEBUG group.stable.StableStorage Cleaned
125 from 1
2007-09-14 11:03:40,381 DEBUG protocols.udpsimple.UdpSimpleSession
$UdpSimpleReader :receiveAndFormat: Reader, creating
org.continuent.appia.protocols.group.sync.Block event.
2007-09-14 11:03:40,381 DEBUG group.stable.StableStorage Cleaned
126 from 1
2007-09-14 11:03:40,381 DEBUG group.stable.StableStorage Cleaned
127 from 1
2007-09-14 11:03:40,381 DEBUG protocols.udpsimple.UdpSimpleSession
$UdpSimpleReader :receiveAndFormat: UDP p2p TOKEN Channel (1135015211)
2007-09-14 11:03:40,381 DEBUG group.stable.StableStorage Cleaned
128 from 1
2007-09-14 11:03:40,382 DEBUG group.stable.StableStorage Cleaned
129 from 1
2007-09-14 11:03:40,382 DEBUG group.stable.StableStorage Cleaned
130 from 1
2007-09-14 11:03:40,382 DEBUG group.stable.StableStorage Cleaned
131 from 1
2007-09-14 11:03:40,382 DEBUG group.stable.StableStorage Cleaned
132 from 1
2007-09-14 11:03:40,382 DEBUG group.stable.StableStorage Cleaned
133 from 1
2007-09-14 11:03:40,382 DEBUG group.stable.StableStorage Cleaned
134 from 1
2007-09-14 11:03:40,382 DEBUG group.stable.StableStorage Cleaned
135 from 1
2007-09-14 11:03:40,382 DEBUG group.stable.StableStorage Cleaned
136 from 1
2007-09-14 11:03:40,382 DEBUG group.stable.StableStorage Cleaned
137 from 1
2007-09-14 11:03:40,383 DEBUG group.stable.StableStorage Cleaned
138 from 1
2007-09-14 11:03:40,383 DEBUG group.stable.StableStorage Cleaned
139 from 1
2007-09-14 11:03:40,383 DEBUG group.stable.StableStorage Cleaned
140 from 1
2007-09-14 11:03:40,383 DEBUG group.stable.StableStorage Cleaned
141 from 1
2007-09-14 11:03:40,383 DEBUG group.stable.StableStorage Cleaned
142 from 1
2007-09-14 11:03:40,383 DEBUG group.stable.StableStorage Cleaned
143 from 1
2007-09-14 11:03:40,383 DEBUG group.stable.StableStorage Cleaned
144 from 1
2007-09-14 11:03:40,383 DEBUG group.stable.StableStorage Cleaned
145 from 1
2007-09-14 11:03:40,384 DEBUG group.stable.StableStorage Cleaned
146 from 1
2007-09-14 11:03:40,384 DEBUG group.stable.StableStorage Cleaned
147 from 1
2007-09-14 11:03:40,384 DEBUG group.stable.StableStorage Cleaned
148 from 1
2007-09-14 11:03:40,384 DEBUG
protocols.udpsimple.UdpSimpleSession :handleSendable:
[EMAIL PROTECTED]
2007-09-14 11:03:40,384 DEBUG group.bottom.GroupBottomSession
Received message
[EMAIL PROTECTED] from 1
2007-09-14 11:03:40,384 DEBUG group.sync.VSyncSession {0} Ended
blocking started synching
2007-09-14 11:03:40,384 DEBUG group.sync.VSyncSession global_casts=
[,,]
2007-09-14 11:03:40,385 DEBUG group.sync.VSyncSession sends_table[0]
=[,,]
2007-09-14 11:03:40,385 DEBUG group.sync.VSyncSession sends_table[1]
=[,,]
2007-09-14 11:03:40,385 DEBUG group.sync.VSyncSession my_casts=[,,]
2007-09-14 11:03:40,385 DEBUG group.sync.VSyncSession testing in_sync
2007-09-14 11:03:40,385 DEBUG group.sync.VSyncSession in_sync:
my_casts==global_casts -> true
2007-09-14 11:03:40,385 DEBUG group.sync.VSyncSession in_sync:
my_sends_recv== global_sends -> true
2007-09-14 11:03:40,385 DEBUG total.token.TotalTokenSession My rank
= 0 hasToken = 1
2007-09-14 11:03:40,385 DEBUG total.token.TotalTokenSession
Received Group Sendable from the network with seq = 296 token = true
2007-09-14 11:03:40,385 DEBUG total.token.TotalTokenSession
Delivering message with seq = 296
2007-09-14 11:03:40,386 DEBUG group.bottom.GroupBottomSession
Sending message (isSend=true)
[EMAIL PROTECTED]
2007-09-14 11:03:40,386 DEBUG
protocols.udpsimple.UdpSimpleSession :handleSendable:
[EMAIL PROTECTED]
2007-09-14 11:03:40,386 DEBUG
protocols.udpsimple.UdpSimpleSession :formatAndSend: 128 bytes
datagram sent to 192.168.87.64 (port 32768)
2007-09-14 11:03:40,389 DEBUG protocols.udpsimple.UdpSimpleSession
$UdpSimpleReader :run: PtP datagram received. Size = 108
2007-09-14 11:03:40,389 DEBUG protocols.udpsimple.UdpSimpleSession
$UdpSimpleReader :receiveAndFormat: Reader, creating
org.continuent.appia.protocols.group.sync.Sync event.
2007-09-14 11:03:40,389 DEBUG protocols.udpsimple.UdpSimpleSession
$UdpSimpleReader :receiveAndFormat: UDP p2p TOKEN Channel (1135015211)
2007-09-14 11:03:40,389 DEBUG
protocols.udpsimple.UdpSimpleSession :handleSendable:
[EMAIL PROTECTED]
2007-09-14 11:03:40,390 DEBUG group.bottom.GroupBottomSession
Received message
[EMAIL PROTECTED] from 1
2007-09-14 11:03:40,390 DEBUG
protocols.udpsimple.UdpSimpleSession :handleSendable:
[EMAIL PROTECTED]
2007-09-14 11:03:40,390 DEBUG
protocols.udpsimple.UdpSimpleSession :formatAndSend: 85 bytes
datagram sent to 192.168.87.64 (port 32768)
2007-09-14 11:03:40,390 DEBUG group.bottom.GroupBottomSession
Sending message (isSend=false)
[EMAIL PROTECTED]
2007-09-14 11:03:40,391 DEBUG
protocols.udpsimple.UdpSimpleSession :handleSendable:
[EMAIL PROTECTED]
2007-09-14 11:03:40,391 DEBUG
protocols.udpsimple.UdpSimpleSession :formatAndSend: 248 bytes
datagram sent to 192.168.87.64 (port 32768)
2007-09-14 11:03:40,391 DEBUG group.bottom.GroupBottomSession
Recived new view: group=-711498822 view=1146261631
2007-09-14 11:03:40,391 DEBUG group.heal.HealSession Sending Gossip
to Server
2007-09-14 11:03:40,391 DEBUG total.token.TotalTokenSession
Received new view with 1 members
2007-09-14 11:03:40,391 DEBUG total.token.TotalTokenSession I'll
try to send some messages
2007-09-14 11:03:40,392 DEBUG continuent.hedera.appia Received new
view:
version: 1
group: [Group:MATISSEDB]
id: [ViewID:2;[AppiaHedera@/192.168.87.54:32768]]
previous: [[ViewID:1;[AppiaHedera@/192.168.87.54:32768]],]
view: [[AppiaHedera@/192.168.87.54:32768],]
addresses: [/192.168.87.54:32768,]
2007-09-14 11:03:40,392 DEBUG group.heal.GossipOutSession placing
my address /192.168.87.54:32768 on message to /224.1.1.5:45566
2007-09-14 11:03:40,392 DEBUG continuent.hedera.gms Appia reported
new view:
version: 1
group: [Group:MATISSEDB]
id: [ViewID:2;[AppiaHedera@/192.168.87.54:32768]]
previous: [[ViewID:1;[AppiaHedera@/192.168.87.54:32768]],]
view: [[AppiaHedera@/192.168.87.54:32768],]
addresses: [/192.168.87.54:32768,]
2007-09-14 11:03:40,392 DEBUG
protocols.udpsimple.UdpSimpleSession :handleSendable:
[EMAIL PROTECTED]
2007-09-14 11:03:40,392 DEBUG continuent.hedera.gms Member(address=/
192.168.87.64:32768, uid=192.168.87.64:32768) leaves Group
(gid=MATISSEDB).
At this point, they are separated again.
So, in my eyes they see each other and join. What happen after that
causes Sequoia to suspend the activity and separate the group again,
I do not understand. Maybe you get some clues if you check the
Sequoia debug logs before the LeaveEvent.
Hope this helps.
Regards,
--
Nuno Carvalho
University of Lisbon, Portugal
http://lasige.di.fc.ul.pt/~ncarvalho
_______________________________________________
Sequoia mailing list
[email protected]
https://forge.continuent.org/mailman/listinfo/sequoia
