ClickHouse / ClickHouse/ClickHouse

Errors seem cached in executed dictionaries

Open
#49,465 0 comments 3 reactions 0 assignees View on GitHub
comp-dictionary external unexpected behaviour
Dominant language
C++
Stars
49.9k
Forks
9k
Avg merge
21h 32m
Merged PRs (30d)
515

Description

Hello!

# Describe the unexpected behaviour

The issue seems to be that errors that occur during the execution of a ClickHouse dictionary with an `executable` source layout and a `complex_key_cache` layout seem to be cached.
If a request causes an error during script execution, subsequent requests with the same key will not execute the script again and will return the previous – empty or faulty – response.

This is an unexpected behavior since a key with an empty or faulty cached value is almost unusable for its entire `lifetime`, which can be long.

# How to reproduce

In this minimal reproducible example, I have:

- A dictionary with the `complex_key_cache` layout and the `executable` source.
- The dictionary will execute `process.py`, which simulates the generation of the `value` string.
- The `process.py` script logs to `/var/log/clickhouse-server/process.log`, which allows us to track when it is executed.
- When `key` starts with, the script simulates an error and exits `1`.

## Version

```bash
$ docker run --rm clickhouse/clickhouse-server --version
ClickHouse server version 23.4.1.1943 (official build).
```

## Dictionary config

Note that the `executable` dictionary source can be configured only via XML configuration.

```xml


my_dictionary




key
String


value
String




process.py
TabSeparated
1



16384


39600
43200

```

## Script

```python
#!/bin/python3

import sys
import traceback
import logging

LOG_FILE = "/var/log/clickhouse-server/process.log"

if __name__ == "__main__":
log_fd = open(LOG_FILE, "a+")

logging.basicConfig(
stream=log_fd,
level=logging.DEBUG,
format=f"%(asctime)s %(levelname)s: %(message)s",
)

logging.debug("-- HELLO ------------------")

try:
for line in sys.stdin:
request = line.rstrip()
logging.debug("request: '%s'", request)

if request.startswith("BAD_REQUEST"):
sys.exit(1)

processed = f"{request}_PROCESSED"
response = f"{request}\t{processed}"

logging.debug("response: '%s'", response)
print(response)
except Exception as e:
traceback.print_exc(file=log_fd)
finally:
logging.debug("-- BYE --------------------")
log_fd.close()
```

## Example

### Scenario

We start with a clean dictionary.

Here, we run the same query twice with only a few seconds between them:

- The first query executes `process.py`, stores the value in the cache, and returns it.
- The second query does not execute the script (check the logs below), as the result is cached.

```bash
$ docker exec -it clickhouse-server clickhouse-client -q "SELECT dictGet('my_dictionary', 'value', 'A')"
A_PROCESSED
$ docker exec -it clickhouse-server clickhouse-client -q "SELECT dictGet('my_dictionary', 'value', 'A')"
A_PROCESSED
```

Is it the expected behavior: **YES.**

Here, we run the same query twice with only a few seconds between them:

- The first query executes `process.py`, which exits `1` and prints nothing to `STDOUT`. The empty `null_value` provided in the dictionary definition for the `value` attribute looks cached in the dictionary.
- The second query does not execute the script (check the logs below). The result seems cached.
- The third query seems to validate that the `null_value` has been cached. (One entry for the `A` key and another one for the `BAD_REQUEST`)

```bash
$ docker exec -it clickhouse-server clickhouse-client -q "SELECT dictGet('my_dictionary', 'value', 'BAD_REQUEST')"

$ docker exec -it clickhouse-server clickhouse-client -q "SELECT dictGet('my_dictionary', 'value', 'BAD_REQUEST')"

$ docker exec -it clickhouse-server clickhouse-client -q "SELECT element_count from system.dictionaries where name = 'my_dictionary';"
2
```

Is it the expected behavior: **NO.**

### Python process.py script logs

```bash
$ docker exec clickhouse-server cat /var/log/clickhouse-server/process.log
2023-05-03 13:44:36,659 DEBUG: -- HELLO ------------------
2023-05-03 13:44:36,659 DEBUG: request: 'A'
2023-05-03 13:44:36,659 DEBUG: response: 'A A_PROCESSED'
2023-05-03 13:44:36,659 DEBUG: -- BYE --------------------
2023-05-03 13:44:56,134 DEBUG: -- HELLO ------------------
2023-05-03 13:44:56,134 DEBUG: request: 'BAD_REQUEST'
2023-05-03 13:44:56,134 DEBUG: -- BYE --------------------
```

## **Expected behavior**

It would be better if the `SELECT dictGet('my_dictionary', 'value', 'BAD_REQUEST')` raised an exception. This would allow to retry later without waiting for the `lifetime` to expire.

I can't find a way to make Clickhouse behave this way. The `null_value` argument seems mandatory. A `DB::Exception: Not found: dictionary.structure.attribute.null_value. (POCO_EXCEPTION)` is raised if I don't set it.

Let me know if you want a repository with a minimal reproducible example so you can reproduce it yourself.

Thanks a lot for your help! 🙂

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.