[CASSANDRA-15503] Slow query log indicates opposite LTE when GTE operator

• Type: Bug
• Status: Resolved
• Priority: Normal
• Resolution: Fixed
• Fix Version/s: 3.11.7, 4.0-beta1, 4.0
• Component/s: Observability/Logging
• Bug Category: Correctness
• Severity: Normal
• Complexity: Normal
• Discovered By: User Report
• Platform: All
• Since Version: 3.10

Source Control Link

https://github.com/apache/cassandra/commit/406a8596eb7ad18079df20121521b1c659063ef4

Test and Documentation Plan

https://github.com/apache/cassandra-dtest/pull/67

• Assignee: Andres de la Peña
• Reporter: Wallace Baggaley

Authors

Andres de la Peña

Reviewers

Andres de la Peña, Berenguer Blasi

• Created: 14/Jan/20 23:21
• Updated: 18/Jun/20 13:11
• Resolved: 11/May/20 11:20

Description

Slow query log is indicating a '<=' when a ">=" operator was sent. This appears to be a logging only issue, but it threw off development for a day figuring this out. Please fix.

How to reproduce. Set slow query log timeout to 1 millisecond.

In cqlsh run

CREATE TABLE atable (
      .id text,
      timestamp timestamp,
      PRIMARY KEY ((id), timestamp)
 ) WITH CLUSTERING ORDER BY (timestamp DESC);
insert into atable (id, timestamp) VALUES ( '1',1);
insert into atable (id, timestamp) VALUES ( '2',2);
insert into atable (id, timestamp) VALUES ( '3',3);
insert into atable (id, timestamp) VALUES ( '4',4);
insert into atable (id, timestamp) VALUES ( '5',5);
insert into atable (id, timestamp) VALUES ( '6',6);
insert into atable (id, timestamp) VALUES ( '7',7);
insert into atable (id, timestamp) VALUES ( '8',8);
insert into atable (id, timestamp) VALUES ( '9',9);
insert into atable (id, timestamp) VALUES ( '10',10);
insert into atable (id, timestamp) VALUES ( '11',11);

select * from atable where timestamp >= '1970-01-01 00:00:00.006+0000' allow filtering;

In the logs it prints:

DEBUG 1 operations were slow in the last 5003 msecs:
<SELECT * FROM ks.atable WHERE timestamp <= 1970-01-01 00:00Z LIMIT 100>, time 7 msec - slow timeout 1 msec

But the query works appropriately and returns

 id | timestamp
----+---------------------------------
  6 | 1970-01-01 00:00:00.006000+0000
  7 | 1970-01-01 00:00:00.007000+0000
  9 | 1970-01-01 00:00:00.009000+0000
 10 | 1970-01-01 00:00:00.010000+0000
  8 | 1970-01-01 00:00:00.008000+0000
 11 | 1970-01-01 00:00:00.011000+0000

(6 rows)

Issue Links

• fixes: CASSANDRA-15500 Slow query logging emits incomplete predicates
• relates to: CASSANDRA-12403 Slow query detecting