Scylla: Alternator: modifying write-isolation tag is not propagated to a node of another DC

[yarongilor]

Installation details
Scylla version: 4.0
Cluster size: 6 nodes (3 per DC)
OS (RHEL/CentOS/Ubuntu/AWS AMI): Dtest

scenario:

1. set write-isolation = 'forbid' to table 'user-table' (via node1 resource of dc1 )
2. Issue a wait for new tag value to be updated (on node2 resource of dc2)
   ==> result: the table tag is not updated for 30 seconds timeout threshold (failing the test).

full Dtest is:
https://github.com/scylladb/scylla-dtest/blob/8fcd725e03e7c97922c8c7be13c6f4c778eb02f7/alternator_tests.py#L215

log:

test_update_condition_expression_and_write_isolation (alternator_tests.AlternatorTest) ... 2020-05-26 11:53:45.757334 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - cluster ccm directory: /home/yarongilor/.dtest/dtest-m2_8hs07
2020-05-26 11:53:45.757528 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - Starting Scylla cluster version unstable/master:MASTER_FIX
2020-05-26 11:53:45.767884 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - Allocated cluster ID 5: /home/yarongilor/.dtest/dtest-m2_8hs07
2020-05-26 11:53:45.819339 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - Cluster *_request_timeout_in_ms=10000, cql request_timeout=30
2020-05-26 11:53:45.834130 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - Populating a cluster with 3 nodes for multi DC..
2020-05-26 11:53:46.748761 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - Starting cluster..
2020-05-26 11:54:31.115766 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - Adding data for all nodes from DC1
2020-05-26 11:54:31.115887 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - Creating a new table 'user_table' using node 'node1'..
2020-05-26 11:54:31.537817 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - The table 'user_table' successfully created..
2020-05-26 11:54:31.541175 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - Table's schema and configuration are: {'Table': {'AttributeDefinitions': [{'AttributeName': 'pk', 'AttributeType': 'S'}], 'TableName': 'user_table', 'KeySchema': [{'AttributeName': 'pk', 'KeyType': 'HASH'}], 'TableStatus': 'ACTIVE', 'CreationDateTime': datetime.datetime(2020, 5, 26, 11, 54, 31, tzinfo=tzlocal()), 'TableArn': 'arn:scylla:alternator:alternator_user_table:scylla:table/user_table', 'BillingModeSummary': {'BillingMode': 'PAY_PER_REQUEST', 'LastUpdateToPayPerRequestDateTime': datetime.datetime(2020, 5, 26, 11, 54, 31, tzinfo=tzlocal())}}, 'ResponseMetadata': {'HTTPStatusCode': 200, 'HTTPHeaders': {'content-type': 'application/json', 'content-length': '394', 'server': 'Seastar httpd', 'date': 'Tue, 26 May 2020 08:54:30 GMT'}, 'RetryAttempts': 0}}
2020-05-26 11:54:31.541373 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - Adding new 100 items to table 'user_table'..
2020-05-26 11:54:31.613174 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - Stopping node2 (before testing update query with key condition expression)
2020-05-26 11:54:34.641576 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - Testing and validating an update query using key condition expression
2020-05-26 11:54:34.642377 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - simple update from dc1
2020-05-26 11:54:34.684196 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - ConditionExpression update from dc2:
2020-05-26 11:54:34.684400 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - {'Key': {'pk': 'BCZ18'}, 'UpdateExpression': 'SET c = :val', 'ConditionExpression': 'attribute_exists (a)', 'ExpressionAttributeValues': {':val': 2}}
2020-05-26 11:54:34.684560 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - Check that conditional update fails on write-isolation 'forbid' mode (dc2)
2020-05-26 11:54:34.712616 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - Table dynamodb.Table(name='user_table') tags are: [{'Key': 'system:write_isolation', 'Value': 'forbid_rmw'}]
2020-05-26 11:54:35.714504 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - Checking table user_table schema sync on nodes:
2020-05-26 11:54:35.715054 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - node1
2020-05-26 11:54:35.715488 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - node4
2020-05-26 11:54:35.744106 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - user_table http://127.0.5.1:8080 tags: [{'Key': 'system:write_isolation', 'Value': 'forbid_rmw'}]
2020-05-26 11:54:35.744215 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - user_table http://127.0.5.1:8080 describe: {'AttributeDefinitions': [{'AttributeName': 'pk', 'AttributeType': 'S'}], 'TableName': 'user_table', 'KeySchema': [{'AttributeName': 'pk', 'KeyType': 'HASH'}], 'TableStatus': 'ACTIVE', 'CreationDateTime': datetime.datetime(2020, 5, 26, 11, 54, 35, tzinfo=tzlocal()), 'TableArn': 'arn:scylla:alternator:alternator_user_table:scylla:table/user_table', 'BillingModeSummary': {'BillingMode': 'PAY_PER_REQUEST', 'LastUpdateToPayPerRequestDateTime': datetime.datetime(2020, 5, 26, 11, 54, 35, tzinfo=tzlocal())}}
2020-05-26 11:54:35.750554 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - user_table http://127.0.5.4:8080 tags: []
2020-05-26 11:54:35.750660 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - user_table http://127.0.5.4:8080 describe: {'AttributeDefinitions': [{'AttributeName': 'pk', 'AttributeType': 'S'}], 'TableName': 'user_table', 'KeySchema': [{'AttributeName': 'pk', 'KeyType': 'HASH'}], 'TableStatus': 'ACTIVE', 'CreationDateTime': datetime.datetime(2020, 5, 26, 11, 54, 35, tzinfo=tzlocal()), 'TableArn': 'arn:scylla:alternator:alternator_user_table:scylla:table/user_table', 'BillingModeSummary': {'BillingMode': 'PAY_PER_REQUEST', 'LastUpdateToPayPerRequestDateTime': datetime.datetime(2020, 5, 26, 11, 54, 35, tzinfo=tzlocal())}}
2020-05-26 11:54:35.750868 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - (Waiting until table schema is updated (1.0381262302398682 s)
...
2020-05-26 11:55:04.986987 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - Checking table user_table schema sync on nodes:
2020-05-26 11:55:04.987485 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - node1
2020-05-26 11:55:04.987890 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - node4
2020-05-26 11:55:05.015624 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - user_table http://127.0.5.1:8080 tags: [{'Key': 'system:write_isolation', 'Value': 'forbid_rmw'}]
2020-05-26 11:55:05.015736 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - user_table http://127.0.5.1:8080 describe: {'AttributeDefinitions': [{'AttributeName': 'pk', 'AttributeType': 'S'}], 'TableName': 'user_table', 'KeySchema': [{'AttributeName': 'pk', 'KeyType': 'HASH'}], 'TableStatus': 'ACTIVE', 'CreationDateTime': datetime.datetime(2020, 5, 26, 11, 55, 5, tzinfo=tzlocal()), 'TableArn': 'arn:scylla:alternator:alternator_user_table:scylla:table/user_table', 'BillingModeSummary': {'BillingMode': 'PAY_PER_REQUEST', 'LastUpdateToPayPerRequestDateTime': datetime.datetime(2020, 5, 26, 11, 55, 5, tzinfo=tzlocal())}}
2020-05-26 11:55:05.022070 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - user_table http://127.0.5.4:8080 tags: []
2020-05-26 11:55:05.022175 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - user_table http://127.0.5.4:8080 describe: {'AttributeDefinitions': [{'AttributeName': 'pk', 'AttributeType': 'S'}], 'TableName': 'user_table', 'KeySchema': [{'AttributeName': 'pk', 'KeyType': 'HASH'}], 'TableStatus': 'ACTIVE', 'CreationDateTime': datetime.datetime(2020, 5, 26, 11, 55, 5, tzinfo=tzlocal()), 'TableArn': 'arn:scylla:alternator:alternator_user_table:scylla:table/user_table', 'BillingModeSummary': {'BillingMode': 'PAY_PER_REQUEST', 'LastUpdateToPayPerRequestDateTime': datetime.datetime(2020, 5, 26, 11, 55, 5, tzinfo=tzlocal())}}
2020-05-26 11:55:05.022439 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - (Waiting until table schema is updated (30.309685230255127 s)
2020-05-26 11:55:05.022519 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - Wait for: Waiting until table schema is updated: timeout - 30 seconds - expired
2020-05-26 11:55:05.025456 alternator_tests.py:AlternatorTest.test_update_condition_expression_and_write_isolation - Test failed with errors: [(<alternator_tests.AlternatorTest testMethod=test_update_condition_expression_and_write_isolation>, (<class 'dtest.WaitTimeoutExpired'>, WaitTimeoutExpired('Wait for: Waiting until table schema is updated: timeout - 30 seconds - expired'), <traceback object at 0x7f1edc3d9e00>))]

[nyh]

@yarongilor can you please write a test specifically for this issue - i.e., write the tags on dc1 and not how they are not readable on dc2? You can strip anything irrelevant from this test (no need to actually do a conditional update, no need to have more than one node on each dc, etc.) to have a clean reproducer for this issue.

[yarongilor]

node1_system.log
node4_system.log

[yarongilor]

Added a new test "test_modified_tag_is_propagated_to_other_dc" in:
https://github.com/scylladb/scylla-dtest/blob/4ab73604afbf2cc84fd762eac34811ee8f751024/alternator_tests.py#L269

[yarongilor]

system.log
system.log

[slivne]

@yarongilor does the dtest reproduce this ?

[nyh]

@slivne in an above comment, @yarongilor did point to a dtest reproducing this, test_modified_tag_is_propagated_to_other_dc - https://github.com/scylladb/scylla-dtest/blob/4ab73604afbf2cc84fd762eac34811ee8f751024/alternator_tests.py#L269

This may be a bigger issue than just Alternator (Alternator is just using Scylla's schema agreement protocols) but we still haven't started to debug what's causing it. The dtest reproduces just the Alternator-specific example.

[nyh]

@yarongilor, in #6455 @amoskong noticed that even without separate DCs, schema agreement can take a long time (in his test, 11 seconds). If I understand correctly, your test had a longer timeout (30 seconds), but still, can you please check whether "eventually" (e.g., after 5 minutes) the change does reach that other DC - or it actually never does reach the other DC? Thanks.

[yarongilor]

reproduced on increasing to 5 minutes timeout as well:

Traceback (most recent call last):
  File "/home/yarongilor/git/scylla-dtest/alternator_tests.py", line 313, in test_modified_tag_is_propagated_to_other_dc
    res = wait_for(self.is_table_schema_synced, timeout=300, step=3, text='Waiting until table schema is updated',
  File "/home/yarongilor/git/scylla-dtest/dtest.py", line 198, in wait_for
    raise WaitTimeoutExpired(err)
dtest.WaitTimeoutExpired: Wait for: Waiting until table schema is updated: timeout - 300 seconds - expired

2020-06-01 10:46:33.426463 alternator_tests.py:AlternatorTest.test_modified_tag_is_propagated_to_other_dc - user_table http://127.0.76.1:8080 tags: [{'Key': 'system:write_isolation', 'Value': 'forbid_rmw'}]
2020-06-01 10:46:33.426608 alternator_tests.py:AlternatorTest.test_modified_tag_is_propagated_to_other_dc - user_table http://127.0.76.1:8080 describe: {'AttributeDefinitions': [{'AttributeName': 'hash_key', 'AttributeType': 'S'}], 'TableName': 'user_table', 'KeySchema': [{'AttributeName': 'hash_key', 'KeyType': 'HASH'}], 'TableStatus': 'ACTIVE', 'CreationDateTime': datetime.datetime(2020, 6, 1, 10, 46, 33, tzinfo=tzlocal()), 'TableArn': 'arn:scylla:alternator:alternator_user_table:scylla:table/user_table', 'BillingModeSummary': {'BillingMode': 'PAY_PER_REQUEST', 'LastUpdateToPayPerRequestDateTime': datetime.datetime(2020, 6, 1, 10, 46, 33, tzinfo=tzlocal())}}
2020-06-01 10:46:33.431748 alternator_tests.py:AlternatorTest.test_modified_tag_is_propagated_to_other_dc - user_table http://127.0.76.2:8080 tags: []
2020-06-01 10:46:33.431879 alternator_tests.py:AlternatorTest.test_modified_tag_is_propagated_to_other_dc - user_table http://127.0.76.2:8080 describe: {'AttributeDefinitions': [{'AttributeName': 'hash_key', 'AttributeType': 'S'}], 'TableName': 'user_table', 'KeySchema': [{'AttributeName': 'hash_key', 'KeyType': 'HASH'}], 'TableStatus': 'ACTIVE', 'CreationDateTime': datetime.datetime(2020, 6, 1, 10, 46, 33, tzinfo=tzlocal()), 'TableArn': 'arn:scylla:alternator:alternator_user_table:scylla:table/user_table', 'BillingModeSummary': {'BillingMode': 'PAY_PER_REQUEST', 'LastUpdateToPayPerRequestDateTime': datetime.datetime(2020, 6, 1, 10, 46, 33, tzinfo=tzlocal())}}
2020-06-01 10:46:33.432060 alternator_tests.py:AlternatorTest.test_modified_tag_is_propagated_to_other_dc - (Waiting until table schema is updated (300.21320939064026 s)
2020-06-01 10:46:33.432112 alternator_tests.py:AlternatorTest.test_modified_tag_is_propagated_to_other_dc - Wait for: Waiting until table schema is updated: timeout - 300 seconds - expired
2020-06-01 10:46:33.432775 alternator_tests.py:AlternatorTest.test_modified_tag_is_propagated_to_other_dc - Test failed with errors: [(<alternator_tests.AlternatorTest testMethod=test_modified_tag_is_propagated_to_other_dc>, (<class 'dtest.WaitTimeoutExpired'>, WaitTimeoutExpired('Wait for: Waiting until table schema is updated: timeout - 300 seconds - expired'), <traceback object at 0x7f0b3c1a0700>))]

[fruch]

we merged those tests, and they are failing on master now
https://jenkins.scylladb.com/view/master/job/scylla-master/job/dtest-release/501/testReport/alternator_tests/AlternatorTest/test_modified_tag_is_propagated_to_other_dc/

[fruch]

@nyh did anyone took a look into this issue/test ?

[nyh]

No, sorry, I didn't get time to look at it yet. I'm unassigning myself from it, hoping someone else will have time for it. I'm not even sure this is an Alternator-specific bug, but I guess this will be part of the debugging.

[psarna]

This test case never works for me locally, because it always hits:

ERROR 2020-06-23 17:24:51,853 [shard 0] init - Startup failed: std::_Nested_exception<std::runtime_error> (Failed to set up Alternator HTTP server on 0.0.0.0 port 8080, TLS port OFF): std::system_error (error system:98, posix_listen failed for address 0.0.0.0:8080: Address already in use)

How to work around it? I checked and port 8080 is not taken by any processes before I start the test, so it looks like a clash of different alternator servers starting on the same machine.

[psarna]

Ok, I figured that my dtest repo was outdated, but now I can't run because of

ImportError: cannot import name 'AttributeValueTypeDef' from 'mypy_boto3_dynamodb.type_defs' (/home/sarna/.local/lib/python3.8/site-packages/mypy_boto3_dynamodb/type_defs.py)

I have mypy_boto3 installed in the latest version - is the test adapted for Fedora32? I'll try hacking around this issue for now.

[psarna]

Alright, the first error still applies - the test always fails because it's unable to bind to 0.0.0.0:8080. Wasn't the idea to bind to local addresses instead of 0.0.0.0? Is it a known issue I can easily work around?

[psarna]

The issue disappeared after updating scylla-ccm.

[psarna]

The problem is as follows: in order to update tags I used an internal CQL call (ALTER TABLE), naively thinking that schema propagation will take care of the rest. Unfortunately, internal statements have a special flag which prevents the schema from propagating! Which is useful for local system tables, but not for distributed tags. Effectively, tags will only be visible for the node which received the request, until gossip detects that schemas does not match. I'll fix it by altering the table in a different way which ensures propagation. Once this fix is ready, hopefully tomorrow at the latest, it should be backported to 4.1, 4.0.

[nyh]

@psarna great you found the reason. And @yarongilor thanks again for finding this bug, which would have otherwise gone unnoticed.

[psarna]

Well, that's is embarassing. I wrote the original code which uses internal CQL queries because I was too lazy, but it turns out the correct code is even shorter... I'll send a fix soon, the test already started passing.

[nyh]

@psarna I think you should also open a new issue about these "internal CQL queries" doing the wrong thing. Why should an "internal CQL query" do almost the right thing, but not quite? If "internal CQL queries" are not usable (for whatever reasons) for non-local tables then the code should contain an assert(), and a clear comment saying it shouldn't be used. Otherwise we can make the same mistake again in the future - and it's not easy to catch these mistakes because it requires testing on multiple DCs. I think now that you know what the problem is, maybe it will be easier for you to add such an assert() and/or comment - or - alternatively - fix the behavior of these internal queries to be correctly also for global tables.

[psarna]

Yeah, the internal queries do the right thing, since they expect local tables, I just used them in a wrong way - I'll try to find a place to add an assertion, so that people do not make the same mistake.

[nyh]

backported to next-4.1 (dfa464c35b9f403a3ba1e9b6f9baa6c0ce776ee2) and next-4.0 (e95bcd0f8f2f8f99875a66e320dfa56163e4430e)