"SELECT * FROM ks1.table1" fails: Failed decoding result column "ck2" of type timestamp: days=2147458792; must have magnitude <= 999999999

[vponomaryov]

Issue description

• This issue is a regression.
• It is unknown if this issue is a regression.

Running the rebuild_streaming_err nemesis in the gemini CI job using gemini-v1.8.6, where we walk through the test tables and check for data presence, we get following error:

> Executing CQL '<SimpleStatement query="SELECT * FROM ks1.table1", consistency=Not Set>' ...
> Error decoding response from Cassandra. ver(3); flags(0000); stream(2); op(8); offset(9); len(145621); buffer: b'\x83 ... <huge piece of data> ... \x15'
> Traceback (most recent call last):
>   File "cassandra/obj_parser.pyx", line 72, in cassandra.obj_parser.TupleRowParser.unpack_row
>   File "cassandra/deserializers.pxd", line 41, in cassandra.deserializers.from_binary
>   File "cassandra/deserializers.pyx", line 143, in cassandra.deserializers.DesDateType.deserialize
>   File "cassandra/cython_utils.pyx", line 62, in cassandra.cython_utils.datetime_from_timestamp
>   File ".eggs/Cython-0.29.32-py3.10-linux-x86_64.egg/Cython/Includes/cpython/datetime.pxd", line 125, in cpython.datetime.timedelta_new
> OverflowError: days=2147458792; must have magnitude <= 999999999
>
> During handling of the above exception, another exception occurred:
>
> Traceback (most recent call last):
>   File "cassandra/row_parser.pyx", line 38, in cassandra.row_parser.make_recv_results_rows.recv_results_rows
>   File "cassandra/obj_parser.pyx", line 31, in cassandra.obj_parser.ListParser.parse_rows
>   File "cassandra/obj_parser.pyx", line 74, in cassandra.obj_parser.TupleRowParser.unpack_row
> cassandra.DriverException: Failed decoding result column "ck2" of type timestamp: days=2147458792; must have magnitude <= 999999999
>
> During handling of the above exception, another exception occurred:
>
> Traceback (most recent call last):
>   File "cassandra/obj_parser.pyx", line 72, in cassandra.obj_parser.TupleRowParser.unpack_row
>   File "cassandra/deserializers.pxd", line 41, in cassandra.deserializers.from_binary
>   File "cassandra/deserializers.pyx", line 143, in cassandra.deserializers.DesDateType.deserialize
>   File "cassandra/cython_utils.pyx", line 62, in cassandra.cython_utils.datetime_from_timestamp
>   File ".eggs/Cython-0.29.32-py3.10-linux-x86_64.egg/Cython/Includes/cpython/datetime.pxd", line 125, in cpython.datetime.timedelta_new
> OverflowError: days=2147458792; must have magnitude <= 999999999
>
> During handling of the above exception, another exception occurred:
>
> Traceback (most recent call last):
>   File "cassandra/connection.py", line 1266, in cassandra.connection.Connection.process_msg
>   File "cassandra/protocol.py", line 1196, in cassandra.protocol._ProtocolHandler.decode_message
>   File "cassandra/protocol.py", line 744, in cassandra.protocol.ResultMessage.recv_body
>   File "cassandra/protocol.py", line 730, in cassandra.protocol.ResultMessage.recv
>   File "cassandra/row_parser.pyx", line 46, in cassandra.row_parser.make_recv_results_rows.recv_results_rows
>   File "cassandra/obj_parser.pyx", line 57, in cassandra.obj_parser.TupleRowParser.unpack_row
>   File "cassandra/obj_parser.pyx", line 74, in cassandra.obj_parser.TupleRowParser.unpack_row
> cassandra.DriverException: Failed decoding result column "ck2" of type timestamp: days=2147458792; must have magnitude <= 999999999

Impact

Describe the impact this issue causes to the user.

How frequently does it reproduce?

Happens in about 50% cases using gemini-v1.8.6 in the gemini CI job if no data mismatches get caught.

Installation details

Kernel Version: 5.15.0-1040-aws
Scylla version (or git commit hash): 5.2.6-20230730.58acf071bf28 with build-id 17961be569f8503b27ff284a8de1e00a9d83811e

Cluster size: 3 nodes (i3.large)

