Ksenia Rybakova created IGNITE-4734:
---------------------------------------
Summary: Sporadic GridServiceNotFoundException in ServiceExample
Key: IGNITE-4734
URL: https://issues.apache.org/jira/browse/IGNITE-4734
Project: Ignite
Issue Type: Bug
Components: general
Affects Versions: 1.7
Reporter: Ksenia Rybakova
Sometimes ServiceExample thows GridServiceNotFoundException
Configs might be different - 1 node/3 nodes, linux/windows
Driver node log:
{noformat}
[10:50:31,428][INFO][main][GridDiscoveryManager] Topology snapshot [ver=2,
servers=1, clients=1, CPUs=4, heap=2.0GB]
>>>
>>> Starting service proxy example.
>>>
[10:50:31,768][SEVERE][sys-#32%null%][GridTaskWorker] Failed to obtain remote
job result policy for result from ComputeTask.result(..) method (will fail the
whole task): GridJobResultImpl [job=C2V2 [c=ServiceProxyCallable [mtdName=put,
svcName=myNodeSingletonService, ignite=null]], sib=GridJobSiblingImpl
[sesId=b2c66af5a51-87f5f92a-d9ee-4119-90a5-35659bd7e50d,
jobId=d2c66af5a51-87f5f92a-d9ee-4119-90a5-35659bd7e50d,
nodeId=01aea3a3-0981-4760-a26b-732afc4a8a27, isJobDone=false],
jobCtx=GridJobContextImpl
[jobId=d2c66af5a51-87f5f92a-d9ee-4119-90a5-35659bd7e50d, timeoutObj=null,
attrs={}], node=TcpDiscoveryNode [id=01aea3a3-0981-4760-a26b-732afc4a8a27,
addrs=[127.0.0.1, 172.25.2.17], sockAddrs=[/172.25.2.17:47500,
/127.0.0.1:47500], discPort=47500, order=1, intOrder=1,
lastExchangeTime=1487663430926, loc=false, ver=1.7.8#20170220-sha1:6112bce9,
isClient=false], ex=class o.a.i.IgniteException: Service not found:
myNodeSingletonService, hasRes=true, isCancelled=false, isOccupied=true]
class org.apache.ignite.IgniteException: Remote job threw user exception
(override or implement ComputeTask.result(..) method if you would like to have
automatic failover for this exception).
at
org.apache.ignite.compute.ComputeTaskAdapter.result(ComputeTaskAdapter.java:101)
at
org.apache.ignite.internal.processors.task.GridTaskWorker$5.apply(GridTaskWorker.java:1031)
at
org.apache.ignite.internal.processors.task.GridTaskWorker$5.apply(GridTaskWorker.java:1024)
at
org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.java:6596)
at
org.apache.ignite.internal.processors.task.GridTaskWorker.result(GridTaskWorker.java:1024)
at
org.apache.ignite.internal.processors.task.GridTaskWorker.onResponse(GridTaskWorker.java:842)
at
org.apache.ignite.internal.processors.task.GridTaskProcessor.processJobExecuteResponse(GridTaskProcessor.java:996)
at
org.apache.ignite.internal.processors.task.GridTaskProcessor$JobMessageListener.onMessage(GridTaskProcessor.java:1221)
at
org.apache.ignite.internal.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1082)
at
org.apache.ignite.internal.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:710)
at
org.apache.ignite.internal.managers.communication.GridIoManager.access$1700(GridIoManager.java:102)
at
org.apache.ignite.internal.managers.communication.GridIoManager$5.run(GridIoManager.java:673)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: class org.apache.ignite.IgniteException: Service not found:
myNodeSingletonService
at
org.apache.ignite.internal.processors.closure.GridClosureProcessor$C2V2.execute(GridClosureProcessor.java:2059)
at
org.apache.ignite.internal.processors.job.GridJobWorker$2.call(GridJobWorker.java:560)
at
org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.java:6564)
at
org.apache.ignite.internal.processors.job.GridJobWorker.execute0(GridJobWorker.java:554)
at
org.apache.ignite.internal.processors.job.GridJobWorker.body(GridJobWorker.java:483)
at
org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110)
at
org.apache.ignite.internal.processors.job.GridJobProcessor.processJobExecuteRequest(GridJobProcessor.java:1180)
at
org.apache.ignite.internal.processors.job.GridJobProcessor$JobExecutionListener.onMessage(GridJobProcessor.java:1894)
... 7 more
Caused by: class
org.apache.ignite.internal.processors.service.GridServiceNotFoundException:
Service not found: myNodeSingletonService
at
org.apache.ignite.internal.processors.service.GridServiceProxy$ServiceProxyCallable.call(GridServiceProxy.java:397)
at
org.apache.ignite.internal.processors.closure.GridClosureProcessor$C2V2.execute(GridClosureProcessor.java:2056)
... 14 more
Map service size: 10
>>>
>>> Starting service injection example.
>>>
[10:50:31,905][INFO][main][GridDeploymentLocalStore] Class locally deployed:
class org.apache.ignite.examples.servicegrid.ServicesExample$SimpleClosure
Closure execution result: [10]
[10:50:32,035][INFO][main][GridCacheProcessor] Stopped cache:
ignite-marshaller-sys-cache
[10:50:32,035][INFO][main][GridCacheProcessor] Stopped cache: ignite-sys-cache
[10:50:32,035][INFO][main][GridCacheProcessor] Stopped cache:
ignite-atomics-sys-cache
[10:50:32,037][INFO][main][GridDeploymentLocalStore] Removed undeployed class:
GridDeployment [ts=1487663431355, depMode=SHARED,
clsLdr=sun.misc.Launcher$AppClassLoader@10b28f30,
clsLdrId=80c66af5a51-87f5f92a-d9ee-4119-90a5-35659bd7e50d, userVer=0, loc=true,
sampleClsName=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionFullMap,
pendingUndeploy=false, undeployed=true, usage=0]
[10:50:32,041][INFO][main][IgniteKernal]
>>> +---------------------------------------------------------------------------------+
>>> Ignite ver. 1.7.8#20170220-sha1:6112bce906c417c0c4723f42281616c667347a65
>>> stopped OK
>>> +---------------------------------------------------------------------------------+
{noformat}
Server node log:
{noformat}
[10:50:30,916][INFO][disco-event-worker-#22%null%][GridDiscoveryManager]
Topology snapshot [ver=2, servers=1, clients=1, CPUs=4, heap=2.0GB]
[10:50:30,944][INFO][exchange-worker-#25%null%][GridCachePartitionExchangeManager]
Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion
[topVer=2, minorTopVer=0], evt=NODE_JOINED,
node=87f5f92a-d9ee-4119-90a5-35659bd7e50d]
[10:50:31,622][INFO][exchange-worker-#25%null%][GridCacheProcessor] Started
cache [name=myClusterSingletonService, mode=PARTITIONED]
Service was initialized: myClusterSingletonService
[10:50:31,662][INFO][srvc-deploy-#26%null%][GridServiceProcessor] Starting
service instance [name=myClusterSingletonService,
execId=b6895479-ad51-44f4-9109-5a2e290168e9]
Executing distributed service: myClusterSingletonService
[10:50:31,679][INFO][exchange-worker-#25%null%][GridCachePartitionExchangeManager]
Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion
[topVer=2, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT,
node=01aea3a3-0981-4760-a26b-732afc4a8a27]
[10:50:31,701][INFO][exchange-worker-#25%null%][GridCacheProcessor] Started
cache [name=myNodeSingletonService, mode=PARTITIONED]
[10:50:31,750][SEVERE][pub-#45%null%][GridJobWorker] Failed to execute job
[jobId=d2c66af5a51-87f5f92a-d9ee-4119-90a5-35659bd7e50d, ses=GridJobSessionImpl
[ses=GridTaskSessionImpl
[taskName=o.a.i.i.processors.service.GridServiceProxy$ServiceProxyCallable,
dep=GridDeployment [ts=1487663431313, depMode=SHARED,
clsLdr=sun.misc.Launcher$AppClassLoader@10b28f30,
clsLdrId=74936af5a51-01aea3a3-0981-4760-a26b-732afc4a8a27, userVer=0, loc=true,
sampleClsName=o.a.i.i.processors.cache.distributed.dht.preloader.GridDhtPartitionMap2,
pendingUndeploy=false, undeployed=false, usage=1],
taskClsName=o.a.i.i.processors.service.GridServiceProxy$ServiceProxyCallable,
sesId=b2c66af5a51-87f5f92a-d9ee-4119-90a5-35659bd7e50d,
startTime=1487663431738, endTime=9223372036854775807,
taskNodeId=87f5f92a-d9ee-4119-90a5-35659bd7e50d,
clsLdr=sun.misc.Launcher$AppClassLoader@10b28f30, closed=false, cpSpi=null,
failSpi=null, loadSpi=null, usage=1, fullSup=false, internal=false,
subjId=87f5f92a-d9ee-4119-90a5-35659bd7e50d, mapFut=IgniteFuture
[orig=GridFutureAdapter [resFlag=0, res=null, startTime=1487663431738,
endTime=0, ignoreInterrupts=false, state=INIT]]],
jobId=d2c66af5a51-87f5f92a-d9ee-4119-90a5-35659bd7e50d]]
class org.apache.ignite.IgniteException: Service not found:
myNodeSingletonService
at
org.apache.ignite.internal.processors.closure.GridClosureProcessor$C2V2.execute(GridClosureProcessor.java:2059)
at
org.apache.ignite.internal.processors.job.GridJobWorker$2.call(GridJobWorker.java:560)
at
org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.java:6564)
at
org.apache.ignite.internal.processors.job.GridJobWorker.execute0(GridJobWorker.java:554)
at
org.apache.ignite.internal.processors.job.GridJobWorker.body(GridJobWorker.java:483)
at
org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:110)
at
org.apache.ignite.internal.processors.job.GridJobProcessor.processJobExecuteRequest(GridJobProcessor.java:1180)
at
org.apache.ignite.internal.processors.job.GridJobProcessor$JobExecutionListener.onMessage(GridJobProcessor.java:1894)
at
org.apache.ignite.internal.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1082)
at
org.apache.ignite.internal.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:710)
at
org.apache.ignite.internal.managers.communication.GridIoManager.access$1700(GridIoManager.java:102)
at
org.apache.ignite.internal.managers.communication.GridIoManager$5.run(GridIoManager.java:673)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: class
org.apache.ignite.internal.processors.service.GridServiceNotFoundException:
Service not found: myNodeSingletonService
at
org.apache.ignite.internal.processors.service.GridServiceProxy$ServiceProxyCallable.call(GridServiceProxy.java:397)
at
org.apache.ignite.internal.processors.closure.GridClosureProcessor$C2V2.execute(GridClosureProcessor.java:2056)
... 14 more
Service was initialized: myNodeSingletonService
[10:50:31,758][INFO][srvc-deploy-#26%null%][GridServiceProcessor] Starting
service instance [name=myNodeSingletonService,
execId=42a2cebc-da76-4146-9f99-9c9b044e485b]
[10:50:31,773][INFO][exchange-worker-#25%null%][GridCachePartitionExchangeManager]
Skipping rebalancing (obsolete exchange ID) [top=AffinityTopologyVersion
[topVer=2, minorTopVer=2], evt=DISCOVERY_CUSTOM_EVT,
node=01aea3a3-0981-4760-a26b-732afc4a8a27]
[10:50:31,782][INFO][exchange-worker-#25%null%][GridCacheProcessor] Started
cache [name=myMultiService, mode=PARTITIONED]
Executing distributed service: myNodeSingletonService
Service was initialized: myMultiService
[10:50:31,812][INFO][srvc-deploy-#26%null%][GridServiceProcessor] Starting
service instance [name=myMultiService,
execId=cfacf805-7c54-4769-b853-96b7194425c0]
Service was initialized: myMultiService
[10:50:31,812][INFO][srvc-deploy-#26%null%][GridServiceProcessor] Starting
service instance [name=myMultiService,
execId=3094db41-35da-4a32-9fec-51bff2508d40]
Executing distributed service: myMultiService
Executing distributed service: myMultiService
[10:50:31,826][INFO][exchange-worker-#25%null%][GridCachePartitionExchangeManager]
Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion
[topVer=2, minorTopVer=3], evt=DISCOVERY_CUSTOM_EVT,
node=01aea3a3-0981-4760-a26b-732afc4a8a27]
[10:50:31,925][INFO][pub-#57%null%][GridDeploymentLocalStore] Class locally
deployed: class
org.apache.ignite.examples.servicegrid.ServicesExample$SimpleClosure
Executing closure [mapSize=10]
[10:50:31,955][INFO][exchange-worker-#25%null%][GridCacheProcessor] Stopped
cache: myNodeSingletonService
Service was cancelled: myNodeSingletonService
[10:50:31,955][INFO][srvc-deploy-#26%null%][GridServiceProcessor] Cancelled
service instance [name=myNodeSingletonService,
execId=42a2cebc-da76-4146-9f99-9c9b044e485b]
[10:50:31,970][INFO][exchange-worker-#25%null%][GridCachePartitionExchangeManager]
Skipping rebalancing (obsolete exchange ID) [top=AffinityTopologyVersion
[topVer=2, minorTopVer=4], evt=DISCOVERY_CUSTOM_EVT,
node=01aea3a3-0981-4760-a26b-732afc4a8a27]
[10:50:31,972][INFO][exchange-worker-#25%null%][GridCacheProcessor] Stopped
cache: myClusterSingletonService
Service was cancelled: myClusterSingletonService
[10:50:31,973][INFO][srvc-deploy-#26%null%][GridServiceProcessor] Cancelled
service instance [name=myClusterSingletonService,
execId=b6895479-ad51-44f4-9109-5a2e290168e9]
[10:50:31,976][INFO][exchange-worker-#25%null%][GridCachePartitionExchangeManager]
Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion
[topVer=2, minorTopVer=5], evt=DISCOVERY_CUSTOM_EVT,
node=01aea3a3-0981-4760-a26b-732afc4a8a27]
[10:50:32,019][INFO][exchange-worker-#25%null%][GridCacheProcessor] Stopped
cache: myMultiService
Service was cancelled: myMultiService
[10:50:32,020][INFO][srvc-deploy-#26%null%][GridServiceProcessor] Cancelled
service instance [name=myMultiService,
execId=cfacf805-7c54-4769-b853-96b7194425c0]
Service was cancelled: myMultiService
[10:50:32,020][INFO][srvc-deploy-#26%null%][GridServiceProcessor] Cancelled
service instance [name=myMultiService,
execId=3094db41-35da-4a32-9fec-51bff2508d40]
[10:50:32,020][INFO][exchange-worker-#25%null%][GridCachePartitionExchangeManager]
Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion
[topVer=2, minorTopVer=6], evt=DISCOVERY_CUSTOM_EVT,
node=01aea3a3-0981-4760-a26b-732afc4a8a27]
[10:50:32,030][INFO][disco-event-worker-#22%null%][GridDiscoveryManager] Node
left topology: TcpDiscoveryNode [id=87f5f92a-d9ee-4119-90a5-35659bd7e50d,
addrs=[127.0.0.1, 172.25.2.17], sockAddrs=[/172.25.2.17:0, /127.0.0.1:0],
discPort=0, order=2, intOrder=2, lastExchangeTime=1487663430876, loc=false,
ver=1.7.8#20170220-sha1:6112bce9, isClient=true]
[10:50:32,031][INFO][disco-event-worker-#22%null%][GridDiscoveryManager]
Topology snapshot [ver=3, servers=1, clients=0, CPUs=4, heap=1.0GB]
[10:50:32,033][INFO][exchange-worker-#25%null%][GridCachePartitionExchangeManager]
Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion
[topVer=3, minorTopVer=0], evt=NODE_LEFT,
node=87f5f92a-d9ee-4119-90a5-35659bd7e50d]
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)
