This message was deleted.
# troubleshooting
s
This message was deleted.
j
it seems like if the lookup takes long to get registered for some more realtime intervals?
v
is this kafka ingest and is 2023-02-27T105403Z/2023-02-27T112403Z currentky being ingested?
j
it is kinesis ingest and yes, it should be ingested however I would need to double check
would it give that exception tho? instead of empty data?
v
it may be that the lookup is not loaded on the workers. can you look at the kinesis supervisor and task logs and see if there are nay messages about this lookup?
j
I have couple of lookups that connects to postgresql and from the logs I can see:
Copy code
2023-02-27T12:07:01,561 WARN [qtp1679714298-135] org.apache.druid.query.lookup.LookupUtils - Lookup [zip_to_country] could not be serialized properly. Please check its configuration. Error: Cannot construct instance of `org.apache.druid.query.lookup.namespace.JdbcExtractionNamespace`, problem: java.lang.ClassNotFoundException: org.postgresql.Driver
 at [Source: (byte[])":)
��versionW2023-02-23T18:11:40.729Z�lookupExtractorFactory��typeNcachedNamespace�extractionNamespace�BCjdbc�connectorConfig��connectURI�jdbc:<postgresql://test-db.wddrr5tyuj9o.us-east-1.rds.amazonaws.com:5432/analytics>��userJtestuser�password12345�createTables"��keyColumnXzip_key�tableXref_zip_to_country�valueColumnCname�tsColumnNlast_updated_at�pollPeriodBP1D�namespaceTzip_to_country��injective#��"; line: -1, column: 452] (through reference chain: org.apache.druid.query.lookup.LookupExtractorFactoryContainer["lookupExtractorFactory"]->org.apache.druid.query.lookup.NamespaceLookupExtractorFactory["extractionNamespace"])
2023-02-27T12:07:01,562 WARN [qtp1679714298-135] org.apache.druid.query.lookup.LookupUtils - Lookup [geo_to_city] could not be serialized properly. Please check its configuration. Error: Cannot construct instance of `org.apache.druid.query.lookup.namespace.JdbcExtractionNamespace`, problem: java.lang.ClassNotFoundException: org.postgresql.Driver
 at [Source: (byte[])":)
��versionW2023-02-23T18:08:26.770Z�lookupExtractorFactory��typeNcachedNamespace�extractionNamespace�BCjdbc�namespaceLgeo_to_city�connectorConfig��connectURI�jdbc:<postgresql://db-lookups.cluster-wddrr5tyuj9o.us-east-1.rds.amazonaws.com:5432/lookups>��userJtestuser�password12345��tableLgeo_to_city�keyColumnFuser_id�valueColumnDemail�pollPeriodBP1D�tsColumnAts��firstCacheTimeout��injective#��"; line: -1, column: 388] (through reference chain: org.apache.druid.query.lookup.LookupExtractorFactoryContainer["lookupExtractorFactory"]->org.apache.druid.query.lookup.NamespaceLookupExtractorFactory["extractionNamespace"])
2023-02-27T12:07:01,563 WARN [qtp1679714298-135] org.apache.druid.query.lookup.LookupUtils - Lookup [test] could not be serialized properly. Please check its configuration. Error: Cannot construct instance of `org.apache.druid.query.lookup.namespace.JdbcExtractionNamespace`, problem: java.lang.ClassNotFoundException: org.postgresql.Driver
 at [Source: (byte[])":)
��versionW2023-02-23T18:09:27.119Z�lookupExtractorFactory��typeNcachedNamespace�extractionNamespace�BCjdbc�namespaceItest�connectorConfig��connectURI�jdbc:<postgresql://test-db.wddrr5tyuj9o.us-east-1.rds.amazonaws.com:5432/analytics>��userJtestuser�password12345��tableSref_test�keyColumnBhex�valueColumnCtext�pollPeriodBP1D��firstCacheTimeout��injective"��"; line: -1, column: 375] (through reference chain: org.apache.druid.query.lookup.LookupExtractorFactoryContainer["lookupExtractorFactory"]->org.apache.druid.query.lookup.NamespaceLookupExtractorFactory["extractionNamespace"])
2023-02-27T12:07:01,564 WARN [qtp1679714298-135] org.apache.druid.query.lookup.LookupUtils - Lookup [id_to_email] could not be serialized properly. Please check its configuration. Error: Cannot construct instance of `org.apache.druid.query.lookup.namespace.JdbcExtractionNamespace`, problem: java.lang.ClassNotFoundException: org.postgresql.Driver
 at [Source: (byte[])":)
��versionW2023-02-23T18:08:07.423Z�lookupExtractorFactory��typeNcachedNamespace�extractionNamespace�BCjdbc�namespaceTid_to_email�connectorConfig��connectURI�jdbc:<postgresql://db-lookups.cluster-wddrr5tyuj9o.us-east-1.rds.amazonaws.com:5432/lookups>��userJtestuser�password12345��tableTid_to_email�keyColumnIpid�valueColumnDemail�pollPeriodBP1D�tsColumnAts��firstCacheTimeout��injective#��"; line: -1, column: 407] (through reference chain: org.apache.druid.query.lookup.LookupExtractorFactoryContainer["lookupExtractorFactory"]->org.apache.druid.query.lookup.NamespaceLookupExtractorFactory["extractionNamespace"])
2023-02-27T12:07:01,586 DEBUG [qtp1679714298-135] org.apache.druid.jetty.RequestLog - 10.5.137.163 POST //10.5.149.74:8105/druid/listen/v1/lookups/updates HTTP/1.1 202
however if I go to lookups section in the unified console, I can see the lookups and fetch the data without errors
v
what logs are these?
do you have the postgresql-metadata-storage extension added in the extension load list for the historicals?
j
logs are from one random index_kinesis task
and about the extensions:
Copy code
{
  "version": "25.0.0",
  "modules": [
    {
      "name": "org.apache.druid.common.aws.AWSModule",
      "artifact": "druid-aws-common",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.common.gcp.GcpModule",
      "artifact": "druid-gcp-common",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.query.aggregation.histogram.ApproximateHistogramDruidModule",
      "artifact": "druid-histogram",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.query.aggregation.datasketches.theta.SketchModule",
      "artifact": "druid-datasketches",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.query.aggregation.datasketches.theta.oldapi.OldApiSketchModule",
      "artifact": "druid-datasketches",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.query.aggregation.datasketches.quantiles.DoublesSketchModule",
      "artifact": "druid-datasketches",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.query.aggregation.datasketches.tuple.ArrayOfDoublesSketchModule",
      "artifact": "druid-datasketches",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.query.aggregation.datasketches.hll.HllSketchModule",
      "artifact": "druid-datasketches",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.query.aggregation.datasketches.kll.KllSketchModule",
      "artifact": "druid-datasketches",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.metadata.storage.postgresql.PostgreSQLMetadataStorageModule",
      "artifact": "postgresql-metadata-storage",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.indexing.kinesis.KinesisIndexingServiceModule",
      "artifact": "druid-kinesis-indexing-service",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.data.input.parquet.ParquetExtensionsModule",
      "artifact": "druid-parquet-extensions",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.security.basic.BasicSecurityDruidModule",
      "artifact": "druid-basic-security",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.storage.s3.output.S3StorageConnectorModule",
      "artifact": "druid-s3-extensions",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.storage.s3.S3StorageDruidModule",
      "artifact": "druid-s3-extensions",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.firehose.s3.S3FirehoseDruidModule",
      "artifact": "druid-s3-extensions",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.data.input.s3.S3InputSourceDruidModule",
      "artifact": "druid-s3-extensions",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.indexing.kafka.KafkaIndexTaskModule",
      "artifact": "druid-kafka-indexing-service",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.emitter.statsd.StatsDEmitterModule",
      "artifact": "statsd-emitter",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.data.input.avro.AvroExtensionsModule",
      "artifact": "druid-avro-extensions",
      "version": "25.0.0"
    },
    {
      "name": "org.apache.druid.server.lookup.namespace.NamespaceExtractionModule",
      "artifact": "druid-lookups-cached-global",
      "version": "25.0.0"
    }
  ],
  "memory": {
    "maxMemory": 1572864000,
    "totalMemory": 1572864000,
    "freeMemory": 1035019832,
    "usedMemory": 537844168,
    "directMemory": 134217728
  }
}
v
ok...it seems that the worker is not loading the postgres driver.
Can you paste the common run time properties here? Specifically from the node running the worker with the error in the log
j
gathering them, in the meantime, logs from the peon:
Copy code
2023-02-27T12:06:38,482 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-histogram], jars: druid-histogram-25.0.0.jar
2023-02-27T12:06:38,483 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-datasketches], jars: commons-math3-3.6.1.jar, druid-datasketches-25.0.0.jar
2023-02-27T12:06:38,484 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [postgresql-metadata-storage], jars: checker-qual-3.5.0.jar, postgresql-42.4.1.jar, postgresql-metadata-storage-25.0.0.jar
2023-02-27T12:06:38,486 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-kinesis-indexing-service], jars: amazon-kinesis-client-1.14.4.jar, aws-java-sdk-kinesis-1.12.317.jar, aws-java-sdk-sts-1.12.317.jar, commons-lang3-3.12.0.jar, commons-logging-1.1.1.jar, druid-kinesis-indexing-service-25.0.0.jar, guava-16.0.1.jar, jmespath-java-1.12.317.jar, protobuf-java-3.21.7.jar
2023-02-27T12:06:38,489 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-parquet-extensions], jars: audience-annotations-0.12.0.jar, avro-1.9.2.jar, commons-configuration-1.6.jar, druid-parquet-extensions-25.0.0.jar, hadoop-annotations-2.8.5.jar, hadoop-auth-2.8.5.jar, hadoop-common-2.8.5.jar, hadoop-hdfs-client-2.8.5.jar, hadoop-mapreduce-client-core-2.8.5.jar, htrace-core4-4.0.1-incubating.jar, jackson-core-asl-1.9.13.jar, jackson-mapper-asl-1.9.13.jar, javax.annotation-api-1.3.2.jar, parquet-avro-1.12.0.jar, parquet-column-1.12.0.jar, parquet-common-1.12.0.jar, parquet-encoding-1.12.0.jar, parquet-format-structures-1.12.0.jar, parquet-hadoop-1.12.0.jar, parquet-jackson-1.12.0.jar, slf4j-api-1.7.36.jar, snappy-java-1.1.8.4.jar, zstd-jni-1.5.2-3.jar
2023-02-27T12:06:38,494 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-basic-security], jars: druid-basic-security-25.0.0.jar
2023-02-27T12:06:38,495 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-s3-extensions], jars: aws-java-sdk-core-1.12.317.jar, aws-java-sdk-sts-1.12.317.jar, commons-codec-1.13.jar, commons-logging-1.1.1.jar, druid-s3-extensions-25.0.0.jar, httpclient-4.5.13.jar, httpcore-4.4.11.jar, ion-java-1.0.2.jar, jackson-dataformat-cbor-2.10.5.jar, jmespath-java-1.12.317.jar, joda-time-2.10.5.jar
2023-02-27T12:06:38,498 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-kafka-indexing-service], jars: druid-kafka-indexing-service-25.0.0.jar, kafka-clients-3.3.1.jar, lz4-java-1.8.0.jar, snappy-java-1.1.8.4.jar, zstd-jni-1.5.2-3.jar
2023-02-27T12:06:38,500 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [statsd-emitter], jars: asm-9.3.jar, asm-analysis-7.1.jar, asm-commons-9.3.jar, asm-tree-7.1.jar, asm-util-7.1.jar, java-dogstatsd-client-4.0.0.jar, jffi-1.2.23-native.jar, jffi-1.2.23.jar, jnr-a64asm-1.0.0.jar, jnr-constants-0.9.17.jar, jnr-enxio-0.30.jar, jnr-ffi-2.1.16.jar, jnr-posix-3.0.61.jar, jnr-unixsocket-0.36.jar, jnr-x86asm-1.0.2.jar, statsd-emitter-25.0.0.jar
2023-02-27T12:06:38,503 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-avro-extensions], jars: avro-1.9.2.jar, avro-ipc-1.9.2.jar, avro-ipc-jetty-1.9.2.jar, avro-mapred-1.9.2.jar, common-config-5.5.1.jar, common-utils-5.5.1.jar, druid-avro-extensions-25.0.0.jar, gson-2.3.1.jar, jakarta.activation-1.2.1.jar, jakarta.annotation-api-1.3.5.jar, jakarta.inject-2.6.1.jar, javax.annotation-api-1.3.2.jar, jersey-client-1.19.4.jar, jersey-common-2.30.jar, kafka-clients-5.5.1-ccs.jar, kafka-schema-registry-client-5.5.1.jar, lz4-java-1.8.0.jar, osgi-resource-locator-1.0.3.jar, schema-repo-api-0.1.3.jar, schema-repo-avro-0.1.3.jar, schema-repo-client-0.1.3.jar, schema-repo-common-0.1.3.jar, slf4j-api-1.7.36.jar, snappy-java-1.1.8.4.jar, swagger-annotations-1.6.0.jar, velocity-engine-core-2.2.jar, zstd-jni-1.5.2-3.jar
2023-02-27T12:06:38,507 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-lookups-cached-global], jars: druid-lookups-cached-global-25.0.0.jar, mapdb-1.0.8.jar
[1.302s][info   ][gc] GC(5) Pause Young (Normal) (G1 Evacuation Pause) 55M->20M(768M) 5.588ms
2023-02-27T12:06:38,692 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-histogram], jars: druid-histogram-25.0.0.jar
2023-02-27T12:06:38,694 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-datasketches], jars: commons-math3-3.6.1.jar, druid-datasketches-25.0.0.jar
2023-02-27T12:06:38,700 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [postgresql-metadata-storage], jars: checker-qual-3.5.0.jar, postgresql-42.4.1.jar, postgresql-metadata-storage-25.0.0.jar
2023-02-27T12:06:38,702 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-kinesis-indexing-service], jars: amazon-kinesis-client-1.14.4.jar, aws-java-sdk-kinesis-1.12.317.jar, aws-java-sdk-sts-1.12.317.jar, commons-lang3-3.12.0.jar, commons-logging-1.1.1.jar, druid-kinesis-indexing-service-25.0.0.jar, guava-16.0.1.jar, jmespath-java-1.12.317.jar, protobuf-java-3.21.7.jar
2023-02-27T12:06:38,703 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-parquet-extensions], jars: audience-annotations-0.12.0.jar, avro-1.9.2.jar, commons-configuration-1.6.jar, druid-parquet-extensions-25.0.0.jar, hadoop-annotations-2.8.5.jar, hadoop-auth-2.8.5.jar, hadoop-common-2.8.5.jar, hadoop-hdfs-client-2.8.5.jar, hadoop-mapreduce-client-core-2.8.5.jar, htrace-core4-4.0.1-incubating.jar, jackson-core-asl-1.9.13.jar, jackson-mapper-asl-1.9.13.jar, javax.annotation-api-1.3.2.jar, parquet-avro-1.12.0.jar, parquet-column-1.12.0.jar, parquet-common-1.12.0.jar, parquet-encoding-1.12.0.jar, parquet-format-structures-1.12.0.jar, parquet-hadoop-1.12.0.jar, parquet-jackson-1.12.0.jar, slf4j-api-1.7.36.jar, snappy-java-1.1.8.4.jar, zstd-jni-1.5.2-3.jar
2023-02-27T12:06:38,705 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-basic-security], jars: druid-basic-security-25.0.0.jar
2023-02-27T12:06:38,706 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-s3-extensions], jars: aws-java-sdk-core-1.12.317.jar, aws-java-sdk-sts-1.12.317.jar, commons-codec-1.13.jar, commons-logging-1.1.1.jar, druid-s3-extensions-25.0.0.jar, httpclient-4.5.13.jar, httpcore-4.4.11.jar, ion-java-1.0.2.jar, jackson-dataformat-cbor-2.10.5.jar, jmespath-java-1.12.317.jar, joda-time-2.10.5.jar
2023-02-27T12:06:38,708 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-kafka-indexing-service], jars: druid-kafka-indexing-service-25.0.0.jar, kafka-clients-3.3.1.jar, lz4-java-1.8.0.jar, snappy-java-1.1.8.4.jar, zstd-jni-1.5.2-3.jar
2023-02-27T12:06:38,710 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [statsd-emitter], jars: asm-9.3.jar, asm-analysis-7.1.jar, asm-commons-9.3.jar, asm-tree-7.1.jar, asm-util-7.1.jar, java-dogstatsd-client-4.0.0.jar, jffi-1.2.23-native.jar, jffi-1.2.23.jar, jnr-a64asm-1.0.0.jar, jnr-constants-0.9.17.jar, jnr-enxio-0.30.jar, jnr-ffi-2.1.16.jar, jnr-posix-3.0.61.jar, jnr-unixsocket-0.36.jar, jnr-x86asm-1.0.2.jar, statsd-emitter-25.0.0.jar
2023-02-27T12:06:38,711 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-avro-extensions], jars: avro-1.9.2.jar, avro-ipc-1.9.2.jar, avro-ipc-jetty-1.9.2.jar, avro-mapred-1.9.2.jar, common-config-5.5.1.jar, common-utils-5.5.1.jar, druid-avro-extensions-25.0.0.jar, gson-2.3.1.jar, jakarta.activation-1.2.1.jar, jakarta.annotation-api-1.3.5.jar, jakarta.inject-2.6.1.jar, javax.annotation-api-1.3.2.jar, jersey-client-1.19.4.jar, jersey-common-2.30.jar, kafka-clients-5.5.1-ccs.jar, kafka-schema-registry-client-5.5.1.jar, lz4-java-1.8.0.jar, osgi-resource-locator-1.0.3.jar, schema-repo-api-0.1.3.jar, schema-repo-avro-0.1.3.jar, schema-repo-client-0.1.3.jar, schema-repo-common-0.1.3.jar, slf4j-api-1.7.36.jar, snappy-java-1.1.8.4.jar, swagger-annotations-1.6.0.jar, velocity-engine-core-2.2.jar, zstd-jni-1.5.2-3.jar
2023-02-27T12:06:38,712 INFO [main] org.apache.druid.guice.ExtensionsLoader - Loading extension [druid-lookups-cached-global], jars: druid-lookups-cached-global-25.0.0.jar, mapdb-1.0.8.jar
v
I see the following in the docs
Copy code
If using JDBC, you will need to add your database's client JAR files to the extension's directory. For Postgres, the connector JAR is already included. See the MySQL extension documentation for instructions to obtain MySQL or MariaDB connector libraries. The connector JAR should reside in the classpath of Druid's main class loader. To add the connector JAR to the classpath, you can copy the downloaded file to lib/ under the distribution root directory. Alternatively, create a symbolic link to the connector in the lib directory.
can you copy the postgresql-42.4.1.jar from extesnions/postgresql-metadata-storage to lib and check?
j
hmm I think I know where the problem is, I have deployed it in k8s by using pulumi and I have following transformation to copy the jar:
Copy code
// Copy postgresql driver to lib
                if (obj.kind === 'Deployment' && (
                    obj.metadata.name === 'druid-' + clusterName + '-coordinator' ||
                    obj.metadata.name === 'druid-' + clusterName + '-router' ||
                    obj.metadata.name === 'druid-' + clusterName + '-broker'
                )) {
                    const lifecycle: k8sInputs.core.v1.Lifecycle = {
                        postStart: {
                            exec: {
                                command: [
                                    '/bin/sh',
                                    '-c',
                                    'cp /opt/druid/extensions/postgresql-metadata-storage/postgresql-42.4.1.jar /opt/druid/lib/ && cd -',
                                ]
                            }
                        }
                    }
                    obj.spec.template.spec.containers[0].lifecycle = lifecycle
                }