Scylla Nodes used in this run:

• gemini-with-nemesis-3h-normal-vp-br-oracle-db-node-985fe5dc-1 (34.236.254.9 | 10.12.3.62) (shards: 30)
• gemini-with-nemesis-3h-normal-vp-br-db-node-985fe5dc-3 (3.218.141.202 | 10.12.3.158) (shards: 2)
• gemini-with-nemesis-3h-normal-vp-br-db-node-985fe5dc-2 (3.237.192.240 | 10.12.0.29) (shards: 2)
• gemini-with-nemesis-3h-normal-vp-br-db-node-985fe5dc-1 (44.202.78.252 | 10.12.0.131) (shards: 2)

OS / Image: ami-0f1f419420235978b (aws: us-east-1)

Test: vp-gemini-3h-with-nemesis-test
Test id: 985fe5dc-f634-47d6-b517-814916df7a5e
Test name: scylla-staging/valerii/vp-gemini-3h-with-nemesis-test
Test config file(s):

• gemini-3h-with-nemesis.yaml

Logs and commands

• Restore Monitor Stack command: $ hydra investigate show-monitor 985fe5dc-f634-47d6-b517-814916df7a5e
• Restore monitor on AWS instance using Jenkins job
• Show all stored logs command: $ hydra investigate show-logs 985fe5dc-f634-47d6-b517-814916df7a5e

Logs:

• db-cluster-985fe5dc.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/985fe5dc-f634-47d6-b517-814916df7a5e/20230804_014205/db-cluster-985fe5dc.tar.gz
• sct-runner-events-985fe5dc.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/985fe5dc-f634-47d6-b517-814916df7a5e/20230804_014205/sct-runner-events-985fe5dc.tar.gz
• sct-985fe5dc.log.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/985fe5dc-f634-47d6-b517-814916df7a5e/20230804_014205/sct-985fe5dc.log.tar.gz
• monitor-set-985fe5dc.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/985fe5dc-f634-47d6-b517-814916df7a5e/20230804_014205/monitor-set-985fe5dc.tar.gz
• loader-set-985fe5dc.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/985fe5dc-f634-47d6-b517-814916df7a5e/20230804_014205/loader-set-985fe5dc.tar.gz
• parallel-timelines-report-985fe5dc.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/985fe5dc-f634-47d6-b517-814916df7a5e/20230804_014205/parallel-timelines-report-985fe5dc.tar.gz

Jenkins job URL
Argus

[vponomaryov]

Since it is flaky failure.
Here is another passed test run with completely the same setting, but without bug reproduction:

Installation details

Kernel Version: 5.15.0-1040-aws
Scylla version (or git commit hash): 5.2.6-20230730.58acf071bf28 with build-id 17961be569f8503b27ff284a8de1e00a9d83811e

Cluster size: 3 nodes (i3.large)

Scylla Nodes used in this run:

• gemini-with-nemesis-3h-normal-vp-br-oracle-db-node-04811d3b-1 (44.204.203.83 | 10.12.1.202) (shards: 2)
• gemini-with-nemesis-3h-normal-vp-br-db-node-04811d3b-3 (44.200.197.190 | 10.12.0.95) (shards: 2)
• gemini-with-nemesis-3h-normal-vp-br-db-node-04811d3b-2 (3.231.22.139 | 10.12.3.76) (shards: 2)
• gemini-with-nemesis-3h-normal-vp-br-db-node-04811d3b-1 (18.207.111.201 | 10.12.3.117) (shards: 2)

OS / Image: ami-0f1f419420235978b (aws: us-east-1)

Test: vp-gemini-3h-with-nemesis-test
Test id: 04811d3b-6563-4cb7-9336-e454663457ce
Test name: scylla-staging/valerii/vp-gemini-3h-with-nemesis-test
Test config file(s):

• gemini-3h-with-nemesis.yaml

Logs and commands

• Restore Monitor Stack command: $ hydra investigate show-monitor 04811d3b-6563-4cb7-9336-e454663457ce
• Restore monitor on AWS instance using Jenkins job
• Show all stored logs command: $ hydra investigate show-logs 04811d3b-6563-4cb7-9336-e454663457ce

Logs:

