https://linen.dev logo
Join Slack
Powered by
This message was deleted.
# troubleshooting
s
This message was deleted.
s
Are all segment intervals in that table on 2021-06-29?
k
One segment in 2021-06-29 should have 500M data at least
s
In theory, all rows within that time interval should be returned. Have you compared rows from a 
SELECT count(*)
for the same time interval and the number of rows returned to your result file? You might need to remove the "pretty" to get one row per line in your result. Is this a clustered deployment, is that URL the broker? I'm just checking that you are not issuing the request to a historical in a cluster of multiple historicals.
k
This showed that on 2021-06-29, there are multiple segments with 500M data and 1M rows.
I can confirm this request is to the router. In fact, this cluster has only one broker and one historical.
g
did the JSON end up being cut off?
like, is it valid?
if there is some error (or timeout) during query processing, then the response will be cut off early
s
Just making sure,... the "size" column in the result you are showing is the size in bytes of the segment partition, does the num_rows column in that result have the numbers you expect?
k
The response may be cut out. There is only one line here for this 70M file. Let me retry use "list" instead of "compact list"
Actually, without "?pretty", it is one line. Let me use "?pretty" to confirm if the response is "cut off"
Yes, the response is cut off. Bellow is the last 100 lines of the response file.
Copy code
}, {
    "__time" : 1624925857991,
    "dc" : "pzh",
    "device" : "<http://stmfa1la2-lapp1-3-prd.eng.sfdc.net|stmfa1la2-lapp1-3-prd.eng.sfdc.net>",
    "env" : "perf",
    "eventType" : "transaction",
    "name" : "xosvvrnw",
    "orgId" : "org-hxpijeqprl",
    "pod" : "pod-baz",
    "superPod" : "superpod-pt",
    "userId" : "04158427",
    "sampled" : "false",
    "serviceName" : "scrt",
    "traceId" : "0000000000000000000000c08ca0c8ec",
    "spanId" : "00004ada0c3f40e5",
    "error" : "false",
    "errorMessage" : "errMsg:-tlksffquufvfwzpftgytwswfyomcea",
    "errorType" : "rmava",
    "httpStatusCode" : "404",
    "uri" : "/zyppowbiultrgdv",
    "transactionType" : "hybernate",
    "closed" : "true",
    "closingTimestamp" : "1674363913877",
    "dbCallCount" : 41962,
    "duration" : 335132,
    "dbCallDuration" : 8891576,
    "externalCallCount" : 62862,
    "externalCallDuration" : 4186772
  }, {
    "__time" : 1624925858001,
    "dc" : "fqo",
    "device" : "<http://stmfa1la2-lapp1-1-prd.eng.sfdc.net|stmfa1la2-lapp1-1-prd.eng.sfdc.net>",
    "env" : "perf",
    "eventType" : "transaction",
    "name" : "upmaaiuc",
    "orgId" : "org-xibawqscka",
    "pod" : "pod-umq",
    "superPod" : "superpod-vy",
    "userId" : "%
Just making sure,... the "size" column in the result you are showing is the size in bytes of the segment partition, does the num_rows column in that result have the numbers you expect?
No, it does not have the number of lines I expect. Way lower
Wondering is this due to the druid query context time out? or curl time out? I think curl timeout is unlikely. This always around 22 secs.
s
Do you see any errors in the historical or broker logs?
k
Let me check the logs. Here, I did see 
druid.server.http.defaultQueryTimeout
is set as 
druid.server.http.defaultQueryTimeout=600000
This is 10 minutes query timeout. It does not seem to apply here.
Here is the error logs from Druid brokers:
Copy code
2022-10-19T00:05:29,867 ERROR [qtp1727196188-246] org.apache.druid.server.QueryResource - Unable to send query response. (com.fasterxml.jackson.databind.JsonMappingException: Query[0b6845d6-714b-46ff-a495-bb4bef152d74] url[<http://10.64.210.125:8088/druid/v2/>] failed with exception msg [Channel disconnected])
2022-10-19T00:05:29,868 WARN [qtp1727196188-246] org.apache.druid.server.QueryLifecycle - Exception while processing queryId [0b6845d6-714b-46ff-a495-bb4bef152d74] (com.fasterxml.jackson.databind.JsonMappingException: Query[0b6845d6-714b-46ff-a495-bb4bef152d74] url[<http://10.64.210.125:8088/druid/v2/>] failed with exception msg [Channel disconnected])
2022-10-19T00:05:29,869 WARN [qtp1727196188-246] org.eclipse.jetty.server.HttpChannel - handleException /druid/v2/ com.fasterxml.jackson.databind.JsonMappingException: Query[0b6845d6-714b-46ff-a495-bb4bef152d74] url[<http://10.64.210.125:8088/druid/v2/>] failed with exception msg [Channel disconnected]
Here is the error logs from Druid historical:
Copy code
2022-10-19T00:05:28,864 ERROR [qtp2085313771-134[scan_[perf_data_1T_1]_0b6845d6-714b-46ff-a495-bb4bef152d74]] org.apache.druid.server.QueryResource - Unable to send query response. (org.eclipse.jetty.io.EofException)
2022-10-19T00:05:28,864 WARN [qtp2085313771-134] org.apache.druid.server.QueryLifecycle - Exception while processing queryId [0b6845d6-714b-46ff-a495-bb4bef152d74] (org.eclipse.jetty.io.EofException)
s
I'm reading this which seems relevant.
k
Let me get the router error messages to you too.
s
Do you see a TimeoutException in the Historical log?
k
Here is the error logs from Druid router
Copy code
2022-10-19T00:05:30,959 ERROR [qtp774840504-131] org.apache.druid.server.AsyncQueryForwardingServlet - Exception handling request: {class=org.apache.druid.server.AsyncQueryForwardingServlet, exceptionType=class java.io.EOFException, exceptionMessage=HttpConnectionOverHTTP@698f503a::SocketChannelEndPoint@1c4942b6{l=/10.64.196.185:49932,r=/10.64.196.217:8088,ISHUT,fill=-,flush=-,to=0/900000}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@698f503a(l:/10.64.196.185:49932 <-> r:/10.64.196.217:8088,closed=false)=>HttpChannelOverHTTP@11826201(exchange=HttpExchange@4d81d165{req=HttpRequest[POST /druid/v2/ HTTP/1.1]@5e9c566f[TERMINATED/null] res=HttpResponse[HTTP/1.1 200 OK]@896f3f8[PENDING/null]})[send=HttpSenderOverHTTP@a860a81(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@49cfe84d{s=START}],recv=HttpReceiverOverHTTP@755cf035(rsp=CONTENT,failure=null)[HttpParser{s=CLOSED,78527284 of -1}]], exception=java.io.EOFException: HttpConnectionOverHTTP@698f503a::SocketChannelEndPoint@1c4942b6{l=/10.64.196.185:49932,r=/10.64.196.217:8088,ISHUT,fill=-,flush=-,to=0/900000}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@698f503a(l:/10.64.196.185:49932 <-> r:/10.64.196.217:8088,closed=false)=>HttpChannelOverHTTP@11826201(exchange=HttpExchange@4d81d165{req=HttpRequest[POST /druid/v2/ HTTP/1.1]@5e9c566f[TERMINATED/null] res=HttpResponse[HTTP/1.1 200 OK]@896f3f8[PENDING/null]})[send=HttpSenderOverHTTP@a860a81(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@49cfe84d{s=START}],recv=HttpReceiverOverHTTP@755cf035(rsp=CONTENT,failure=null)[HttpParser{s=CLOSED,78527284 of -1}]], query=ScanQuery{dataSource='perf_data_1T_1', querySegmentSpec=LegacySegmentSpec{intervals=[2021-06-29T00:00:00.000Z/2021-06-30T00:00:00.000Z]}, virtualColumns=[], resultFormat='list', batchSize=20480, offset=0, limit=9223372036854775807, dimFilter=null, columns=[], context={queryId=0b6845d6-714b-46ff-a495-bb4bef152d74}}, peer=127.0.0.1}
java.io.EOFException: HttpConnectionOverHTTP@698f503a::SocketChannelEndPoint@1c4942b6{l=/10.64.196.185:49932,r=/10.64.196.217:8088,ISHUT,fill=-,flush=-,to=0/900000}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@698f503a(l:/10.64.196.185:49932 <-> r:/10.64.196.217:8088,closed=false)=>HttpChannelOverHTTP@11826201(exchange=HttpExchange@4d81d165{req=HttpRequest[POST /druid/v2/ HTTP/1.1]@5e9c566f[TERMINATED/null] res=HttpResponse[HTTP/1.1 200 OK]@896f3f8[PENDING/null]})[send=HttpSenderOverHTTP@a860a81(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@49cfe84d{s=START}],recv=HttpReceiverOverHTTP@755cf035(rsp=CONTENT,failure=null)[HttpParser{s=CLOSED,78527284 of -1}]]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.earlyEOF(HttpReceiverOverHTTP.java:385) ~[jetty-client-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1620) ~[jetty-http-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.shutdown(HttpReceiverOverHTTP.java:269) ~[jetty-client-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:185) ~[jetty-client-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:80) ~[jetty-client-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.client.HttpReceiver.demand(HttpReceiver.java:118) ~[jetty-client-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.client.HttpReceiver$ContentListeners.demand(HttpReceiver.java:701) ~[jetty-client-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.client.ResponseNotifier.lambda$notifyContent$1(ResponseNotifier.java:139) ~[jetty-client-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.client.api.Response$AsyncContentListener.lambda$onContent$0(Response.java:192) ~[jetty-client-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.util.Callback$3.succeeded(Callback.java:142) [jetty-util-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.util.Callback$Nested.succeeded(Callback.java:285) [jetty-util-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.proxy.AsyncProxyServlet$StreamWriter.complete(AsyncProxyServlet.java:284) [jetty-proxy-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.proxy.AsyncProxyServlet$StreamWriter.onWritePossible(AsyncProxyServlet.java:265) [jetty-proxy-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.server.HttpOutput.run(HttpOutput.java:1541) [jetty-server-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1525) [jetty-server-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:600) [jetty-server-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:439) [jetty-server-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [jetty-util-9.4.47.v20220610.jar:9.4.47.v20220610]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [jetty-util-9.4.47.v20220610.jar:9.4.47.v20220610]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162]
Do you see a TimeoutException in the Historical log?
Do you have some string to search? In fact, I don't think so. Because I tried it one more time and there is the single historical. I did wait for the error message with a 
tail -f
and the above are the only ones.
s
And the default for 
druid.server.http.maxIdleTime
is 5 minutes, so that's not it either.
Just thinking out loud...Really seems like a network problem. Seems like the historical was attempting to return more results when the connection to the broker was lost.
k
Here is some information may help.
historical has ip 10.64.210.125
broker has ip 10.64.196.217
s
one thing that seems odd is that all the ports are set to 8088, not necessarily a problem because they are on different hosts, but this is unusual.
k
right. That is due to some historical reasons. As you said, this was not an problem that we are aware of.
s
Were you able to do this scan query before?
k
@Sergio Ferragut, is it that we are say the broker and historical connections somehow breaks? From this error message in broker:
Copy code
2022-10-19T00:05:29,867 ERROR [qtp1727196188-246] org.apache.druid.server.QueryResource - Unable to send query response. (com.fasterxml.jackson.databind.JsonMappingException: Query[0b6845d6-714b-46ff-a495-bb4bef152d74] url[<http://10.64.210.125:8088/druid/v2/>] failed with exception msg [Channel disconnected])
Basically Broker complains it can't send query response to router due to 
<http://10.64.210.125:8088/druid/v2/>
end point failed? And subsequent router exception is due to broker close the connection/ sending error to the router?
Were you able to do this scan query before?
This is for perf test. We did do quite some query before, but not this large scale scans.
s
At this point in the query, the historical seems to be returning results and half way through it encounters the
Copy code
Unable to send query response. (org.eclipse.jetty.io.EofException)
The broker then errors out right after that with a
Copy code
Query[0b6845d6-714b-46ff-a495-bb4bef152d74] url[<http://10.64.210.125:8088/druid/v2/>] failed with exception msg [Channel disconnected]
I think the router error is just a side effect. You can prove this by submitting the request directly to the broker. But we still don't know why the connection is being lost between historical and broker.
k
I actually did a little bit more testings. • I used k8 port-forwarding to run this scan against the historical ◦ This turned out to last for over 3 minutes and streamed 1G data. ◦ The response json is also correctly formed at the last line • I used k8 port-forwarding to run this scan agains the broker ◦ I got the same error in around 22 secs
This seems to be related to some broker/historical settings? The setting somehow breaks the historical and broker connection (maybe by closing it?) after 20 secs.
s
Both historical and broker can have 
druid.server.http.defaultQueryTimeout
. Is it maybe lower on the brokers?
k
Just checked, both broker and historical, the setting is 
druid.server.http.defaultQueryTimeout=600000
Also, if this timeout is triggered, based on this, it should have 
java.util.concurrent.TimeoutException: Idle timeout expired:
in the historical log. And in my case, there is no such log.
In fact, what I have in historical is this 
EofException
Copy code
2022-10-19T00:05:28,864 ERROR [qtp2085313771-134[scan_[perf_data_1T_1]_0b6845d6-714b-46ff-a495-bb4bef152d74]] org.apache.druid.server.QueryResource - Unable to send query response. (org.eclipse.jetty.io.EofException)
EofException means end of file, right? It is likely that the broker side closed the socket somehow?
g
Yeah the historical side error looks like it thinks the Broker closed the connection
no real reason it'd do that after only 22 seconds -- default timeouts are all way longer than that
i wonder if you have a proxy or load balancer between you and Druid that is closing these connections early?
If you do have one -- try contacting the Broker directly
k
If you do have one -- try contacting the Broker directly
@Gian Merlino, Can you illustrated a little bit what you want to try by contacting broker directly? Here, I deployed all the servers in k8. I did try using port forwarding to issue the query against broker and historical respectively. Trying historical individually has not such EOF exception. While trying broker with this query, it still terminate at 22 seconds.
g
I mean as directly as you can, with as little stuff in the middle as possible (whatever that means for your environment)
I was guessing, based on your URL, that https://monc-ra-common-lab1.sfproxy.monitoring.dev1-uswest2.aws.sfdc.cl/ is some kind of proxy or load balancer and not the Broker itself
you could try getting a shell on the Broker pod and contacting 
localhost
that's pretty direct 🙂
k
That is a good point. The URL is from mesh network settings. Let me try and report the result here.
Here is the test result from broker shell directly:
Copy code
bash-4.2$ curl -X POST '<http://127.0.0.1:8088/druid/v2/?pretty>' -H 'Content-Type:application/json'  -d @tst.json > his.out
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  491M    0  491M  100   157  30.7M      9  0:00:17  0:00:16  0:00:01 34.4M
Basically, at 17 secs, the network connection would terminate. And the result is partial result.
Copy code
bash-4.2$ head his.out 
[ {
  "segmentId" : "perf_data_1T_1_2021-06-28T00:00:00.000Z_2021-06-29T00:00:00.000Z_2022-10-14T21:45:47.249Z",
  "columns" : [ "__time", "dc", "device", "env", "eventType", "name", "orgId", "pod", "superPod", "userId", "sampled", "serviceName", "traceId", "spanId", "error", "errorMessage", "errorType", "httpStatusCode", "uri", "transactionType", "closed", "closingTimestamp", "dbCallCount", "duration", "dbCallDuration", "externalCallCount", "externalCallDuration" ],
  "events" : [ {
    "__time" : 1624838400001,
    "dc" : "ifc",
    "device" : "<http://istla4la2-lapp1-4-prd.eng.sfdc.net|istla4la2-lapp1-4-prd.eng.sfdc.net>",
    "env" : "test",
    "eventType" : "transaction",
    "name" : "rqrxxpqj",
bash-4.2$ vim his.out 
bash: vim: command not found
bash-4.2$ vi his.out 

[1]+  Stopped                 vi his.out
bash-4.2$ fg
vi his.out
bash-4.2$ tail his.out 
    "transactionType" : "hybernate",
    "closed" : "false",
    "closingTimestamp" : "1722314312545",
    "dbCallCount" : 23803,
    "duration" : 532518,
    "dbCallDuration" : 8444575,
    "externalCallCount" : 59096,
    "externalCallDuration" : 4503417
  } ]
}
s
That looks like a complete set for at least one segment. If you grep for “segmentId” on the file, do you see more segments?
k
This is at the end of a complete segment, but still not well-formed json. It should end with 
]
. Also, let me post the error logs, this time, a little bit more from historical side.
Error logs from Druid historical
Copy code
2022-10-19T18:51:41,474 WARN [qtp1727196188-205] org.apache.druid.client.JsonParserIterator - Query [b6759bd2-1936-4efa-acef-ee26c651eeaf] to host [10.64.210.125:8088] interrupted
java.io.IOException: Query[b6759bd2-1936-4efa-acef-ee26c651eeaf] url[<http://10.64.210.125:8088/druid/v2/>] failed with exception msg [Channel disconnected]
        at org.apache.druid.client.DirectDruidClient$1$3.read(DirectDruidClient.java:408) ~[druid-server-0.23.0-sfmc.jar:0.23.0-sfmc]
        at java.io.InputStream.read(InputStream.java:170) ~[?:1.8.0_162]
        at java.io.SequenceInputStream.read(SequenceInputStream.java:207) ~[?:1.8.0_162]
        at com.fasterxml.jackson.dataformat.smile.SmileParser._loadToHaveAtLeast(SmileParser.java:289) ~[jackson-dataformat-smile-2.10.5.jar:2.10.5]
        at com.fasterxml.jackson.dataformat.smile.SmileParser._decodeShortAsciiValue(SmileParser.java:2223) ~[jackson-dataformat-smile-2.10.5.jar:2.10.5]
        at com.fasterxml.jackson.dataformat.smile.SmileParser.getText(SmileParser.java:996) ~[jackson-dataformat-smile-2.10.5.jar:2.10.5]
        at com.fasterxml.jackson.databind.deser.std.UntypedObjectDeserializer$Vanilla.deserialize(UntypedObjectDeserializer.java:672) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
        at com.fasterxml.jackson.databind.deser.std.UntypedObjectDeserializer$Vanilla.mapObject(UntypedObjectDeserializer.java:895) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
        at com.fasterxml.jackson.databind.deser.std.UntypedObjectDeserializer$Vanilla.deserialize(UntypedObjectDeserializer.java:654) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
        at com.fasterxml.jackson.databind.deser.std.UntypedObjectDeserializer$Vanilla.mapArray(UntypedObjectDeserializer.java:831) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
        at com.fasterxml.jackson.databind.deser.std.UntypedObjectDeserializer$Vanilla.deserialize(UntypedObjectDeserializer.java:668) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
        at com.fasterxml.jackson.databind.deser.SettableBeanProperty.deserialize(SettableBeanProperty.java:530) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
        at com.fasterxml.jackson.databind.deser.BeanDeserializer._deserializeWithErrorWrapping(BeanDeserializer.java:528) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
        at com.fasterxml.jackson.databind.deser.BeanDeserializer._deserializeUsingPropertyBased(BeanDeserializer.java:417) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
        at com.fasterxml.jackson.databind.deser.BeanDeserializerBase.deserializeFromObjectUsingNonDefault(BeanDeserializerBase.java:1292) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
        at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserializeFromObject(BeanDeserializer.java:326) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
        at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:159) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
        at com.fasterxml.jackson.databind.ObjectMapper._readValue(ObjectMapper.java:4189) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
        at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:2525) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
        at org.apache.druid.client.JsonParserIterator.next(JsonParserIterator.java:112) ~[druid-server-0.23.0-sfmc.jar:0.23.0-sfmc]
        at org.apache.druid.java.util.common.guava.BaseSequence.makeYielder(BaseSequence.java:90) ~[druid-core-0.23.0-sfmc.jar:0.23.0-sfmc]
        at org.apache.druid.java.util.common.guava.BaseSequence.access$000(BaseSequence.java:27) ~[druid-core-0.23.0-sfmc.jar:0.23.0-sfmc]
        at org.apache.druid.java.util.common.guava.BaseSequence$1.next(BaseSequence.java:114) ~[druid-core-0.23.0-sfmc.jar:0.23.0-sfmc]
        at org.apache.druid.java.util.common.guava.MergeSequence.makeYielder(MergeSequence.java:132) ~[druid-core-0.23.0-sfmc.jar:0.23.0-sfmc]
...
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) [jetty-util-9.4.47.v20220610.jar:9.4.47.v20220610]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [jetty-util-9.4.47.v20220610.jar:9.4.47.v20220610]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [jetty-util-9.4.47.v20220610.jar:9.4.47.v20220610]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162]
Caused by: org.jboss.netty.channel.ChannelException: Channel disconnected
        at org.apache.druid.java.util.http.client.NettyHttpClient$1.channelDisconnected(NettyHttpClient.java:345) ~[druid-core-0.23.0-sfmc.jar:0.23.0-sfmc]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:102) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.channelDisconnected(SimpleChannelUpstreamHandler.java:208) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:102) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.channelDisconnected(SimpleChannelUpstreamHandler.java:208) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:102) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.handler.codec.replay.ReplayingDecoder.cleanup(ReplayingDecoder.java:570) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.handler.codec.frame.FrameDecoder.channelDisconnected(FrameDecoder.java:365) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:102) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.handler.codec.http.HttpClientCodec.handleUpstream(HttpClientCodec.java:92) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.Channels.fireChannelDisconnected(Channels.java:396) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.socket.nio.AbstractNioWorker.close(AbstractNioWorker.java:360) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:93) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:108) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:89) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) ~[netty-3.10.6.Final.jar:?]
        at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42) ~[netty-3.10.6.Final.jar:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_162]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_162]
        ... 1 more
2022-10-19T18:51:41,476 ERROR [qtp1727196188-205] org.apache.druid.server.QueryResource - Unable to send query response. (com.fasterxml.jackson.databind.JsonMappingException: Query[b6759bd2-1936-4efa-acef-ee26c651eeaf] url[<http://10.64.210.125:8088/druid/v2/>] failed with exception msg [Channel disconnected])
2022-10-19T18:51:41,477 WARN [qtp1727196188-205] org.apache.druid.server.QueryLifecycle - Exception while processing queryId [b6759bd2-1936-4efa-acef-ee26c651eeaf] (com.fasterxml.jackson.databind.JsonMappingException: Query[b6759bd2-1936-4efa-acef-ee26c651eeaf] url[<http://10.64.210.125:8088/druid/v2/>] failed with exception msg [Channel disconnected])
2022-10-19T18:51:41,477 WARN [qtp1727196188-205] org.eclipse.jetty.server.HttpChannel - handleException /druid/v2/ com.fasterxml.jackson.databind.JsonMappingException: Query[b6759bd2-1936-4efa-acef-ee26c651eeaf] url[<http://10.64.210.125:8088/druid/v2/>] failed with exception msg [Channel disconnected]
broker thinks channel disconnected.
And historical side, the error message is still
Copy code
2022-10-19T18:51:40,471 ERROR [qtp2085313771-179[scan_[perf_data_1T_1]_b6759bd2-1936-4efa-acef-ee26c651eeaf]] org.apache.druid.server.QueryResource - Unable to send query response. (org.eclipse.jetty.io.EofException)
2022-10-19T18:51:40,472 WARN [qtp2085313771-179] org.apache.druid.server.QueryLifecycle - Exception while processing queryId [b6759bd2-1936-4efa-acef-ee26c651eeaf] (org.eclipse.jetty.io.EofException)
@Gian Merlino, @Sergio Ferragut, if I try from the shell of the historical server to run this scan, after 2 minutes, 36sec or so, I did have timeout exception. Do we have any idea of what is this timeout? Here is the log:
Copy code
2022-10-19T19:19:36,275 ERROR [qtp2085313771-120[scan_[perf_data_1T_1]_40b50275-9167-475a-82a9-e185f9f261d2]] org.apache.druid.server.QueryResource - Unable to send query response. (com.fasterxml.jackson.databind.JsonM
appingException: Query [40b50275-9167-475a-82a9-e185f9f261d2] timed out)
2022-10-19T19:19:36,275 WARN [qtp2085313771-120] org.apache.druid.server.QueryLifecycle - Exception while processing queryId [40b50275-9167-475a-82a9-e185f9f261d2] (com.fasterxml.jackson.databind.JsonMappingException: 
Query [40b50275-9167-475a-82a9-e185f9f261d2] timed out)
2022-10-19T19:19:36,275 WARN [qtp2085313771-120] org.eclipse.jetty.server.HttpChannel - handleException /druid/v2/ com.fasterxml.jackson.databind.JsonMappingException: Query [40b50275-9167-475a-82a9-e185f9f261d2] timed
 out
And the query is:
Copy code
bash-4.2$ date; curl -X POST '<http://127.0.0.1:8088/druid/v2/?pretty>' -H 'Content-Type:application/json' -d @scan.json > his.out
Wed Oct 19 19:16:59 GMT 2022
 % Total  % Received % Xferd Average Speed  Time  Time   Time Current
                 Dload Upload  Total  Spent  Left Speed
100 11.3G  0 11.3G 100  157 74.2M   1 0:02:37 0:02:36 0:00:01 78.0M
s
I couldn't find any timeout setting on the historical that would do that in 2:37 timeframe. The defaults are set to 5 minutes. This still seems like a networking issue. What version of k8s are you on? I found a related article which is kind of old that refers to unexpected connection loss with large workloads (like large file downloads) here: https://kubernetes.io/blog/2019/03/29/kube-proxy-subtleties-debugging-an-intermittent-connection-reset/ It says this is resolved in kubernetes version 1.15+.
k
I will check with the K8 teams, but I think or k8 is above 1.15 which is pretty old.
That said, this error with 
timed out
is different. We can search the code to have some clue.
Copy code
2022-10-19T19:19:36,275 ERROR [qtp2085313771-120[scan_[perf_data_1T_1]_40b50275-9167-475a-82a9-e185f9f261d2]] org.apache.druid.server.QueryResource - Unable to send query response. (com.fasterxml.jackson.databind.JsonM
appingException: Query [40b50275-9167-475a-82a9-e185f9f261d2] timed out)
In fact, this line is from QueryResource.java:
Copy code
log.noStackTrace().error(ex, "Unable to send query response.");
Copy code
Response.ResponseBuilder responseBuilder = Response
    .ok(
        new StreamingOutput()
        {
          @Override
          public void write(OutputStream outputStream) throws WebApplicationException
          {
            Exception e = null;

            CountingOutputStream os = new CountingOutputStream(outputStream);
            try {
              // json serializer will always close the yielder
              jsonWriter.writeValue(os, yielder);

              os.flush(); // Some types of OutputStream suppress flush errors in the .close() method.
              os.close();
            }
            catch (Exception ex) {
              e = ex;
              log.noStackTrace().error(ex, "Unable to send query response.");
              throw new RuntimeException(ex);
            }
            finally {
              Thread.currentThread().setName(currThreadName);

              queryLifecycle.emitLogsAndMetrics(e, req.getRemoteAddr(), os.getCount());
s
I think that means that the output stream failed to write, flush or close. The stack trace above also indicates a network communication problem, this is where the failure occurred: https://github.com/netty/netty/blob/netty-3.10.6.Final/src/main/java/org/jboss/netty/channel/socket/nio/NioWorker.java#L93 which seems to indicate that the read failed here https://github.com/netty/netty/blob/5f56a03bcb0aa23bdc9f68686e5c2abcf963a9cd/src/main/java/org/jboss/netty/channel/socket/nio/NioWorker.java#L64 (could've been a ClosedChannel exception which is caught in line 72 and intentionally ignored which would lead to either ret=0 or failure=true and therefore end up firing the ChannelDisconnectedException here:
Copy code
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.close(AbstractNioWorker.java:360)
https://github.com/netty/netty/blob/5f56a03bcb0aa23bdc9f68686e5c2abcf963a9cd/src/main/java/org/jboss/netty/channel/socket/nio/AbstractNioWorker.java#L360 so, I'm still thinking network problem.
k
@Sergio Ferragut, with the code pointers, are you talking about the last historical timeout issue?
s
I was following the bottom of the stack trace that you posted last. I've been trying to find similar conditions. Some users report this with large queries as well, here: https://github.com/apache/druid/issues/5340 and they are describing solutions/workarounds by adjusting thread count and/or heap and maxmemory on the broker and historical (see comment here) perhaps it is worth a try.
k
My understanding if the code is kind of limited as I haven't really dig deep in this codebase. That said, here is my digging. Let me know if I am wrong somewhere. 1/ Setup of Json serialization mapper is in DefaultObjectMapper.java. With this setup, this line in response 
jsonWriter.writeValue(os, yielder);
knows how to serialize a 
Sequence
Yielder.
Copy code
public DefaultObjectMapper(JsonFactory factory)
{
  super(factory);
  registerModule(new DruidDefaultSerializersModule());
  registerModule(new GuavaModule());
  registerModule(new GranularityModule());
  registerModule(new AggregatorsModule());
Note, here it is registering Jackson module, not Guice module. 2/ DruidDefaultSerializersModule we have how to serialize a Yielder (sequence's yielder), which basically yield one object at a time, and call 
jgen.writeObject(o)
Copy code
addSerializer(
    Yielder.class,
    new JsonSerializer<Yielder>()
    {
      @Override
      public void serialize(Yielder yielder, final JsonGenerator jgen, SerializerProvider provider)
          throws IOException
      {
        try {
          jgen.writeStartArray();
          while (!yielder.isDone()) {
            final Object o = yielder.get();
            jgen.writeObject(o);
            yielder = yielder.next(null);
          }
          jgen.writeEndArray();
        }
        finally {
          yielder.close();
        }
      }
    }
);
3/ In the QueryResource code to build response
Copy code
try {
  // json serializer will always close the yielder
  jsonWriter.writeValue(os, yielder);

  os.flush(); // Some types of OutputStream suppress flush errors in the .close() method.
  os.close();
}
catch (Exception ex) {
  e = ex;
  log.noStackTrace().error(ex, "Unable to send query response.");
  throw new RuntimeException(ex);
}
Here, 
jsonWriter
actually wraps a DefaultObjectMapper above to write yielders. Note, this is a streaming operation. One the main reason to use Yielder/Sequence (not common pattern) is to stream the data while doing some business logic processing. And here, the 
ex
has the following message `
Copy code
(com.fasterxml.jackson.databind.JsonM
appingException: Query [40b50275-9167-475a-82a9-e185f9f261d2] timed out)
This 
ex
is thrown out from the above serialization code
Copy code
jgen.writeStartArray();
          while (!yielder.isDone()) {
            final Object o = yielder.get();
            jgen.writeObject(o);
            yielder = yielder.next(null);
          }
          jgen.writeEndArray();
Note, this san test is from historical. So this yielder is not really get data from another server via network socket. Instead, it is getting the data from the local disk. So I think the timeout it complains is with some disk/cache/mmaped segment file etc.
@Sergio Ferragut, I see. https://github.com/apache/druid/issues/5340 is also an interesting read. In fact, now I have seen two problems here. 1/ From broker, run scan, I see exception similar to https://github.com/apache/druid/issues/5340 2/ Taking advice from @Gian Merlino, run scan on historical, I see the timeout in around 100sec (2 mins, 37sec). The above code going through is for the 2/ timeout issue.
s
You probably understand it better than I do. Given the comments on that issue. I'm wondering if you are having a memory issue on the historical that is causing this when dealing with large results. What are your JVM settings for the historical?
k
Following this post, I did a little bit more digging. The basic idea is that this line 
log.noStackTrace().error(ex, "Unable to send query response.");
which give 
timeout
is from the 
ex
exception, whose stack trace was not logged. However, we can still find out where in the code it may be logged out. The current intellij has an older copy of code that I did not find the exact pattern of 
Query [40b50275-9167-475a-82a9-e185f9f261d2] timed out
. However, from latest code repo here, I did find out several having this pattern. And this one, https://github.com/apache/druid/blob/c83115e4e19a5825413c09566d165aa142a712a7/proc[…]/src/main/java/org/apache/druid/query/scan/ScanQueryEngine.java seem to be the line emitting the 
Query xxxxx timed out
exception when serialization of json response.
And the timeout seems from query context. as this line showed here https://github.com/apache/druid/blob/c83115e4e19a5825413c09566d165aa142a712a7/proc[…]/src/main/java/org/apache/druid/query/scan/ScanQueryEngine.java
Copy code
final boolean hasTimeout = query.context().hasTimeout();
    final Long timeoutAt = responseContext.getTimeoutTime();
Wondering if we have a doc about where to set/check query context timeout from the native query, or sql?
s
I followed that back to the query context attribute called "timeout" here.
k
Actually, see this doc https://druid.apache.org/docs/latest/querying/query-context.html, query context may be tuned from query input.
however, it does not have the 100sec that I experienced.
s
just found that too. should be defaulting to 5 minutes. but maybe we can disprove the timeout as the root cause by setting the query context with timeout really high.
k
Let me try. I will post the result here later.
Some updates: 1/ Validated that there are some platform issues. Disable some feature in k8/mesh, I do see 10minutes (configured and expected) time out streaming data from router using native scan query. Thus, the EOF exception historical see is due to this platform config. 2/ However, issuing the same scan query to the historical local shell, we still have the 2 mins 37 sec (100sec or so) query context timeout. I don't know where this time out is from. This is a minor issue though.
s
Glad you found the main issue.
@Kai Sun could you share what the k8/mesh feature/setting was that was causing this? It'll be useful to know if anyone else encounters this symptom.
k
Istio mesh sidecar has a default timeout. Tuning this one would help.
s
👍 thank you
g
wow, glad you got it figured out!
2 Views
Open in Slack
PreviousNext
Powered by