Mailing-List: contact user-help@ignite.apache.org; run by ezmlm
Precedence: bulk
Reply-To: user@ignite.apache.org
MIME-Version: 1.0
References: <1507282775619-0.post@n6.nabble.com>
In-Reply-To: <1507282775619-0.post@n6.nabble.com>
From: Denis Mekhanikov <dmekhanikov@gmail.com>
Date: Fri, 06 Oct 2017 13:48:35 +0000
Message-ID: <CAMP9FTR3uBNHEsLLHVvSQc=tU3ND=iGNyX5OEczHM4jTXpciJw@mail.gmail.com>
Subject: Re: Race in Service Grid deployment?
To: user@ignite.apache.org
Content-Type: multipart/alternative; boundary="001a113fc3ca870c46055ae11990"
archived-at: Fri, 06 Oct 2017 13:48:53 -0000

--001a113fc3ca870c46055ae11990
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

Hi Artem!

This is a known issue. I created a JIRA ticket for it:
https://issues.apache.org/jira/browse/IGNITE-6571

The exception that you see in log doesn't mean anything bad, it just means
that you are trying to call a method of a service that is already deployed,
but haven't initialized yet.
After the appearance of this error in log, operation finishes successfully
and returns a correct value, so you don't need to worry about it.

Denis

=D0=BF=D1=82, 6 =D0=BE=D0=BA=D1=82. 2017 =D0=B3. =D0=B2 12:39, Art=D1=91m B=
asov <basov.artem@gmail.com>:

