search

puniverse / quasar

Fibers, Channels and Actors for the JVM
http://docs.paralleluniverse.co/quasar/
Other
4.56k stars 575 forks source link

Actor discovery fails sometimes with Galaxy #113

Open hsestupin opened 9 years ago

hsestupin commented 9 years ago

Hey, its really hard to reproduce this problem because I don't have any ideas why it happens. But this problem appears quite rarely

java.util.concurrent.ExecutionException: java.lang.RuntimeException: Actor discovery failed
    at com.oracle.tools.util.FutureCompletionListener.get(FutureCompletionListener.java:152)
    at actor.ActorsRpcTest.testExchangeActorAndSendMessageTo(ActorsRpcTest.java:36)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:85)
    at org.testng.internal.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:46)
    at org.testng.internal.InvokeMethodRunnable.run(InvokeMethodRunnable.java:37)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.RuntimeException: Actor discovery failed
    at co.paralleluniverse.remote.galaxy.GlxGlobalRegistry.getActor0(GlxGlobalRegistry.java:245)
    at co.paralleluniverse.remote.galaxy.GlxGlobalRegistry.getActor(GlxGlobalRegistry.java:158)
    at co.paralleluniverse.actors.ActorRegistry.getActor(ActorRegistry.java:84)
    at co.paralleluniverse.actors.ActorRegistry.getActor(ActorRegistry.java:94)
    at service.actor.ActorRegistry.getActor(ActorRegistry.java:45)
    at actor.ActorsRpcTest$PeerReceiver.call(ActorsRpcTest.java:46)
    at actor.ActorsRpcTest$PeerReceiver.call(ActorsRpcTest.java:39)
    at actor.BaseActorTester$PeerRemoteRunner.call(BaseActorTester.java:148)
    at com.oracle.tools.runtime.java.ContainerBasedJavaApplicationBuilder$ContainerBasedJavaApplicationProcess$1.run(ContainerBasedJavaApplicationBuilder.java:533)
    ... 5 more

Actually dunno is it a Galaxy problem or Quasar. May be method co.paralleluniverse.remote.galaxy.GlxGlobalRegistry#getActor0 shouldn't hide the cause which is TimeoutException ? And should rethrow it in RuntimeException? I\m thinking this will help to find out the core problem

pron commented 9 years ago

If you turn on DEBUG logging for co.paralleluniverse.galaxy.core.Cache you'll see whether there's a timeout involved,

hsestupin commented 8 years ago

I don't understand what should I observe in Cache logs. There are last words from peer where actor registration attempt was made

