ClickHouse / ClickHouse/ClickHouse
Errors seem cached in executed dictionaries
- 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
Assessment
This issue has not been assessed yet.