Khurram Faraaz created DRILL-5573:
-------------------------------------
Summary: Query profiles missing from Web UI and physical
*.sys.drill file missing for query that was in CANCELLATION_REQUESTED state
Key: DRILL-5573
URL: https://issues.apache.org/jira/browse/DRILL-5573
Project: Apache Drill
Issue Type: Bug
Components: Web Server
Affects Versions: 1.11.0
Environment: 3 node CentOS cluster
Reporter: Khurram Faraaz
A query that was in CANCELLATION_REQUESTED state after the Java concurrent
program was terminated by issuing Ctrl-C from the command line.
Next, stop and start Drillbits (Drill 1.11.0 commit id: d11aba2) on all nodes,
and we see the below error message on Drill's Web UI, and we do not find the
physical file <query-id>.sys.drill under drill-1.11.0/logs/profiles folder
clush -a /opt/mapr/drill/drill-1.11.0/bin/drillbit.sh stop
clush -a /opt/mapr/drill/drill-1.11.0/bin/drillbit.sh start
http://<IPADDRESS>:8047/profiles/26c9073d-a8ff-17b0-5a86-34042bdfb494
{
"errorMessage" : "VALIDATION ERROR: No profile with given query id
'26c9073d-a8ff-17b0-5a86-34042bdfb494' exists. Please verify the query
id.\n\n\n[Error Id: c8f1ed5c-d93f-42b7-840d-54a1ed8da132 ]"
}
Stack trace from drillbit.log from foreman node, for the above error id.
{noformat}
2017-06-07 10:18:37,612 [main] INFO o.a.drill.exec.server.rest.WebServer -
Setting up HTTP connector for web server
2017-06-07 10:18:38,601 [main] INFO o.apache.drill.exec.server.Drillbit -
Startup completed (4149 ms).
2017-06-07 10:20:03,718 [qtp1575043618-89] INFO
o.a.d.e.s.r.profile.ProfileResources - User Error Occurred: No profile with
given query id '26c9073d-a8ff-17b0-5a86-34042bdfb494' exists. Please verify the
query id.
org.apache.drill.common.exceptions.UserException: VALIDATION ERROR: No profile
with given query id '26c9073d-a8ff-17b0-5a86-34042bdfb494' exists. Please
verify the query id.
[Error Id: c8f1ed5c-d93f-42b7-840d-54a1ed8da132 ]
at
org.apache.drill.common.exceptions.UserException$Builder.build(UserException.java:544)
~[drill-common-1.11.0-SNAPSHOT.jar:1.11.0-SNAPSHOT]
at
org.apache.drill.exec.server.rest.profile.ProfileResources.getQueryProfile(ProfileResources.java:288)
[drill-java-exec-1.11.0-SNAPSHOT.jar:1.11.0-SNAPSHOT]
at
org.apache.drill.exec.server.rest.profile.ProfileResources.getProfile(ProfileResources.java:310)
[drill-java-exec-1.11.0-SNAPSHOT.jar:1.11.0-SNAPSHOT]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
~[na:1.8.0_91]
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
~[na:1.8.0_91]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[na:1.8.0_91]
at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_91]
at
org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)
[jersey-server-2.8.jar:na]
at
org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:151)
[jersey-server-2.8.jar:na]
at
org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:171)
[jersey-server-2.8.jar:na]
at
org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$TypeOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:195)
[jersey-server-2.8.jar:na]
at
org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:104)
[jersey-server-2.8.jar:na]
at
org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:387)
[jersey-server-2.8.jar:na]
at
org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:331)
[jersey-server-2.8.jar:na]
at
org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:103)
[jersey-server-2.8.jar:na]
at
org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:269)
[jersey-server-2.8.jar:na]
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
[jersey-common-2.8.jar:na]
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
[jersey-common-2.8.jar:na]
at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
[jersey-common-2.8.jar:na]
at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
[jersey-common-2.8.jar:na]
at org.glassfish.jersey.internal.Errors.process(Errors.java:267)
[jersey-common-2.8.jar:na]
at
org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:297)
[jersey-common-2.8.jar:na]
at
org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:252)
[jersey-server-2.8.jar:na]
at
org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1023)
[jersey-server-2.8.jar:na]
at
org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:372)
[jersey-container-servlet-core-2.8.jar:na]
at
org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:382)
[jersey-container-servlet-core-2.8.jar:na]
at
org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:345)
[jersey-container-servlet-core-2.8.jar:na]
at
org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:220)
[jersey-container-servlet-core-2.8.jar:na]
at
org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:738)
[jetty-servlet-9.1.5.v20140505.jar:9.1.5.v20140505]
at
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:551)
[jetty-servlet-9.1.5.v20140505.jar:9.1.5.v20140505]
at
org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:219)
[jetty-server-9.1.5.v20140505.jar:9.1.5.v20140505]
at
org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1111)
[jetty-server-9.1.5.v20140505.jar:9.1.5.v20140505]
at
org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:478)
[jetty-servlet-9.1.5.v20140505.jar:9.1.5.v20140505]
at
org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:183)
[jetty-server-9.1.5.v20140505.jar:9.1.5.v20140505]
at
org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1045)
[jetty-server-9.1.5.v20140505.jar:9.1.5.v20140505]
at
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
[jetty-server-9.1.5.v20140505.jar:9.1.5.v20140505]
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
[jetty-server-9.1.5.v20140505.jar:9.1.5.v20140505]
at org.eclipse.jetty.server.Server.handle(Server.java:462)
[jetty-server-9.1.5.v20140505.jar:9.1.5.v20140505]
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:279)
[jetty-server-9.1.5.v20140505.jar:9.1.5.v20140505]
at
org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:232)
[jetty-server-9.1.5.v20140505.jar:9.1.5.v20140505]
at
org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:534)
[jetty-io-9.1.5.v20140505.jar:9.1.5.v20140505]
at
org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:607)
[jetty-util-9.1.5.v20140505.jar:9.1.5.v20140505]
at
org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:536)
[jetty-util-9.1.5.v20140505.jar:9.1.5.v20140505]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
{noformat}
Details related to the above query id (26c9073d-a8ff-17b0-5a86-34042bdfb494)
from drillbit.log
{noformat}
...
...
2017-06-06 18:47:57,149 [UserServer-1] INFO
o.a.d.e.w.fragment.FragmentExecutor - 26c9073d-a8ff-17b0-5a86-34042bdfb494:0:0:
State change requested RUNNING --> FAILED
...
...
2017-06-06 18:47:57,159 [26c9073d-a8ff-17b0-5a86-34042bdfb494:frag:0:0] INFO
o.a.d.e.w.fragment.FragmentExecutor - 26c9073d-a8ff-17b0-5a86-34042bdfb494:0:0:
State change requested FAILED --> FAILED
...
...
2017-06-06 18:47:57,238 [BitServer-5] INFO o.a.d.e.w.fragment.FragmentExecutor
- 26c9073d-a8ff-17b0-5a86-34042bdfb494:0:0: State change requested FAILED -->
CANCELLATION_REQUESTED
2017-06-06 18:47:57,238 [BitServer-5] WARN o.a.d.e.w.fragment.FragmentExecutor
- 26c9073d-a8ff-17b0-5a86-34042bdfb494:0:0: Ignoring unexpected state
transition FAILED --> CANCELLATION_REQUESTED
...
2017-06-07 10:18:19,006 [26c9073d-a8ff-17b0-5a86-34042bdfb494:frag:0:0] WARN
o.a.drill.exec.ops.SendingAccountor - Interrupted while waiting for send
complete. Continuing to wait.
java.lang.InterruptedException: null
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:998)
~[na:1.8.0_91]
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
~[na:1.8.0_91]
at java.util.concurrent.Semaphore.acquire(Semaphore.java:467)
~[na:1.8.0_91]
at
org.apache.drill.exec.ops.SendingAccountor.waitForSendComplete(SendingAccountor.java:48)
~[drill-java-exec-1.11.0-SNAPSHOT.jar:1.11.0-SNAPSHOT]
at
org.apache.drill.exec.ops.FragmentContext.waitForSendComplete(FragmentContext.java:486)
[drill-java-exec-1.11.0-SNAPSHOT.jar:1.11.0-SNAPSHOT]
at
org.apache.drill.exec.physical.impl.BaseRootExec.close(BaseRootExec.java:134)
[drill-java-exec-1.11.0-SNAPSHOT.jar:1.11.0-SNAPSHOT]
at
org.apache.drill.exec.physical.impl.ScreenCreator$ScreenRoot.close(ScreenCreator.java:141)
[drill-java-exec-1.11.0-SNAPSHOT.jar:1.11.0-SNAPSHOT]
at
org.apache.drill.exec.work.fragment.FragmentExecutor.closeOutResources(FragmentExecutor.java:313)
[drill-java-exec-1.11.0-SNAPSHOT.jar:1.11.0-SNAPSHOT]
at
org.apache.drill.exec.work.fragment.FragmentExecutor.cleanup(FragmentExecutor.java:155)
[drill-java-exec-1.11.0-SNAPSHOT.jar:1.11.0-SNAPSHOT]
at
org.apache.drill.exec.work.fragment.FragmentExecutor.run(FragmentExecutor.java:264)
[drill-java-exec-1.11.0-SNAPSHOT.jar:1.11.0-SNAPSHOT]
at
org.apache.drill.common.SelfCleaningRunnable.run(SelfCleaningRunnable.java:38)
[drill-common-1.11.0-SNAPSHOT.jar:1.11.0-SNAPSHOT]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[na:1.8.0_91]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[na:1.8.0_91]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
...
...
Allocator(query:26c9073d-a8ff-17b0-5a86-34042bdfb494) 1048576/0/0/268435456
(res/actual/peak/limit)
child allocators: 0
ledgers: 0
reservations: 0
...
2017-06-07 10:20:03,718 [qtp1575043618-89] INFO
o.a.d.e.s.r.profile.ProfileResources - User Error Occurred: No profile with
given query id '26c9073d-a8ff-17b0-5a86-34042bdfb494' exists. Please verify the
query id.
org.apache.drill.common.exceptions.UserException: VALIDATION ERROR: No profile
with given query id '26c9073d-a8ff-17b0-5a86-34042bdfb494' exists. Please
verify the query id.
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)
