c66275e05c
Mention the type of batch: Logged or Unlogged. The size (warn/fail on too large size) error has different significance depending on the type. Refs: #27605 Closes scylladb/scylladb#27664
155 lines
7.5 KiB
Python
155 lines
7.5 KiB
Python
# Copyright 2021-present ScyllaDB
|
|
#
|
|
# SPDX-License-Identifier: LicenseRef-ScyllaDB-Source-Available-1.0
|
|
|
|
#############################################################################
|
|
# Most cqlpy tests should limit themselves to the CQL API provided by
|
|
# the Cassandra Python driver, and should work when running against any CQL-
|
|
# compatible database, including Scylla and Cassandra, running locally or
|
|
# remotely. In particular, tests should generally *not* attempt to look at
|
|
# Scylla's log file - as this log file is completely different between
|
|
# Scylla and Cassandra, and not available at all when testing a remote server.
|
|
#
|
|
# Nevertheless, in some cases we might want to verify that some specific
|
|
# log messages do appear in Scylla's log file. These tests should be
|
|
# concentrated in this source file. All these tests are skipped when the
|
|
# test is not running against Scylla, or Scylla's log file cannot be
|
|
# found - e.g., because Scylla is running on a remote machine, or configured
|
|
# not to write to a log file).
|
|
#
|
|
# The code below automatically figures out where the log file is, when
|
|
# Scylla is running locally. First the local Scylla process is detected
|
|
# (it is the process listening to the our CQL connection, if we can find
|
|
# one), then its standard output is guessed to be the log file - and then
|
|
# we verify that it really is.
|
|
#############################################################################
|
|
|
|
import pytest
|
|
import os
|
|
import io
|
|
import time
|
|
import re
|
|
|
|
from cassandra import InvalidRequest
|
|
|
|
from .util import new_test_keyspace, new_test_table, local_process_id
|
|
from .test_batch import generate_big_batch
|
|
|
|
# A fixture to find the Scylla log file, returning the log file's path.
|
|
# If the log file cannot be found, or it's not Scylla, the fixture calls
|
|
# pytest.skip() to skip any test which uses it. The fixture has module
|
|
# scope, so looking for the log file only happens once. Individual tests
|
|
# should use the function-scope fixture "logfile" below, which takes care
|
|
# of opening the log file for reading in the right place.
|
|
# We look for the log file by looking for a local process listening to the
|
|
# given CQL connection, assuming its standard output is the log file, and
|
|
# then verifying that this file is a proper Scylla log file.
|
|
@pytest.fixture(scope="module")
|
|
def logfile_path(cql):
|
|
pid = local_process_id(cql)
|
|
if not pid:
|
|
pytest.skip("Can't find local process")
|
|
# Now that we know the process id, use /proc to find if its standard
|
|
# output is redirected to a file. If it is, that's the log file. If it
|
|
# isn't a file, we don't where the user is piping the log.
|
|
try:
|
|
log = os.readlink(f'/proc/{pid}/fd/1')
|
|
except:
|
|
pytest.skip("Can't find local log file")
|
|
# If the process's standard output is some pipe or device, it's
|
|
# not the log file we were hoping for...
|
|
if not log.startswith('/') or not os.path.isfile(log):
|
|
pytest.skip("Can't find local log file")
|
|
# Scylla can be configured to put the log in syslog, not in the standard
|
|
# output. So let's verify that the file which we found actually looks
|
|
# like a Scylla log and isn't just empty or something... The Scylla log
|
|
# file always starts with the line: "Scylla version ... starting ..."
|
|
with open(log, 'r') as f:
|
|
head = f.read(7)
|
|
if head != 'Scylla ':
|
|
pytest.skip("Not a Scylla log file")
|
|
yield log
|
|
|
|
# The "logfile" fixture returns the log file open for reading at the end.
|
|
# Testing if something appears in the log usually involves taking this
|
|
# fixture, and then checking with wait_for_log() for the desired message to
|
|
# have appeared. Because each logfile fixture opens the log file separately,
|
|
# it is ok if several tests are run in parallel - but they will see each
|
|
# other's log messages so should try to ensure that unique strings (e.g.,
|
|
# random table names) appear in the log message.
|
|
@pytest.fixture(scope="function")
|
|
def logfile(logfile_path):
|
|
with open(logfile_path, 'r') as f:
|
|
f.seek(0, io.SEEK_END)
|
|
yield f
|
|
|
|
# wait_for_log() checks if the log, starting at its current position
|
|
# (probably set by the logfile fixture), contains the given message -
|
|
# and if it doesn't call pytest.fail().
|
|
# Because it may take time for the log message to be flushed, and sometimes
|
|
# we may want to look for messages about various delayed events, this
|
|
# function doesn't give up when it reaches the end of file, and rather
|
|
# retries until a given timeout. The timeout may be long, because successful
|
|
# tests will not wait for it. Note, however, that long timeouts will make
|
|
# xfailing tests slow.
|
|
def wait_for_log(logfile, pattern, timeout=5):
|
|
contents = logfile.read()
|
|
prog = re.compile(pattern)
|
|
if prog.search(contents):
|
|
return
|
|
end = time.time() + timeout
|
|
while time.time() < end:
|
|
s = logfile.read()
|
|
if s:
|
|
# Though unlikely, it is possible that a single message got
|
|
# split into two reads, so we need to check (and recheck)
|
|
# the entire content since the beginning of this wait :-(
|
|
contents = contents + s
|
|
if prog.search(contents):
|
|
return
|
|
time.sleep(0.1)
|
|
pytest.fail(f'Timed out ({timeout} seconds) looking for {pattern} in log file. Got:\n' + contents)
|
|
|
|
# A simple example of testing the log file - we check that a table creation,
|
|
# and table deletion, both cause messages to appear on the log.
|
|
def test_log_table_operations(cql, test_keyspace, logfile):
|
|
with new_test_table(cql, test_keyspace, 'p int PRIMARY KEY') as table:
|
|
wait_for_log(logfile, f'Creating {table}')
|
|
wait_for_log(logfile, f'Dropping {table}')
|
|
|
|
|
|
# The test is marked as Scylla-only because Cassandra doesn't allow for RF=0 in ALL of DCs,
|
|
# which is the case here. We must use it because changing the RF in this test to any other value
|
|
# would result in an error since the keyspace would stop being RF-rack-valid.
|
|
def test_log_alter_keyspace_operation(cql, this_dc, logfile, scylla_only):
|
|
ksdef = f"WITH replication = {{'class': 'NetworkTopologyStrategy', '{this_dc}': 1}} AND tablets = {{'initial': 1}};"
|
|
with new_test_keyspace(cql, ksdef) as keyspace:
|
|
cql.execute(f"ALTER KEYSPACE {keyspace} WITH replication = {{'class': 'NetworkTopologyStrategy', '{this_dc}': 0}}")
|
|
wait_for_log(logfile, r'Update Keyspace.*name=%s.*tablets={\"initial\":\d+' % keyspace)
|
|
|
|
|
|
@pytest.fixture(scope="module")
|
|
def table_batch(cql, test_keyspace):
|
|
with new_test_table(cql, test_keyspace, "k int primary key, t text") as table:
|
|
yield table
|
|
|
|
|
|
def test_warning_message_for_batch_exceeding_warning_threshold(cql, table_batch, logfile):
|
|
"""Batch size above threshold should add warning message to scylla logs"""
|
|
warning_pattern = r"WARN .+BatchStatement - Logged batch modifying [\d]+ partitions in [_\w.]+ is of size [\d]+ bytes, "\
|
|
r"exceeding specified WARN threshold of"
|
|
cql.execute(generate_big_batch(table_batch, 256))
|
|
wait_for_log(logfile, warning_pattern, timeout=1)
|
|
|
|
|
|
def test_error_message_for_batch_exceeding_fail_threshold(cql, table_batch, logfile):
|
|
"""Batch size above threshold should add error message to scylla logs"""
|
|
try:
|
|
cql.execute(generate_big_batch(table_batch, 1025))
|
|
except InvalidRequest:
|
|
err_pattern = r"ERROR .+ BatchStatement - Logged batch modifying [\d]+ partitions in [_\w.]+ is of size [\d]+ bytes, "\
|
|
r"exceeding specified FAIL threshold of"
|
|
wait_for_log(logfile, err_pattern, timeout=1)
|
|
else:
|
|
pytest.fail("Oversized batch didn't fail.")
|