• db-cluster-04811d3b.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/04811d3b-6563-4cb7-9336-e454663457ce/20230804_111719/db-cluster-04811d3b.tar.gz
• sct-runner-events-04811d3b.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/04811d3b-6563-4cb7-9336-e454663457ce/20230804_111719/sct-runner-events-04811d3b.tar.gz
• sct-04811d3b.log.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/04811d3b-6563-4cb7-9336-e454663457ce/20230804_111719/sct-04811d3b.log.tar.gz
• monitor-set-04811d3b.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/04811d3b-6563-4cb7-9336-e454663457ce/20230804_111719/monitor-set-04811d3b.tar.gz
• loader-set-04811d3b.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/04811d3b-6563-4cb7-9336-e454663457ce/20230804_111719/loader-set-04811d3b.tar.gz
• parallel-timelines-report-04811d3b.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/04811d3b-6563-4cb7-9336-e454663457ce/20230804_111719/parallel-timelines-report-04811d3b.tar.gz

Jenkins job URL
Argus

[vponomaryov]

The master scylla branch is also affected:

> Executing CQL '<SimpleStatement query="SELECT * FROM ks1.table1", consistency=Not Set>' ...
> Error decoding response from Cassandra. ver(3); flags(0000); stream(2); op(8); offset(9); len(151051); buffer: b'\x83 ... <huge piece of data> ... \x04:J\x96R'
> Traceback (most recent call last):
>   File "cassandra/obj_parser.pyx", line 72, in cassandra.obj_parser.TupleRowParser.unpack_row
>   File "cassandra/deserializers.pxd", line 41, in cassandra.deserializers.from_binary
>   File "cassandra/deserializers.pyx", line 143, in cassandra.deserializers.DesDateType.deserialize
>   File "cassandra/cython_utils.pyx", line 62, in cassandra.cython_utils.datetime_from_timestamp
>   File ".eggs/Cython-0.29.32-py3.10-linux-x86_64.egg/Cython/Includes/cpython/datetime.pxd", line 125, in cpython.datetime.timedelta_new
> OverflowError: days=2147458792; must have magnitude <= 999999999
>
> During handling of the above exception, another exception occurred:
>
> Traceback (most recent call last):
>   File "cassandra/row_parser.pyx", line 38, in cassandra.row_parser.make_recv_results_rows.recv_results_rows
>   File "cassandra/obj_parser.pyx", line 31, in cassandra.obj_parser.ListParser.parse_rows
>   File "cassandra/obj_parser.pyx", line 74, in cassandra.obj_parser.TupleRowParser.unpack_row
> cassandra.DriverException: Failed decoding result column "ck1" of type timestamp: days=2147458792; must have magnitude <= 999999999
>
> During handling of the above exception, another exception occurred:
>
> Traceback (most recent call last):
>   File "cassandra/obj_parser.pyx", line 72, in cassandra.obj_parser.TupleRowParser.unpack_row
>   File "cassandra/deserializers.pxd", line 41, in cassandra.deserializers.from_binary
>   File "cassandra/deserializers.pyx", line 143, in cassandra.deserializers.DesDateType.deserialize
>   File "cassandra/cython_utils.pyx", line 62, in cassandra.cython_utils.datetime_from_timestamp
>   File ".eggs/Cython-0.29.32-py3.10-linux-x86_64.egg/Cython/Includes/cpython/datetime.pxd", line 125, in cpython.datetime.timedelta_new
> OverflowError: days=2147458792; must have magnitude <= 999999999
>
> During handling of the above exception, another exception occurred:
>
> Traceback (most recent call last):
>   File "cassandra/connection.py", line 1266, in cassandra.connection.Connection.process_msg
>   File "cassandra/protocol.py", line 1196, in cassandra.protocol._ProtocolHandler.decode_message
>   File "cassandra/protocol.py", line 744, in cassandra.protocol.ResultMessage.recv_body
>   File "cassandra/protocol.py", line 730, in cassandra.protocol.ResultMessage.recv
>   File "cassandra/row_parser.pyx", line 46, in cassandra.row_parser.make_recv_results_rows.recv_results_rows
>   File "cassandra/obj_parser.pyx", line 57, in cassandra.obj_parser.TupleRowParser.unpack_row
>   File "cassandra/obj_parser.pyx", line 74, in cassandra.obj_parser.TupleRowParser.unpack_row
> cassandra.DriverException: Failed decoding result column "ck1" of type timestamp: days=2147458792; must have magnitude <= 999999999

