Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Pull queries sometimes fail in multi-node deployments #4142

Closed
mikebin opened this issue Dec 16, 2019 · 6 comments · Fixed by #4169
Closed

Pull queries sometimes fail in multi-node deployments #4142

mikebin opened this issue Dec 16, 2019 · 6 comments · Fixed by #4169
Assignees
Labels
Milestone

Comments

@mikebin
Copy link

mikebin commented Dec 16, 2019

Describe the bug

Pull queries in ksqlDB appear to fail when the key to look up exists on a different ksqlDB server than the the one which received the request. This causes sporadic failures in multi-node deployments.

To Reproduce:

docker-compose.yml which starts 2 ksqlDB servers:

---
version: '2'

services:
  zookeeper:
    image: confluentinc/cp-zookeeper:5.3.1
    hostname: zookeeper
    container_name: zookeeper
    ports:
      - "2181:2181"
    environment:
      ZOOKEEPER_CLIENT_PORT: 2181
      ZOOKEEPER_TICK_TIME: 2000

  broker:
    image: confluentinc/cp-enterprise-kafka:5.3.1
    hostname: broker
    container_name: broker
    depends_on:
      - zookeeper
    ports:
      - "29092:29092"
    environment:
      KAFKA_BROKER_ID: 1
      KAFKA_ZOOKEEPER_CONNECT: 'zookeeper:2181'
      KAFKA_LISTENER_SECURITY_PROTOCOL_MAP: PLAINTEXT:PLAINTEXT,PLAINTEXT_HOST:PLAINTEXT
      KAFKA_ADVERTISED_LISTENERS: PLAINTEXT://broker:9092,PLAINTEXT_HOST://localhost:29092
      KAFKA_OFFSETS_TOPIC_REPLICATION_FACTOR: 1
      KAFKA_GROUP_INITIAL_REBALANCE_DELAY_MS: 0

  ksqldb-server1:
    image: confluentinc/ksqldb-server:0.6.0
    hostname: ksqldb-server1
    container_name: ksqldb-server1
    depends_on:
      - broker
    ports:
      - "8088:8088"
    environment:
      KSQL_LISTENERS: http://0.0.0.0:8088
      KSQL_BOOTSTRAP_SERVERS: broker:9092
      KSQL_KSQL_LOGGING_PROCESSING_STREAM_AUTO_CREATE: "true"
      KSQL_KSQL_LOGGING_PROCESSING_TOPIC_AUTO_CREATE: "true"

  ksqldb-server2:
    image: confluentinc/ksqldb-server:0.6.0
    hostname: ksqldb-server2
    container_name: ksqldb-server2
    depends_on:
      - broker
    ports:
      - "8090:8090"
    environment:
      KSQL_LISTENERS: http://0.0.0.0:8090
      KSQL_BOOTSTRAP_SERVERS: broker:9092
      KSQL_KSQL_LOGGING_PROCESSING_STREAM_AUTO_CREATE: "true"
      KSQL_KSQL_LOGGING_PROCESSING_TOPIC_AUTO_CREATE: "true"

  ksqldb-cli:
    image: confluentinc/ksqldb-cli:0.6.0
    container_name: ksqldb-cli
    depends_on:
      - broker
      - ksqldb-server1
    entrypoint: /bin/sh
    tty: true
  1. Create a multi-partition source topic so that processing will be distributed:
kafka-topics --bootstrap-server broker:29092 --topic pageviews --create --partitions 6 --replication-factor 1
  1. Load data into the source topic:
ksql-datagen quickstart=pageviews format=delimited topic=pageviews maxInterval=5000 bootstrap-server=broker:29092
  1. Define a ksqlDB stream for the pageviews topic:
CREATE STREAM pageviews_original (viewtime bigint, userid varchar, pageid varchar) WITH (kafka_topic='pageviews', value_format='DELIMITED');
  1. Create an aggregate table from the stream with a ksqlDB query:
create table pageviews_count as select pageid, count(*) as viewcount from pageviews_original group by pageid;
  1. Query from the aggregate table with a push query (works):
select * from pageviews_count emit changes;
+------------------------------------+------------------------------------+------------------------------------+------------------------------------+
|ROWTIME                             |ROWKEY                              |PAGEID                              |VIEWCOUNT                           |
+------------------------------------+------------------------------------+------------------------------------+------------------------------------+
|1576348011411                       |Page_51                             |Page_51                             |2                                   |
|1576348011193                       |Page_68                             |Page_68                             |2                                   |
  1. Query from the aggregate table with a pull query (sometimes works, sometimes fails):
select * from pageviews_count where rowkey = 'Page_25';
+------------------------------------------------+------------------------------------------------+------------------------------------------------+
|ROWKEY                                          |PAGEID                                          |VIEWCOUNT                                       |
+------------------------------------------------+------------------------------------------------+------------------------------------------------+
|Page_25                                         |Page_25                                         |1                                               |

select * from pageviews_count where rowkey = 'Page_33';
Error issuing POST to KSQL server. path:/query

Expected behaviour

Pull queries would return successfully for all available keys, whether they're local to the ksqlServer the CLI is connected to or not.

Actual behaviour

Some pull queries fail, namely those where the key is not local to the ksqlDB server receiving the request. See above for CLI output.

More detailed debug logging for a failed pull query request here:

