[BUG] no query details in ERROR log

[allen12921]

Describe the bug
When query time exceed max_execution_time,there is no query info in the ERROR log

To Reproduce
set below config for user default in config.yml and run a slow query which needs more than 5s finish
max_execution_time=5s

Expected behavior
the query detail shoulld be logged in ERROR log

Screenshots
May 06 02:38:50 ip-172-27-1-139.cn-northwest-1.compute.internal chproxy[24124]: ERROR: 2023/05/06 02:38:50 proxy.go:339: [ Id: 1759233DE2CB99F8; User "default"(8) proxying as "default"(8) to "172.27.1.85:8123"(6); RemoteAddr: "52.122.89.122"; LocalAddr: "172.27.1.139:8198"; Duration: 5025241 μs]: timeout for user "default" exceeded: 5s; query: ""

Environment information
Linux ip-172-27-2-19.cn-northwest-1.compute.internal 4.14.268-205.500.amzn2.x86_64 #1 SMP Wed Mar 2 18:38:38 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
chproxy ver. 1.24.0, rev. a09b62e, built at 2023-05-03T11:15:18Z

[mga-chka]

Hi, when you say error logs, which files are you referring to? Because, in your screenshots, we can see the query in error.

[allen12921]

@mga-chka
The log is from the chproxy stdout

[sigua-cs]

@allen12921 I'll take it

[sigua-cs]

@allen12921 can you provide your query example please?

[allen12921]

@sigua-cs
pls try set max_execution_time=1s and run SELECT sleep(2) will do

[sigua-cs]

@allen12921 I tested it with the same version. Unfortunately, I can't represent the issue. Works as expected on my side.
Can you please run Chproxy in debug mode, and share the extended log?

[allen12921]

@sigua-cs
I tried two version 1.19 and 1.24 with same settings and query

this is 1.19 debug log:

this is 1.24 debug log:

[allen12921]

FYI
I have tested 1.19-1.24 versions and found the issue comes up with 1.22

[sigua-cs]

@allen12921 I tested v1.22.0 version, works as expected. Prints query in error log message.
Can you share the config file please?

[allen12921]

@sigua-cs here you go

log_debug: true

server:
  proxy:
      enable: true
  http:
      listen_addr: ":8198"
      allowed_networks: ["172.100.0.0/16","172.27.0.0/16"]
      read_timeout: 2m
param_groups:
   - name: consistently
     params: 
     - key: log_queries_min_query_duration_ms
       value: 2000
     - key: log_queries
       value: 1
users:
  - name: "default"
    password: "passwd"
    to_user: "default"
    to_cluster: "report"
    max_concurrent_queries: 200
    max_execution_time: 1s
    allow_cors: true
    deny_http: false
    max_queue_size: 100
    max_queue_time: 5s
    cache: "shortterm"
    params: consistently

clusters:
  - name: "report"
    replicas:
      - name: "gd" 
        nodes: ["172.30.1.165:8188"]        
    users:
    - name: "default"
      password: "passwd"
    heartbeat:
      interval: 5s
    retry_number: 0
    kill_query_user:
      name: "default"
      password: "passwd"


caches:
  - name: "shortterm"
    mode: "file_system"
    file_system:
      dir: "/efs/chproxy_cache"
      max_size: 10024Mb
    expire: 60s
    grace_time: 10s
    shared_with_all_users: true

[sigua-cs]

@allen12921 thanks for sharing the config. I didn't check with caches in my testing. I'll test with shared config and will keep you posted

[sigua-cs]

Hello @allen12921 , we found the root cause. I'm working on fix

[mga-chka]

the version 1.26.1 should fix the issue so I'm closing it. Feel free to reopen it if needed