Installation details

Kernel Version: 5.15.0-1039-aws
Scylla version (or git commit hash): 5.4.0~dev-20230702.1ab2bb69b8a6 with build-id 748a09783d18c97d903f62dcf4d96a6d9db4b527

Cluster size: 3 nodes (i3.large)

Scylla Nodes used in this run:

• gemini-with-nemesis-3h-normal-vp-br-oracle-db-node-bf42fd21-1 (3.236.178.195 | 10.12.2.84) (shards: 2)
• gemini-with-nemesis-3h-normal-vp-br-db-node-bf42fd21-3 (3.238.56.162 | 10.12.1.89) (shards: 2)
• gemini-with-nemesis-3h-normal-vp-br-db-node-bf42fd21-2 (18.214.40.62 | 10.12.2.72) (shards: 2)
• gemini-with-nemesis-3h-normal-vp-br-db-node-bf42fd21-1 (3.235.165.104 | 10.12.0.110) (shards: 2)

OS / Image: ami-027d7b085be72f13c (aws: us-east-1)

Test: vp-gemini-3h-with-nemesis-test
Test id: bf42fd21-7f82-45e9-9424-ec362a75e473
Test name: scylla-staging/valerii/vp-gemini-3h-with-nemesis-test
Test config file(s):

• gemini-3h-with-nemesis.yaml

Logs and commands

• Restore Monitor Stack command: $ hydra investigate show-monitor bf42fd21-7f82-45e9-9424-ec362a75e473
• Restore monitor on AWS instance using Jenkins job
• Show all stored logs command: $ hydra investigate show-logs bf42fd21-7f82-45e9-9424-ec362a75e473

Logs:

• db-cluster-bf42fd21.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/bf42fd21-7f82-45e9-9424-ec362a75e473/20230804_120455/db-cluster-bf42fd21.tar.gz
• sct-runner-events-bf42fd21.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/bf42fd21-7f82-45e9-9424-ec362a75e473/20230804_120455/sct-runner-events-bf42fd21.tar.gz
• sct-bf42fd21.log.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/bf42fd21-7f82-45e9-9424-ec362a75e473/20230804_120455/sct-bf42fd21.log.tar.gz
• monitor-set-bf42fd21.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/bf42fd21-7f82-45e9-9424-ec362a75e473/20230804_120455/monitor-set-bf42fd21.tar.gz
• loader-set-bf42fd21.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/bf42fd21-7f82-45e9-9424-ec362a75e473/20230804_120455/loader-set-bf42fd21.tar.gz
• parallel-timelines-report-bf42fd21.tar.gz - https://cloudius-jenkins-test.s3.amazonaws.com/bf42fd21-7f82-45e9-9424-ec362a75e473/20230804_120455/parallel-timelines-report-bf42fd21.tar.gz

Jenkins job URL
Argus

[vponomaryov]

Looks very similar to the following closed bug: scylladb/scylladb#12239

[fruch]

Looks like a duplicate of
scylladb/scylladb#14645

It was fixed in Gemini, and not sure if it's in 1.8.6 version

[nyh]

It seems this issue is about the "timestamp", the other was about "time".

[DoronArazii]

@eliransin please assign it, adding it as a blocker until we will have some diagnostic from your team.

[mykaul]

@vponomaryov - can you try with gemini pre 1.8.4, to see if it happens? I'm quite sure it's a change in Gemini. It may or may not be a bug that we need to fix in Scylla side, but I'd like to ensure it's not a regression, first of all.
Alternatively, test with an older release of Scylla, to prove it's not a recent regression.

[vponomaryov]

@vponomaryov - can you try with gemini pre 1.8.4, to see if it happens? I'm quite sure it's a change in Gemini. It may or may not be a bug that we need to fix in Scylla side, but I'd like to ensure it's not a regression, first of all. Alternatively, test with an older release of Scylla, to prove it's not a recent regression.

Yes, this bug was caught using the v1.8.6 gemini version only.
Before, we were using 1.7.8 version of the gemini. It became unstable in a different way, probably, due to new versions of other tools including docker.