ksqldb-server1    | [2019-12-16 16:22:07,779] DEBUG Polling for new writes to command topic (io.confluent.ksql.rest.server.computation.CommandRunner:213)
ksqldb-server1    | [2019-12-16 16:22:12,047] DEBUG Queued change org.eclipse.jetty.io.ManagedSelector$Accept@2868b575 on ManagedSelector@675d8c96{STARTED} id=0 keys=0 selected=0 updates=0 (org.eclipse.jetty.io.ManagedSelector:162)
ksqldb-server1    | [2019-12-16 16:22:12,047] DEBUG Wakeup on submit ManagedSelector@675d8c96{STARTED} id=0 keys=0 selected=0 updates=1 (org.eclipse.jetty.io.ManagedSelector:180)
ksqldb-server1    | [2019-12-16 16:22:12,047] DEBUG Selector sun.nio.ch.EPollSelectorImpl@15325bcb woken with none selected (org.eclipse.jetty.io.ManagedSelector:470)
ksqldb-server1    | [2019-12-16 16:22:12,048] DEBUG Selector sun.nio.ch.EPollSelectorImpl@15325bcb woken up from select, 0/0/0 selected (org.eclipse.jetty.io.ManagedSelector:479)
ksqldb-server1    | [2019-12-16 16:22:12,048] DEBUG Selector sun.nio.ch.EPollSelectorImpl@15325bcb processing 0 keys, 1 updates (org.eclipse.jetty.io.ManagedSelector:492)
ksqldb-server1    | [2019-12-16 16:22:12,049] DEBUG updateable 1 (org.eclipse.jetty.io.ManagedSelector:418)
ksqldb-server1    | [2019-12-16 16:22:12,049] DEBUG update org.eclipse.jetty.io.ManagedSelector$Accept@2868b575 (org.eclipse.jetty.io.ManagedSelector:427)
ksqldb-server1    | [2019-12-16 16:22:12,050] DEBUG queue org.eclipse.jetty.io.ManagedSelector$Accept@2868b575 startThread=false (org.eclipse.jetty.util.thread.QueuedThreadPool:521)
ksqldb-server1    | [2019-12-16 16:22:12,051] DEBUG updates 0 (org.eclipse.jetty.io.ManagedSelector:447)
ksqldb-server1    | [2019-12-16 16:22:12,050] DEBUG run org.eclipse.jetty.io.ManagedSelector$Accept@2868b575 in QueuedThreadPool[qtp341853399]@146044d7{STARTED,8<=8<=200,i=4,r=4,q=0}[ReservedThreadExecutor@293d0107{s=0/4,p=0}] (org.eclipse.jetty.util.thread.QueuedThreadPool:917)
ksqldb-server1    | [2019-12-16 16:22:12,053] DEBUG NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=-,to=0/30000}{io=0/0,kio=0,kro=0}-><null> idle timeout check, elapsed: 0 ms, remaining: 30000 ms (org.eclipse.jetty.io.IdleTimeout:161)
ksqldb-server1    | [2019-12-16 16:22:12,052] DEBUG Selector sun.nio.ch.EPollSelectorImpl@15325bcb waiting with 1 keys (org.eclipse.jetty.io.ManagedSelector:465)
ksqldb-server1    | [2019-12-16 16:22:12,055] DEBUG new HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0} -> NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=-,to=1/30000}{io=0/0,kio=0,kro=0}-><null>,null,HttpChannelState@12e94cb9{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false} (org.eclipse.jetty.server.HttpChannel:117)
ksqldb-server1    | [2019-12-16 16:22:12,056] DEBUG New HTTP Connection HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=-,to=3/30000}{io=0/0,kio=0,kro=0}-><null> (org.eclipse.jetty.server.HttpConnection:112)
ksqldb-server1    | [2019-12-16 16:22:12,057] DEBUG onOpen NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=-,to=3/30000}{io=0/0,kio=0,kro=0}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0} (org.eclipse.jetty.io.AbstractEndPoint:345)
ksqldb-server1    | [2019-12-16 16:22:12,057] DEBUG onOpen HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=-,to=4/30000}{io=0/0,kio=0,kro=0}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0} (org.eclipse.jetty.io.AbstractConnection:201)
ksqldb-server1    | [2019-12-16 16:22:12,058] DEBUG fillInterested HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=-,to=4/30000}{io=0/0,kio=0,kro=0}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0} (org.eclipse.jetty.io.AbstractConnection:133)
ksqldb-server1    | [2019-12-16 16:22:12,058] DEBUG interested FillInterest@4373b214{AC.ReadCB@31181366{HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=FI,flush=-,to=0/30000}{io=0/0,kio=0,kro=0}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0}}} (org.eclipse.jetty.io.FillInterest:79)
ksqldb-server1    | [2019-12-16 16:22:12,059] DEBUG changeInterests p=false 0->1 for NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=FI,flush=-,to=0/30000}{io=0/1,kio=0,kro=0}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0} (org.eclipse.jetty.io.ChannelEndPoint:418)
ksqldb-server1    | [2019-12-16 16:22:12,059] DEBUG Queued change org.eclipse.jetty.io.ChannelEndPoint$1@1b27a247 on ManagedSelector@675d8c96{STARTED} id=0 keys=1 selected=0 updates=0 (org.eclipse.jetty.io.ManagedSelector:162)
ksqldb-server1    | [2019-12-16 16:22:12,060] DEBUG Wakeup on submit ManagedSelector@675d8c96{STARTED} id=0 keys=1 selected=0 updates=1 (org.eclipse.jetty.io.ManagedSelector:180)
ksqldb-server1    | [2019-12-16 16:22:12,060] DEBUG Created NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=FI,flush=-,to=2/30000}{io=0/1,kio=0,kro=0}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0} (org.eclipse.jetty.io.ManagedSelector:272)
ksqldb-server1    | [2019-12-16 16:22:12,061] DEBUG ran org.eclipse.jetty.io.ManagedSelector$Accept@2868b575 in QueuedThreadPool[qtp341853399]@146044d7{STARTED,8<=8<=200,i=4,r=4,q=0}[ReservedThreadExecutor@293d0107{s=0/4,p=0}] (org.eclipse.jetty.util.thread.QueuedThreadPool:920)
ksqldb-server1    | [2019-12-16 16:22:12,064] DEBUG Selector sun.nio.ch.EPollSelectorImpl@15325bcb woken with none selected (org.eclipse.jetty.io.ManagedSelector:470)
ksqldb-server1    | [2019-12-16 16:22:12,065] DEBUG Selector sun.nio.ch.EPollSelectorImpl@15325bcb woken up from select, 0/0/1 selected (org.eclipse.jetty.io.ManagedSelector:479)
ksqldb-server1    | [2019-12-16 16:22:12,065] DEBUG Selector sun.nio.ch.EPollSelectorImpl@15325bcb processing 0 keys, 1 updates (org.eclipse.jetty.io.ManagedSelector:492)
ksqldb-server1    | [2019-12-16 16:22:12,066] DEBUG updateable 1 (org.eclipse.jetty.io.ManagedSelector:418)
ksqldb-server1    | [2019-12-16 16:22:12,067] DEBUG update org.eclipse.jetty.io.ChannelEndPoint$1@1b27a247 (org.eclipse.jetty.io.ManagedSelector:427)
ksqldb-server1    | [2019-12-16 16:22:12,069] DEBUG Key interests updated 0 -> 1 on NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=FI,flush=-,to=10/30000}{io=1/1,kio=1,kro=0}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0} (org.eclipse.jetty.io.ChannelEndPoint:384)
ksqldb-server1    | [2019-12-16 16:22:12,069] DEBUG updates 0 (org.eclipse.jetty.io.ManagedSelector:447)
ksqldb-server1    | [2019-12-16 16:22:12,070] DEBUG Selector sun.nio.ch.EPollSelectorImpl@15325bcb waiting with 1 keys (org.eclipse.jetty.io.ManagedSelector:465)
ksqldb-server1    | [2019-12-16 16:22:12,071] DEBUG Selector sun.nio.ch.EPollSelectorImpl@15325bcb woken up from select, 1/1/1 selected (org.eclipse.jetty.io.ManagedSelector:479)
ksqldb-server1    | [2019-12-16 16:22:12,072] DEBUG Selector sun.nio.ch.EPollSelectorImpl@15325bcb processing 1 keys, 0 updates (org.eclipse.jetty.io.ManagedSelector:492)
ksqldb-server1    | [2019-12-16 16:22:12,073] DEBUG selected 1 sun.nio.ch.SelectionKeyImpl@5b29f5e NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=FI,flush=-,to=14/30000}{io=1/1,kio=1,kro=1}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0}  (org.eclipse.jetty.io.ManagedSelector:521)
ksqldb-server1    | [2019-12-16 16:22:12,073] DEBUG onSelected 1->0 r=true w=false for NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=FI,flush=-,to=15/30000}{io=1/0,kio=1,kro=1}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0} (org.eclipse.jetty.io.ChannelEndPoint:344)
ksqldb-server1    | [2019-12-16 16:22:12,074] DEBUG task CEP:NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=FI,flush=-,to=15/30000}{io=1/0,kio=1,kro=1}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0}:runFillable:BLOCKING (org.eclipse.jetty.io.ChannelEndPoint:356)
ksqldb-server1    | [2019-12-16 16:22:12,076] DEBUG ReservedThreadExecutor@293d0107{s=0/4,p=0} tryExecute EatWhatYouKill@7383eae2/SelectorProducer@1643d68f/PRODUCING/p=false/QueuedThreadPool[qtp341853399]@146044d7{STARTED,8<=8<=200,i=5,r=4,q=0}[ReservedThreadExecutor@293d0107{s=0/4,p=0}][pc=0,pic=0,pec=1,epc=6]@2019-12-16T16:22:12.076Z (org.eclipse.jetty.util.thread.ReservedThreadExecutor:191)
ksqldb-server1    | [2019-12-16 16:22:12,076] DEBUG ReservedThreadExecutor@293d0107{s=0/4,p=1} startReservedThread p=1 (org.eclipse.jetty.util.thread.ReservedThreadExecutor:227)
ksqldb-server1    | [2019-12-16 16:22:12,078] DEBUG run ReservedThreadExecutor@293d0107{s=0/4,p=1}@5fac50a7 in QueuedThreadPool[qtp341853399]@146044d7{STARTED,8<=8<=200,i=4,r=4,q=0}[ReservedThreadExecutor@293d0107{s=0/4,p=1}] (org.eclipse.jetty.util.thread.QueuedThreadPool:917)
ksqldb-server1    | [2019-12-16 16:22:12,078] DEBUG ReservedThreadExecutor@293d0107{s=1/4,p=1}@5fac50a7 started (org.eclipse.jetty.util.thread.ReservedThreadExecutor:348)
ksqldb-server1    | [2019-12-16 16:22:12,078] DEBUG queue ReservedThreadExecutor@293d0107{s=0/4,p=1}@5fac50a7 startThread=false (org.eclipse.jetty.util.thread.QueuedThreadPool:521)
ksqldb-server1    | [2019-12-16 16:22:12,079] DEBUG ReservedThreadExecutor@293d0107{s=1/4,p=0}@5fac50a7 waiting (org.eclipse.jetty.util.thread.ReservedThreadExecutor:277)
ksqldb-server1    | [2019-12-16 16:22:12,084] DEBUG EatWhatYouKill@7383eae2/SelectorProducer@1643d68f/PRODUCING/p=false/QueuedThreadPool[qtp341853399]@146044d7{STARTED,8<=8<=200,i=4,r=4,q=0}[ReservedThreadExecutor@293d0107{s=1/4,p=0}][pc=0,pic=0,pec=1,epc=6]@2019-12-16T16:22:12.082Z m=PRODUCE_EXECUTE_CONSUME t=CEP:NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=FI,flush=-,to=24/30000}{io=1/0,kio=1,kro=1}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0}:runFillable:BLOCKING/BLOCKING (org.eclipse.jetty.util.thread.strategy.EatWhatYouKill:291)
ksqldb-server1    | [2019-12-16 16:22:12,085] DEBUG run CEP:NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=FI,flush=-,to=26/30000}{io=1/0,kio=1,kro=1}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0}:runFillable:BLOCKING in QueuedThreadPool[qtp341853399]@146044d7{STARTED,8<=8<=200,i=3,r=4,q=0}[ReservedThreadExecutor@293d0107{s=1/4,p=0}] (org.eclipse.jetty.util.thread.QueuedThreadPool:917)
ksqldb-server1    | [2019-12-16 16:22:12,085] DEBUG fillable FillInterest@4373b214{AC.ReadCB@31181366{HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=FI,flush=-,to=26/30000}{io=1/0,kio=1,kro=1}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0}}} (org.eclipse.jetty.io.FillInterest:99)
ksqldb-server1    | [2019-12-16 16:22:12,085] DEBUG HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=-,to=27/30000}{io=1/0,kio=1,kro=1}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0} onFillable enter HttpChannelState@12e94cb9{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false} null (org.eclipse.jetty.server.HttpConnection:243)
ksqldb-server1    | [2019-12-16 16:22:12,086] DEBUG filled 361 HeapByteBuffer@6caa9e04[p=0,l=361,c=8192,r=361]={<<<POST /query HTTP/...enceNumber":-1}>>>;","streamsProper...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} (org.eclipse.jetty.io.ChannelEndPoint:250)
ksqldb-server1    | [2019-12-16 16:22:12,085] DEBUG queue CEP:NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=FI,flush=-,to=26/30000}{io=1/0,kio=1,kro=1}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0}:runFillable:BLOCKING startThread=false (org.eclipse.jetty.util.thread.QueuedThreadPool:521)
ksqldb-server1    | [2019-12-16 16:22:12,086] DEBUG HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=-,to=0/30000}{io=1/0,kio=1,kro=1}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0} filled 361 HeapByteBuffer@6caa9e04[p=0,l=361,c=8192,r=361]={<<<POST /query HTTP/...enceNumber":-1}>>>;","streamsProper...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} (org.eclipse.jetty.server.HttpConnection:350)
ksqldb-server1    | [2019-12-16 16:22:12,088] DEBUG updateable 0 (org.eclipse.jetty.io.ManagedSelector:418)
ksqldb-server1    | [2019-12-16 16:22:12,088] DEBUG updates 0 (org.eclipse.jetty.io.ManagedSelector:447)
ksqldb-server1    | [2019-12-16 16:22:12,088] DEBUG HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=-,to=2/30000}{io=1/0,kio=1,kro=1}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0} parse HeapByteBuffer@6caa9e04[p=0,l=361,c=8192,r=361]={<<<POST /query HTTP/...enceNumber":-1}>>>;","streamsProper...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} {} (org.eclipse.jetty.server.HttpConnection:367)
ksqldb-server1    | [2019-12-16 16:22:12,091] DEBUG parseNext s=START HeapByteBuffer@6caa9e04[p=0,l=361,c=8192,r=361]={<<<POST /query HTTP/...enceNumber":-1}>>>;","streamsProper...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} (org.eclipse.jetty.http.HttpParser:1450)
ksqldb-server1    | [2019-12-16 16:22:12,091] DEBUG START --> SPACE1 (org.eclipse.jetty.http.HttpParser:1832)
ksqldb-server1    | [2019-12-16 16:22:12,091] DEBUG SPACE1 --> URI (org.eclipse.jetty.http.HttpParser:1832)
ksqldb-server1    | [2019-12-16 16:22:12,091] DEBUG URI --> SPACE2 (org.eclipse.jetty.http.HttpParser:1832)
ksqldb-server1    | [2019-12-16 16:22:12,091] DEBUG SPACE2 --> REQUEST_VERSION (org.eclipse.jetty.http.HttpParser:1832)
ksqldb-server1    | [2019-12-16 16:22:12,092] DEBUG REQUEST_VERSION --> HEADER (org.eclipse.jetty.http.HttpParser:1832)
ksqldb-server1    | [2019-12-16 16:22:12,091] DEBUG Key interests updated 1 -> 0 on NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=-,to=3/30000}{io=0/0,kio=0,kro=1}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=0,c=false,c=false/false,a=IDLE,uri=null,age=0} (org.eclipse.jetty.io.ChannelEndPoint:384)
ksqldb-server1    | [2019-12-16 16:22:12,092] DEBUG HEADER:Content-Type: application/json --> IN_VALUE (org.eclipse.jetty.http.HttpParser:1839)
ksqldb-server1    | [2019-12-16 16:22:12,094] DEBUG HEADER:Content-Type: application/json --> FIELD (org.eclipse.jetty.http.HttpParser:1839)
ksqldb-server1    | [2019-12-16 16:22:12,094] DEBUG HEADER:User-Agent --> VALUE (org.eclipse.jetty.http.HttpParser:1839)
ksqldb-server1    | [2019-12-16 16:22:12,094] DEBUG HEADER:User-Agent --> IN_VALUE (org.eclipse.jetty.http.HttpParser:1839)
ksqldb-server1    | [2019-12-16 16:22:12,094] DEBUG HEADER:User-Agent --> FIELD (org.eclipse.jetty.http.HttpParser:1839)
ksqldb-server1    | [2019-12-16 16:22:12,094] DEBUG HEADER:Host --> VALUE (org.eclipse.jetty.http.HttpParser:1839)
ksqldb-server1    | [2019-12-16 16:22:12,094] DEBUG HEADER:Host --> IN_VALUE (org.eclipse.jetty.http.HttpParser:1839)
ksqldb-server1    | [2019-12-16 16:22:12,095] DEBUG HEADER:Host --> FIELD (org.eclipse.jetty.http.HttpParser:1839)
ksqldb-server1    | [2019-12-16 16:22:12,094] DEBUG Selector sun.nio.ch.EPollSelectorImpl@15325bcb waiting with 1 keys (org.eclipse.jetty.io.ManagedSelector:465)
ksqldb-server1    | [2019-12-16 16:22:12,096] DEBUG HEADER:Accept --> VALUE (org.eclipse.jetty.http.HttpParser:1839)
ksqldb-server1    | [2019-12-16 16:22:12,096] DEBUG HEADER:Accept --> IN_VALUE (org.eclipse.jetty.http.HttpParser:1839)
ksqldb-server1    | [2019-12-16 16:22:12,096] DEBUG HEADER:Accept --> FIELD (org.eclipse.jetty.http.HttpParser:1839)
ksqldb-server1    | [2019-12-16 16:22:12,097] DEBUG HEADER:Connection: keep-alive --> IN_VALUE (org.eclipse.jetty.http.HttpParser:1839)
ksqldb-server1    | [2019-12-16 16:22:12,097] DEBUG HEADER:Connection: keep-alive --> FIELD (org.eclipse.jetty.http.HttpParser:1839)
ksqldb-server1    | [2019-12-16 16:22:12,098] DEBUG HEADER:Content-Length --> VALUE (org.eclipse.jetty.http.HttpParser:1839)
ksqldb-server1    | [2019-12-16 16:22:12,098] DEBUG HEADER:Content-Length --> IN_VALUE (org.eclipse.jetty.http.HttpParser:1839)
ksqldb-server1    | [2019-12-16 16:22:12,098] DEBUG HEADER:Content-Length --> FIELD (org.eclipse.jetty.http.HttpParser:1839)
ksqldb-server1    | [2019-12-16 16:22:12,099] DEBUG HEADER --> CONTENT (org.eclipse.jetty.http.HttpParser:1832)
ksqldb-server1    | [2019-12-16 16:22:12,099] DEBUG REQUEST for //ksqldb-server1:8088/query on HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=IDLE,uri=//ksqldb-server1:8088/query,age=0}
ksqldb-server1    | POST //ksqldb-server1:8088/query HTTP/1.1
ksqldb-server1    | Content-Type: application/json
ksqldb-server1    | User-Agent: Jersey/2.28 (HttpUrlConnection 1.8.0_222)
ksqldb-server1    | Host: ksqldb-server1:8088
ksqldb-server1    | Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2
ksqldb-server1    | Connection: keep-alive
ksqldb-server1    | Content-Length: 116
ksqldb-server1    |
ksqldb-server1    |  (org.eclipse.jetty.server.HttpChannel:712)
ksqldb-server1    | [2019-12-16 16:22:12,100] DEBUG HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=-,to=13/30000}{io=0/0,kio=0,kro=1}->HttpConnection@31181366[p=HttpParser{s=CONTENT,0 of 116},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=IDLE,uri=//ksqldb-server1:8088/query,age=1} parsed true HttpParser{s=CONTENT,0 of 116} (org.eclipse.jetty.server.HttpConnection:372)
ksqldb-server1    | [2019-12-16 16:22:12,101] DEBUG HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=IDLE,uri=//ksqldb-server1:8088/query,age=2} handle //ksqldb-server1:8088/query  (org.eclipse.jetty.server.HttpChannel:323)
ksqldb-server1    | [2019-12-16 16:22:12,101] DEBUG handling HttpChannelState@12e94cb9{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false} (org.eclipse.jetty.server.HttpChannelState:236)
ksqldb-server1    | [2019-12-16 16:22:12,101] DEBUG HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=DISPATCHED,uri=//ksqldb-server1:8088/query,age=2} action DISPATCH (org.eclipse.jetty.server.HttpChannel:337)
ksqldb-server1    | [2019-12-16 16:22:12,101] DEBUG REQUEST POST /query on HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=DISPATCHED,uri=//ksqldb-server1:8088/query,age=2} (org.eclipse.jetty.server.Server:483)
ksqldb-server1    | [2019-12-16 16:22:12,101] DEBUG GzipHandler@1ad777f{STARTED} handle Request(POST //ksqldb-server1:8088/query)@5658953a in null (org.eclipse.jetty.server.handler.gzip.GzipHandler:628)
ksqldb-server1    | [2019-12-16 16:22:12,102] DEBUG scope null||/query @ o.e.j.s.ServletContextHandler@1b822fcc{/,null,AVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:1126)
ksqldb-server1    | [2019-12-16 16:22:12,103] DEBUG context=||/query @ o.e.j.s.ServletContextHandler@1b822fcc{/,null,AVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:1202)
ksqldb-server1    | [2019-12-16 16:22:12,103] DEBUG SessionHandler.doScope (org.eclipse.jetty.server.session:1521)
ksqldb-server1    | [2019-12-16 16:22:12,103] DEBUG sessionHandler=org.eclipse.jetty.server.session.SessionHandler614580607==dftMaxIdleSec=-1 session=null (org.eclipse.jetty.server.session:1546)
ksqldb-server1    | [2019-12-16 16:22:12,104] DEBUG servlet ||/query -> default@5c13d641==org.eclipse.jetty.servlet.DefaultServlet,jsp=null,order=-1,inst=true,async=true (org.eclipse.jetty.servlet.ServletHandler:474)
ksqldb-server1    | [2019-12-16 16:22:12,104] DEBUG chain=org.glassfish.jersey.servlet.ServletContainer-7a56812e@7a56812e==org.glassfish.jersey.servlet.ServletContainer,inst=true,async=true->default@5c13d641==org.eclipse.jetty.servlet.DefaultServlet,jsp=null,order=-1,inst=true,async=true (org.eclipse.jetty.servlet.ServletHandler:522)
ksqldb-server1    | [2019-12-16 16:22:12,105] DEBUG call filter org.glassfish.jersey.servlet.ServletContainer-7a56812e@7a56812e==org.glassfish.jersey.servlet.ServletContainer,inst=true,async=true (org.eclipse.jetty.servlet.ServletHandler:1572)
ksqldb-server1    | [2019-12-16 16:22:12,120] DEBUG HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=-,to=33/30000}{io=0/0,kio=0,kro=1}->HttpConnection@31181366[p=HttpParser{s=CONTENT,0 of 116},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=DISPATCHED,uri=//ksqldb-server1:8088/query,age=21} parse HeapByteBuffer@6caa9e04[p=245,l=361,c=8192,r=116]={POST /query HTTP/...Length: 116\r\n\r\n<<<{"ksql":"select *...enceNumber":-1}>>>;","streamsProper...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} {} (org.eclipse.jetty.server.HttpConnection:367)
ksqldb-server1    | [2019-12-16 16:22:12,120] DEBUG parseNext s=CONTENT HeapByteBuffer@6caa9e04[p=245,l=361,c=8192,r=116]={POST /query HTTP/...Length: 116\r\n\r\n<<<{"ksql":"select *...enceNumber":-1}>>>;","streamsProper...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} (org.eclipse.jetty.http.HttpParser:1450)
ksqldb-server1    | [2019-12-16 16:22:12,120] DEBUG HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=DISPATCHED,uri=//ksqldb-server1:8088/query,age=21} onContent Content@23bea5ec{HeapByteBufferR@1d308195[p=245,l=361,c=8192,r=116]={POST /query HTTP/...Length: 116\r\n\r\n<<<{"ksql":"select *...enceNumber":-1}>>>;","streamsProper...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}} (org.eclipse.jetty.server.HttpChannel:720)
ksqldb-server1    | [2019-12-16 16:22:12,121] DEBUG HttpInputOverHTTP@f53364c[c=0,q=0,[0]=null,s=STREAM] addContent Content@23bea5ec{HeapByteBufferR@1d308195[p=245,l=361,c=8192,r=116]={POST /query HTTP/...Length: 116\r\n\r\n<<<{"ksql":"select *...enceNumber":-1}>>>;","streamsProper...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}} (org.eclipse.jetty.server.HttpInput:608)
ksqldb-server1    | [2019-12-16 16:22:12,122] DEBUG CONTENT --> END (org.eclipse.jetty.http.HttpParser:1832)
ksqldb-server1    | [2019-12-16 16:22:12,122] DEBUG HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=DISPATCHED,uri=//ksqldb-server1:8088/query,age=23} onContentComplete (org.eclipse.jetty.server.HttpChannel:728)
ksqldb-server1    | [2019-12-16 16:22:12,123] DEBUG HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=DISPATCHED,uri=//ksqldb-server1:8088/query,age=24} onRequestComplete (org.eclipse.jetty.server.HttpChannel:744)
ksqldb-server1    | [2019-12-16 16:22:12,124] DEBUG HttpInputOverHTTP@f53364c[c=0,q=1,[0]=EOF,s=STREAM] addContent EOF (org.eclipse.jetty.server.HttpInput:608)
ksqldb-server1    | [2019-12-16 16:22:12,125] DEBUG HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=-,to=38/30000}{io=0/0,kio=0,kro=1}->HttpConnection@31181366[p=HttpParser{s=END,116 of 116},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=DISPATCHED,uri=//ksqldb-server1:8088/query,age=25} parsed false HttpParser{s=END,116 of 116} (org.eclipse.jetty.server.HttpConnection:372)
ksqldb-server1    | [2019-12-16 16:22:12,125] DEBUG HttpInputOverHTTP@f53364c[c=116,q=1,[0]=EOF,s=STREAM] read 116 from Content@23bea5ec{HeapByteBufferR@1d308195[p=361,l=361,c=8192,r=0]={POST /query HTTP/...enceNumber":-1}<<<>>>;","streamsProper...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}} (org.eclipse.jetty.server.HttpInput:308)
ksqldb-server1    | [2019-12-16 16:22:12,126] DEBUG releaseRequestBuffer HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=-,to=40/30000}{io=0/0,kio=0,kro=1}->HttpConnection@31181366[p=HttpParser{s=END,116 of 116},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=DISPATCHED,uri=//ksqldb-server1:8088/query,age=27} (org.eclipse.jetty.server.HttpConnection:220)
ksqldb-server1    | [2019-12-16 16:22:12,172] DEBUG InitialContextFactory.getInitialContext() (org.eclipse.jetty.jndi.InitialContextFactory:77)
ksqldb-server1    | [2019-12-16 16:22:12,172] DEBUG Created initial context delegate for local namespace:org.eclipse.jetty.jndi.local.localContextRoot@42af2dd0 (org.eclipse.jetty.jndi.InitialContextFactory:81)
ksqldb-server1    | [2019-12-16 16:22:12,173] DEBUG >>> new root context requested  (org.eclipse.jetty.jndi.java.javaURLContextFactory:60)
ksqldb-server1    | [2019-12-16 16:22:12,174] DEBUG Looking up name="comp/DefaultManagedScheduledExecutorService" (org.eclipse.jetty.jndi.NamingContext:434)
ksqldb-server1    | [2019-12-16 16:22:12,175] DEBUG Trying thread context classloader (org.eclipse.jetty.jndi.ContextFactory:139)
ksqldb-server1    | [2019-12-16 16:22:12,176] DEBUG Looking up name="DefaultManagedScheduledExecutorService" (org.eclipse.jetty.jndi.NamingContext:434)
ksqldb-server1    | [2019-12-16 16:22:12,228] DEBUG org.eclipse.jetty.server.handler.gzip.GzipHttpOutputInterceptor@20ab6985 exclude by status 400 (org.eclipse.jetty.server.handler.gzip.GzipHttpOutputInterceptor:162)
ksqldb-server1    | [2019-12-16 16:22:12,228] DEBUG sendResponse info=null content=HeapByteBuffer@26aca3a6[p=0,l=209,c=32768,r=209]={<<<{"@type":"stateme...,"entities":[]}>>> PAGEVIEWS_ORIGIN...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} complete=false committing=true callback=Blocker@58937007{null} (org.eclipse.jetty.server.HttpChannel:831)
ksqldb-server1    | [2019-12-16 16:22:12,228] DEBUG COMMIT for /query on HttpChannelOverHttp@6ddde0d6{r=1,c=true,c=false/false,a=DISPATCHED,uri=//ksqldb-server1:8088/query,age=129}
ksqldb-server1    | 400 Bad Request HTTP/1.1
ksqldb-server1    | Date: Mon, 16 Dec 2019 16:22:12 GMT
ksqldb-server1    | Content-Type: application/vnd.ksql.v1+json
ksqldb-server1    |
ksqldb-server1    |  (org.eclipse.jetty.server.HttpChannel:887)
ksqldb-server1    | [2019-12-16 16:22:12,230] DEBUG org.eclipse.jetty.server.HttpConnection$SendCallback@43634dbb[PROCESSING][i=HTTP/1.1{s=400,h=2,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$SendCallback@2d3e3fe5] generate: NEED_HEADER (null,[p=0,l=209,c=32768,r=209],false)@START (org.eclipse.jetty.server.HttpConnection:745)
ksqldb-server1    | [2019-12-16 16:22:12,236] DEBUG generateHeaders HTTP/1.1{s=400,h=2,cl=-1} last=false content=HeapByteBuffer@26aca3a6[p=0,l=209,c=32768,r=209]={<<<{"@type":"stateme...,"entities":[]}>>> PAGEVIEWS_ORIGIN...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} (org.eclipse.jetty.http.HttpGenerator:598)
ksqldb-server1    | [2019-12-16 16:22:12,237] DEBUG Date: Mon, 16 Dec 2019 16:22:12 GMT
ksqldb-server1    | Content-Type: application/vnd.ksql.v1+json
ksqldb-server1    |
ksqldb-server1    |  (org.eclipse.jetty.http.HttpGenerator:599)
ksqldb-server1    | [2019-12-16 16:22:12,237] DEBUG CHUNKED_CONTENT (org.eclipse.jetty.http.HttpGenerator:770)
ksqldb-server1    | [2019-12-16 16:22:12,238] DEBUG org.eclipse.jetty.server.HttpConnection$SendCallback@43634dbb[PROCESSING][i=HTTP/1.1{s=400,h=2,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$SendCallback@2d3e3fe5] generate: FLUSH ([p=0,l=141,c=8192,r=141],[p=0,l=209,c=32768,r=209],false)@COMMITTED (org.eclipse.jetty.server.HttpConnection:745)
ksqldb-server1    | [2019-12-16 16:22:12,238] DEBUG write: WriteFlusher@56a29c86{IDLE}->null [HeapByteBuffer@6caa9e04[p=0,l=141,c=8192,r=141]={<<<HTTP/1.1 400 Bad ...chunked\r\n\r\nD1\r\n>>>t: text/html, ima...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@26aca3a6[p=0,l=209,c=32768,r=209]={<<<{"@type":"stateme...,"entities":[]}>>> PAGEVIEWS_ORIGIN...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}] (org.eclipse.jetty.io.WriteFlusher:270)
ksqldb-server1    | [2019-12-16 16:22:12,238] DEBUG update WriteFlusher@56a29c86{WRITING}->null:IDLE-->WRITING (org.eclipse.jetty.io.WriteFlusher:112)
ksqldb-server1    | [2019-12-16 16:22:12,239] DEBUG flushed 141 NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=W,to=153/30000}{io=0/0,kio=0,kro=1}->HttpConnection@31181366[p=HttpParser{s=END,116 of 116},g=HttpGenerator@412a31b7{s=COMMITTED}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=true,c=false/false,a=DISPATCHED,uri=//ksqldb-server1:8088/query,age=140} (org.eclipse.jetty.io.ChannelEndPoint:279)
ksqldb-server1    | [2019-12-16 16:22:12,240] DEBUG flushed 209 NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=W,to=0/30000}{io=0/0,kio=0,kro=1}->HttpConnection@31181366[p=HttpParser{s=END,116 of 116},g=HttpGenerator@412a31b7{s=COMMITTED}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=true,c=false/false,a=DISPATCHED,uri=//ksqldb-server1:8088/query,age=141} (org.eclipse.jetty.io.ChannelEndPoint:279)
ksqldb-server1    | [2019-12-16 16:22:12,241] DEBUG Flushed=true written=350 remaining=0 WriteFlusher@56a29c86{WRITING}->null (org.eclipse.jetty.io.WriteFlusher:427)
ksqldb-server1    | [2019-12-16 16:22:12,241] DEBUG update WriteFlusher@56a29c86{IDLE}->null:WRITING-->IDLE (org.eclipse.jetty.io.WriteFlusher:112)
ksqldb-server1    | [2019-12-16 16:22:12,247] DEBUG org.eclipse.jetty.server.HttpConnection$SendCallback@43634dbb[PROCESSING][i=HTTP/1.1{s=400,h=2,cl=-1},cb=org.eclipse.jetty.server.HttpChannel$SendCallback@2d3e3fe5] generate: DONE ([p=141,l=141,c=8192,r=0],[p=209,l=209,c=32768,r=0],false)@COMMITTED (org.eclipse.jetty.server.HttpConnection:745)
ksqldb-server1    | [2019-12-16 16:22:12,249] DEBUG sendResponse info=null content=HeapByteBuffer@1727a9c4[p=0,l=0,c=0,r=0]={<<<>>>} complete=false committing=false callback=Blocker@58937007{null} (org.eclipse.jetty.server.HttpChannel:831)
ksqldb-server1    | [2019-12-16 16:22:12,251] DEBUG sendResponse info=null content=HeapByteBuffer@1727a9c4[p=0,l=0,c=0,r=0]={<<<>>>} complete=false committing=false callback=Blocker@58937007{null} (org.eclipse.jetty.server.HttpChannel:831)
ksqldb-server1    | [2019-12-16 16:22:12,253] DEBUG FinalSession=null, old_session_handler=null, this=org.eclipse.jetty.server.session.SessionHandler614580607==dftMaxIdleSec=-1, calling complete=true (org.eclipse.jetty.server.session:1559)
ksqldb-server1    | [2019-12-16 16:22:12,254] DEBUG Complete called with session null (org.eclipse.jetty.server.session:410)
ksqldb-server1    | [2019-12-16 16:22:12,255] DEBUG handled=true async=false committed=true on HttpChannelOverHttp@6ddde0d6{r=1,c=true,c=false/false,a=DISPATCHED,uri=//ksqldb-server1:8088/query,age=156} (org.eclipse.jetty.server.Server:497)
ksqldb-server1    | [2019-12-16 16:22:12,255] DEBUG unhandle HttpChannelState@12e94cb9{s=DISPATCHED a=NOT_ASYNC i=true r=IDLE w=false} (org.eclipse.jetty.server.HttpChannelState:416)
ksqldb-server1    | [2019-12-16 16:22:12,255] DEBUG HttpChannelOverHttp@6ddde0d6{r=1,c=true,c=false/false,a=COMPLETING,uri=//ksqldb-server1:8088/query,age=156} action COMPLETE (org.eclipse.jetty.server.HttpChannel:337)
ksqldb-server1    | [2019-12-16 16:22:12,256] DEBUG sendResponse info=null content=HeapByteBuffer@1727a9c4[p=0,l=0,c=0,r=0]={<<<>>>} complete=true committing=false callback=Blocker@58937007{null} (org.eclipse.jetty.server.HttpChannel:831)
ksqldb-server1    | [2019-12-16 16:22:12,256] DEBUG org.eclipse.jetty.server.HttpConnection$SendCallback@43634dbb[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@1572cd1d] generate: CONTINUE (null,[p=0,l=0,c=0,r=0],true)@COMPLETING (org.eclipse.jetty.server.HttpConnection:745)
ksqldb-server1    | [2019-12-16 16:22:12,257] DEBUG org.eclipse.jetty.server.HttpConnection$SendCallback@43634dbb[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@1572cd1d] generate: NEED_CHUNK (null,[p=0,l=0,c=0,r=0],true)@COMPLETING (org.eclipse.jetty.server.HttpConnection:745)
ksqldb-server1    | [2019-12-16 16:22:12,257] DEBUG org.eclipse.jetty.server.HttpConnection$SendCallback@43634dbb[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@1572cd1d] generate: FLUSH (null,[p=0,l=0,c=0,r=0],true)@COMPLETING (org.eclipse.jetty.server.HttpConnection:745)
ksqldb-server1    | [2019-12-16 16:22:12,258] DEBUG write: WriteFlusher@56a29c86{IDLE}->null [HeapByteBuffer@469cfe98[p=0,l=7,c=1024,r=7]={<<<\r\n0\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}] (org.eclipse.jetty.io.WriteFlusher:270)
ksqldb-server1    | [2019-12-16 16:22:12,260] DEBUG update WriteFlusher@56a29c86{WRITING}->null:IDLE-->WRITING (org.eclipse.jetty.io.WriteFlusher:112)
ksqldb-server1    | [2019-12-16 16:22:12,262] DEBUG flushed 7 NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=W,to=20/30000}{io=0/0,kio=0,kro=1}->HttpConnection@31181366[p=HttpParser{s=END,116 of 116},g=HttpGenerator@412a31b7{s=COMPLETING}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=true,c=false/false,a=COMPLETING,uri=//ksqldb-server1:8088/query,age=163} (org.eclipse.jetty.io.ChannelEndPoint:279)
ksqldb-server1    | [2019-12-16 16:22:12,264] DEBUG Flushed=true written=7 remaining=0 WriteFlusher@56a29c86{WRITING}->null (org.eclipse.jetty.io.WriteFlusher:427)
ksqldb-server1    | [2019-12-16 16:22:12,265] DEBUG update WriteFlusher@56a29c86{IDLE}->null:WRITING-->IDLE (org.eclipse.jetty.io.WriteFlusher:112)
ksqldb-server1    | [2019-12-16 16:22:12,266] DEBUG org.eclipse.jetty.server.HttpConnection$SendCallback@43634dbb[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@1572cd1d] generate: DONE (null,[p=0,l=0,c=0,r=0],true)@END (org.eclipse.jetty.server.HttpConnection:745)
ksqldb-server1    | [2019-12-16 16:22:12,267] DEBUG onComplete HttpChannelState@12e94cb9{s=COMPLETING a=NOT_ASYNC i=false r=IDLE w=false} (org.eclipse.jetty.server.HttpChannelState:877)
ksqldb-server1    | [2019-12-16 16:22:12,268] DEBUG COMPLETE for /query written=209 (org.eclipse.jetty.server.HttpChannel:753)
ksqldb-server1    | [2019-12-16 16:22:12,269] INFO 172.31.0.6 - - [16/Dec/2019:16:22:12 +0000] "POST /query HTTP/1.1" 400 209  170 (io.confluent.rest-utils.requests:62)
ksqldb-server1    | [2019-12-16 16:22:12,270] DEBUG recycle HttpChannelState@12e94cb9{s=COMPLETED a=NOT_ASYNC i=false r=IDLE w=false} (org.eclipse.jetty.server.HttpChannelState:935)
ksqldb-server1    | [2019-12-16 16:22:12,270] DEBUG reset HttpParser{s=END,116 of 116} (org.eclipse.jetty.http.HttpParser:1811)
ksqldb-server1    | [2019-12-16 16:22:12,270] DEBUG END --> START (org.eclipse.jetty.http.HttpParser:1832)
ksqldb-server1    | [2019-12-16 16:22:12,271] DEBUG HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=IDLE,uri=null,age=0} handle exit, result COMPLETE (org.eclipse.jetty.server.HttpChannel:547)
ksqldb-server1    | [2019-12-16 16:22:12,272] DEBUG shutdownInput NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,OPEN,fill=-,flush=-,to=8/30000}{io=0/0,kio=0,kro=1}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=IDLE,uri=null,age=0} (org.eclipse.jetty.io.AbstractEndPoint:66)
ksqldb-server1    | [2019-12-16 16:22:12,272] DEBUG filled -1 HeapByteBuffer@6caa9e04[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 400 Bad ...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} (org.eclipse.jetty.io.ChannelEndPoint:250)
ksqldb-server1    | [2019-12-16 16:22:12,272] DEBUG atEOF HttpParser{s=START,0 of -1} (org.eclipse.jetty.http.HttpParser:1794)
ksqldb-server1    | [2019-12-16 16:22:12,272] DEBUG HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,ISHUT,fill=-,flush=-,to=8/30000}{io=0/0,kio=0,kro=1}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=IDLE,uri=null,age=0} filled -1 HeapByteBuffer@6caa9e04[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 400 Bad ...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} (org.eclipse.jetty.server.HttpConnection:350)
ksqldb-server1    | [2019-12-16 16:22:12,272] DEBUG HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,ISHUT,fill=-,flush=-,to=9/30000}{io=0/0,kio=0,kro=1}->HttpConnection@31181366[p=HttpParser{s=START,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=IDLE,uri=null,age=0} parse HeapByteBuffer@6caa9e04[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 400 Bad ...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} {} (org.eclipse.jetty.server.HttpConnection:367)
ksqldb-server1    | [2019-12-16 16:22:12,273] DEBUG parseNext s=START HeapByteBuffer@6caa9e04[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 400 Bad ...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} (org.eclipse.jetty.http.HttpParser:1450)
ksqldb-server1    | [2019-12-16 16:22:12,273] DEBUG START --> CLOSED (org.eclipse.jetty.http.HttpParser:1832)
ksqldb-server1    | [2019-12-16 16:22:12,274] DEBUG close NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,ISHUT,fill=-,flush=-,to=9/30000}{io=0/0,kio=0,kro=1}->HttpConnection@31181366[p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=IDLE,uri=null,age=0} (org.eclipse.jetty.io.AbstractEndPoint:174)
ksqldb-server1    | [2019-12-16 16:22:12,274] DEBUG close(null) NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,ISHUT,fill=-,flush=-,to=10/30000}{io=0/0,kio=0,kro=1}->HttpConnection@31181366[p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=IDLE,uri=null,age=0} (org.eclipse.jetty.io.AbstractEndPoint:181)
ksqldb-server1    | [2019-12-16 16:22:12,274] DEBUG doClose NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,CLOSED,fill=-,flush=-,to=11/30000}{io=0/0,kio=0,kro=1}->HttpConnection@31181366[p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=IDLE,uri=null,age=0} (org.eclipse.jetty.io.ChannelEndPoint:194)
ksqldb-server1    | [2019-12-16 16:22:12,275] DEBUG ignored: WriteFlusher@56a29c86{IDLE}->null (org.eclipse.jetty.io.WriteFlusher:490)
ksqldb-server1    | java.nio.channels.ClosedChannelException
ksqldb-server1    | 	at org.eclipse.jetty.io.WriteFlusher.onClose(WriteFlusher.java:521)
ksqldb-server1    | 	at org.eclipse.jetty.io.AbstractEndPoint.onClose(AbstractEndPoint.java:354)
ksqldb-server1    | 	at org.eclipse.jetty.io.ChannelEndPoint.onClose(ChannelEndPoint.java:214)
ksqldb-server1    | 	at org.eclipse.jetty.io.NetworkTrafficSelectChannelEndPoint.onClose(NetworkTrafficSelectChannelEndPoint.java:96)
ksqldb-server1    | 	at org.eclipse.jetty.io.AbstractEndPoint.doOnClose(AbstractEndPoint.java:225)
ksqldb-server1    | 	at org.eclipse.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:192)
ksqldb-server1    | 	at org.eclipse.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:175)
ksqldb-server1    | 	at org.eclipse.jetty.io.AbstractConnection.close(AbstractConnection.java:254)
ksqldb-server1    | 	at org.eclipse.jetty.server.HttpChannelOverHttp.earlyEOF(HttpChannelOverHttp.java:233)
ksqldb-server1    | 	at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1526)
ksqldb-server1    | 	at org.eclipse.jetty.server.HttpConnection.parseRequestBuffer(HttpConnection.java:369)
ksqldb-server1    | 	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:258)
ksqldb-server1    | 	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
ksqldb-server1    | 	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
ksqldb-server1    | 	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
ksqldb-server1    | 	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782)
ksqldb-server1    | 	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918)
ksqldb-server1    | 	at java.lang.Thread.run(Thread.java:748)
ksqldb-server1    | [2019-12-16 16:22:12,276] DEBUG onClose FillInterest@4373b214{null} (org.eclipse.jetty.io.FillInterest:147)
ksqldb-server1    | [2019-12-16 16:22:12,277] DEBUG Wakeup ManagedSelector@675d8c96{STARTED} id=0 keys=1 selected=0 updates=0 (org.eclipse.jetty.io.ManagedSelector:188)
ksqldb-server1    | [2019-12-16 16:22:12,278] DEBUG Selector sun.nio.ch.EPollSelectorImpl@15325bcb woken with none selected (org.eclipse.jetty.io.ManagedSelector:470)
ksqldb-server1    | [2019-12-16 16:22:12,279] DEBUG run org.eclipse.jetty.io.ManagedSelector$DestroyEndPoint@46011076 in QueuedThreadPool[qtp341853399]@146044d7{STARTED,8<=8<=200,i=2,r=4,q=0}[ReservedThreadExecutor@293d0107{s=1/4,p=0}] (org.eclipse.jetty.util.thread.QueuedThreadPool:917)
ksqldb-server1    | [2019-12-16 16:22:12,279] DEBUG Selector sun.nio.ch.EPollSelectorImpl@15325bcb woken up from select, 0/0/0 selected (org.eclipse.jetty.io.ManagedSelector:479)
ksqldb-server1    | [2019-12-16 16:22:12,279] DEBUG Destroyed NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,CLOSED,fill=-,flush=-,to=15/30000}{io=0/0,kio=-1,kro=-1}->HttpConnection@31181366[p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=IDLE,uri=null,age=0} (org.eclipse.jetty.io.ManagedSelector:954)
ksqldb-server1    | [2019-12-16 16:22:12,279] DEBUG Selector sun.nio.ch.EPollSelectorImpl@15325bcb processing 0 keys, 0 updates (org.eclipse.jetty.io.ManagedSelector:492)
ksqldb-server1    | [2019-12-16 16:22:12,280] DEBUG updateable 0 (org.eclipse.jetty.io.ManagedSelector:418)
ksqldb-server1    | [2019-12-16 16:22:12,281] DEBUG updates 0 (org.eclipse.jetty.io.ManagedSelector:447)
ksqldb-server1    | [2019-12-16 16:22:12,281] DEBUG Selector sun.nio.ch.EPollSelectorImpl@15325bcb waiting with 0 keys (org.eclipse.jetty.io.ManagedSelector:465)
ksqldb-server1    | [2019-12-16 16:22:12,280] DEBUG onClose HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,CLOSED,fill=-,flush=-,to=16/30000}{io=0/0,kio=-1,kro=-1}->HttpConnection@31181366[p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=IDLE,uri=null,age=0} (org.eclipse.jetty.io.AbstractConnection:225)
ksqldb-server1    | [2019-12-16 16:22:12,282] DEBUG ran org.eclipse.jetty.io.ManagedSelector$DestroyEndPoint@46011076 in QueuedThreadPool[qtp341853399]@146044d7{STARTED,8<=8<=200,i=2,r=4,q=0}[ReservedThreadExecutor@293d0107{s=1/4,p=0}] (org.eclipse.jetty.util.thread.QueuedThreadPool:920)
ksqldb-server1    | [2019-12-16 16:22:12,280] DEBUG queue org.eclipse.jetty.io.ManagedSelector$DestroyEndPoint@46011076 startThread=false (org.eclipse.jetty.util.thread.QueuedThreadPool:521)
ksqldb-server1    | [2019-12-16 16:22:12,285] DEBUG HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,CLOSED,fill=-,flush=-,to=21/30000}{io=0/0,kio=-1,kro=-1}->HttpConnection@31181366[p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=IDLE,uri=null,age=0} parsed false HttpParser{s=CLOSED,0 of -1} (org.eclipse.jetty.server.HttpConnection:372)
ksqldb-server1    | [2019-12-16 16:22:12,285] DEBUG releaseRequestBuffer HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,CLOSED,fill=-,flush=-,to=21/30000}{io=0/0,kio=-1,kro=-1}->HttpConnection@31181366[p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=IDLE,uri=null,age=0} (org.eclipse.jetty.server.HttpConnection:220)
ksqldb-server1    | [2019-12-16 16:22:12,286] DEBUG shutdownOutput NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,CLOSED,fill=-,flush=-,to=22/30000}{io=0/0,kio=-1,kro=-1}->HttpConnection@31181366[p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=IDLE,uri=null,age=0} (org.eclipse.jetty.io.AbstractEndPoint:120)
ksqldb-server1    | [2019-12-16 16:22:12,286] DEBUG HttpConnection@31181366::NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,CLOSED,fill=-,flush=-,to=22/30000}{io=0/0,kio=-1,kro=-1}->HttpConnection@31181366[p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=IDLE,uri=null,age=0} onFillable exit HttpChannelState@12e94cb9{s=IDLE a=NOT_ASYNC i=true r=IDLE w=false} null (org.eclipse.jetty.server.HttpConnection:301)
ksqldb-server1    | [2019-12-16 16:22:12,288] DEBUG ran CEP:NetworkTrafficSelectChannelEndPoint@4676c694{/172.31.0.6:56538<->/172.31.0.5:8088,CLOSED,fill=-,flush=-,to=23/30000}{io=0/0,kio=-1,kro=-1}->HttpConnection@31181366[p=HttpParser{s=CLOSED,0 of -1},g=HttpGenerator@412a31b7{s=START}]=>HttpChannelOverHttp@6ddde0d6{r=1,c=false,c=false/false,a=IDLE,uri=null,age=0}:runFillable:BLOCKING in QueuedThreadPool[qtp341853399]@146044d7{STARTED,8<=8<=200,i=3,r=4,q=0}[ReservedThreadExecutor@293d0107{s=1/4,p=0}] (org.eclipse.jetty.util.thread.QueuedThreadPool:920)
@apurvam
Copy link
Contributor