[ActorsRpcTest-peer2:out]  290: [10-14 17:23:58,041] DEBUG Cache.java:2562 Cache : Allocating storage (0 bytes) for line 100000000
[ActorsRpcTest-peer2:out]  291: [10-14 17:23:58,041] DEBUG Cache.java:1734 Cache : Line 100000000 now has a new version 1. Setting to modified.
[ActorsRpcTest-peer2:out]  292: [10-14 17:23:58,041] DEBUG Cache.java:2646 Cache : Locking line LINE: 100000000 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes) MODIFIED
[ActorsRpcTest-peer2:out]  293: [10-14 17:23:58,041] DEBUG Cache.java:699 Cache : handleOp: Op.PUT(line:ffffffffffffffff, data:[B@40f269c2) -> 4294967296 line: null
[ActorsRpcTest-peer2:out]  294: [10-14 17:23:58,041] DEBUG Cache.java:781 Cache : completeOp: Op.PUT(line:ffffffffffffffff, data:[B@40f269c2) -> 4294967296 line: null
[ActorsRpcTest-peer2:out]  295: [10-14 17:23:58,043] DEBUG Cache.java:530 Cache : Run(fast): Op.GETX(line:2f6ca063)
[ActorsRpcTest-peer2:out]  296: [10-14 17:23:58,043] DEBUG Cache.java:2646 Cache : Locking line LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer2:out]  297: [10-14 17:23:58,046] DEBUG Cache.java:530 Cache : Run(fast): Op.SET(line:2f6ca063)
[ActorsRpcTest-peer2:out]  298: [10-14 17:23:58,064] DEBUG Cache.java:2891 Cache : Deallocating storage for line 2f6ca063
[ActorsRpcTest-peer2:out]  299: [10-14 17:23:58,064] DEBUG Cache.java:2562 Cache : Allocating storage (29 bytes) for line 2f6ca063
[ActorsRpcTest-peer2:out]  300: [10-14 17:23:58,065] DEBUG Cache.java:843 Cache : Received: [GET IN #2 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  301: [10-14 17:23:58,066] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 1 DATA: null LOCKED MODIFIED 2f6ca063 [GET IN #2 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  302: [10-14 17:23:58,068] DEBUG Cache.java:1734 Cache : Line 2f6ca063 now has a new version 2. Setting to modified.
[ActorsRpcTest-peer2:out]  303: [10-14 17:23:58,069] DEBUG Cache.java:957 Cache : Adding message to pending [GET IN #2 FROM 1, line: 2f6ca063] on line LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 2 DATA: (32 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer2:out]  304: [10-14 17:23:58,071] DEBUG Cache.java:2787 Cache : addPendingMessage [GET IN #2 FROM 1, line: 2f6ca063] to line LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 2 DATA: (32 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer2:out]  305: [10-14 17:23:58,073] DEBUG Cache.java:2655 Cache : Unlocking line LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 2 DATA: (32 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer2:out]  306: [10-14 17:23:58,075] DEBUG Cache.java:530 Cache : Run(fast): Op.LSTN(line:100000000, extra:co.paralleluniverse.remote.galaxy.GlxGlobalRegistry$2@1881fb91)
[ActorsRpcTest-peer2:out]  307: [10-14 17:23:58,076] DEBUG Cache.java:1246 Cache : Ending transaction: co.paralleluniverse.galaxy.core.Transaction@148d3cdd COMMIT
[ActorsRpcTest-peer2:out]  308: [10-14 17:23:58,076] DEBUG Cache.java:1267 Cache : Ending transaction: co.paralleluniverse.galaxy.core.Transaction@148d3cdd, line LINE: 100000000 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer2:out]  309: [10-14 17:23:58,076] DEBUG Cache.java:2655 Cache : Unlocking line LINE: 100000000 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer2:out]  310: [10-14 17:23:58,076] DEBUG Cache.java:548 Cache : Run(fast): Op.GETS(line:100000000)
[ActorsRpcTest-peer2:out]  311: [10-14 17:23:58,076] DEBUG Cache.java:2646 Cache : Locking line LINE: 100000000 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes) MODIFIED SLAVE
[ActorsRpcTest-peer2:out]  312: [10-14 17:23:58,091] DEBUG Cache.java:843 Cache : Received: [BACKUP_PACKETACK IN #_R FROM 0, id: 100000]
[ActorsRpcTest-peer2:out]  313: [10-14 17:23:58,098] DEBUG Cache.java:843 Cache : Received: [BACKUPACK IN #_ FROM 0, line: 2f6ca063, version: 2]
[ActorsRpcTest-peer2:out]  314: [10-14 17:23:58,098] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 2 DATA: (32 bytes) MODIFIED SLAVE 2f6ca063 [BACKUPACK IN #_ FROM 0, line: 2f6ca063, version: 2]
[ActorsRpcTest-peer2:out]  315: [10-14 17:23:58,099] DEBUG Cache.java:2069 Cache : Backup of line 2f6ca063 version 2 done. Setting to unmodified.
[ActorsRpcTest-peer2:out]  316: [10-14 17:23:58,099] DEBUG Cache.java:1084 Cache : Handling pending message [GET IN #2 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  317: [10-14 17:23:58,099] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 E -> O
[ActorsRpcTest-peer2:out]  318: [10-14 17:23:58,099] DEBUG Cache.java:2666 Cache : Sending: [PUT OUT #2R TO 1, line: 2f6ca063, version: 2, data: (29 bytes)]
[ActorsRpcTest-peer2:out]  319: [10-14 17:23:58,100] DEBUG Cache.java:2675 Cache : Sent: [PUT OUT #2R TO 1, line: 2f6ca063, version: 2, data: (32 bytes)]
[ActorsRpcTest-peer2:out]  320: [10-14 17:23:58,104] DEBUG Cache.java:843 Cache : Received: [BACKUP_PACKETACK IN #_R FROM 0, id: 100001]
[ActorsRpcTest-peer2:out]  321: [10-14 17:23:58,104] DEBUG Cache.java:850 Cache : Received short-circuit: [BACKUPACK IN #_ FROM 0, line: 100000000, version: 1]
[ActorsRpcTest-peer2:out]  322: [10-14 17:23:58,105] DEBUG Cache.java:893 Cache : runMessage: LINE: 100000000 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes) LOCKED MODIFIED SLAVE 100000000 [BACKUPACK IN #_ FROM 0, line: 100000000, version: 1]
[ActorsRpcTest-peer2:out]  323: [10-14 17:23:58,106] DEBUG Cache.java:2069 Cache : Backup of line 100000000 version 1 done. Setting to unmodified.
[ActorsRpcTest-peer2:out]  324: [10-14 17:23:58,118] DEBUG Cache.java:2655 Cache : Unlocking line LINE: 100000000 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes) LOCKED SLAVE
[ActorsRpcTest-peer2:out]  325: [10-14 17:23:58,139] DEBUG GlxGlobalRegistry.java:267 GlxGlobalRegistry : Store returned null for root TestActor
[ActorsRpcTest-peer2:out]  326: [10-14 17:23:58,149] DEBUG Cache.java:843 Cache : Received: [GETX IN #4 FROM 1, line: 100000000]
[ActorsRpcTest-peer2:out]  327: [10-14 17:23:58,149] DEBUG Cache.java:893 Cache : runMessage: LINE: 100000000 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes) SLAVE 100000000 [GETX IN #4 FROM 1, line: 100000000]
[ActorsRpcTest-peer2:out]  328: [10-14 17:23:58,151] DEBUG Cache.java:2355 Cache : Set state 100000000 E -> I
hsestupin commented 8 years ago

It might help. I've caught an underlying TimeoutException - 

java.lang.RuntimeException: Actor registration failed
java.util.concurrent.ExecutionException: java.lang.RuntimeException: Actor registration failed
    at com.oracle.tools.util.FutureCompletionListener.get(FutureCompletionListener.java:152)
    at actor.ActorsRpcTest.testExchangeActorAndSendMessageTo(ActorsRpcTest.java:35)
    at sun.reflect.GeneratedMethodAccessor1134.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:85)
    at org.testng.internal.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:46)
    at org.testng.internal.InvokeMethodRunnable.run(InvokeMethodRunnable.java:37)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.RuntimeException: Actor registration failed
    at co.paralleluniverse.remote.galaxy.GlxGlobalRegistry.register(GlxGlobalRegistry.java:89)
    at co.paralleluniverse.actors.ActorRegistry.register(ActorRegistry.java:52)
    at co.paralleluniverse.actors.Actor.register(Actor.java:983)
    at actor.ActorsRpcTest$PeerRegistrator.call(ActorsRpcTest.java:59)
    at actor.ActorsRpcTest$PeerRegistrator.call(ActorsRpcTest.java:52)
    at actor.BaseActorTester$PeerRemoteRunner.call(BaseActorTester.java:178)
    at com.oracle.tools.runtime.java.ContainerBasedJavaApplicationBuilder$ContainerBasedJavaApplicationProcess$1.run(ContainerBasedJavaApplicationBuilder.java:533)
    ... 5 more
Caused by: co.paralleluniverse.galaxy.TimeoutException: Timeout while processing op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026): [TIMEOUT IN #4R FROM 2, line: 2f6ca063]
    at co.paralleluniverse.galaxy.core.Cache.handleMessageTimeout(Cache.java:2025)
    at co.paralleluniverse.galaxy.core.Cache.handleMessage1(Cache.java:993)
    at co.paralleluniverse.galaxy.core.Cache.handleMessage(Cache.java:947)
    at co.paralleluniverse.galaxy.core.Cache.runMessage(Cache.java:903)
    at co.paralleluniverse.galaxy.core.Cache.receive1(Cache.java:884)
    at co.paralleluniverse.galaxy.core.Cache.receive(Cache.java:844)
    at co.paralleluniverse.galaxy.core.AbstractComm.receive(AbstractComm.java:154)
    at co.paralleluniverse.galaxy.netty.UDPComm.access$1400(UDPComm.java:77)
    at co.paralleluniverse.galaxy.netty.UDPComm$NodePeer.call(UDPComm.java:712)
    at co.paralleluniverse.galaxy.netty.UDPComm$NodePeer.call(UDPComm.java:591)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
    ... 3 more

And previous log trace is the following - 

[ActorsRpcTest-peer1:out]  259: [10-15 11:53:59,391] INFO ActorRegistry.java:49 ActorRegistry : Registering TestActor: NubLookupImpl@TestActor[owner: TestActor]
[ActorsRpcTest-peer1:out]  260: [10-15 11:53:59,394] INFO GlxGlobalRegistry.java:67 GlxGlobalRegistry : Registering actor ActorRef@5fa9150f{NubLookupImpl@TestActor[owner: TestActor]} at root TestActor
[ActorsRpcTest-peer1:out]  261: [10-15 11:53:59,417] DEBUG Cache.java:1221 Cache : Starting transaction: co.paralleluniverse.galaxy.core.Transaction@1a5cf023
[ActorsRpcTest-peer1:out]  262: [10-15 11:53:59,419] DEBUG Cache.java:530 Cache : Run(fast): Op.GET(line:2f6ca063, extra:0)
[ActorsRpcTest-peer1:out]  263: [10-15 11:53:59,420] DEBUG Cache.java:804 Cache : Line 2f6ca063 not found.
[ActorsRpcTest-peer1:out]  264: [10-15 11:53:59,432] DEBUG Cache.java:2666 Cache : Sending: [GET OUT #_ TO 0, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  265: [10-15 11:53:59,448] DEBUG Cache.java:2675 Cache : Sent: [GET OUT #1 TO 0, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  266: [10-15 11:53:59,449] DEBUG Cache.java:625 Cache : Run: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0)
[ActorsRpcTest-peer1:out]  267: [10-15 11:53:59,450] DEBUG Cache.java:680 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0) line: LINE: 2f6ca063 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer1:out]  268: [10-15 11:53:59,450] DEBUG Cache.java:699 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0) -> PENDING line: LINE: 2f6ca063 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer1:out]  269: [10-15 11:53:59,450] DEBUG Cache.java:670 Cache : Adding op to pending Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0) on line LINE: 2f6ca063 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer1:out]  270: [10-15 11:53:59,460] DEBUG Cache.java:843 Cache : Received: [CHNGD_OWNR IN #1R FROM 0, line: 2f6ca063, newOwner: 2, certain: true]
[ActorsRpcTest-peer1:out]  271: [10-15 11:53:59,462] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null 2f6ca063 [CHNGD_OWNR IN #1R FROM 0, line: 2f6ca063, newOwner: 2, certain: true]
[ActorsRpcTest-peer1:out]  272: [10-15 11:53:59,465] DEBUG Cache.java:2384 Cache : Set owner 2f6ca063 -1 -> 2
[ActorsRpcTest-peer1:out]  273: [10-15 11:53:59,465] DEBUG Cache.java:831 Cache : Handling pending op Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0), change = 2
[ActorsRpcTest-peer1:out]  274: [10-15 11:53:59,465] DEBUG Cache.java:680 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0) line: LINE: 2f6ca063 I  OWN: 2 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer1:out]  275: [10-15 11:53:59,465] DEBUG Cache.java:2666 Cache : Sending: [GET OUT #_ TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  276: [10-15 11:53:59,466] DEBUG Cache.java:2675 Cache : Sent: [GET OUT #2 TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  277: [10-15 11:53:59,466] DEBUG Cache.java:699 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0) -> PENDING line: LINE: 2f6ca063 I (->S) OWN: 2 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer1:out]  278: [10-15 11:53:59,489] DEBUG Cache.java:843 Cache : Received: [PUT IN #2R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes)]
[ActorsRpcTest-peer1:out]  279: [10-15 11:53:59,489] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 I (->S) OWN: 2 SHARE: null VER: 0 DATA: null 2f6ca063 [PUT IN #2R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes)]
[ActorsRpcTest-peer1:out]  280: [10-15 11:53:59,491] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 I -> S
[ActorsRpcTest-peer1:out]  281: [10-15 11:53:59,498] DEBUG Cache.java:2562 Cache : Allocating storage (0 bytes) for line 2f6ca063
[ActorsRpcTest-peer1:out]  282: [10-15 11:53:59,500] DEBUG Cache.java:2915 Cache : fireLineReceived LINE: 2f6ca063 S  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  283: [10-15 11:53:59,500] DEBUG Cache.java:831 Cache : Handling pending op Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0), change = 1
[ActorsRpcTest-peer1:out]  284: [10-15 11:53:59,500] DEBUG Cache.java:680 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0) line: LINE: 2f6ca063 S  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  285: [10-15 11:53:59,501] DEBUG Cache.java:699 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0) -> null line: LINE: 2f6ca063 S  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  286: [10-15 11:53:59,501] DEBUG Cache.java:781 Cache : completeOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0) -> null line: LINE: 2f6ca063 S  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  287: [10-15 11:53:59,505] DEBUG Cache.java:530 Cache : Run(fast): Op.GETX(line:2f6ca063)
[ActorsRpcTest-peer1:out]  288: [10-15 11:53:59,510] DEBUG Cache.java:2666 Cache : Sending: [GETX OUT #_ TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  289: [10-15 11:53:59,513] DEBUG Cache.java:2675 Cache : Sent: [GETX OUT #3 TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  290: [10-15 11:53:59,513] DEBUG Cache.java:625 Cache : Run: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026)
[ActorsRpcTest-peer1:out]  291: [10-15 11:53:59,513] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026) line: LINE: 2f6ca063 S (->O) OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  292: [10-15 11:53:59,513] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026) -> PENDING line: LINE: 2f6ca063 S (->O) OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  293: [10-15 11:53:59,513] DEBUG Cache.java:670 Cache : Adding op to pending Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026) on line LINE: 2f6ca063 S (->O) OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  294: [10-15 11:53:59,515] DEBUG Cache.java:843 Cache : Received: [INV IN #2 FROM 2, line: 2f6ca063, previousOwner: 2]
[ActorsRpcTest-peer1:out]  295: [10-15 11:53:59,515] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 S (->O) OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes) 2f6ca063 [INV IN #2 FROM 2, line: 2f6ca063, previousOwner: 2]
[ActorsRpcTest-peer1:out]  296: [10-15 11:53:59,515] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 S -> I
[ActorsRpcTest-peer1:out]  297: [10-15 11:53:59,515] DEBUG Cache.java:2666 Cache : Sending: [INVACK OUT #2R TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  298: [10-15 11:53:59,518] DEBUG Cache.java:2675 Cache : Sent: [INVACK OUT #2R TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  299: [10-15 11:53:59,518] DEBUG Cache.java:2897 Cache : fireLineInvalidated LINE: 2f6ca063 I  OWN: 2 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  300: [10-15 11:53:59,518] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026), change = 1
[ActorsRpcTest-peer1:out]  301: [10-15 11:53:59,518] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026) line: LINE: 2f6ca063 I  OWN: 2 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  302: [10-15 11:53:59,518] DEBUG Cache.java:2666 Cache : Sending: [GETX OUT #_ TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  303: [10-15 11:53:59,518] DEBUG Cache.java:2675 Cache : Sent: [GETX OUT #4 TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  304: [10-15 11:53:59,518] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026) -> PENDING line: LINE: 2f6ca063 I (->O) OWN: 2 SHARE: null VER: 1 DATA: (0 bytes)

Actually I have no idea what is going on... This situation happens 1 of 20 test runs.

pron commented 8 years ago

Well, outgoing message #4 to node 2 did not get a response on time. I need to see node 2's log as well.

hsestupin commented 8 years ago

So it was a mistake of mine to clear up logs from peer2 messages :) Here it is a full message log -

[ActorsRpcTest-peer1:out]  260: [10-15 11:53:59,394] INFO GlxGlobalRegistry.java:67 GlxGlobalRegistry : Registering actor ActorRef@5fa9150f{NubLookupImpl@TestActor[owner: TestActor]} at root TestActor
[ActorsRpcTest-peer1:out]  261: [10-15 11:53:59,417] DEBUG Cache.java:1221 Cache : Starting transaction: co.paralleluniverse.galaxy.core.Transaction@1a5cf023
[ActorsRpcTest-peer1:out]  262: [10-15 11:53:59,419] DEBUG Cache.java:530 Cache : Run(fast): Op.GET(line:2f6ca063, extra:0)
[ActorsRpcTest-peer1:out]  263: [10-15 11:53:59,420] DEBUG Cache.java:804 Cache : Line 2f6ca063 not found.
[ActorsRpcTest-peer1:out]  264: [10-15 11:53:59,432] DEBUG Cache.java:2666 Cache : Sending: [GET OUT #_ TO 0, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  265: [10-15 11:53:59,448] DEBUG Cache.java:2675 Cache : Sent: [GET OUT #1 TO 0, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  266: [10-15 11:53:59,449] DEBUG Cache.java:625 Cache : Run: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0)
[ActorsRpcTest-peer1:out]  267: [10-15 11:53:59,450] DEBUG Cache.java:680 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0) line: LINE: 2f6ca063 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer1:out]  268: [10-15 11:53:59,450] DEBUG Cache.java:699 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0) -> PENDING line: LINE: 2f6ca063 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer1:out]  269: [10-15 11:53:59,450] DEBUG Cache.java:670 Cache : Adding op to pending Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0) on line LINE: 2f6ca063 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer1:out]  270: [10-15 11:53:59,460] DEBUG Cache.java:843 Cache : Received: [CHNGD_OWNR IN #1R FROM 0, line: 2f6ca063, newOwner: 2, certain: true]
[ActorsRpcTest-peer1:out]  271: [10-15 11:53:59,462] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null 2f6ca063 [CHNGD_OWNR IN #1R FROM 0, line: 2f6ca063, newOwner: 2, certain: true]
[ActorsRpcTest-peer1:out]  272: [10-15 11:53:59,465] DEBUG Cache.java:2384 Cache : Set owner 2f6ca063 -1 -> 2
[ActorsRpcTest-peer2:out]  265: [10-15 11:53:59,370] DEBUG Cache.java:680 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4472c582, extra:0) line: LINE: 2f6ca063 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer1:out]  273: [10-15 11:53:59,465] DEBUG Cache.java:831 Cache : Handling pending op Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0), change = 2
[ActorsRpcTest-peer1:out]  274: [10-15 11:53:59,465] DEBUG Cache.java:680 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0) line: LINE: 2f6ca063 I  OWN: 2 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer2:out]  266: [10-15 11:53:59,370] DEBUG Cache.java:699 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4472c582, extra:0) -> PENDING line: LINE: 2f6ca063 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer1:out]  275: [10-15 11:53:59,465] DEBUG Cache.java:2666 Cache : Sending: [GET OUT #_ TO 2, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  267: [10-15 11:53:59,370] DEBUG Cache.java:670 Cache : Adding op to pending Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4472c582, extra:0) on line LINE: 2f6ca063 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer1:out]  276: [10-15 11:53:59,466] DEBUG Cache.java:2675 Cache : Sent: [GET OUT #2 TO 2, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  268: [10-15 11:53:59,433] DEBUG Cache.java:843 Cache : Received: [PUTX IN #1R FROM 0, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer1:out]  277: [10-15 11:53:59,466] DEBUG Cache.java:699 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0) -> PENDING line: LINE: 2f6ca063 I (->S) OWN: 2 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer2:out]  269: [10-15 11:53:59,436] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null 2f6ca063 [PUTX IN #1R FROM 0, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer2:out]  270: [10-15 11:53:59,443] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 I -> E
[ActorsRpcTest-peer1:out]  278: [10-15 11:53:59,489] DEBUG Cache.java:843 Cache : Received: [PUT IN #2R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes)]
[ActorsRpcTest-peer2:out]  271: [10-15 11:53:59,447] DEBUG Cache.java:2384 Cache : Set owner 2f6ca063 -1 -> 2
[ActorsRpcTest-peer1:out]  279: [10-15 11:53:59,489] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 I (->S) OWN: 2 SHARE: null VER: 0 DATA: null 2f6ca063 [PUT IN #2R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes)]
[ActorsRpcTest-peer2:out]  272: [10-15 11:53:59,465] DEBUG Cache.java:2562 Cache : Allocating storage (0 bytes) for line 2f6ca063
[ActorsRpcTest-peer1:out]  280: [10-15 11:53:59,491] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 I -> S
[ActorsRpcTest-peer2:out]  273: [10-15 11:53:59,469] DEBUG Cache.java:2915 Cache : fireLineReceived LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  281: [10-15 11:53:59,498] DEBUG Cache.java:2562 Cache : Allocating storage (0 bytes) for line 2f6ca063
[ActorsRpcTest-peer2:out]  274: [10-15 11:53:59,470] DEBUG Cache.java:831 Cache : Handling pending op Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4472c582, extra:0), change = 3
[ActorsRpcTest-peer1:out]  282: [10-15 11:53:59,500] DEBUG Cache.java:2915 Cache : fireLineReceived LINE: 2f6ca063 S  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  275: [10-15 11:53:59,470] DEBUG Cache.java:680 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4472c582, extra:0) line: LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  283: [10-15 11:53:59,500] DEBUG Cache.java:831 Cache : Handling pending op Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0), change = 1
[ActorsRpcTest-peer2:out]  276: [10-15 11:53:59,471] DEBUG Cache.java:699 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4472c582, extra:0) -> null line: LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  277: [10-15 11:53:59,471] DEBUG Cache.java:781 Cache : completeOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4472c582, extra:0) -> null line: LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  284: [10-15 11:53:59,500] DEBUG Cache.java:680 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0) line: LINE: 2f6ca063 S  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  278: [10-15 11:53:59,475] DEBUG Cache.java:530 Cache : Run(fast): Op.GETX(line:2f6ca063)
[ActorsRpcTest-peer1:out]  285: [10-15 11:53:59,501] DEBUG Cache.java:699 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0) -> null line: LINE: 2f6ca063 S  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  279: [10-15 11:53:59,479] DEBUG Cache.java:843 Cache : Received: [GET IN #2 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  280: [10-15 11:53:59,480] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes) 2f6ca063 [GET IN #2 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  286: [10-15 11:53:59,501] DEBUG Cache.java:781 Cache : completeOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026, extra:0) -> null line: LINE: 2f6ca063 S  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  281: [10-15 11:53:59,480] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 E -> O
[ActorsRpcTest-peer1:out]  287: [10-15 11:53:59,505] DEBUG Cache.java:530 Cache : Run(fast): Op.GETX(line:2f6ca063)
[ActorsRpcTest-peer1:out]  288: [10-15 11:53:59,510] DEBUG Cache.java:2666 Cache : Sending: [GETX OUT #_ TO 2, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  282: [10-15 11:53:59,480] DEBUG Cache.java:2666 Cache : Sending: [PUT OUT #2R TO 1, line: 2f6ca063, version: 1, data: (0 bytes)]
[ActorsRpcTest-peer1:out]  289: [10-15 11:53:59,513] DEBUG Cache.java:2675 Cache : Sent: [GETX OUT #3 TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  290: [10-15 11:53:59,513] DEBUG Cache.java:625 Cache : Run: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026)
[ActorsRpcTest-peer2:out]  283: [10-15 11:53:59,481] DEBUG Cache.java:2675 Cache : Sent: [PUT OUT #2R TO 1, line: 2f6ca063, version: 1, data: (0 bytes)]
[ActorsRpcTest-peer1:out]  291: [10-15 11:53:59,513] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026) line: LINE: 2f6ca063 S (->O) OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  284: [10-15 11:53:59,482] DEBUG Cache.java:2666 Cache : Sending: [INV OUT #_ TO 1, line: 2f6ca063, previousOwner: 2]
[ActorsRpcTest-peer1:out]  292: [10-15 11:53:59,513] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026) -> PENDING line: LINE: 2f6ca063 S (->O) OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  285: [10-15 11:53:59,484] DEBUG Cache.java:2675 Cache : Sent: [INV OUT #2 TO 1, line: 2f6ca063, previousOwner: 2]
[ActorsRpcTest-peer1:out]  293: [10-15 11:53:59,513] DEBUG Cache.java:670 Cache : Adding op to pending Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026) on line LINE: 2f6ca063 S (->O) OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  286: [10-15 11:53:59,484] DEBUG Cache.java:625 Cache : Run: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4472c582)
[ActorsRpcTest-peer2:out]  287: [10-15 11:53:59,485] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4472c582) line: LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {1} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  294: [10-15 11:53:59,515] DEBUG Cache.java:843 Cache : Received: [INV IN #2 FROM 2, line: 2f6ca063, previousOwner: 2]
[ActorsRpcTest-peer1:out]  295: [10-15 11:53:59,515] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 S (->O) OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes) 2f6ca063 [INV IN #2 FROM 2, line: 2f6ca063, previousOwner: 2]
[ActorsRpcTest-peer1:out]  296: [10-15 11:53:59,515] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 S -> I
[ActorsRpcTest-peer1:out]  297: [10-15 11:53:59,515] DEBUG Cache.java:2666 Cache : Sending: [INVACK OUT #2R TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  298: [10-15 11:53:59,518] DEBUG Cache.java:2675 Cache : Sent: [INVACK OUT #2R TO 2, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  288: [10-15 11:53:59,485] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4472c582) -> PENDING line: LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {1} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  299: [10-15 11:53:59,518] DEBUG Cache.java:2897 Cache : fireLineInvalidated LINE: 2f6ca063 I  OWN: 2 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  289: [10-15 11:53:59,485] DEBUG Cache.java:670 Cache : Adding op to pending Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4472c582) on line LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {1} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  300: [10-15 11:53:59,518] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026), change = 1
[ActorsRpcTest-peer2:out]  290: [10-15 11:53:59,515] DEBUG Cache.java:843 Cache : Received: [GETX IN #3 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  301: [10-15 11:53:59,518] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026) line: LINE: 2f6ca063 I  OWN: 2 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  291: [10-15 11:53:59,515] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {1} VER: 1 DATA: (0 bytes) 2f6ca063 [GETX IN #3 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  302: [10-15 11:53:59,518] DEBUG Cache.java:2666 Cache : Sending: [GETX OUT #_ TO 2, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  292: [10-15 11:53:59,515] DEBUG Cache.java:957 Cache : Adding message to pending [GETX IN #3 FROM 1, line: 2f6ca063] on line LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {1} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  303: [10-15 11:53:59,518] DEBUG Cache.java:2675 Cache : Sent: [GETX OUT #4 TO 2, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  293: [10-15 11:53:59,518] DEBUG Cache.java:2787 Cache : addPendingMessage [GETX IN #3 FROM 1, line: 2f6ca063] to line LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {1} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  304: [10-15 11:53:59,518] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026) -> PENDING line: LINE: 2f6ca063 I (->O) OWN: 2 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  294: [10-15 11:53:59,518] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4472c582), change = 0
[ActorsRpcTest-peer2:out]  295: [10-15 11:53:59,518] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4472c582) line: LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {1} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  296: [10-15 11:53:59,518] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4472c582) -> PENDING line: LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {1} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  297: [10-15 11:53:59,522] DEBUG Cache.java:843 Cache : Received: [INVACK IN #2R FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  298: [10-15 11:53:59,522] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {1} VER: 1 DATA: (0 bytes) 2f6ca063 [INVACK IN #2R FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  299: [10-15 11:53:59,522] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 O -> E
[ActorsRpcTest-peer2:out]  300: [10-15 11:53:59,522] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4472c582), change = 1
[ActorsRpcTest-peer2:out]  301: [10-15 11:53:59,522] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4472c582) line: LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  302: [10-15 11:53:59,522] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4472c582) -> PENDING line: LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  303: [10-15 11:53:59,522] DEBUG Cache.java:1084 Cache : Handling pending message [GETX IN #3 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  304: [10-15 11:53:59,522] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 E -> I
[ActorsRpcTest-peer2:out]  305: [10-15 11:53:59,525] DEBUG Cache.java:2384 Cache : Set owner 2f6ca063 2 -> 1
[ActorsRpcTest-peer2:out]  306: [10-15 11:53:59,525] DEBUG Cache.java:2666 Cache : Sending: [PUTX OUT #3R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
pron commented 8 years ago

The first node (node 1?) sends a message in line 303 [GETX OUT #4] to node 2. Node 2 should say that it's received [GETX IN #4], but it doesn't appear. This might be a network problem. Try to look at the network and/or increase the timeout.

You can also tell Galaxy to generate networking logs by enabling the co.paralleluniverse.galaxy.netty.UDPComm logger.

hsestupin commented 8 years ago

Actually both nodes are spawned from one JVM process as child processes. So there is one physical machine.

pron commented 8 years ago

How do they communicate, then? Because it seems like a message isn't getting through (in any case, networking logs will help; there could be a problem in the networking layer).

hsestupin commented 8 years ago

OK, same error reproduced with UDPComm log set to DEBUG - 

[ActorsRpcTest-peer1:out]  263: [10-15 17:08:48,204] INFO GlxGlobalRegistry.java:67 GlxGlobalRegistry : Registering actor ActorRef@60b29677{NubLookupImpl@TestActor[owner: TestActor]} at root TestActor
[ActorsRpcTest-peer1:out]  264: [10-15 17:08:48,221] DEBUG Cache.java:1221 Cache : Starting transaction: co.paralleluniverse.galaxy.core.Transaction@1d99f40f
[ActorsRpcTest-peer1:out]  265: [10-15 17:08:48,224] DEBUG Cache.java:530 Cache : Run(fast): Op.GET(line:2f6ca063, extra:0)
[ActorsRpcTest-peer1:out]  266: [10-15 17:08:48,224] DEBUG Cache.java:804 Cache : Line 2f6ca063 not found.
[ActorsRpcTest-peer1:out]  267: [10-15 17:08:48,240] DEBUG Cache.java:2666 Cache : Sending: [GET OUT #_ TO 0, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  268: [10-15 17:08:48,255] DEBUG Cache.java:2675 Cache : Sent: [GET OUT #1 TO 0, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  269: [10-15 17:08:48,258] DEBUG Cache.java:625 Cache : Run: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9, extra:0)
[ActorsRpcTest-peer1:out]  270: [10-15 17:08:48,259] DEBUG Cache.java:680 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9, extra:0) line: LINE: 2f6ca063 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer1:out]  271: [10-15 17:08:48,259] DEBUG Cache.java:699 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9, extra:0) -> PENDING line: LINE: 2f6ca063 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer1:out]  272: [10-15 17:08:48,259] DEBUG Cache.java:670 Cache : Adding op to pending Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9, extra:0) on line LINE: 2f6ca063 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer1:out]  273: [10-15 17:08:48,270] DEBUG Cache.java:843 Cache : Received: [CHNGD_OWNR IN #1R FROM 0, line: 2f6ca063, newOwner: 2, certain: true]
[ActorsRpcTest-peer1:out]  274: [10-15 17:08:48,272] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null 2f6ca063 [CHNGD_OWNR IN #1R FROM 0, line: 2f6ca063, newOwner: 2, certain: true]
[ActorsRpcTest-peer1:out]  275: [10-15 17:08:48,275] DEBUG Cache.java:2384 Cache : Set owner 2f6ca063 -1 -> 2
[ActorsRpcTest-peer1:out]  276: [10-15 17:08:48,275] DEBUG Cache.java:831 Cache : Handling pending op Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9, extra:0), change = 2
[ActorsRpcTest-peer1:out]  277: [10-15 17:08:48,275] DEBUG Cache.java:680 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9, extra:0) line: LINE: 2f6ca063 I  OWN: 2 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer1:out]  278: [10-15 17:08:48,276] DEBUG Cache.java:2666 Cache : Sending: [GET OUT #_ TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  279: [10-15 17:08:48,276] DEBUG UDPComm.java:403 UDPComm : Sending to node 2 (/100.111.6.14:14732): [GET OUT #_ TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  280: [10-15 17:08:48,276] DEBUG Cache.java:2675 Cache : Sent: [GET OUT #2 TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  281: [10-15 17:08:48,276] DEBUG Cache.java:699 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9, extra:0) -> PENDING line: LINE: 2f6ca063 I (->S) OWN: 2 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer1:out]  282: [10-15 17:08:48,279] DEBUG UDPComm.java:938 UDPComm : Adding message [GET OUT #2 TO 2, line: 2f6ca063] to sent-packet
[ActorsRpcTest-peer1:out]  283: [10-15 17:08:48,281] DEBUG UDPComm.java:703 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578108883256, sentPacket=MessagePacket[[[GET OUT #2 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} sending packet MessagePacket[[[GET OUT #2 TO 2, line: 2f6ca063]]]
[ActorsRpcTest-peer1:out]  284: [10-15 17:08:48,282] DEBUG UDPComm.java:554 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578108883256, sentPacket=MessagePacket[[[GET OUT #2 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} rescheduling in 60000000
[ActorsRpcTest-peer1:out]  285: [10-15 17:08:48,297] DEBUG UDPComm.java:456 UDPComm : Received packet MessagePacket[[[PUT IN #2R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes)]]]
[ActorsRpcTest-peer1:out]  286: [10-15 17:08:48,297] DEBUG UDPComm.java:723 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578108883256, sentPacket=MessagePacket[[[GET OUT #2 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} has received packet MessagePacket[[[PUT IN #2R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes)]]]
[ActorsRpcTest-peer1:out]  287: [10-15 17:08:48,299] DEBUG UDPComm.java:768 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578108883256, sentPacket=MessagePacket[[[GET OUT #2 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} received response [PUT IN #2R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes)] for request ([GET OUT #2 TO 2, line: 2f6ca063])
[ActorsRpcTest-peer1:out]  288: [10-15 17:08:48,299] DEBUG UDPComm.java:669 UDPComm : Passing received message [PUT IN #2R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes)] to cache
[ActorsRpcTest-peer1:out]  289: [10-15 17:08:48,299] DEBUG Cache.java:843 Cache : Received: [PUT IN #2R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes)]
[ActorsRpcTest-peer1:out]  290: [10-15 17:08:48,299] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 I (->S) OWN: 2 SHARE: null VER: 0 DATA: null 2f6ca063 [PUT IN #2R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes)]
[ActorsRpcTest-peer1:out]  291: [10-15 17:08:48,302] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 I -> S
[ActorsRpcTest-peer1:out]  292: [10-15 17:08:48,308] DEBUG Cache.java:2562 Cache : Allocating storage (0 bytes) for line 2f6ca063
[ActorsRpcTest-peer1:out]  293: [10-15 17:08:48,311] DEBUG Cache.java:2915 Cache : fireLineReceived LINE: 2f6ca063 S  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  294: [10-15 17:08:48,311] DEBUG Cache.java:831 Cache : Handling pending op Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9, extra:0), change = 1
[ActorsRpcTest-peer1:out]  295: [10-15 17:08:48,311] DEBUG Cache.java:680 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9, extra:0) line: LINE: 2f6ca063 S  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  296: [10-15 17:08:48,313] DEBUG Cache.java:699 Cache : handleOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9, extra:0) -> null line: LINE: 2f6ca063 S  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  297: [10-15 17:08:48,313] DEBUG Cache.java:781 Cache : completeOp: Op.GET(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9, extra:0) -> null line: LINE: 2f6ca063 S  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  298: [10-15 17:08:48,317] DEBUG Cache.java:530 Cache : Run(fast): Op.GETX(line:2f6ca063)
[ActorsRpcTest-peer1:out]  299: [10-15 17:08:48,319] DEBUG Cache.java:2666 Cache : Sending: [GETX OUT #_ TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  300: [10-15 17:08:48,319] DEBUG UDPComm.java:403 UDPComm : Sending to node 2 (/100.111.6.14:14732): [GETX OUT #_ TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  301: [10-15 17:08:48,322] DEBUG Cache.java:2675 Cache : Sent: [GETX OUT #3 TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  302: [10-15 17:08:48,322] DEBUG UDPComm.java:938 UDPComm : Adding message [GETX OUT #3 TO 2, line: 2f6ca063] to sent-packet
[ActorsRpcTest-peer1:out]  303: [10-15 17:08:48,322] DEBUG Cache.java:625 Cache : Run: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9)
[ActorsRpcTest-peer1:out]  304: [10-15 17:08:48,322] DEBUG UDPComm.java:456 UDPComm : Received packet MessagePacket[[[PUT IN #2R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes)], [INV IN #2 FROM 2, line: 2f6ca063, previousOwner: 2]]]
[ActorsRpcTest-peer1:out]  305: [10-15 17:08:48,322] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) line: LINE: 2f6ca063 S (->O) OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  306: [10-15 17:08:48,322] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) -> PENDING line: LINE: 2f6ca063 S (->O) OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  307: [10-15 17:08:48,322] DEBUG Cache.java:670 Cache : Adding op to pending Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) on line LINE: 2f6ca063 S (->O) OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  308: [10-15 17:08:48,324] DEBUG UDPComm.java:703 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578151721211, sentPacket=MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} sending packet MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063]]]
[ActorsRpcTest-peer1:out]  309: [10-15 17:08:48,324] DEBUG UDPComm.java:554 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578151721211, sentPacket=MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} rescheduling in 60000000
[ActorsRpcTest-peer1:out]  310: [10-15 17:08:48,324] DEBUG UDPComm.java:723 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578151721211, sentPacket=MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} has received packet MessagePacket[[[PUT IN #2R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes)], [INV IN #2 FROM 2, line: 2f6ca063, previousOwner: 2]]]
[ActorsRpcTest-peer1:out]  311: [10-15 17:08:48,324] DEBUG UDPComm.java:764 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578151721211, sentPacket=MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} ignoring repeat response [PUT IN #2R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes)]
[ActorsRpcTest-peer1:out]  312: [10-15 17:08:48,324] DEBUG UDPComm.java:669 UDPComm : Passing received message [INV IN #2 FROM 2, line: 2f6ca063, previousOwner: 2] to cache
[ActorsRpcTest-peer1:out]  313: [10-15 17:08:48,324] DEBUG Cache.java:843 Cache : Received: [INV IN #2 FROM 2, line: 2f6ca063, previousOwner: 2]
[ActorsRpcTest-peer1:out]  314: [10-15 17:08:48,324] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 S (->O) OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes) 2f6ca063 [INV IN #2 FROM 2, line: 2f6ca063, previousOwner: 2]
[ActorsRpcTest-peer1:out]  315: [10-15 17:08:48,324] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 S -> I
[ActorsRpcTest-peer1:out]  316: [10-15 17:08:48,325] DEBUG Cache.java:2666 Cache : Sending: [INVACK OUT #2R TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  317: [10-15 17:08:48,325] DEBUG UDPComm.java:403 UDPComm : Sending to node 2 (/100.111.6.14:14732): [INVACK OUT #2R TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  318: [10-15 17:08:48,325] DEBUG Cache.java:2675 Cache : Sent: [INVACK OUT #2R TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  319: [10-15 17:08:48,325] DEBUG Cache.java:2897 Cache : fireLineInvalidated LINE: 2f6ca063 I  OWN: 2 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  320: [10-15 17:08:48,325] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9), change = 1
[ActorsRpcTest-peer1:out]  321: [10-15 17:08:48,327] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) line: LINE: 2f6ca063 I  OWN: 2 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  322: [10-15 17:08:48,327] DEBUG Cache.java:2666 Cache : Sending: [GETX OUT #_ TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  323: [10-15 17:08:48,327] DEBUG UDPComm.java:403 UDPComm : Sending to node 2 (/100.111.6.14:14732): [GETX OUT #_ TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  324: [10-15 17:08:48,327] DEBUG Cache.java:2675 Cache : Sent: [GETX OUT #4 TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  325: [10-15 17:08:48,327] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) -> PENDING line: LINE: 2f6ca063 I (->O) OWN: 2 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  326: [10-15 17:08:48,331] DEBUG UDPComm.java:938 UDPComm : Adding message [INVACK OUT #2R TO 2, line: 2f6ca063] to sent-packet
[ActorsRpcTest-peer1:out]  327: [10-15 17:08:48,331] DEBUG UDPComm.java:703 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578154994185, sentPacket=MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063], [INVACK OUT #2R TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[[GETX OUT #4 TO 2, line: 2f6ca063]], broadcast=false} sending packet MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063], [INVACK OUT #2R TO 2, line: 2f6ca063]]]
[ActorsRpcTest-peer1:out]  328: [10-15 17:08:48,331] DEBUG UDPComm.java:554 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578154994185, sentPacket=MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063], [INVACK OUT #2R TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[[GETX OUT #4 TO 2, line: 2f6ca063]], broadcast=false} rescheduling in 60000000
[ActorsRpcTest-peer1:out]  329: [10-15 17:08:48,331] DEBUG UDPComm.java:938 UDPComm : Adding message [GETX OUT #4 TO 2, line: 2f6ca063] to sent-packet
[ActorsRpcTest-peer1:out]  330: [10-15 17:08:48,335] DEBUG UDPComm.java:703 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578161432550, sentPacket=MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063], [INVACK OUT #2R TO 2, line: 2f6ca063], [GETX OUT #4 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} sending packet MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063], [INVACK OUT #2R TO 2, line: 2f6ca063], [GETX OUT #4 TO 2, line: 2f6ca063]]]
[ActorsRpcTest-peer1:out]  331: [10-15 17:08:48,335] DEBUG UDPComm.java:554 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578161432550, sentPacket=MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063], [INVACK OUT #2R TO 2, line: 2f6ca063], [GETX OUT #4 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} rescheduling in 60000000
[ActorsRpcTest-peer1:out]  332: [10-15 17:08:48,335] DEBUG UDPComm.java:456 UDPComm : Received packet MessagePacket[[[INV IN #2 FROM 2, line: 2f6ca063, previousOwner: 2]]]
[ActorsRpcTest-peer1:out]  333: [10-15 17:08:48,335] DEBUG UDPComm.java:723 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578161432550, sentPacket=MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063], [INVACK OUT #2R TO 2, line: 2f6ca063], [GETX OUT #4 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} has received packet MessagePacket[[[INV IN #2 FROM 2, line: 2f6ca063, previousOwner: 2]]]
[ActorsRpcTest-peer1:out]  334: [10-15 17:08:48,336] DEBUG UDPComm.java:781 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578161432550, sentPacket=MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063], [INVACK OUT #2R TO 2, line: 2f6ca063], [GETX OUT #4 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} already has a response for message [INV IN #2 FROM 2, line: 2f6ca063, previousOwner: 2]
[ActorsRpcTest-peer1:out]  335: [10-15 17:08:48,336] DEBUG UDPComm.java:703 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578165882902, sentPacket=MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063], [INVACK OUT #2R TO 2, line: 2f6ca063], [GETX OUT #4 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} sending packet MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063], [INVACK OUT #2R TO 2, line: 2f6ca063], [GETX OUT #4 TO 2, line: 2f6ca063]]]
[ActorsRpcTest-peer1:out]  336: [10-15 17:08:48,336] DEBUG UDPComm.java:554 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578165882902, sentPacket=MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063], [INVACK OUT #2R TO 2, line: 2f6ca063], [GETX OUT #4 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} rescheduling in 60000000
[ActorsRpcTest-peer1:out]  337: [10-15 17:08:48,339] DEBUG UDPComm.java:456 UDPComm : Received packet MessagePacket[[[PUTX IN #3R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX IN #3 FROM 2, line: 2f6ca063]]]
[ActorsRpcTest-peer1:out]  338: [10-15 17:08:48,339] DEBUG UDPComm.java:723 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578165882902, sentPacket=MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063], [INVACK OUT #2R TO 2, line: 2f6ca063], [GETX OUT #4 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} has received packet MessagePacket[[[PUTX IN #3R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX IN #3 FROM 2, line: 2f6ca063]]]
[ActorsRpcTest-peer1:out]  339: [10-15 17:08:48,339] DEBUG UDPComm.java:749 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578165882902, sentPacket=MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063], [INVACK OUT #2R TO 2, line: 2f6ca063], [GETX OUT #4 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} removing response [INVACK OUT #2R TO 2, line: 2f6ca063] from sent packet because it was no longer asked for.
[ActorsRpcTest-peer1:out]  340: [10-15 17:08:48,340] DEBUG UDPComm.java:768 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578165882902, sentPacket=MessagePacket[[[GETX OUT #3 TO 2, line: 2f6ca063], [GETX OUT #4 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} received response [PUTX IN #3R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0] for request ([GETX OUT #3 TO 2, line: 2f6ca063])
[ActorsRpcTest-peer1:out]  341: [10-15 17:08:48,340] DEBUG UDPComm.java:669 UDPComm : Passing received message [PUTX IN #3R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0] to cache
[ActorsRpcTest-peer1:out]  342: [10-15 17:08:48,340] DEBUG Cache.java:843 Cache : Received: [PUTX IN #3R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer1:out]  343: [10-15 17:08:48,341] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 I (->O) OWN: 2 SHARE: null VER: 1 DATA: (0 bytes) 2f6ca063 [PUTX IN #3R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer1:out]  344: [10-15 17:08:48,343] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 I -> O
[ActorsRpcTest-peer1:out]  345: [10-15 17:08:48,351] DEBUG UDPComm.java:703 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578173777697, sentPacket=MessagePacket[[[GETX OUT #4 TO 2, line: 2f6ca063]]], pendingRequests={3}, next=null, queue=[], broadcast=false} sending packet MessagePacket[[[GETX OUT #4 TO 2, line: 2f6ca063]]]
[ActorsRpcTest-peer1:out]  346: [10-15 17:08:48,351] DEBUG UDPComm.java:554 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578173777697, sentPacket=MessagePacket[[[GETX OUT #4 TO 2, line: 2f6ca063]]], pendingRequests={3}, next=null, queue=[], broadcast=false} rescheduling in 60000000
[ActorsRpcTest-peer1:out]  347: [10-15 17:08:48,372] DEBUG Cache.java:2915 Cache : fireLineReceived LINE: 2f6ca063 O  OWN: 2 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  348: [10-15 17:08:48,372] DEBUG Cache.java:2666 Cache : Sending: [INV OUT #_ TO 0, line: 2f6ca063, previousOwner: 2]
[ActorsRpcTest-peer1:out]  349: [10-15 17:08:48,372] DEBUG Cache.java:2675 Cache : Sent: [INV OUT #5 TO 0, line: 2f6ca063, previousOwner: 2]
[ActorsRpcTest-peer1:out]  350: [10-15 17:08:48,372] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9), change = 3
[ActorsRpcTest-peer1:out]  351: [10-15 17:08:48,372] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) line: LINE: 2f6ca063 O  OWN: 2 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  352: [10-15 17:08:48,373] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) -> PENDING line: LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  353: [10-15 17:08:48,374] DEBUG UDPComm.java:669 UDPComm : Passing received message [GETX IN #3 FROM 2, line: 2f6ca063] to cache
[ActorsRpcTest-peer1:out]  354: [10-15 17:08:48,374] DEBUG Cache.java:843 Cache : Received: [GETX IN #3 FROM 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  355: [10-15 17:08:48,374] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {0} VER: 1 DATA: (0 bytes) 2f6ca063 [GETX IN #3 FROM 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  356: [10-15 17:08:48,374] DEBUG Cache.java:957 Cache : Adding message to pending [GETX IN #3 FROM 2, line: 2f6ca063] on line LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  357: [10-15 17:08:48,374] DEBUG Cache.java:2787 Cache : addPendingMessage [GETX IN #3 FROM 2, line: 2f6ca063] to line LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  358: [10-15 17:08:48,374] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9), change = 0
[ActorsRpcTest-peer1:out]  359: [10-15 17:08:48,374] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) line: LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  360: [10-15 17:08:48,374] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) -> PENDING line: LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  361: [10-15 17:08:48,374] DEBUG Cache.java:843 Cache : Received: [INVACK IN #5R FROM 0, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  362: [10-15 17:08:48,374] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {0} VER: 1 DATA: (0 bytes) 2f6ca063 [INVACK IN #5R FROM 0, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  363: [10-15 17:08:48,375] DEBUG UDPComm.java:456 UDPComm : Received packet MessagePacket[[[PUTX IN #3R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX IN #3 FROM 2, line: 2f6ca063], [CHNGD_OWNR IN #4R FROM 2, line: 2f6ca063, newOwner: 1, certain: false]]]
[ActorsRpcTest-peer1:out]  364: [10-15 17:08:48,375] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 O -> E
[ActorsRpcTest-peer1:out]  365: [10-15 17:08:48,375] DEBUG UDPComm.java:723 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578173777697, sentPacket=MessagePacket[[[GETX OUT #4 TO 2, line: 2f6ca063]]], pendingRequests={3}, next=null, queue=[], broadcast=false} has received packet MessagePacket[[[PUTX IN #3R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX IN #3 FROM 2, line: 2f6ca063], [CHNGD_OWNR IN #4R FROM 2, line: 2f6ca063, newOwner: 1, certain: false]]]
[ActorsRpcTest-peer1:out]  366: [10-15 17:08:48,375] DEBUG Cache.java:2384 Cache : Set owner 2f6ca063 2 -> 1
[ActorsRpcTest-peer1:out]  367: [10-15 17:08:48,375] DEBUG UDPComm.java:764 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578173777697, sentPacket=MessagePacket[[[GETX OUT #4 TO 2, line: 2f6ca063]]], pendingRequests={3}, next=null, queue=[], broadcast=false} ignoring repeat response [PUTX IN #3R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer1:out]  368: [10-15 17:08:48,375] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9), change = 3
[ActorsRpcTest-peer1:out]  369: [10-15 17:08:48,375] DEBUG UDPComm.java:785 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578173777697, sentPacket=MessagePacket[[[GETX OUT #4 TO 2, line: 2f6ca063]]], pendingRequests={3}, next=null, queue=[], broadcast=false} already has a request pending for message [GETX IN #3 FROM 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  370: [10-15 17:08:48,375] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) line: LINE: 2f6ca063 E  OWN: 1 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  371: [10-15 17:08:48,375] DEBUG UDPComm.java:768 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578173777697, sentPacket=MessagePacket[[[GETX OUT #4 TO 2, line: 2f6ca063]]], pendingRequests={3}, next=null, queue=[], broadcast=false} received response [CHNGD_OWNR IN #4R FROM 2, line: 2f6ca063, newOwner: 1, certain: false] for request ([GETX OUT #4 TO 2, line: 2f6ca063])
[ActorsRpcTest-peer1:out]  372: [10-15 17:08:48,375] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) -> PENDING line: LINE: 2f6ca063 E  OWN: 1 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  373: [10-15 17:08:48,375] DEBUG UDPComm.java:669 UDPComm : Passing received message [CHNGD_OWNR IN #4R FROM 2, line: 2f6ca063, newOwner: 1, certain: false] to cache
[ActorsRpcTest-peer1:out]  374: [10-15 17:08:48,376] DEBUG Cache.java:1084 Cache : Handling pending message [GETX IN #3 FROM 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  375: [10-15 17:08:48,376] DEBUG Cache.java:843 Cache : Received: [CHNGD_OWNR IN #4R FROM 2, line: 2f6ca063, newOwner: 1, certain: false]
[ActorsRpcTest-peer1:out]  376: [10-15 17:08:48,376] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 E -> I
[ActorsRpcTest-peer1:out]  377: [10-15 17:08:48,376] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 E  OWN: 1 SHARE: {} VER: 1 DATA: (0 bytes) 2f6ca063 [CHNGD_OWNR IN #4R FROM 2, line: 2f6ca063, newOwner: 1, certain: false]
[ActorsRpcTest-peer1:out]  378: [10-15 17:08:48,376] DEBUG Cache.java:2384 Cache : Set owner 2f6ca063 1 -> 2
[ActorsRpcTest-peer1:out]  379: [10-15 17:08:48,376] DEBUG Cache.java:2666 Cache : Sending: [PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer1:out]  380: [10-15 17:08:48,376] DEBUG UDPComm.java:403 UDPComm : Sending to node 2 (/100.111.6.14:14732): [PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer1:out]  381: [10-15 17:08:48,377] DEBUG Cache.java:2675 Cache : Sent: [PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer1:out]  382: [10-15 17:08:48,377] DEBUG UDPComm.java:938 UDPComm : Adding message [PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0] to sent-packet
[ActorsRpcTest-peer1:out]  383: [10-15 17:08:48,377] DEBUG Cache.java:2897 Cache : fireLineInvalidated LINE: 2f6ca063 I  OWN: 2 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  384: [10-15 17:08:48,377] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9), change = 3
[ActorsRpcTest-peer1:out]  385: [10-15 17:08:48,377] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) line: LINE: 2f6ca063 I  OWN: 2 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  386: [10-15 17:08:48,377] DEBUG Cache.java:2666 Cache : Sending: [GETX OUT #_ TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  387: [10-15 17:08:48,377] DEBUG UDPComm.java:403 UDPComm : Sending to node 2 (/100.111.6.14:14732): [GETX OUT #_ TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  388: [10-15 17:08:48,377] DEBUG Cache.java:2675 Cache : Sent: [GETX OUT #6 TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  389: [10-15 17:08:48,377] DEBUG UDPComm.java:938 UDPComm : Adding message [GETX OUT #6 TO 2, line: 2f6ca063] to sent-packet
[ActorsRpcTest-peer1:out]  390: [10-15 17:08:48,378] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) -> PENDING line: LINE: 2f6ca063 I (->O) OWN: 2 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  391: [10-15 17:08:48,378] DEBUG Cache.java:1950 Cache : Not changing owner of 2f6ca063 to 1 because node is not in the cluster.
[ActorsRpcTest-peer1:out]  392: [10-15 17:08:48,378] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9), change = 2
[ActorsRpcTest-peer1:out]  393: [10-15 17:08:48,378] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) line: LINE: 2f6ca063 I  OWN: 2 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  394: [10-15 17:08:48,378] DEBUG Cache.java:2666 Cache : Sending: [GETX OUT #_ TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  395: [10-15 17:08:48,378] DEBUG UDPComm.java:403 UDPComm : Sending to node 2 (/100.111.6.14:14732): [GETX OUT #_ TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  396: [10-15 17:08:48,378] DEBUG Cache.java:2675 Cache : Sent: [GETX OUT #7 TO 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  397: [10-15 17:08:48,378] DEBUG UDPComm.java:938 UDPComm : Adding message [GETX OUT #7 TO 2, line: 2f6ca063] to sent-packet
[ActorsRpcTest-peer1:out]  398: [10-15 17:08:48,378] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) -> PENDING line: LINE: 2f6ca063 I (->O) OWN: 2 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  399: [10-15 17:08:48,378] DEBUG UDPComm.java:703 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578206897383, sentPacket=MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} sending packet MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]]
[ActorsRpcTest-peer1:out]  400: [10-15 17:08:48,379] DEBUG UDPComm.java:554 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578206897383, sentPacket=MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} rescheduling in 60000000
[ActorsRpcTest-peer1:out]  401: [10-15 17:08:48,379] DEBUG UDPComm.java:456 UDPComm : Received packet MessagePacket[[[PUTX IN #3R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX IN #3 FROM 2, line: 2f6ca063], [CHNGD_OWNR IN #4R FROM 2, line: 2f6ca063, newOwner: 1, certain: false]]]
[ActorsRpcTest-peer1:out]  402: [10-15 17:08:48,379] DEBUG UDPComm.java:723 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578206897383, sentPacket=MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} has received packet MessagePacket[[[PUTX IN #3R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX IN #3 FROM 2, line: 2f6ca063], [CHNGD_OWNR IN #4R FROM 2, line: 2f6ca063, newOwner: 1, certain: false]]]
[ActorsRpcTest-peer1:out]  403: [10-15 17:08:48,379] DEBUG UDPComm.java:764 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578206897383, sentPacket=MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} ignoring repeat response [PUTX IN #3R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer1:out]  404: [10-15 17:08:48,379] DEBUG UDPComm.java:781 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578206897383, sentPacket=MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} already has a response for message [GETX IN #3 FROM 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  405: [10-15 17:08:48,379] DEBUG UDPComm.java:764 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578206897383, sentPacket=MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} ignoring repeat response [CHNGD_OWNR IN #4R FROM 2, line: 2f6ca063, newOwner: 1, certain: false]
[ActorsRpcTest-peer1:out]  406: [10-15 17:08:48,379] DEBUG UDPComm.java:703 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578209490207, sentPacket=MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} sending packet MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]]
[ActorsRpcTest-peer1:out]  407: [10-15 17:08:48,379] DEBUG UDPComm.java:554 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578209490207, sentPacket=MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} rescheduling in 60000000
[ActorsRpcTest-peer1:out]  408: [10-15 17:08:48,380] DEBUG UDPComm.java:456 UDPComm : Received packet MessagePacket[[[GETX IN #3 FROM 2, line: 2f6ca063], [CHNGD_OWNR IN #4R FROM 2, line: 2f6ca063, newOwner: 1, certain: false]]]
[ActorsRpcTest-peer1:out]  409: [10-15 17:08:48,380] DEBUG UDPComm.java:723 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578209490207, sentPacket=MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} has received packet MessagePacket[[[GETX IN #3 FROM 2, line: 2f6ca063], [CHNGD_OWNR IN #4R FROM 2, line: 2f6ca063, newOwner: 1, certain: false]]]
[ActorsRpcTest-peer2:out]  347: [10-15 17:08:48,339] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 I (->O) OWN: 1 SHARE: null VER: 1 DATA: (0 bytes) 2f6ca063 [GETX IN #4 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  348: [10-15 17:08:48,340] DEBUG Cache.java:2666 Cache : Sending: [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]
[ActorsRpcTest-peer2:out]  349: [10-15 17:08:48,340] DEBUG UDPComm.java:403 UDPComm : Sending to node 1 (/100.111.6.14:33639): [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]
[ActorsRpcTest-peer2:out]  350: [10-15 17:08:48,340] DEBUG Cache.java:2675 Cache : Sent: [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]
[ActorsRpcTest-peer2:out]  351: [10-15 17:08:48,340] DEBUG UDPComm.java:938 UDPComm : Adding message [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false] to sent-packet
[ActorsRpcTest-peer2:out]  352: [10-15 17:08:48,340] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4), change = 0
[ActorsRpcTest-peer2:out]  353: [10-15 17:08:48,341] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4) line: LINE: 2f6ca063 I (->O) OWN: 1 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  354: [10-15 17:08:48,341] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4) -> PENDING line: LINE: 2f6ca063 I (->O) OWN: 1 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  355: [10-15 17:08:48,342] DEBUG UDPComm.java:703 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578170595430, sentPacket=MessagePacket[[[PUTX OUT #3R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]], pendingRequests={}, next=null, queue=[], broadcast=false} sending packet MessagePacket[[[PUTX OUT #3R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]]
[ActorsRpcTest-peer2:out]  356: [10-15 17:08:48,342] DEBUG UDPComm.java:554 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578170595430, sentPacket=MessagePacket[[[PUTX OUT #3R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]], pendingRequests={}, next=null, queue=[], broadcast=false} rescheduling in 60000000
[ActorsRpcTest-peer2:out]  357: [10-15 17:08:48,342] DEBUG UDPComm.java:456 UDPComm : Received packet MessagePacket[[[GETX IN #3 FROM 1, line: 2f6ca063], [INVACK IN #2R FROM 1, line: 2f6ca063], [GETX IN #4 FROM 1, line: 2f6ca063]]]
[ActorsRpcTest-peer2:out]  358: [10-15 17:08:48,342] DEBUG UDPComm.java:723 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578170595430, sentPacket=MessagePacket[[[PUTX OUT #3R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]], pendingRequests={}, next=null, queue=[], broadcast=false} has received packet MessagePacket[[[GETX IN #3 FROM 1, line: 2f6ca063], [INVACK IN #2R FROM 1, line: 2f6ca063], [GETX IN #4 FROM 1, line: 2f6ca063]]]
[ActorsRpcTest-peer2:out]  359: [10-15 17:08:48,342] DEBUG UDPComm.java:781 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578170595430, sentPacket=MessagePacket[[[PUTX OUT #3R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]], pendingRequests={}, next=null, queue=[], broadcast=false} already has a response for message [GETX IN #3 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  360: [10-15 17:08:48,342] DEBUG UDPComm.java:764 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578170595430, sentPacket=MessagePacket[[[PUTX OUT #3R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]], pendingRequests={}, next=null, queue=[], broadcast=false} ignoring repeat response [INVACK IN #2R FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  361: [10-15 17:08:48,342] DEBUG UDPComm.java:781 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578170595430, sentPacket=MessagePacket[[[PUTX OUT #3R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]], pendingRequests={}, next=null, queue=[], broadcast=false} already has a response for message [GETX IN #4 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  362: [10-15 17:08:48,343] DEBUG UDPComm.java:703 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578172789567, sentPacket=MessagePacket[[[PUTX OUT #3R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]], pendingRequests={}, next=null, queue=[], broadcast=false} sending packet MessagePacket[[[PUTX OUT #3R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]]
[ActorsRpcTest-peer2:out]  363: [10-15 17:08:48,343] DEBUG UDPComm.java:554 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578172789567, sentPacket=MessagePacket[[[PUTX OUT #3R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]], pendingRequests={}, next=null, queue=[], broadcast=false} rescheduling in 60000000
[ActorsRpcTest-peer2:out]  364: [10-15 17:08:48,352] DEBUG UDPComm.java:456 UDPComm : Received packet MessagePacket[[[GETX IN #4 FROM 1, line: 2f6ca063]]]
[ActorsRpcTest-peer2:out]  365: [10-15 17:08:48,352] DEBUG UDPComm.java:723 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578172789567, sentPacket=MessagePacket[[[PUTX OUT #3R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]], pendingRequests={}, next=null, queue=[], broadcast=false} has received packet MessagePacket[[[GETX IN #4 FROM 1, line: 2f6ca063]]]
[ActorsRpcTest-peer2:out]  366: [10-15 17:08:48,352] DEBUG UDPComm.java:749 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578172789567, sentPacket=MessagePacket[[[PUTX OUT #3R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]], pendingRequests={}, next=null, queue=[], broadcast=false} removing response [PUTX OUT #3R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0] from sent packet because it was no longer asked for.
[ActorsRpcTest-peer2:out]  367: [10-15 17:08:48,352] DEBUG UDPComm.java:781 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578172789567, sentPacket=MessagePacket[[[GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]], pendingRequests={}, next=null, queue=[], broadcast=false} already has a response for message [GETX IN #4 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  368: [10-15 17:08:48,352] DEBUG UDPComm.java:703 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578182622652, sentPacket=MessagePacket[[[GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]], pendingRequests={}, next=null, queue=[], broadcast=false} sending packet MessagePacket[[[GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]]
[ActorsRpcTest-peer2:out]  369: [10-15 17:08:48,353] DEBUG UDPComm.java:554 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578182622652, sentPacket=MessagePacket[[[GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]], pendingRequests={}, next=null, queue=[], broadcast=false} rescheduling in 60000000
[ActorsRpcTest-peer2:out]  370: [10-15 17:08:48,379] DEBUG UDPComm.java:456 UDPComm : Received packet MessagePacket[[[PUTX IN #3R FROM 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX IN #6 FROM 1, line: 2f6ca063], [GETX IN #7 FROM 1, line: 2f6ca063]]]
[ActorsRpcTest-peer2:out]  371: [10-15 17:08:48,379] DEBUG UDPComm.java:723 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578182622652, sentPacket=MessagePacket[[[GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]], pendingRequests={}, next=null, queue=[], broadcast=false} has received packet MessagePacket[[[PUTX IN #3R FROM 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX IN #6 FROM 1, line: 2f6ca063], [GETX IN #7 FROM 1, line: 2f6ca063]]]
[ActorsRpcTest-peer2:out]  372: [10-15 17:08:48,379] DEBUG UDPComm.java:749 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578182622652, sentPacket=MessagePacket[[[GETX OUT #3 TO 1, line: 2f6ca063], [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false]]], pendingRequests={}, next=null, queue=[], broadcast=false} removing response [CHNGD_OWNR OUT #4R TO 1, line: 2f6ca063, newOwner: 1, certain: false] from sent packet because it was no longer asked for.
[ActorsRpcTest-peer2:out]  373: [10-15 17:08:48,379] DEBUG UDPComm.java:768 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578182622652, sentPacket=MessagePacket[[[GETX OUT #3 TO 1, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} received response [PUTX IN #3R FROM 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0] for request ([GETX OUT #3 TO 1, line: 2f6ca063])
[ActorsRpcTest-peer2:out]  374: [10-15 17:08:48,379] DEBUG UDPComm.java:669 UDPComm : Passing received message [PUTX IN #3R FROM 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0] to cache
[ActorsRpcTest-peer2:out]  375: [10-15 17:08:48,380] DEBUG Cache.java:843 Cache : Received: [PUTX IN #3R FROM 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer2:out]  376: [10-15 17:08:48,380] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 I (->O) OWN: 1 SHARE: null VER: 1 DATA: (0 bytes) 2f6ca063 [PUTX IN #3R FROM 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer2:out]  377: [10-15 17:08:48,380] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 I -> O
[ActorsRpcTest-peer2:out]  378: [10-15 17:08:48,380] DEBUG Cache.java:2915 Cache : fireLineReceived LINE: 2f6ca063 O  OWN: 1 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  379: [10-15 17:08:48,380] DEBUG Cache.java:2666 Cache : Sending: [INV OUT #_ TO 0, line: 2f6ca063, previousOwner: 1]
[ActorsRpcTest-peer2:out]  380: [10-15 17:08:48,381] DEBUG Cache.java:2675 Cache : Sent: [INV OUT #4 TO 0, line: 2f6ca063, previousOwner: 1]
[ActorsRpcTest-peer2:out]  381: [10-15 17:08:48,381] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4), change = 3
[ActorsRpcTest-peer2:out]  382: [10-15 17:08:48,390] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4) line: LINE: 2f6ca063 O  OWN: 1 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  383: [10-15 17:08:48,390] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4) -> PENDING line: LINE: 2f6ca063 O (->E) OWN: 1 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  384: [10-15 17:08:48,390] DEBUG UDPComm.java:669 UDPComm : Passing received message [GETX IN #6 FROM 1, line: 2f6ca063] to cache
[ActorsRpcTest-peer2:out]  385: [10-15 17:08:48,390] DEBUG Cache.java:843 Cache : Received: [GETX IN #6 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  386: [10-15 17:08:48,390] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 O (->E) OWN: 1 SHARE: {0} VER: 1 DATA: (0 bytes) 2f6ca063 [GETX IN #6 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  387: [10-15 17:08:48,391] DEBUG Cache.java:957 Cache : Adding message to pending [GETX IN #6 FROM 1, line: 2f6ca063] on line LINE: 2f6ca063 O (->E) OWN: 1 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  388: [10-15 17:08:48,391] DEBUG Cache.java:2787 Cache : addPendingMessage [GETX IN #6 FROM 1, line: 2f6ca063] to line LINE: 2f6ca063 O (->E) OWN: 1 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  389: [10-15 17:08:48,391] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4), change = 0
[ActorsRpcTest-peer2:out]  390: [10-15 17:08:48,391] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4) line: LINE: 2f6ca063 O (->E) OWN: 1 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  391: [10-15 17:08:48,391] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4) -> PENDING line: LINE: 2f6ca063 O (->E) OWN: 1 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  392: [10-15 17:08:48,391] DEBUG UDPComm.java:669 UDPComm : Passing received message [GETX IN #7 FROM 1, line: 2f6ca063] to cache
[ActorsRpcTest-peer2:out]  393: [10-15 17:08:48,391] DEBUG Cache.java:843 Cache : Received: [GETX IN #7 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  394: [10-15 17:08:48,391] DEBUG Cache.java:843 Cache : Received: [INVACK IN #4R FROM 0, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  395: [10-15 17:08:48,391] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 O (->E) OWN: 1 SHARE: {0} VER: 1 DATA: (0 bytes) 2f6ca063 [GETX IN #7 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  396: [10-15 17:08:48,391] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 O (->E) OWN: 1 SHARE: {0} VER: 1 DATA: (0 bytes) 2f6ca063 [INVACK IN #4R FROM 0, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  397: [10-15 17:08:48,392] DEBUG Cache.java:957 Cache : Adding message to pending [GETX IN #7 FROM 1, line: 2f6ca063] on line LINE: 2f6ca063 O (->E) OWN: 1 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  398: [10-15 17:08:48,392] DEBUG Cache.java:2787 Cache : addPendingMessage [GETX IN #7 FROM 1, line: 2f6ca063] to line LINE: 2f6ca063 O (->E) OWN: 1 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  399: [10-15 17:08:48,392] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4), change = 0
[ActorsRpcTest-peer2:out]  400: [10-15 17:08:48,392] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4) line: LINE: 2f6ca063 O (->E) OWN: 1 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  401: [10-15 17:08:48,392] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4) -> PENDING line: LINE: 2f6ca063 O (->E) OWN: 1 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  402: [10-15 17:08:48,392] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 O -> E
[ActorsRpcTest-peer2:out]  403: [10-15 17:08:48,392] DEBUG UDPComm.java:456 UDPComm : Received packet MessagePacket[[[PUTX IN #3R FROM 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX IN #6 FROM 1, line: 2f6ca063], [GETX IN #7 FROM 1, line: 2f6ca063]]]
[ActorsRpcTest-peer2:out]  404: [10-15 17:08:48,392] DEBUG Cache.java:2384 Cache : Set owner 2f6ca063 1 -> 2
[ActorsRpcTest-peer2:out]  405: [10-15 17:08:48,393] DEBUG UDPComm.java:723 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=0, sentPacket=null, pendingRequests={6, 7}, next=null, queue=[], broadcast=false} has received packet MessagePacket[[[PUTX IN #3R FROM 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX IN #6 FROM 1, line: 2f6ca063], [GETX IN #7 FROM 1, line: 2f6ca063]]]
[ActorsRpcTest-peer2:out]  406: [10-15 17:08:48,393] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4), change = 3
[ActorsRpcTest-peer2:out]  407: [10-15 17:08:48,393] DEBUG UDPComm.java:764 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=0, sentPacket=null, pendingRequests={6, 7}, next=null, queue=[], broadcast=false} ignoring repeat response [PUTX IN #3R FROM 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer2:out]  408: [10-15 17:08:48,393] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4) line: LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  410: [10-15 17:08:48,380] DEBUG UDPComm.java:781 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578209490207, sentPacket=MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} already has a response for message [GETX IN #3 FROM 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  411: [10-15 17:08:48,380] DEBUG UDPComm.java:764 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578209490207, sentPacket=MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} ignoring repeat response [CHNGD_OWNR IN #4R FROM 2, line: 2f6ca063, newOwner: 1, certain: false]
[ActorsRpcTest-peer1:out]  412: [10-15 17:08:48,381] DEBUG UDPComm.java:703 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578210801687, sentPacket=MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} sending packet MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]]
[ActorsRpcTest-peer1:out]  413: [10-15 17:08:48,381] DEBUG UDPComm.java:554 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578210801687, sentPacket=MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} rescheduling in 60000000
[ActorsRpcTest-peer1:out]  414: [10-15 17:08:48,398] DEBUG UDPComm.java:456 UDPComm : Received packet MessagePacket[[[PUTX IN #6R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [CHNGD_OWNR IN #7R FROM 2, line: 2f6ca063, newOwner: 1, certain: false], [GETX IN #5 FROM 2, line: 2f6ca063]]]
[ActorsRpcTest-peer1:out]  415: [10-15 17:08:48,399] DEBUG UDPComm.java:723 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578210801687, sentPacket=MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} has received packet MessagePacket[[[PUTX IN #6R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [CHNGD_OWNR IN #7R FROM 2, line: 2f6ca063, newOwner: 1, certain: false], [GETX IN #5 FROM 2, line: 2f6ca063]]]
[ActorsRpcTest-peer1:out]  416: [10-15 17:08:48,399] DEBUG UDPComm.java:749 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578210801687, sentPacket=MessagePacket[[[PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} removing response [PUTX OUT #3R TO 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0] from sent packet because it was no longer asked for.
[ActorsRpcTest-peer1:out]  417: [10-15 17:08:48,399] DEBUG UDPComm.java:768 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578210801687, sentPacket=MessagePacket[[[GETX OUT #6 TO 2, line: 2f6ca063], [GETX OUT #7 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} received response [PUTX IN #6R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0] for request ([GETX OUT #6 TO 2, line: 2f6ca063])
[ActorsRpcTest-peer1:out]  418: [10-15 17:08:48,399] DEBUG UDPComm.java:768 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578210801687, sentPacket=MessagePacket[[[GETX OUT #7 TO 2, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} received response [CHNGD_OWNR IN #7R FROM 2, line: 2f6ca063, newOwner: 1, certain: false] for request ([GETX OUT #7 TO 2, line: 2f6ca063])
[ActorsRpcTest-peer1:out]  419: [10-15 17:08:48,399] DEBUG UDPComm.java:669 UDPComm : Passing received message [PUTX IN #6R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0] to cache
[ActorsRpcTest-peer1:out]  420: [10-15 17:08:48,399] DEBUG Cache.java:843 Cache : Received: [PUTX IN #6R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer1:out]  421: [10-15 17:08:48,400] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 I (->O) OWN: 2 SHARE: null VER: 1 DATA: (0 bytes) 2f6ca063 [PUTX IN #6R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer1:out]  422: [10-15 17:08:48,400] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 I -> O
[ActorsRpcTest-peer1:out]  423: [10-15 17:08:48,403] DEBUG Cache.java:2915 Cache : fireLineReceived LINE: 2f6ca063 O  OWN: 2 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  424: [10-15 17:08:48,403] DEBUG Cache.java:2666 Cache : Sending: [INV OUT #_ TO 0, line: 2f6ca063, previousOwner: 2]
[ActorsRpcTest-peer1:out]  425: [10-15 17:08:48,404] DEBUG Cache.java:2675 Cache : Sent: [INV OUT #8 TO 0, line: 2f6ca063, previousOwner: 2]
[ActorsRpcTest-peer1:out]  426: [10-15 17:08:48,404] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9), change = 3
[ActorsRpcTest-peer1:out]  427: [10-15 17:08:48,404] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) line: LINE: 2f6ca063 O  OWN: 2 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  428: [10-15 17:08:48,404] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) -> PENDING line: LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  429: [10-15 17:08:48,405] DEBUG UDPComm.java:669 UDPComm : Passing received message [CHNGD_OWNR IN #7R FROM 2, line: 2f6ca063, newOwner: 1, certain: false] to cache
[ActorsRpcTest-peer1:out]  430: [10-15 17:08:48,405] DEBUG Cache.java:843 Cache : Received: [CHNGD_OWNR IN #7R FROM 2, line: 2f6ca063, newOwner: 1, certain: false]
[ActorsRpcTest-peer1:out]  431: [10-15 17:08:48,405] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {0} VER: 1 DATA: (0 bytes) 2f6ca063 [CHNGD_OWNR IN #7R FROM 2, line: 2f6ca063, newOwner: 1, certain: false]
[ActorsRpcTest-peer1:out]  432: [10-15 17:08:48,405] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9), change = 0
[ActorsRpcTest-peer1:out]  433: [10-15 17:08:48,405] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) line: LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  434: [10-15 17:08:48,405] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) -> PENDING line: LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {0} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  435: [10-15 17:08:48,405] DEBUG Cache.java:843 Cache : Received: [INVACK IN #8R FROM 0, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  436: [10-15 17:08:48,406] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 O (->E) OWN: 2 SHARE: {0} VER: 1 DATA: (0 bytes) 2f6ca063 [INVACK IN #8R FROM 0, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  437: [10-15 17:08:48,405] DEBUG UDPComm.java:669 UDPComm : Passing received message [GETX IN #5 FROM 2, line: 2f6ca063] to cache
[ActorsRpcTest-peer1:out]  438: [10-15 17:08:48,406] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 O -> E
[ActorsRpcTest-peer1:out]  439: [10-15 17:08:48,406] DEBUG Cache.java:843 Cache : Received: [GETX IN #5 FROM 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  440: [10-15 17:08:48,406] DEBUG Cache.java:2384 Cache : Set owner 2f6ca063 2 -> 1
[ActorsRpcTest-peer1:out]  441: [10-15 17:08:48,406] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes) 2f6ca063 [GETX IN #5 FROM 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  442: [10-15 17:08:48,406] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9), change = 3
[ActorsRpcTest-peer1:out]  443: [10-15 17:08:48,407] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) line: LINE: 2f6ca063 E  OWN: 1 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer1:out]  444: [10-15 17:08:48,407] DEBUG Cache.java:2646 Cache : Locking line LINE: 2f6ca063 E  OWN: 1 SHARE: {} VER: 1 DATA: (0 bytes) MODIFIED
[ActorsRpcTest-peer1:out]  445: [10-15 17:08:48,407] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) -> null line: LINE: 2f6ca063 E  OWN: 1 SHARE: {} VER: 1 DATA: (0 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer1:out]  446: [10-15 17:08:48,407] DEBUG Cache.java:781 Cache : completeOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@51b469b9) -> null line: LINE: 2f6ca063 E  OWN: 1 SHARE: {} VER: 1 DATA: (0 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer1:out]  447: [10-15 17:08:48,407] DEBUG Cache.java:957 Cache : Adding message to pending [GETX IN #5 FROM 2, line: 2f6ca063] on line LINE: 2f6ca063 E  OWN: 1 SHARE: {} VER: 1 DATA: (0 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer1:out]  448: [10-15 17:08:48,407] DEBUG Cache.java:530 Cache : Run(fast): Op.PUT(line:ffffffffffffffff)
[ActorsRpcTest-peer1:out]  449: [10-15 17:08:48,407] DEBUG Cache.java:2787 Cache : addPendingMessage [GETX IN #5 FROM 2, line: 2f6ca063] to line LINE: 2f6ca063 E  OWN: 1 SHARE: {} VER: 1 DATA: (0 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer1:out]  450: [10-15 17:08:48,407] DEBUG Cache.java:625 Cache : Run: Op.PUT(line:ffffffffffffffff, data:[B@1a0569a1)
[ActorsRpcTest-peer1:out]  451: [10-15 17:08:48,408] DEBUG Cache.java:680 Cache : handleOp: Op.PUT(line:ffffffffffffffff, data:[B@1a0569a1) line: null
[ActorsRpcTest-peer1:out]  452: [10-15 17:08:48,409] DEBUG Cache.java:699 Cache : handleOp: Op.PUT(line:ffffffffffffffff, data:[B@1a0569a1) -> PENDING line: null
[ActorsRpcTest-peer1:out]  453: [10-15 17:08:48,409] DEBUG Cache.java:670 Cache : Adding op to pending Op.PUT(line:ffffffffffffffff, data:[B@1a0569a1) on line null
[ActorsRpcTest-peer1:out]  454: [10-15 17:08:48,414] DEBUG Cache.java:843 Cache : Received: [ALLOCED_REF IN #9R FROM 0, start: 100000000, num: 10000]
[ActorsRpcTest-peer1:out]  455: [10-15 17:08:48,415] DEBUG Cache.java:625 Cache : Run: Op.PUT(line:ffffffffffffffff, data:[B@1a0569a1)
[ActorsRpcTest-peer1:out]  456: [10-15 17:08:48,415] DEBUG Cache.java:680 Cache : handleOp: Op.PUT(line:ffffffffffffffff, data:[B@1a0569a1) line: null
[ActorsRpcTest-peer1:out]  457: [10-15 17:08:48,415] DEBUG Cache.java:2355 Cache : Set state 100000000 I -> E
[ActorsRpcTest-peer1:out]  458: [10-15 17:08:48,416] DEBUG Cache.java:2384 Cache : Set owner 100000000 -1 -> 1
[ActorsRpcTest-peer1:out]  459: [10-15 17:08:48,416] DEBUG Cache.java:2562 Cache : Allocating storage (0 bytes) for line 100000000
[ActorsRpcTest-peer1:out]  460: [10-15 17:08:48,416] DEBUG Cache.java:1734 Cache : Line 100000000 now has a new version 1. Setting to modified.
[ActorsRpcTest-peer1:out]  461: [10-15 17:08:48,416] DEBUG Cache.java:2646 Cache : Locking line LINE: 100000000 E  OWN: 1 SHARE: {} VER: 1 DATA: (0 bytes) MODIFIED
[ActorsRpcTest-peer1:out]  462: [10-15 17:08:48,416] DEBUG Cache.java:699 Cache : handleOp: Op.PUT(line:ffffffffffffffff, data:[B@1a0569a1) -> 4294967296 line: null
[ActorsRpcTest-peer1:out]  463: [10-15 17:08:48,416] DEBUG Cache.java:781 Cache : completeOp: Op.PUT(line:ffffffffffffffff, data:[B@1a0569a1) -> 4294967296 line: null
[ActorsRpcTest-peer1:out]  464: [10-15 17:08:48,418] DEBUG Cache.java:530 Cache : Run(fast): Op.GETX(line:2f6ca063)
[ActorsRpcTest-peer1:out]  465: [10-15 17:08:48,418] DEBUG Cache.java:2646 Cache : Locking line LINE: 2f6ca063 E  OWN: 1 SHARE: {} VER: 1 DATA: (0 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer1:out]  466: [10-15 17:08:48,419] DEBUG Cache.java:530 Cache : Run(fast): Op.SET(line:2f6ca063)
[ActorsRpcTest-peer1:out]  467: [10-15 17:08:48,432] DEBUG Cache.java:2891 Cache : Deallocating storage for line 2f6ca063
[ActorsRpcTest-peer1:out]  468: [10-15 17:08:48,432] DEBUG Cache.java:2562 Cache : Allocating storage (29 bytes) for line 2f6ca063
[ActorsRpcTest-peer1:out]  469: [10-15 17:08:48,437] DEBUG Cache.java:1734 Cache : Line 2f6ca063 now has a new version 2. Setting to modified.
[ActorsRpcTest-peer1:out]  470: [10-15 17:08:48,438] DEBUG Cache.java:2655 Cache : Unlocking line LINE: 2f6ca063 E  OWN: 1 SHARE: {} VER: 2 DATA: (32 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer1:out]  471: [10-15 17:08:48,440] DEBUG Cache.java:548 Cache : Run(fast): Op.GETX(line:100000000)
[ActorsRpcTest-peer1:out]  472: [10-15 17:08:48,440] DEBUG Cache.java:2646 Cache : Locking line LINE: 100000000 E  OWN: 1 SHARE: {} VER: 1 DATA: (0 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer1:out]  473: [10-15 17:08:48,449] DEBUG Cache.java:843 Cache : Received: [BACKUP_PACKETACK IN #_R FROM 0, id: 100000]
[ActorsRpcTest-peer1:out]  474: [10-15 17:08:48,460] DEBUG UDPComm.java:456 UDPComm : Received packet MessagePacket[[[PUTX IN #6R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [CHNGD_OWNR IN #7R FROM 2, line: 2f6ca063, newOwner: 1, certain: false], [GETX IN #5 FROM 2, line: 2f6ca063]]]
[ActorsRpcTest-peer1:out]  475: [10-15 17:08:48,460] DEBUG UDPComm.java:723 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=0, sentPacket=null, pendingRequests={5}, next=null, queue=[], broadcast=false} has received packet MessagePacket[[[PUTX IN #6R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [CHNGD_OWNR IN #7R FROM 2, line: 2f6ca063, newOwner: 1, certain: false], [GETX IN #5 FROM 2, line: 2f6ca063]]]
[ActorsRpcTest-peer1:out]  476: [10-15 17:08:48,460] DEBUG UDPComm.java:764 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=0, sentPacket=null, pendingRequests={5}, next=null, queue=[], broadcast=false} ignoring repeat response [PUTX IN #6R FROM 2, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer1:out]  477: [10-15 17:08:48,460] DEBUG UDPComm.java:764 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=0, sentPacket=null, pendingRequests={5}, next=null, queue=[], broadcast=false} ignoring repeat response [CHNGD_OWNR IN #7R FROM 2, line: 2f6ca063, newOwner: 1, certain: false]
[ActorsRpcTest-peer1:out]  478: [10-15 17:08:48,460] DEBUG UDPComm.java:785 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=0, sentPacket=null, pendingRequests={5}, next=null, queue=[], broadcast=false} already has a request pending for message [GETX IN #5 FROM 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  479: [10-15 17:08:48,465] DEBUG Cache.java:843 Cache : Received: [BACKUPACK IN #_ FROM 0, line: 2f6ca063, version: 2]
[ActorsRpcTest-peer1:out]  480: [10-15 17:08:48,465] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 E  OWN: 1 SHARE: {} VER: 2 DATA: (32 bytes) MODIFIED SLAVE 2f6ca063 [BACKUPACK IN #_ FROM 0, line: 2f6ca063, version: 2]
[ActorsRpcTest-peer1:out]  481: [10-15 17:08:48,465] DEBUG Cache.java:2069 Cache : Backup of line 2f6ca063 version 2 done. Setting to unmodified.
[ActorsRpcTest-peer1:out]  482: [10-15 17:08:48,465] DEBUG Cache.java:1084 Cache : Handling pending message [GETX IN #5 FROM 2, line: 2f6ca063]
[ActorsRpcTest-peer1:out]  483: [10-15 17:08:48,466] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 E -> I
[ActorsRpcTest-peer1:out]  484: [10-15 17:08:48,466] DEBUG Cache.java:2384 Cache : Set owner 2f6ca063 1 -> 2
[ActorsRpcTest-peer1:out]  485: [10-15 17:08:48,466] DEBUG Cache.java:2666 Cache : Sending: [PUTX OUT #5R TO 2, line: 2f6ca063, version: 2, data: (29 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer1:out]  486: [10-15 17:08:48,466] DEBUG UDPComm.java:403 UDPComm : Sending to node 2 (/100.111.6.14:14732): [PUTX OUT #5R TO 2, line: 2f6ca063, version: 2, data: (29 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer1:out]  487: [10-15 17:08:48,466] DEBUG Cache.java:2675 Cache : Sent: [PUTX OUT #5R TO 2, line: 2f6ca063, version: 2, data: (32 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer1:out]  488: [10-15 17:08:48,466] DEBUG UDPComm.java:938 UDPComm : Adding message [PUTX OUT #5R TO 2, line: 2f6ca063, version: 2, data: (32 bytes), sharers: [], messages: 0] to sent-packet
[ActorsRpcTest-peer1:out]  489: [10-15 17:08:48,466] DEBUG Cache.java:2897 Cache : fireLineInvalidated LINE: 2f6ca063 I  OWN: 2 SHARE: null VER: 2 DATA: (32 bytes)
[ActorsRpcTest-peer1:out]  490: [10-15 17:08:48,468] DEBUG UDPComm.java:703 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578296158467, sentPacket=MessagePacket[[[PUTX OUT #5R TO 2, line: 2f6ca063, version: 2, data: (32 bytes), sharers: [], messages: 0]]], pendingRequests={}, next=null, queue=[], broadcast=false} sending packet MessagePacket[[[PUTX OUT #5R TO 2, line: 2f6ca063, version: 2, data: (32 bytes), sharers: [], messages: 0]]]
[ActorsRpcTest-peer1:out]  491: [10-15 17:08:48,503] DEBUG UDPComm.java:456 UDPComm : Received packet MessagePacket[[[GET IN #8 FROM 2, line: 100000000]]]
[ActorsRpcTest-peer1:out]  492: [10-15 17:08:48,503] DEBUG UDPComm.java:723 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578296158467, sentPacket=MessagePacket[[[PUTX OUT #5R TO 2, line: 2f6ca063, version: 2, data: (32 bytes), sharers: [], messages: 0]]], pendingRequests={}, next=null, queue=[], broadcast=false} has received packet MessagePacket[[[GET IN #8 FROM 2, line: 100000000]]]
[ActorsRpcTest-peer2:out]  409: [10-15 17:08:48,393] DEBUG UDPComm.java:785 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=0, sentPacket=null, pendingRequests={6, 7}, next=null, queue=[], broadcast=false} already has a request pending for message [GETX IN #6 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  410: [10-15 17:08:48,393] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4) -> PENDING line: LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  411: [10-15 17:08:48,394] DEBUG UDPComm.java:785 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=0, sentPacket=null, pendingRequests={6, 7}, next=null, queue=[], broadcast=false} already has a request pending for message [GETX IN #7 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  412: [10-15 17:08:48,394] DEBUG Cache.java:1084 Cache : Handling pending message [GETX IN #6 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  413: [10-15 17:08:48,394] DEBUG UDPComm.java:456 UDPComm : Received packet MessagePacket[[[PUTX IN #3R FROM 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX IN #6 FROM 1, line: 2f6ca063], [GETX IN #7 FROM 1, line: 2f6ca063]]]
[ActorsRpcTest-peer2:out]  414: [10-15 17:08:48,394] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 E -> I
[ActorsRpcTest-peer2:out]  415: [10-15 17:08:48,394] DEBUG UDPComm.java:723 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=0, sentPacket=null, pendingRequests={6, 7}, next=null, queue=[], broadcast=false} has received packet MessagePacket[[[PUTX IN #3R FROM 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [GETX IN #6 FROM 1, line: 2f6ca063], [GETX IN #7 FROM 1, line: 2f6ca063]]]
[ActorsRpcTest-peer2:out]  416: [10-15 17:08:48,394] DEBUG Cache.java:2384 Cache : Set owner 2f6ca063 2 -> 1
[ActorsRpcTest-peer2:out]  417: [10-15 17:08:48,394] DEBUG UDPComm.java:764 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=0, sentPacket=null, pendingRequests={6, 7}, next=null, queue=[], broadcast=false} ignoring repeat response [PUTX IN #3R FROM 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer2:out]  418: [10-15 17:08:48,394] DEBUG Cache.java:2666 Cache : Sending: [PUTX OUT #6R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer2:out]  419: [10-15 17:08:48,395] DEBUG UDPComm.java:785 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=0, sentPacket=null, pendingRequests={6, 7}, next=null, queue=[], broadcast=false} already has a request pending for message [GETX IN #6 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  420: [10-15 17:08:48,395] DEBUG UDPComm.java:403 UDPComm : Sending to node 1 (/100.111.6.14:33639): [PUTX OUT #6R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer2:out]  421: [10-15 17:08:48,395] DEBUG UDPComm.java:785 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=0, sentPacket=null, pendingRequests={6, 7}, next=null, queue=[], broadcast=false} already has a request pending for message [GETX IN #7 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  422: [10-15 17:08:48,395] DEBUG Cache.java:2675 Cache : Sent: [PUTX OUT #6R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer2:out]  423: [10-15 17:08:48,395] DEBUG UDPComm.java:938 UDPComm : Adding message [PUTX OUT #6R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0] to sent-packet
[ActorsRpcTest-peer2:out]  424: [10-15 17:08:48,395] DEBUG Cache.java:2897 Cache : fireLineInvalidated LINE: 2f6ca063 I  OWN: 1 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  425: [10-15 17:08:48,395] DEBUG Cache.java:1084 Cache : Handling pending message [GETX IN #7 FROM 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  426: [10-15 17:08:48,396] DEBUG Cache.java:2666 Cache : Sending: [CHNGD_OWNR OUT #7R TO 1, line: 2f6ca063, newOwner: 1, certain: false]
[ActorsRpcTest-peer2:out]  427: [10-15 17:08:48,396] DEBUG UDPComm.java:403 UDPComm : Sending to node 1 (/100.111.6.14:33639): [CHNGD_OWNR OUT #7R TO 1, line: 2f6ca063, newOwner: 1, certain: false]
[ActorsRpcTest-peer2:out]  428: [10-15 17:08:48,396] DEBUG Cache.java:2675 Cache : Sent: [CHNGD_OWNR OUT #7R TO 1, line: 2f6ca063, newOwner: 1, certain: false]
[ActorsRpcTest-peer2:out]  429: [10-15 17:08:48,396] DEBUG UDPComm.java:938 UDPComm : Adding message [CHNGD_OWNR OUT #7R TO 1, line: 2f6ca063, newOwner: 1, certain: false] to sent-packet
[ActorsRpcTest-peer2:out]  430: [10-15 17:08:48,396] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4), change = 3
[ActorsRpcTest-peer2:out]  431: [10-15 17:08:48,396] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4) line: LINE: 2f6ca063 I  OWN: 1 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  432: [10-15 17:08:48,396] DEBUG Cache.java:2666 Cache : Sending: [GETX OUT #_ TO 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  433: [10-15 17:08:48,396] DEBUG UDPComm.java:403 UDPComm : Sending to node 1 (/100.111.6.14:33639): [GETX OUT #_ TO 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  434: [10-15 17:08:48,396] DEBUG Cache.java:2675 Cache : Sent: [GETX OUT #5 TO 1, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  435: [10-15 17:08:48,396] DEBUG UDPComm.java:938 UDPComm : Adding message [GETX OUT #5 TO 1, line: 2f6ca063] to sent-packet
[ActorsRpcTest-peer2:out]  436: [10-15 17:08:48,397] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4) -> PENDING line: LINE: 2f6ca063 I (->O) OWN: 1 SHARE: null VER: 1 DATA: (0 bytes)
[ActorsRpcTest-peer2:out]  437: [10-15 17:08:48,398] DEBUG UDPComm.java:703 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578225336149, sentPacket=MessagePacket[[[PUTX OUT #6R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [CHNGD_OWNR OUT #7R TO 1, line: 2f6ca063, newOwner: 1, certain: false], [GETX OUT #5 TO 1, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} sending packet MessagePacket[[[PUTX OUT #6R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [CHNGD_OWNR OUT #7R TO 1, line: 2f6ca063, newOwner: 1, certain: false], [GETX OUT #5 TO 1, line: 2f6ca063]]]
[ActorsRpcTest-peer2:out]  438: [10-15 17:08:48,398] DEBUG UDPComm.java:554 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578225336149, sentPacket=MessagePacket[[[PUTX OUT #6R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [CHNGD_OWNR OUT #7R TO 1, line: 2f6ca063, newOwner: 1, certain: false], [GETX OUT #5 TO 1, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} rescheduling in 60000000
[ActorsRpcTest-peer2:out]  439: [10-15 17:08:48,459] DEBUG UDPComm.java:703 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578288791639, sentPacket=MessagePacket[[[PUTX OUT #6R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [CHNGD_OWNR OUT #7R TO 1, line: 2f6ca063, newOwner: 1, certain: false], [GETX OUT #5 TO 1, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} sending packet MessagePacket[[[PUTX OUT #6R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [CHNGD_OWNR OUT #7R TO 1, line: 2f6ca063, newOwner: 1, certain: false], [GETX OUT #5 TO 1, line: 2f6ca063]]]
[ActorsRpcTest-peer2:out]  440: [10-15 17:08:48,459] DEBUG UDPComm.java:554 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578288791639, sentPacket=MessagePacket[[[PUTX OUT #6R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [CHNGD_OWNR OUT #7R TO 1, line: 2f6ca063, newOwner: 1, certain: false], [GETX OUT #5 TO 1, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} rescheduling in 120000000
[ActorsRpcTest-peer2:out]  441: [10-15 17:08:48,468] DEBUG UDPComm.java:456 UDPComm : Received packet MessagePacket[[[PUTX IN #5R FROM 1, line: 2f6ca063, version: 2, data: (32 bytes), sharers: [], messages: 0]]]
[ActorsRpcTest-peer2:out]  442: [10-15 17:08:48,468] DEBUG UDPComm.java:723 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578288791639, sentPacket=MessagePacket[[[PUTX OUT #6R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [CHNGD_OWNR OUT #7R TO 1, line: 2f6ca063, newOwner: 1, certain: false], [GETX OUT #5 TO 1, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} has received packet MessagePacket[[[PUTX IN #5R FROM 1, line: 2f6ca063, version: 2, data: (32 bytes), sharers: [], messages: 0]]]
[ActorsRpcTest-peer2:out]  443: [10-15 17:08:48,469] DEBUG UDPComm.java:749 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578288791639, sentPacket=MessagePacket[[[PUTX OUT #6R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0], [CHNGD_OWNR OUT #7R TO 1, line: 2f6ca063, newOwner: 1, certain: false], [GETX OUT #5 TO 1, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} removing response [PUTX OUT #6R TO 1, line: 2f6ca063, version: 1, data: (0 bytes), sharers: [], messages: 0] from sent packet because it was no longer asked for.
[ActorsRpcTest-peer2:out]  444: [10-15 17:08:48,469] DEBUG UDPComm.java:749 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578288791639, sentPacket=MessagePacket[[[CHNGD_OWNR OUT #7R TO 1, line: 2f6ca063, newOwner: 1, certain: false], [GETX OUT #5 TO 1, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} removing response [CHNGD_OWNR OUT #7R TO 1, line: 2f6ca063, newOwner: 1, certain: false] from sent packet because it was no longer asked for.
[ActorsRpcTest-peer2:out]  445: [10-15 17:08:48,469] DEBUG UDPComm.java:768 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578288791639, sentPacket=MessagePacket[[[GETX OUT #5 TO 1, line: 2f6ca063]]], pendingRequests={}, next=null, queue=[], broadcast=false} received response [PUTX IN #5R FROM 1, line: 2f6ca063, version: 2, data: (32 bytes), sharers: [], messages: 0] for request ([GETX OUT #5 TO 1, line: 2f6ca063])
[ActorsRpcTest-peer2:out]  446: [10-15 17:08:48,469] DEBUG UDPComm.java:669 UDPComm : Passing received message [PUTX IN #5R FROM 1, line: 2f6ca063, version: 2, data: (32 bytes), sharers: [], messages: 0] to cache
[ActorsRpcTest-peer2:out]  447: [10-15 17:08:48,469] DEBUG Cache.java:843 Cache : Received: [PUTX IN #5R FROM 1, line: 2f6ca063, version: 2, data: (32 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer2:out]  448: [10-15 17:08:48,469] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 I (->O) OWN: 1 SHARE: null VER: 1 DATA: (0 bytes) 2f6ca063 [PUTX IN #5R FROM 1, line: 2f6ca063, version: 2, data: (32 bytes), sharers: [], messages: 0]
[ActorsRpcTest-peer2:out]  449: [10-15 17:08:48,469] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 I -> O
[ActorsRpcTest-peer2:out]  450: [10-15 17:08:48,472] DEBUG Cache.java:2891 Cache : Deallocating storage for line 2f6ca063
[ActorsRpcTest-peer2:out]  451: [10-15 17:08:48,472] DEBUG Cache.java:2562 Cache : Allocating storage (32 bytes) for line 2f6ca063
[ActorsRpcTest-peer2:out]  452: [10-15 17:08:48,476] DEBUG Cache.java:2915 Cache : fireLineReceived LINE: 2f6ca063 O  OWN: 1 SHARE: {0} VER: 2 DATA: (32 bytes)
[ActorsRpcTest-peer2:out]  453: [10-15 17:08:48,476] DEBUG Cache.java:2666 Cache : Sending: [INV OUT #_ TO 0, line: 2f6ca063, previousOwner: 1]
[ActorsRpcTest-peer2:out]  454: [10-15 17:08:48,476] DEBUG Cache.java:2675 Cache : Sent: [INV OUT #6 TO 0, line: 2f6ca063, previousOwner: 1]
[ActorsRpcTest-peer2:out]  455: [10-15 17:08:48,477] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4), change = 3
[ActorsRpcTest-peer2:out]  456: [10-15 17:08:48,477] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4) line: LINE: 2f6ca063 O  OWN: 1 SHARE: {0} VER: 2 DATA: (32 bytes)
[ActorsRpcTest-peer2:out]  457: [10-15 17:08:48,477] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4) -> PENDING line: LINE: 2f6ca063 O (->E) OWN: 1 SHARE: {0} VER: 2 DATA: (32 bytes)
[ActorsRpcTest-peer2:out]  458: [10-15 17:08:48,478] DEBUG Cache.java:843 Cache : Received: [INVACK IN #6R FROM 0, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  459: [10-15 17:08:48,478] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 O (->E) OWN: 1 SHARE: {0} VER: 2 DATA: (32 bytes) 2f6ca063 [INVACK IN #6R FROM 0, line: 2f6ca063]
[ActorsRpcTest-peer2:out]  460: [10-15 17:08:48,478] DEBUG Cache.java:2355 Cache : Set state 2f6ca063 O -> E
[ActorsRpcTest-peer2:out]  461: [10-15 17:08:48,478] DEBUG Cache.java:2384 Cache : Set owner 2f6ca063 1 -> 2
[ActorsRpcTest-peer2:out]  462: [10-15 17:08:48,478] DEBUG Cache.java:831 Cache : Handling pending op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4), change = 3
[ActorsRpcTest-peer2:out]  463: [10-15 17:08:48,478] DEBUG Cache.java:680 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4) line: LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 2 DATA: (32 bytes)
[ActorsRpcTest-peer2:out]  464: [10-15 17:08:48,478] DEBUG Cache.java:2646 Cache : Locking line LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 2 DATA: (32 bytes) MODIFIED
[ActorsRpcTest-peer2:out]  465: [10-15 17:08:48,479] DEBUG Cache.java:699 Cache : handleOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4) -> null line: LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 2 DATA: (32 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer2:out]  466: [10-15 17:08:48,479] DEBUG Cache.java:781 Cache : completeOp: Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@36e2cbc4) -> null line: LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 2 DATA: (32 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer2:out]  467: [10-15 17:08:48,479] DEBUG Cache.java:2655 Cache : Unlocking line LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 2 DATA: (32 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer2:out]  468: [10-15 17:08:48,481] DEBUG Cache.java:530 Cache : Run(fast): Op.LSTN(line:100000000, extra:co.paralleluniverse.remote.galaxy.GlxGlobalRegistry$2@1d02da82)
[ActorsRpcTest-peer2:out]  469: [10-15 17:08:48,482] DEBUG Cache.java:804 Cache : Line 100000000 not found.
[ActorsRpcTest-peer2:out]  470: [10-15 17:08:48,482] DEBUG Cache.java:1246 Cache : Ending transaction: co.paralleluniverse.galaxy.core.Transaction@562806ee COMMIT
[ActorsRpcTest-peer2:out]  471: [10-15 17:08:48,493] DEBUG Cache.java:548 Cache : Run(fast): Op.GETS(line:100000000)
[ActorsRpcTest-peer2:out]  472: [10-15 17:08:48,493] DEBUG Cache.java:2666 Cache : Sending: [GET OUT #_ TO -1, line: 100000000]
[ActorsRpcTest-peer2:out]  473: [10-15 17:08:48,493] DEBUG Cache.java:2675 Cache : Sent: [GET OUT #7 TO 0, line: 100000000]
[ActorsRpcTest-peer2:out]  474: [10-15 17:08:48,493] DEBUG Cache.java:625 Cache : Run: Op.GETS(line:100000000)
[ActorsRpcTest-peer2:out]  475: [10-15 17:08:48,493] DEBUG Cache.java:680 Cache : handleOp: Op.GETS(line:100000000) line: LINE: 100000000 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer2:out]  476: [10-15 17:08:48,493] DEBUG Cache.java:699 Cache : handleOp: Op.GETS(line:100000000) -> PENDING line: LINE: 100000000 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer2:out]  477: [10-15 17:08:48,493] DEBUG Cache.java:670 Cache : Adding op to pending Op.GETS(line:100000000) on line LINE: 100000000 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer2:out]  478: [10-15 17:08:48,497] DEBUG Cache.java:843 Cache : Received: [CHNGD_OWNR IN #7R FROM 0, line: 100000000, newOwner: 1, certain: true]
[ActorsRpcTest-peer2:out]  479: [10-15 17:08:48,497] DEBUG Cache.java:893 Cache : runMessage: LINE: 100000000 I (->S) OWN: -1 SHARE: null VER: 0 DATA: null 100000000 [CHNGD_OWNR IN #7R FROM 0, line: 100000000, newOwner: 1, certain: true]
[ActorsRpcTest-peer2:out]  480: [10-15 17:08:48,500] DEBUG Cache.java:2384 Cache : Set owner 100000000 -1 -> 1
[ActorsRpcTest-peer2:out]  481: [10-15 17:08:48,500] DEBUG Cache.java:831 Cache : Handling pending op Op.GETS(line:100000000), change = 2
[ActorsRpcTest-peer2:out]  482: [10-15 17:08:48,500] DEBUG Cache.java:680 Cache : handleOp: Op.GETS(line:100000000) line: LINE: 100000000 I  OWN: 1 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer2:out]  483: [10-15 17:08:48,500] DEBUG Cache.java:2666 Cache : Sending: [GET OUT #_ TO 1, line: 100000000]
[ActorsRpcTest-peer2:out]  484: [10-15 17:08:48,500] DEBUG UDPComm.java:403 UDPComm : Sending to node 1 (/100.111.6.14:33639): [GET OUT #_ TO 1, line: 100000000]
[ActorsRpcTest-peer2:out]  485: [10-15 17:08:48,501] DEBUG Cache.java:2675 Cache : Sent: [GET OUT #8 TO 1, line: 100000000]
[ActorsRpcTest-peer2:out]  486: [10-15 17:08:48,501] DEBUG UDPComm.java:938 UDPComm : Adding message [GET OUT #8 TO 1, line: 100000000] to sent-packet
[ActorsRpcTest-peer2:out]  487: [10-15 17:08:48,501] DEBUG Cache.java:699 Cache : handleOp: Op.GETS(line:100000000) -> PENDING line: LINE: 100000000 I (->S) OWN: 1 SHARE: null VER: 0 DATA: null
[ActorsRpcTest-peer2:out]  488: [10-15 17:08:48,503] DEBUG UDPComm.java:703 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578330794852, sentPacket=MessagePacket[[[GET OUT #8 TO 1, line: 100000000]]], pendingRequests={}, next=null, queue=[], broadcast=false} sending packet MessagePacket[[[GET OUT #8 TO 1, line: 100000000]]]
[ActorsRpcTest-peer2:out]  489: [10-15 17:08:48,503] DEBUG UDPComm.java:554 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578330794852, sentPacket=MessagePacket[[[GET OUT #8 TO 1, line: 100000000]]], pendingRequests={}, next=null, queue=[], broadcast=false} rescheduling in 60000000
[ActorsRpcTest-peer1:out]  493: [10-15 17:08:48,503] DEBUG UDPComm.java:749 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=26578296158467, sentPacket=MessagePacket[[[PUTX OUT #5R TO 2, line: 2f6ca063, version: 2, data: (32 bytes), sharers: [], messages: 0]]], pendingRequests={}, next=null, queue=[], broadcast=false} removing response [PUTX OUT #5R TO 2, line: 2f6ca063, version: 2, data: (32 bytes), sharers: [], messages: 0] from sent packet because it was no longer asked for.
[ActorsRpcTest-peer1:out]  494: [10-15 17:08:48,504] DEBUG UDPComm.java:669 UDPComm : Passing received message [GET IN #8 FROM 2, line: 100000000] to cache
[ActorsRpcTest-peer1:out]  495: [10-15 17:08:48,504] DEBUG Cache.java:843 Cache : Received: [GET IN #8 FROM 2, line: 100000000]
[ActorsRpcTest-peer1:out]  496: [10-15 17:08:48,504] DEBUG Cache.java:893 Cache : runMessage: LINE: 100000000 E  OWN: 1 SHARE: {} VER: 1 DATA: (0 bytes) LOCKED MODIFIED 100000000 [GET IN #8 FROM 2, line: 100000000]
[ActorsRpcTest-peer1:out]  497: [10-15 17:08:48,507] DEBUG Cache.java:957 Cache : Adding message to pending [GET IN #8 FROM 2, line: 100000000] on line LINE: 100000000 E  OWN: 1 SHARE: {} VER: 1 DATA: (0 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer1:out]  498: [10-15 17:08:48,507] DEBUG Cache.java:2787 Cache : addPendingMessage [GET IN #8 FROM 2, line: 100000000] to line LINE: 100000000 E  OWN: 1 SHARE: {} VER: 1 DATA: (0 bytes) LOCKED MODIFIED
[ActorsRpcTest-peer1:out]  499: [10-15 17:08:48,565] DEBUG UDPComm.java:456 UDPComm : Received packet MessagePacket[[[GET IN #8 FROM 2, line: 100000000]]]
[ActorsRpcTest-peer1:out]  500: [10-15 17:08:48,565] DEBUG UDPComm.java:723 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=0, sentPacket=null, pendingRequests={8}, next=null, queue=[], broadcast=false} has received packet MessagePacket[[[GET IN #8 FROM 2, line: 100000000]]]
[ActorsRpcTest-peer2:out]  490: [10-15 17:08:48,564] DEBUG UDPComm.java:703 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578393810671, sentPacket=MessagePacket[[[GET OUT #8 TO 1, line: 100000000]]], pendingRequests={}, next=null, queue=[], broadcast=false} sending packet MessagePacket[[[GET OUT #8 TO 1, line: 100000000]]]
[ActorsRpcTest-peer1:out]  501: [10-15 17:08:48,565] DEBUG UDPComm.java:785 UDPComm : Peer NodePeer{node=2, nodeAddress=/100.111.6.14:14732, lastSent=0, sentPacket=null, pendingRequests={8}, next=null, queue=[], broadcast=false} already has a request pending for message [GET IN #8 FROM 2, line: 100000000]
[ActorsRpcTest-peer2:out]  491: [10-15 17:08:48,564] DEBUG UDPComm.java:554 UDPComm : Peer NodePeer{node=1, nodeAddress=/100.111.6.14:33639, lastSent=26578393810671, sentPacket=MessagePacket[[[GET OUT #8 TO 1, line: 100000000]]], pendingRequests={}, next=null, queue=[], broadcast=false} rescheduling in 120000000
[ActorsRpcTest-peer2:out]  492: [10-15 17:08:48,617] DEBUG Cache.java:843 Cache : Received: [BACKUP_PACKETACK IN #_R FROM 0, id: 100000]
[ActorsRpcTest-peer2:out]  493: [10-15 17:08:48,625] DEBUG Cache.java:843 Cache : Received: [BACKUPACK IN #_ FROM 0, line: 2f6ca063, version: 2]
[ActorsRpcTest-peer2:out]  494: [10-15 17:08:48,626] DEBUG Cache.java:893 Cache : runMessage: LINE: 2f6ca063 E  OWN: 2 SHARE: {} VER: 2 DATA: (32 bytes) MODIFIED SLAVE 2f6ca063 [BACKUPACK IN #_ FROM 0, line: 2f6ca063, version: 2]
[ActorsRpcTest-peer2:out]  495: [10-15 17:08:48,626] DEBUG Cache.java:2069 Cache : Backup of line 2f6ca063 version 2 done. Setting to unmodified.
pron commented 8 years ago

I don't see a timeout in the log. What message generates the timeout?

hsestupin commented 8 years ago

I don't know what message generates the timeout but as I see 

java.lang.RuntimeException: Actor discovery failed
java.util.concurrent.ExecutionException: java.lang.RuntimeException: Actor discovery failed
    at com.oracle.tools.util.FutureCompletionListener.get(FutureCompletionListener.java:152)
    at actor.ActorsRpcTest.testExchangeActorAndSendMessageTo(ActorsRpcTest.java:36)
    at sun.reflect.GeneratedMethodAccessor1134.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:85)
    at org.testng.internal.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:46)
    at org.testng.internal.InvokeMethodRunnable.run(InvokeMethodRunnable.java:37)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.RuntimeException: Actor discovery failed
    at co.paralleluniverse.remote.galaxy.GlxGlobalRegistry.getActor0(GlxGlobalRegistry.java:291)
    at co.paralleluniverse.remote.galaxy.GlxGlobalRegistry.getActor(GlxGlobalRegistry.java:156)
    at co.paralleluniverse.actors.ActorRegistry.getActor(ActorRegistry.java:83)
    at co.paralleluniverse.actors.ActorRegistry.getActor(ActorRegistry.java:93)
    at service.actor.ActorRegistry.getActor(ActorRegistry.java:45)
    at actor.ActorsRpcTest$PeerReceiver.call(ActorsRpcTest.java:44)
    at actor.ActorsRpcTest$PeerReceiver.call(ActorsRpcTest.java:39)
    at actor.BaseActorTester$PeerRemoteRunner.call(BaseActorTester.java:178)
    at com.oracle.tools.runtime.java.ContainerBasedJavaApplicationBuilder$ContainerBasedJavaApplicationProcess$1.run(ContainerBasedJavaApplicationBuilder.java:533)
    ... 5 more

at the end of the tests I can conclude that galaxy timeout occured somehow. Because line GlxGlobalRegistry.java:291 can be found in catching TimeoutException block

pron commented 8 years ago

But before you had Caused by: co.paralleluniverse.galaxy.TimeoutException: Timeout while processing op Op.GETX(line:2f6ca063, data:co.paralleluniverse.galaxy.core.StringRootManager$StringRootPageHandler@4cbca026): [TIMEOUT IN #4R FROM 2, line: 2f6ca063]. The word TIMEOUT doesn't appear anywhere in your logs?

hsestupin commented 8 years ago

Yeah, it seems some last log messages (just before exception has occured) haven't enough time to be written to the output. We use https://github.com/coherence-community/oracle-tools for running multi-jvm tests so I don't know what guarantees they provide for System.out writing from multiple nodes. So need some time to go deeper

pron commented 8 years ago

OK. In the meantime I'll see if I can make out anything from the logs you have. Node 1 is the one that failed here, too?

hsestupin commented 8 years ago

Yeah, node 1 just tries to do the following

final NubLookupImpl nubLookup = new NubLookupImpl(RegisterActorName);
      nubLookup.spawnThread();
      nubLookup.register(); // fails here
      return 0;

and fails