> So we found this one while testing nodes shutdown and startup under light
> but
> steady load.
>
> Setup:
>
> We have 2 types of nodes let's call them Vehicle node (VehicleService
> deployed there) and client node.
> Client node have constant load applied to Vehicle grid (could be many
> nodes.
> We will stick with 1 since it reproducible even there) via following code=
:
>
>  public static void main(String[] args) throws IgniteException,
> InterruptedException {
>         Ignite ignite =3D Ignition.start("config/client-node-config.xml")=
;
>         VehicleService vehicleService =3D
> ignite.services().serviceProxy(VehicleService.SERVICE_NAME,
>                 VehicleService.class, false);
>
>         int cnt =3D 0;
>         while(!Thread.currentThread().isInterrupted()) {
>             String answer =3D null;
>             try {
>                 answer =3D "" +  vehicleService.testService();
>             } catch (Exception e) {
>                 answer =3D e.getMessage();
>             }
>             System.out.println("#"+ cnt++ + "a=3D" + answer);
>             TimeUnit.MILLISECONDS.sleep(10);
>         }
>     }
>
> From the VehicleService side testService() is dead simple:
>
>  @Override
>     public int testService() {
>         return 1;
>     }
>
> And i added some delay in init() of VehicleService:
> public void init(ServiceContext ctx) throws Exception {
>         System.out.println("Initializing Vehicle Service on node:" +
> ignite.cluster().localNode() + " within 10 seconds");
>
>         SECONDS.sleep(10);
>     }
>
> Steps:
>
> 1) Start Vehicle service node
> Observation: VehicleService deployed
>
> 2) Start main() provided above
> Observation: output, as expected will be printing counter+ 1 as result of
> service execution - OK
>
> 3) Stop VehicleService node
> Observation: output of main() :
> [12:06:06] Topology snapshot [ver=3D7, servers=3D1, clients=3D0, CPUs=3D4=
,
> heap=3D3.5GB]
> #286a=3DNode has left grid: 34c87a31-12b5-4e9f-a172-3f881d12d949
> [12:06:06,040][SEVERE][pub-#53%null%][GridTaskWorker] Failed to obtain
> remote job result policy for result from ComputeTask.result(..) method
> (will
> fail the whole task): GridJobResultImpl [job=3DC2V2
>
> [c=3Do.a.i.i.processors.service.GridServiceProcessor$ServiceTopologyCalla=
ble@3f672204
> ],
> sib=3DGridJobSiblingImpl
> [sesId=3D520eee0fe51-710996c1-c154-4fca-af30-0a067ec16009,
> jobId=3D620eee0fe51-710996c1-c154-4fca-af30-0a067ec16009,
> nodeId=3D34c87a31-12b5-4e9f-a172-3f881d12d949, isJobDone=3Dfalse],
> jobCtx=3DGridJobContextImpl
> [jobId=3D620eee0fe51-710996c1-c154-4fca-af30-0a067ec16009, timeoutObj=3Dn=
ull,
> attrs=3D{}], node=3DTcpDiscoveryNode [id=3D34c87a31-12b5-4e9f-a172-3f881d=
12d949,
> addrs=3D[0:0:0:0:0:0:0:1, 127.0.0.1, 192.168.6.251],
> sockAddrs=3D[/0:0:0:0:0:0:0:1:47500, /127.0.0.1:47500,
> BASOV/192.168.6.251:47500], discPort=3D47500, order=3D4, intOrder=3D3,
> lastExchangeTime=3D1507280749135, loc=3Dfalse,
> ver=3D1.9.0#20170302-sha1:a8169d0a,
> isClient=3Dfalse], ex=3Dclass o.a.i.cluster.ClusterTopologyException: Nod=
e has
> left grid: 34c87a31-12b5-4e9f-a172-3f881d12d949, hasRes=3Dtrue,
> isCancelled=3Dfalse, isOccupied=3Dtrue]
> class org.apache.ignite.cluster.ClusterTopologyException: Node has left
> grid: 34c87a31-12b5-4e9f-a172-3f881d12d949
>         at
>
> org.apache.ignite.internal.processors.task.GridTaskWorker.onNodeLeft(Grid=
TaskWorker.java:1460)
>         at
>
> org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscover=
yListener$1.run(GridTaskProcessor.java:1248)
>         at
>
> org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.=
java:6674)
>         at
>
> org.apache.ignite.internal.processors.closure.GridClosureProcessor$1.body=
(GridClosureProcessor.java:783)
>         at
> org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110=
)
>         at
>
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java=
:1142)
>         at
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.jav=
a:617)
>         at java.lang.Thread.run(Thread.java:748)
> #287a=3DFailed to find deployed service: VehicleService
> #288a=3DFailed to find deployed service: VehicleService
> which is expected behavior.
>
> 4) Start VehicleService node. VehicleService deployed
> Observation: suddenly, output contains:
> Initializing Vehicle Service on node:TcpDiscoveryNode
> [id=3Ddd38ff63-b3b2-486a-8974-5bebcb576cd8, addrs=3D[0:0:0:0:0:0:0:1,
> 127.0.0.1,
> 192.168.6.251], sockAddrs=3D[BASOV/192.168.6.251:47501,
> /0:0:0:0:0:0:0:1:47501, /127.0.0.1:47501], discPort=3D47501, order=3D2,
> intOrder=3D2, lastExchangeTime=3D1507280863055, loc=3Dtrue,
> ver=3D1.9.0#20170302-sha1:a8169d0a, isClient=3Dfalse] within 10 seconds
> [12:07:43,691][SEVERE][pub-#46%null%][GridJobWorker] Failed to execute jo=
b
> [jobId=3Dd7180f0fe51-0fd41e8b-385e-4480-8510-dca328846008,
> ses=3DGridJobSessionImpl [ses=3DGridTaskSessionImpl
> [taskName=3Do.a.i.i.processors.service.GridServiceProxy$ServiceProxyCalla=
ble,
> dep=3DGridDeployment [ts=3D1507280863375, depMode=3DSHARED,
> clsLdr=3Dsun.misc.Launcher$AppClassLoader@18b4aac2,
> clsLdrId=3D9a2b0f0fe51-dd38ff63-b3b2-486a-8974-5bebcb576cd8, userVer=3D0,
> loc=3Dtrue,
>
> sampleClsName=3Do.a.i.i.processors.cache.distributed.dht.preloader.GridDh=
tPartitionFullMap,
> pendingUndeploy=3Dfalse, undeployed=3Dfalse, usage=3D1],
>
> taskClsName=3Do.a.i.i.processors.service.GridServiceProxy$ServiceProxyCal=
lable,
> sesId=3Dc7180f0fe51-0fd41e8b-385e-4480-8510-dca328846008,
> startTime=3D1507280863660, endTime=3D9223372036854775807,
> taskNodeId=3D0fd41e8b-385e-4480-8510-dca328846008,
> clsLdr=3Dsun.misc.Launcher$AppClassLoader@18b4aac2, closed=3Dfalse,
> cpSpi=3Dnull,
> failSpi=3Dnull, loadSpi=3Dnull, usage=3D1, fullSup=3Dfalse, internal=3Dfa=
lse,
> subjId=3D0fd41e8b-385e-4480-8510-dca328846008, mapFut=3DIgniteFuture
> [orig=3DGridFutureAdapter [resFlag=3D0, res=3Dnull, startTime=3D150728086=
3678,
> endTime=3D0, ignoreInterrupts=3Dfalse, state=3DINIT]]],
> jobId=3Dd7180f0fe51-0fd41e8b-385e-4480-8510-dca328846008]]
> class org.apache.ignite.IgniteException: Service not found: VehicleServic=
e
>         at
>
> org.apache.ignite.internal.processors.closure.GridClosureProcessor$C2V2.e=
xecute(GridClosureProcessor.java:2059)
>         at
>
> org.apache.ignite.internal.processors.job.GridJobWorker$2.call(GridJobWor=
ker.java:560)
>         at
>
> org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.=
java:6618)
>         at
>
> org.apache.ignite.internal.processors.job.GridJobWorker.execute0(GridJobW=
orker.java:554)
>         at
>
> org.apache.ignite.internal.processors.job.GridJobWorker.body(GridJobWorke=
r.java:483)
>         at
> org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110=
)
>         at
>
> org.apache.ignite.internal.processors.job.GridJobProcessor.processJobExec=
uteRequest(GridJobProcessor.java:1180)
>         at
>
> org.apache.ignite.internal.processors.job.GridJobProcessor$JobExecutionLi=
stener.onMessage(GridJobProcessor.java:1894)
>         at
>
> org.apache.ignite.internal.managers.communication.GridIoManager.invokeLis=
tener(GridIoManager.java:1222)
>         at
>
> org.apache.ignite.internal.managers.communication.GridIoManager.processRe=
gularMessage0(GridIoManager.java:850)
>         at
>
> org.apache.ignite.internal.managers.communication.GridIoManager.access$21=
00(GridIoManager.java:108)
>         at
>
> org.apache.ignite.internal.managers.communication.GridIoManager$7.run(Gri=
dIoManager.java:790)
>         at
>
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java=
:1142)
>         at
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.jav=
a:617)
>         at java.lang.Thread.run(Thread.java:748)
> Caused by: class
> org.apache.ignite.internal.processors.service.GridServiceNotFoundExceptio=
n:
> Service not found: VehicleService
>         at
>
> org.apache.ignite.internal.processors.service.GridServiceProxy$ServicePro=
xyCallable.call(GridServiceProxy.java:397)
>         at
>
> org.apache.ignite.internal.processors.closure.GridClosureProcessor$C2V2.e=
xecute(GridClosureProcessor.java:2056)
>         ... 14 more
> Executing Vehicle Service on node:TcpDiscoveryNode
> [id=3Ddd38ff63-b3b2-486a-8974-5bebcb576cd8, addrs=3D[0:0:0:0:0:0:0:1,
> 127.0.0.1,
> 192.168.6.251], sockAddrs=3D[BASOV/192.168.6.251:47501,
> /0:0:0:0:0:0:0:1:47501, /127.0.0.1:47501], discPort=3D47501, order=3D2,
> intOrder=3D2, lastExchangeTime=3D1507280873066, loc=3Dtrue,
> ver=3D1.9.0#20170302-sha1:a8169d0a, isClient=3Dfalse]
>
>
> From my understanding, this means that Client node got the information
> about
> VehicleService deployment before VehicleService deployment node.
>
> Steps 1 and 3 is somewhat optional - i had reproduced this issue without
> them as well.
>
> Question is - is this is expected behaviour (race intentionally allowed) =
or
> is a bug?
>
> Here is sample project - It is somewhat messy. Sorry about that.
> MicroServicesExample-master.zip
> <
> http://apache-ignite-users.70518.x6.nabble.com/file/t1099/MicroServicesEx=
ample-master.zip
> >
>  It is modified example https://github.com/dmagda/MicroServicesExample.
> You
> only interested in VehicleServiceNodeStartup and ServiceRaceTest entry
> points.
>
>
>
>
> --
> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>

--001a113fc3ca870c46055ae11990
Content-Type: text/html; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

<div dir=3D"ltr">Hi Artem!<div><br></div><div>This is a known issue. I crea=
ted a JIRA ticket for it:=C2=A0<a href=3D"https://issues.apache.org/jira/br=
owse/IGNITE-6571">https://issues.apache.org/jira/browse/IGNITE-6571</a></di=
v><div><br></div><div>The exception that you see in log doesn&#39;t mean an=
ything bad, it just means that you are trying to call a method of a service=
 that is already deployed, but haven&#39;t initialized yet.</div><div>After=
 the appearance of this error in log, operation finishes successfully and r=
eturns a correct value, so you don&#39;t need to worry about it.</div><div>=
<br></div><div>Denis</div></div><br><div class=3D"gmail_quote"><div dir=3D"=
ltr">=D0=BF=D1=82, 6 =D0=BE=D0=BA=D1=82. 2017 =D0=B3. =D0=B2 12:39, Art=D1=
=91m Basov &lt;<a href=3D"mailto:basov.artem@gmail.com">basov.artem@gmail.c=
om</a>&gt;:<br></div><blockquote class=3D"gmail_quote" style=3D"margin:0 0 =
0 .8ex;border-left:1px #ccc solid;padding-left:1ex">So we found this one wh=
ile testing nodes shutdown and startup under light but<br>
steady load.<br>
<br>
Setup:<br>
<br>
We have 2 types of nodes let&#39;s call them Vehicle node (VehicleService<b=
r>
deployed there) and client node.<br>
Client node have constant load applied to Vehicle grid (could be many nodes=
.<br>
We will stick with 1 since it reproducible even there) via following code:<=
br>
<br>
=C2=A0public static void main(String[] args) throws IgniteException,<br>
InterruptedException {<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 Ignite ignite =3D Ignition.start(&quot;config/c=
lient-node-config.xml&quot;);<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 VehicleService vehicleService =3D<br>
ignite.services().serviceProxy(VehicleService.SERVICE_NAME,<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 VehicleService.clas=
s, false);<br>
<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 int cnt =3D 0;<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 while(!Thread.currentThread().isInterrupted()) =
{<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 String answer =3D null;<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 try {<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 answer =3D &quot;&q=
uot; +=C2=A0 vehicleService.testService();<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 } catch (Exception e) {<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 answer =3D e.getMes=
sage();<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 }<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 System.out.println(&quot;#&quot;+=
 cnt++ + &quot;a=3D&quot; + answer);<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 TimeUnit.MILLISECONDS.sleep(10);<=
br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 }<br>
=C2=A0 =C2=A0 }<br>
<br>
From the VehicleService side testService() is dead simple:<br>
<br>
=C2=A0@Override<br>
=C2=A0 =C2=A0 public int testService() {<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 return 1;<br>
=C2=A0 =C2=A0 }<br>
<br>
And i added some delay in init() of VehicleService:<br>
public void init(ServiceContext ctx) throws Exception {<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 System.out.println(&quot;Initializing Vehicle S=
ervice on node:&quot; +<br>
ignite.cluster().localNode() + &quot; within 10 seconds&quot;);<br>
<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 SECONDS.sleep(10);<br>
=C2=A0 =C2=A0 }<br>
<br>
Steps:<br>
<br>
1) Start Vehicle service node<br>
Observation: VehicleService deployed<br>
<br>
2) Start main() provided above<br>
Observation: output, as expected will be printing counter+ 1 as result of<b=
r>
service execution - OK<br>
<br>
3) Stop VehicleService node<br>
Observation: output of main() :<br>
[12:06:06] Topology snapshot [ver=3D7, servers=3D1, clients=3D0, CPUs=3D4,<=
br>
heap=3D3.5GB]<br>
#286a=3DNode has left grid: 34c87a31-12b5-4e9f-a172-3f881d12d949<br>
[12:06:06,040][SEVERE][pub-#53%null%][GridTaskWorker] Failed to obtain<br>
remote job result policy for result from ComputeTask.result(..) method (wil=
l<br>
fail the whole task): GridJobResultImpl [job=3DC2V2<br>
[c=3Do.a.i.i.processors.service.GridServiceProcessor$ServiceTopologyCallabl=
e@3f672204],<br>
sib=3DGridJobSiblingImpl<br>
[sesId=3D520eee0fe51-710996c1-c154-4fca-af30-0a067ec16009,<br>
jobId=3D620eee0fe51-710996c1-c154-4fca-af30-0a067ec16009,<br>
nodeId=3D34c87a31-12b5-4e9f-a172-3f881d12d949, isJobDone=3Dfalse],<br>
jobCtx=3DGridJobContextImpl<br>
[jobId=3D620eee0fe51-710996c1-c154-4fca-af30-0a067ec16009, timeoutObj=3Dnul=
l,<br>
attrs=3D{}], node=3DTcpDiscoveryNode [id=3D34c87a31-12b5-4e9f-a172-3f881d12=
d949,<br>
addrs=3D[0:0:0:0:0:0:0:1, 127.0.0.1, 192.168.6.251],<br>
sockAddrs=3D[/0:0:0:0:0:0:0:1:47500, /<a href=3D"http://127.0.0.1:47500" re=
l=3D"noreferrer" target=3D"_blank">127.0.0.1:47500</a>,<br>
BASOV/<a href=3D"http://192.168.6.251:47500" rel=3D"noreferrer" target=3D"_=
blank">192.168.6.251:47500</a>], discPort=3D47500, order=3D4, intOrder=3D3,=
<br>
lastExchangeTime=3D1507280749135, loc=3Dfalse, ver=3D1.9.0#20170302-sha1:a8=
169d0a,<br>
isClient=3Dfalse], ex=3Dclass o.a.i.cluster.ClusterTopologyException: Node =
has<br>
left grid: 34c87a31-12b5-4e9f-a172-3f881d12d949, hasRes=3Dtrue,<br>
isCancelled=3Dfalse, isOccupied=3Dtrue]<br>
class org.apache.ignite.cluster.ClusterTopologyException: Node has left<br>
grid: 34c87a31-12b5-4e9f-a172-3f881d12d949<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.processors.task.GridTaskWorker.onNodeLeft(GridTa=
skWorker.java:1460)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryL=
istener$1.run(GridTaskProcessor.java:1248)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.ja=
va:6674)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.processors.closure.GridClosureProcessor$1.body(G=
ridClosureProcessor.java:783)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110)<=
br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1=
142)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:=
617)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at java.lang.Thread.run(Thread.java:748)<br>
#287a=3DFailed to find deployed service: VehicleService<br>
#288a=3DFailed to find deployed service: VehicleService<br>
which is expected behavior.<br>
<br>
4) Start VehicleService node. VehicleService deployed<br>
Observation: suddenly, output contains:<br>
Initializing Vehicle Service on node:TcpDiscoveryNode<br>
[id=3Ddd38ff63-b3b2-486a-8974-5bebcb576cd8, addrs=3D[0:0:0:0:0:0:0:1, 127.0=
.0.1,<br>
192.168.6.251], sockAddrs=3D[BASOV/<a href=3D"http://192.168.6.251:47501" r=
el=3D"noreferrer" target=3D"_blank">192.168.6.251:47501</a>,<br>
/0:0:0:0:0:0:0:1:47501, /<a href=3D"http://127.0.0.1:47501" rel=3D"noreferr=
er" target=3D"_blank">127.0.0.1:47501</a>], discPort=3D47501, order=3D2,<br=
>
intOrder=3D2, lastExchangeTime=3D1507280863055, loc=3Dtrue,<br>
ver=3D1.9.0#20170302-sha1:a8169d0a, isClient=3Dfalse] within 10 seconds<br>
[12:07:43,691][SEVERE][pub-#46%null%][GridJobWorker] Failed to execute job<=
br>
[jobId=3Dd7180f0fe51-0fd41e8b-385e-4480-8510-dca328846008,<br>
ses=3DGridJobSessionImpl [ses=3DGridTaskSessionImpl<br>
[taskName=3Do.a.i.i.processors.service.GridServiceProxy$ServiceProxyCallabl=
e,<br>
dep=3DGridDeployment [ts=3D1507280863375, depMode=3DSHARED,<br>
clsLdr=3Dsun.misc.Launcher$AppClassLoader@18b4aac2,<br>
clsLdrId=3D9a2b0f0fe51-dd38ff63-b3b2-486a-8974-5bebcb576cd8, userVer=3D0,<b=
r>
loc=3Dtrue,<br>
sampleClsName=3Do.a.i.i.processors.cache.distributed.dht.preloader.GridDhtP=
artitionFullMap,<br>
pendingUndeploy=3Dfalse, undeployed=3Dfalse, usage=3D1],<br>
taskClsName=3Do.a.i.i.processors.service.GridServiceProxy$ServiceProxyCalla=
ble,<br>
sesId=3Dc7180f0fe51-0fd41e8b-385e-4480-8510-dca328846008,<br>
startTime=3D1507280863660, endTime=3D9223372036854775807,<br>
taskNodeId=3D0fd41e8b-385e-4480-8510-dca328846008,<br>
clsLdr=3Dsun.misc.Launcher$AppClassLoader@18b4aac2, closed=3Dfalse, cpSpi=
=3Dnull,<br>
failSpi=3Dnull, loadSpi=3Dnull, usage=3D1, fullSup=3Dfalse, internal=3Dfals=
e,<br>
subjId=3D0fd41e8b-385e-4480-8510-dca328846008, mapFut=3DIgniteFuture<br>
[orig=3DGridFutureAdapter [resFlag=3D0, res=3Dnull, startTime=3D15072808636=
78,<br>
endTime=3D0, ignoreInterrupts=3Dfalse, state=3DINIT]]],<br>
jobId=3Dd7180f0fe51-0fd41e8b-385e-4480-8510-dca328846008]]<br>
class org.apache.ignite.IgniteException: Service not found: VehicleService<=
br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.processors.closure.GridClosureProcessor$C2V2.exe=
cute(GridClosureProcessor.java:2059)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.processors.job.GridJobWorker$2.call(GridJobWorke=
r.java:560)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.ja=
va:6618)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.processors.job.GridJobWorker.execute0(GridJobWor=
ker.java:554)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.processors.job.GridJobWorker.body(GridJobWorker.=
java:483)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110)<=
br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.processors.job.GridJobProcessor.processJobExecut=
eRequest(GridJobProcessor.java:1180)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.processors.job.GridJobProcessor$JobExecutionList=
ener.onMessage(GridJobProcessor.java:1894)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.managers.communication.GridIoManager.invokeListe=
ner(GridIoManager.java:1222)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.managers.communication.GridIoManager.processRegu=
larMessage0(GridIoManager.java:850)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.managers.communication.GridIoManager.access$2100=
(GridIoManager.java:108)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.managers.communication.GridIoManager$7.run(GridI=
oManager.java:790)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1=
142)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:=
617)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at java.lang.Thread.run(Thread.java:748)<br>
Caused by: class<br>
org.apache.ignite.internal.processors.service.GridServiceNotFoundException:=
<br>
Service not found: VehicleService<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.processors.service.GridServiceProxy$ServiceProxy=
Callable.call(GridServiceProxy.java:397)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 at<br>
org.apache.ignite.internal.processors.closure.GridClosureProcessor$C2V2.exe=
cute(GridClosureProcessor.java:2056)<br>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 ... 14 more<br>
Executing Vehicle Service on node:TcpDiscoveryNode<br>
[id=3Ddd38ff63-b3b2-486a-8974-5bebcb576cd8, addrs=3D[0:0:0:0:0:0:0:1, 127.0=
.0.1,<br>
192.168.6.251], sockAddrs=3D[BASOV/<a href=3D"http://192.168.6.251:47501" r=
el=3D"noreferrer" target=3D"_blank">192.168.6.251:47501</a>,<br>
/0:0:0:0:0:0:0:1:47501, /<a href=3D"http://127.0.0.1:47501" rel=3D"noreferr=
er" target=3D"_blank">127.0.0.1:47501</a>], discPort=3D47501, order=3D2,<br=
>
intOrder=3D2, lastExchangeTime=3D1507280873066, loc=3Dtrue,<br>
ver=3D1.9.0#20170302-sha1:a8169d0a, isClient=3Dfalse]<br>
<br>
<br>
From my understanding, this means that Client node got the information abou=
t<br>
VehicleService deployment before VehicleService deployment node.<br>
<br>
Steps 1 and 3 is somewhat optional - i had reproduced this issue without<br=
>
them as well.<br>
<br>
Question is - is this is expected behaviour (race intentionally allowed) or=
<br>
is a bug?<br>
<br>
Here is sample project - It is somewhat messy. Sorry about that.<br>
MicroServicesExample-master.zip<br>
&lt;<a href=3D"http://apache-ignite-users.70518.x6.nabble.com/file/t1099/Mi=
croServicesExample-master.zip" rel=3D"noreferrer" target=3D"_blank">http://=
apache-ignite-users.70518.x6.nabble.com/file/t1099/MicroServicesExample-mas=
ter.zip</a>&gt;<br>
=C2=A0It is modified example <a href=3D"https://github.com/dmagda/MicroServ=
icesExample" rel=3D"noreferrer" target=3D"_blank">https://github.com/dmagda=
/MicroServicesExample</a>. You<br>
only interested in VehicleServiceNodeStartup and ServiceRaceTest entry<br>
points.<br>
<br>
<br>
<br>
<br>
--<br>
Sent from: <a href=3D"http://apache-ignite-users.70518.x6.nabble.com/" rel=
=3D"noreferrer" target=3D"_blank">http://apache-ignite-users.70518.x6.nabbl=
e.com/</a><br>
</blockquote></div>

--001a113fc3ca870c46055ae11990--