apurvam commented Dec 16, 2019

@AlanConfluent is this something you are already looking at?

@vinothchandar
Copy link
Contributor

#4151 is what @AlanConfluent was hitting. @mikebin Will triage.

@vinothchandar vinothchandar added this to the 0.7.0 milestone Dec 17, 2019
@AlanConfluent
Copy link
Member

Yes, I have been looking into this. I'm not sure I've witnessed sporadic failures with the error message above. What I've seen is that it's hard to setup the environment correctly such that each node can issue requests to other nodes (which own a given rowkey). When they cannot, I've seen errors similar to the above. One question I have: Can you run a CLI (bin/ksql <ip>:8088) from one ksql node, pointing to another? This is equivalent to the types of proxy calls it does.

There are certain sporadic issued I've seen when rebalancing occurs, but I've witnessed empty results, not errors.

@mikebin
Copy link
Author

mikebin commented Dec 17, 2019

@big-andy-coates did some investigation on the issue above, and determined the following:

The issue is its using localhost for the url for proxying

@AlanConfluent
Copy link
Member

Ah, yes, sorry forgot to mention that too. I wrote a fix for the above hardcoded localhost issue as well. I'll create a PR for that soon.

@big-andy-coates big-andy-coates self-assigned this Dec 18, 2019
@big-andy-coates
Copy link
Contributor