it looks like I only copied to deployments and thats why it works in druid unified console but it does not in middlemanager because they are StatefulSets
however not sure why it worked for some other intervals..
v
if the interval has no data in the worker (data already in historical) then the query won't go to the worker at all
j
all right so thats why for some other intervals will work
updated statefulsets and now works perfectly
b
wow, nice!
j
it looks like I keep getting following errors in broker when queries sent via API to druid
Copy code
2023-02-28T13:01:12,511 INFO [qtp1333929103-165[groupBy_[test_data]_7013cfd7-0a11-42d0-b859-bf655a6f46c1]] org.apache.druid.server.log.LoggingRequestLogger - 2023-02-28T13:01:12.450Z    10.5.189.1    {"queryType":"groupBy","dataSource":{"type":"table","name":"test_data"},"intervals":{"type":"LegacySegmentSpec","intervals":["2023-02-28T12:31:10.000Z/2023-02-28T13:01:10.000Z"]},"filter":{"type":"and","fields":[{"type":"selector","dimension":"id","value":"12345"}]},"granularity":{"type":"all"},"dimensions":[{"type":"default","dimension":"to","outputName":"address","outputType":"STRING"},{"type":"default","dimension":"net","outputName":"net","outputType":"STRING"},{"type":"lookup","dimension":"test","outputName":"test","lookup":null,"retainMissingValue":false,"replaceMissingValueWith":"unknown test","name":"test_lookup","optimize":true}],"aggregations":[{"type":"doubleSum","name":"count","fieldName":"count"}],"limitSpec":{"type":"default","columns":[{"dimension":"address","direction":"descending","dimensionOrder":{"type":"lexicographic"}}],"limit":100},"context":{"priority":"100","queryId":"7013cfd7-0a11-42d0-b859-bf655a6f46c1","sqlQueryId":"3267738187128657978_timeseries_count_all_30m"}}    {"query/time":61,"query/bytes":-1,"success":false,"identity":"test_analytics","exception":"QueryInterruptedException{msg=Lookup [test_lookup] not found, code=Unknown exception, class=org.apache.druid.java.util.common.ISE, host=10.5.138.26:8106}","interrupted":true,"reason":"QueryInterruptedException{msg=Lookup [test_lookup] not found, code=Unknown exception, class=org.apache.druid.java.util.common.ISE, host=10.5.138.26:8106}"}
the lookup is def there, and some queries work and other I got above error
it is hard to find the pattern here, looks like it happens for queries fetching near realtime data, but not sure 100%
b
Could be related to druid.lookup.enableLookupSyncOnStartup, maybe druid.manager.lookups.threadPoolSize (see druid.manager.lookups.threadPoolSize)
j
I do not have any of them configured in my settings, I guess then it is using default values
I am seeing this in my task logs,
2023-02-25T17:50:52,118 INFO [main] org.apache.druid.cli.CliPeon - * druid.lookup.enableLookupSyncOnStartup: false
so I guess that might be?
I think
druid.manager.lookups.threadPoolSize
should be probably set to 2 as default
b
turning on enableLookupSyncOnStartup could help, I think it's worth trying. From what you describe, I thought a bit more and threadPoolSize is less likely. (It controls how many background threads are available to communicate with the servers that load lookups to tell them when new versions are available and push out lookup changes to these nodes.) Whereas enableLookupSyncOnStartup tells peons to load the lookups right away when they start up, iiuc.
j
Will that help with queries? Because the problem I'm seeing is with queries and the error log comes from coordinator
b
If you're seeing it for the near-real-time queries, I think it could help. You'd want to enable it on MMs so the peons get the setting.
You applied, and restarted MMs (which should stop and restart any ongoing tasks)? Is this constant, or occurs at times (like when tasks start?
j
I have not applied it yet. It looks like it is not constant, it happens from time to time, and only affecting queries. It does not affect ingestion
b
Oh, I misunderstood. I think there's a good chance it would help.
j
I finally applied the changes however I do not think they are causing any effect. The error I get in coordinators:
Copy code
2023-03-01T13:19:34,040 WARN [qtp1333929103-159[groupBy_[test]_922f46e1-ec95-4042-8588-19776e45eb62]] org.apache.druid.server.QueryLifecycle - Exception while processing queryId [922f46e1-ec95-4042-8588-19776e45eb62] (QueryInterruptedException{msg=Lookup [sigs_test] not found, code=Unknown exception, class=org.apache.druid.java.util.common.ISE, host=10.5.168.46:8102})
2023-03-01T13:19:34,040 INFO [qtp1333929103-159[groupBy_[test]_922f46e1-ec95-4042-8588-19776e45eb62]] org.apache.druid.server.log.LoggingRequestLogger - 2023-03-01T13:19:33.984Z    10.5.100.235    {"queryType":"groupBy","dataSource":{"type":"table","name":"test"},"intervals":{"type":"LegacySegmentSpec","intervals":["2023-03-01T12:49:33.000Z/2023-03-01T13:19:33.000Z"]},"filter":{"type":"and","fields":[{"type":"selector","dimension":"id","value":"1234abcd"}]},"granularity":{"type":"all"},"dimensions":[{"type":"default","dimension":"addr","outputName":"address","outputType":"STRING"},{"type":"default","dimension":"code","outputName":"code","outputType":"STRING"},{"type":"lookup","dimension":"signature","outputName":"signature","lookup":null,"retainMissingValue":false,"replaceMissingValueWith":"unknown signature","name":"sigs_test","optimize":true}],"aggregations":[{"type":"doubleSum","name":"count","fieldName":"count"}],"limitSpec":{"type":"default","columns":[{"dimension":"address","direction":"descending","dimensionOrder":{"type":"lexicographic"}}],"limit":100},"context":{"priority":"100","queryId":"922f46e1-ec95-4042-8588-19776e45eb62","sqlQueryId":"222550709180619544_timeseries_count_all_30m"}}    {"query/time":56,"query/bytes":-1,"success":false,"identity":"analytics_user","exception":"QueryInterruptedException{msg=Lookup [sigs_test] not found, code=Unknown exception, class=org.apache.druid.java.util.common.ISE, host=10.5.168.46:8102}","interrupted":true,"reason":"QueryInterruptedException{msg=Lookup [sigs_test] not found, code=Unknown exception, class=org.apache.druid.java.util.common.ISE, host=10.5.168.46:8102}"}
2023-03-01T13:19:34,040 DEBUG [qtp1333929103-159] org.apache.druid.jetty.RequestLog - 10.5.100.235 POST //10.5.152.192:8082/druid/v2 HTTP/1.1 500
2023-03-01T13:19:34,847 WARN [qtp1333929103-137[groupBy_[test]_c71b4679-8e68-4ee3-a725-f1844aacbe0f]] org.apache.druid.client.JsonParserIterator - Query [c71b4679-8e68-4ee3-a725-f1844aacbe0f] to host [10.5.168.46:8102] interrupted
org.apache.druid.query.QueryException: Lookup [sigs_test] not found
at jdk.internal.reflect.GeneratedConstructorAccessor136.newInstance(Unknown Source) ~[?:?]
at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
at java.lang.reflect.Constructor.newInstance(Constructor.java:490) ~[?:?]
at com.fasterxml.jackson.databind.introspect.AnnotatedConstructor.call(AnnotatedConstructor.java:124) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
at com.fasterxml.jackson.databind.deser.std.StdValueInstantiator.createFromObjectWith(StdValueInstantiator.java:283) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
at com.fasterxml.jackson.databind.deser.ValueInstantiator.createFromObjectWith(ValueInstantiator.java:229) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
at com.fasterxml.jackson.databind.deser.impl.PropertyBasedCreator.build(PropertyBasedCreator.java:198) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
at com.fasterxml.jackson.databind.deser.BeanDeserializer._deserializeUsingPropertyBased(BeanDeserializer.java:422) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
at com.fasterxml.jackson.databind.deser.std.ThrowableDeserializer.deserializeFromObject(ThrowableDeserializer.java:65) ~[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:2476) ~[jackson-databind-2.10.5.1.jar:2.10.5.1]
at org.apache.druid.client.JsonParserIterator.init(JsonParserIterator.java:183) ~[druid-server-25.0.0.jar:25.0.0]
at org.apache.druid.client.JsonParserIterator.hasNext(JsonParserIterator.java:93) ~[druid-server-25.0.0.jar:25.0.0]
at org.apache.druid.java.util.common.guava.BaseSequence.toYielder(BaseSequence.java:70) ~[druid-core-25.0.0.jar:25.0.0]
at org.apache.druid.java.util.common.guava.BaseSequence.accumulate(BaseSequence.java:44) ~[druid-core-25.0.0.jar:25.0.0]
at org.apache.druid.java.util.common.guava.MergeSequence.toYielder(MergeSequence.java:63) ~[druid-core-25.0.0.jar:25.0.0]
at org.apache.druid.query.RetryQueryRunner$1.toYielder(RetryQueryRunner.java:133) ~[druid-server-25.0.0.jar:25.0.0]
at org.apache.druid.java.util.common.guava.YieldingSequenceBase.accumulate(YieldingSequenceBase.java:35) ~[druid-core-25.0.0.jar:25.0.0]
at org.apache.druid.common.guava.CombiningSequence.accumulate(CombiningSequence.java:62) ~[druid-core-25.0.0.jar:25.0.0]
at org.apache.druid.java.util.common.guava.TopNSequence$1.make(TopNSequence.java:54) ~[druid-core-25.0.0.jar:25.0.0]
at org.apache.druid.java.util.common.guava.BaseSequence.toYielder(BaseSequence.java:66) ~[druid-core-25.0.0.jar:25.0.0]
at org.apache.druid.java.util.common.guava.WrappingSequence$2.get(WrappingSequence.java:88) ~[druid-core-25.0.0.jar:25.0.0]
at org.apache.druid.java.util.common.guava.WrappingSequence$2.get(WrappingSequence.java:84) ~[druid-core-25.0.0.jar:25.0.0]
at org.apache.druid.java.util.common.guava.SequenceWrapper.wrap(SequenceWrapper.java:55) ~[druid-core-25.0.0.jar:25.0.0]
...
at java.lang.Thread.run(Thread.java:829) ~[?:?]
2023-03-01T13:19:34,849 WARN [qtp1333929103-137[groupBy_[test]_c71b4679-8e68-4ee3-a725-f1844aacbe0f]] org.apache.druid.server.QueryLifecycle - Exception while processing queryId [c71b4679-8e68-4ee3-a725-f1844aacbe0f] (QueryInterruptedException{msg=Lookup [sigs_test] not found, code=Unknown exception, class=org.apache.druid.java.util.common.ISE, host=10.5.168.46:8102})
2023-03-01T13:19:34,849 INFO [qtp1333929103-137[groupBy_[test]_c71b4679-8e68-4ee3-a725-f1844aacbe0f]] org.apache.druid.server.log.LoggingRequestLogger - 2023-03-01T13:19:34.786Z    10.5.152.134    {"queryType":"groupBy","dataSource":{"type":"table","name":"test"},"intervals":{"type":"LegacySegmentSpec","intervals":["2023-03-01T12:49:33.000Z/2023-03-01T13:19:33.000Z"]},"filter":{"type":"and","fields":[{"type":"selector","dimension":"id","value":"1234abcd"}]},"granularity":{"type":"all"},"dimensions":[{"type":"default","dimension":"addr","outputName":"address","outputType":"STRING"},{"type":"default","dimension":"code","outputName":"code","outputType":"STRING"},{"type":"lookup","dimension":"signature","outputName":"signature","lookup":null,"retainMissingValue":false,"replaceMissingValueWith":"unknown signature","name":"sigs_test","optimize":true}],"aggregations":[{"type":"doubleSum","name":"count","fieldName":"count"}],"limitSpec":{"type":"default","columns":[{"dimension":"address","direction":"descending","dimensionOrder":{"type":"lexicographic"}}],"limit":100},"context":{"priority":"100","queryId":"c71b4679-8e68-4ee3-a725-f1844aacbe0f","sqlQueryId":"222550709180619544_timeseries_count_all_30m"}}    {"query/time":63,"query/bytes":-1,"success":false,"identity":"analytics_user","exception":"QueryInterruptedException{msg=Lookup [sigs_test] not found, code=Unknown exception, class=org.apache.druid.java.util.common.ISE, host=10.5.168.46:8102}","interrupted":true,"reason":"QueryInterruptedException{msg=Lookup [sigs_test] not found, code=Unknown exception, class=org.apache.druid.java.util.common.ISE, host=10.5.168.46:8102}"}
2023-03-01T13:19:34,849 DEBUG [qtp1333929103-137] org.apache.druid.jetty.RequestLog - 10.5.152.134 POST //10.5.152.192:8082/druid/v2 HTTP/1.1 500
2023-03-01T13:19:35,021 DEBUG [qtp1333929103-169] org.apache.druid.jetty.RequestLog - 10.5.147.124 GET //10.5.152.192:8082/status/health HTTP/1.1 200
2023-03-01T13:19:35,070 DEBUG [qtp1333929103-160] org.apache.druid.jetty.RequestLog - 10.5.147.124 GET //10.5.152.192:8082/status/health HTTP/1.1 200
2023-03-01T13:19:35,749 INFO [NodeRoleWatcher[PEON]] org.apache.druid.discovery.BaseNodeRoleWatcher - Node [<http://10.5.146.8:8106>] of role [peon] went offline.
2023-03-01T13:19:35,749 INFO [CuratorDruidNodeDiscoveryProvider-ListenerExecutor] org.apache.druid.client.HttpServerInventoryView - Server[10.5.146.8:8106] disappeared.
2023-03-01T13:19:35,749 INFO [CuratorDruidNodeDiscoveryProvider-ListenerExecutor] org.apache.druid.server.coordination.ChangeRequestHttpSyncer - Stopping ChangeRequestHttpSyncer[<http://10.5.146.8:8106/_1677676721376>].
2023-03-01T13:19:35,749 INFO [CuratorDruidNodeDiscoveryProvider-ListenerExecutor] org.apache.druid.server.coordination.ChangeRequestHttpSyncer - Stopped ChangeRequestHttpSyncer[<http://10.5.146.8:8106/_1677676721376>].
2023-03-01T13:19:35,767 INFO [FilteredHttpServerInventoryView-0] org.apache.druid.server.coordination.ChangeRequestHttpSyncer - Skipping sync() success for server[<http://10.5.146.8:8106/_1677676721376>].
2023-03-01T13:19:35,887 INFO [NodeRoleWatcher[PEON]] org.apache.druid.discovery.BaseNodeRoleWatcher - Node [<http://10.5.174.204:8101>] of role [peon] went offline.
v
how big is this lookup?
j
it is fetched from a postgresql, not sure how many rows it fetches into memory but the table itself has around 200k entries, I do not consider that a lot for a key/value map pair
v
true. Is this error always happening with queries accessing the data in the peon and not the data in the historical?
j
I think so, I think the error happens when near realtime and for this particular query, it always looks at last 30 minutes of current time. It is exposed through a public facing API so when users visit their stats dashboard a query is launched to see last 30 minutes
I made a rollout restart and I think this time the parameter has been picked up correctly. Have not seen many error but I keep monitoring it