Either Scylla or python driver have bug: Scylla allows to write values which driver complains about.
Gemini should have failed with impossibility to write data, but it passed.

From the try 1.8.4- gemini version point of view I can say that I had successful run using 1.7.8 and lots of failures with another kind of an error.
Also, tried 1.8.2, failed with one another error, not this one.

To summarize:

• this bug is not blocker from my point of view, but it is not only geminis bug, gemini only highlights it.
• I already satisfied the request to run older gemini versions.

[DoronArazii]

@cvybhu is this in your plans for this Q?

[cvybhu]

@cvybhu is this in your plans for this Q?

No, I haven't seen this before.

To me this looks like a python driver bug.

The rust driver allows to insert and select a timestamp equal to i64::MAX (2^63 - 1) and i64::MIN.

use scylla::{Session, SessionBuilder};

#[tokio::main]
async fn main() {
    let session: Session = SessionBuilder::new()
        .known_node("127.0.0.1:9042")
        .build()
        .await
        .unwrap();

    session.query("CREATE KEYSPACE IF NOT EXISTS ks WITH REPLICATION = {'class' : 'SimpleStrategy', 'replication_factor' : 1}", &[]).await.unwrap();

    session
        .query(
            "CREATE TABLE IF NOT EXISTS ks.t (p timestamp PRIMARY KEY)",
            &[],
        )
        .await
        .unwrap();

    session
        .query("INSERT INTO ks.t (p) VALUES (?)", (i64::MAX,))
        .await
        .unwrap();

    session
        .query("INSERT INTO ks.t (p) VALUES (?)", (i64::MIN,))
        .await
        .unwrap();

    let ps: Vec<i64> = session
        .query("SELECT p FROM ks.t", &[])
        .await
        .unwrap()
        .rows_typed::<(i64,)>()
        .unwrap()
        .map(|parse_res| parse_res.unwrap())
        .map(|p: (i64,)| p.0)
        .collect();

    for p in ps {
        println!("p: {}", p)
    }
}

# Output:
p: 9223372036854775807
p: -9223372036854775808

OTOH cqlsh (which uses the python driver underneath) reports an overflow:

[cqlsh 6.0.9 | Scylla 5.2.3-0.20230608.ea08d409f155 | CQL spec 3.3.1 | Native protocol v4]
Use HELP for help.
cqlsh> SELECT p FROM ks.t;
/home/jancio/.local/lib/python3.11/site-packages/cqlsh/cqlsh.py:403: DateOverFlowWarning: Some timestamps are larger than Python datetime can represent. Timestamps are displayed in milliseconds from epoch.

 p
----------------------
  9223372036854775807
 -9223372036854775808

(2 rows)

The CQL spec defines timestamp as an 8 byte signed integer, so IMO both of these values should be legal:
https://github.com/apache/cassandra/blob/7750a9430bf8cec73c25e302642a3b0b77a78703/doc/native_protocol_v4.spec#L946-L950

To me it doesn't look like a Scylla bug. Scylla correctly writes and reads timestamp values, it's the driver that complains about "out of range values", so the bug is in the driver.

/cc @avelanarius

[fruch]

To me it doesn't look like a Scylla bug. Scylla correctly writes and reads timestamp values, it's the driver that complains about "out of range values", so the bug is in the driver.

/cc @avelanarius

It's not the first time we are running into such a warning, since in some cases it surfaced a real scylla issue (like using the wrong clock), I would argue we shouldn't remove the warning from cqlsh/python-driver

In this case I do agree it's not scylla core fault and caused by a change in scylla-bench, one if those were already fixed in scylla-bench,

if a user puts a timestamp of 292471209 years into the future, I think he would like to know it...

[nyh]

The same problem was reported in Cassandra eight years ago - see https://issues.apache.org/jira/browse/CASSANDRA-10625. They fixed cqlsh (see apache/cassandra@trunk...pauloricardomg:trunk-10625) to print the warning that @cvybhu saw above instead of failing, but didn't fix the driver. Maybe there are additional cases (not just cqlsh...) that need to be fixed?

But this issue should probably be reopened in the driver repository, not here. I think Scylla's handling of the "timestamp" column type isn't the problem here.