I've got fixes for these three related issues...

big-andy-coates added a commit to big-andy-coates/ksql that referenced this issue Dec 18, 2019
Fixes: confluentinc#4142
Fixes: confluentinc#4151
Fixes: confluentinc#4152

Introduces a new `inter.node.listener` that can be used to specify a URL that the node can be contacted on by other nodes.  This can be different to the listeners defined in `listeners`. This can be required if `listeners` is set to a wildcard address, i.e. IPv4 `0.0.0.0` or IPv6 `[::]`, or if the node sits behind network infrastructure that requires other nodes to reach it using a different URL.

If `inter.node.listener` is not set it still defaults to the first listener in `listener` config. However, it now replaces an wildcard address with `localHost`. This means inter-node comms is still possible for nodes running on the same host.

Warnings are logged if the inter-node listener resolves to a loopback or local address.
big-andy-coates added a commit that referenced this issue Dec 20, 2019
* fix: pull queries should work across nodes

Fixes: #4142
Fixes: #4151
Fixes: #4152

Introduces a new `inter.node.listener` that can be used to specify a URL that the node can be contacted on by other nodes.  This can be different to the listeners defined in `listeners`. This can be required if `listeners` is set to a wildcard address, i.e. IPv4 `0.0.0.0` or IPv6 `[::]`, or if the node sits behind network infrastructure that requires other nodes to reach it using a different URL.

