Hi Nuno,
Can you explain the following 2 logs:
14:33:45,489 DEBUG protocols.udpsimple.UdpSimpleSession$UdpSimpleReader
:run: Ignored Last received message
14:33:49,759 DEBUG protocols.nakfifo.NakFifoSession @Timer Peer:
/192.168.87.65:32804
I found them when trying on 2 other machines.
Also, when I did the shutdown of the 2nd controller, the following
exception is thrown:
14:33:02,153 DEBUG protocols.udpsimple.UdpSimpleSession :formatAndSend:
129 bytes datagram sent to 192.168.87.55 (port 32798)
14:33:02,155 DEBUG continuent.hedera.adapters PullPushAdapter: Error
while reading from channel
org.continuent.hedera.channel.ChannelException:
org.continuent.hedera.appia.interfaces.ClosedChannelException: Channel
is closed
at
org.continuent.hedera.channel.AppiaReliableGroupChannel.receive(AppiaReliableGroupChannel.java:211)
at
org.continuent.hedera.adapters.PullPushAdapter.run(PullPushAdapter.java:166)
at java.lang.Thread.run(Thread.java:595)
Caused by:
org.continuent.hedera.appia.interfaces.ClosedChannelException: Channel
is closed
at
org.continuent.hedera.appia.AppiaGMS.receive(AppiaGMS.java:201)
at
org.continuent.hedera.channel.AppiaReliableGroupChannel.receive(AppiaReliableGroupChannel.java:207)
It seems the controller sends messages to first controller, even if it
was not in the group
Nuno Carvalho a écrit :
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.SuspendActivity):
[EMAIL PROTECTED]
2007-09-14 11:03:37,309 DEBUG controller.virtualdatabase.MATISSEDB
handleMessageMultiThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.SuspendActivity):
[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
[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
--
Gérard
BUNEL
Chef
de Projet
____________________________________________________________________
Technopôle
Brest Iroise
Site du Vernis – CS 23866
29238
Brest Cedex 3
Tél : + 33 2 98 05 43 21
Fax : + 33 2 98 05 20 34
www.altran.com
|