If `inter.node.listener` is not set it still defaults to the first listener in `listener` config. However, it now replaces an wildcard address with `localHost`. This means inter-node comms is still possible for nodes running on the same host.

Warnings are logged if the inter-node listener resolves to a loopback or local address.
big-andy-coates added a commit to big-andy-coates/ksql that referenced this issue Jan 10, 2020
Backport of confluentinc#4169

Fixes: confluentinc#4142
Fixes: confluentinc#4151
Fixes: confluentinc#4152

Introduces a new `inter.node.listener` that can be used to specify a URL that the node can be contacted on by other nodes.  This can be different to the listeners defined in `listeners`. This can be required if `listeners` is set to a wildcard address, i.e. IPv4 `0.0.0.0` or IPv6 `[::]`, or if the node sits behind network infrastructure that requires other nodes to reach it using a different URL.

If `inter.node.listener` is not set it still defaults to the first listener in `listener` config. However, it now replaces an wildcard address with `localHost`. This means inter-node comms is still possible for nodes running on the same host.

Warnings are logged if the inter-node listener resolves to a loopback or local address.

(cherry picked from commit 0ac71cf)
big-andy-coates added a commit that referenced this issue Jan 26, 2020
Backport of #4169

Fixes: #4142
Fixes: #4151
Fixes: #4152

Introduces a new `inter.node.listener` that can be used to specify a URL that the node can be contacted on by other nodes.  This can be different to the listeners defined in `listeners`. This can be required if `listeners` is set to a wildcard address, i.e. IPv4 `0.0.0.0` or IPv6 `[::]`, or if the node sits behind network infrastructure that requires other nodes to reach it using a different URL.

If `inter.node.listener` is not set it still defaults to the first listener in `listener` config. However, it now replaces an wildcard address with `localHost`. This means inter-node comms is still possible for nodes running on the same host.

Warnings are logged if the inter-node listener resolves to a loopback or local address.

(cherry picked from commit 0ac71cf)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants