# Binding tester heisenbug with API version 710 and tenant **URL:** \ **Category:** Development\ **Tags:** bindings\ **Created:** [May 9, 2022, 4:23am UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306 "2022-05-09T04:23:30Z")\ **Posts on this page:** 20\ **Page:** 1
**Author:** ![rajivr](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/rajivr/32/1100_2.png) [@rajivr](https://forums.foundationdb.org/u/rajivr)\ **Post date:** [May 9, 2022, 4:23am UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/1 "2022-05-09T04:23:30Z")
I’ve Tokio/Rust bindings CI setup to continuously run binding tester. Recently I encountered an [unusual failure](https://github.com/fdb-rs/fdb/runs/6340413041) with FDB version 7.1.3 and API version 710. The failing seed according to CI is `1191235632` and it fails with the following error message ```auto Incorrect result: rust - ('tester_output', 'stack', 630, 24440) = b'\x01GOT_RANGE_SPLIT_POINTS\x00' python - ('tester_output', 'stack', 630, 24440) = b'\x01\x01ERROR\x00\xff\x012131\x00\xff\x00' Test with seed 1191235632 and concurrency 1 had 1 incorrect result(s) and 0 error(s) at API version 710 ``` From the failure, it looks like Python bindings detected a `2131` (`tenant_not_found`) error, whereas the Rust bindings was able to complete the `get_range_split_points` instruction successfully. When I tried to replicate failure locally, using the failing seed, the error disappeared, and the seed passed successfully. What would be the recommended approach for dealing with such heisenbugs? ---
**Author:** ![ajbeamon](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/ajbeamon/32/13_2.png) [@ajbeamon](https://forums.foundationdb.org/u/ajbeamon)\ **Post date:** [May 9, 2022, 3:40pm UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/2 "2022-05-09T15:40:20Z")
Some of these types of issues can be a bit tricky. Sometimes I’ll set up a bindingtester job to run the same seed repeatedly to see how common the failure reproduces. If it’s frequent enough, then that kind of reproduction can be enough to debug what’s happening and validate a fix. Another strategy is to look at the sequence of instructions leading up to the failed instruction, often with some extra debugging output added. For example, in this case you have a tenant that isn’t found, and so you could determine what tenant is being used and what kind of operations have been performed on that tenant. If you see that it was recently created or deleted for example, then there may be some sort of race between the creation/deletion and the use of the tenant. It can help to manually run through the instructions to determine what you think should happen, which can give clues to where things might go wrong. If what you are seeing is that typically both bindings report a successful call to get the split points but only Python failed the one time, then it’s likely the problem isn’t the rust bindings. It could be something in the Python bindings or tester, something non-deterministic about the generated test, or even an issue in the core FoundationDB client. In any of these cases, I would expect the error to appear occasionally for us as well, so perhaps we’ll come across it soon. ---
**Author:** ![rajivr](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/rajivr/32/1100_2.png) [@rajivr](https://forums.foundationdb.org/u/rajivr)\ **Post date:** [May 9, 2022, 10:56pm UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/3 "2022-05-09T22:56:21Z")
Thanks @ajbeamon for the reply! ---
**Author:** ![rajivr](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/rajivr/32/1100_2.png) [@rajivr](https://forums.foundationdb.org/u/rajivr)\ **Post date:** [May 10, 2022, 3:33am UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/4 "2022-05-10T03:33:30Z")
I just had another similar [failure](https://github.com/fdb-rs/fdb/runs/6360741531), so I decided to investigate further. For the seed `1191235632`, the sequence of instructions is as follows. ```auto 24433. 'RESET' 24435. 'TENANT_DELETE' 24436. 'WAIT_FUTURE' 24440. 'GET_RANGE_SPLIT_POINTS' 24443. 'READ_CONFLICT_RANGE' ``` For the seed `3275318271`, the sequence of instructions is very similar and is as follows. ```auto 26949. 'RESET' 26951. 'TENANT_DELETE' 26952. 'WAIT_FUTURE' 26956. 'GET_RANGE_SPLIT_POINTS' 26957. 'RESET' ``` The code that implements `TENANT_DELETE` instruction in Rust is very similar to the Java implementation. Rust implementation is [here](https://github.com/fdb-rs/fdb/blob/fdb-0.3.1/fdb/src/tenant/tenant_management.rs#L78-L119). Java implementation is [here](https://github.com/apple/foundationdb/blob/7.1.3/bindings/java/src/main/com/apple/foundationdb/TenantManagement.java#L171-L190). I was wondering if you might be able to spot any issue in the Rust implementation? I could be wrong, but It looks to me that in the Rust implementation, for some reason the C binding layer is returning that tenant deletion was successful, and in some cases _not returning an error_ for the subsequent `GET_RANGE_SPLIT_POINTS` instruction. Also when I was investigating this issue, I tried to figure out where [`_TENANT`](https://github.com/apple/foundationdb/blob/7.1.3/bindings/bindingtester/spec/tenantTester.md#_tenant-suffix) suffix instructions were getting added in [`api.py`](https://github.com/apple/foundationdb/blob/7.1.3/bindings/bindingtester/tests/api.py#L150-L168) since I didn’t find any `_TENANT` suffix instructions. Shouldn’t `api.py`'s `generate` method contain something along the lines? ```auto tenant_reads = [x + '_TENANT' for x in reads] tenant_mutations = [x + '_TENANT' for x in mutations] ``` ---
**Author:** ![ajbeamon](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/ajbeamon/32/13_2.png) [@ajbeamon](https://forums.foundationdb.org/u/ajbeamon)\ **Post date:** [May 11, 2022, 6:15pm UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/5 "2022-05-11T18:15:10Z")
> [@rajivr](#): > > Also when I was investigating this issue, I tried to figure out where [`_TENANT`](https://github.com/apple/foundationdb/blob/7.1.3/bindings/bindingtester/spec/tenantTester.md#_tenant-suffix) suffix instructions were getting added in [`api.py`](https://github.com/apple/foundationdb/blob/7.1.3/bindings/bindingtester/tests/api.py#L150-L168) since I didn’t find any `_TENANT` suffix instructions. > > Shouldn’t `api.py` 's `generate` method contain something along the lines? Good catch, yes that should be added. > I was wondering if you might be able to spot any issue in the Rust implementation? I don’t spot anything in a first look. You said re-running the test doesn’t fail every time, do you know if in that case both bindings are reporting that the split points operation failed or if both cases had the operation succeed? ---
**Author:** ![rajivr](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/rajivr/32/1100_2.png) [@rajivr](https://forums.foundationdb.org/u/rajivr)\ **Post date:** [May 12, 2022, 1:22am UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/6 "2022-05-12T01:22:15Z")
> [@ajbeamon](#): > > You said re-running the test doesn’t fail every time, do you know if in that case both bindings are reporting that the split points operation failed or if both cases had the operation succeed? AFAICT, its is only the Rust bindings that occasionally reports `GOT_RANGE_SPLIT_POINTS` when it should be reporting an error. The Tokio/Rust implementation of `get_range_split_points` is [here](https://github.com/fdb-rs/fdb/blob/fdb-0.3.1/fdb/src/transaction/fdb_transaction.rs#L273-L286) and [here](https://github.com/fdb-rs/fdb/blob/fdb-0.3.1/fdb/src/transaction/fdb_transaction.rs#L744-L769). I am not really doing anything other than just calling the C API. ---
**Author:** ![PierreZ](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/pierrez/32/866_2.png) [@PierreZ](https://forums.foundationdb.org/u/PierreZ)\ **Post date:** [October 6, 2022, 10:25am UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/7 "2022-10-06T10:25:01Z")
Funny story, I’m also [experiencing `2131` errors during bindingTester](https://github.com/foundationdb-rs/foundationdb-rs/actions/runs/3196194750/jobs/5217799983) 🙃 Digging 👀 @rajivr, did you disable some tests on your side? ---
**Author:** ![rajivr](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/rajivr/32/1100_2.png) [@rajivr](https://forums.foundationdb.org/u/rajivr)\ **Post date:** [October 6, 2022, 11:26am UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/8 "2022-10-06T11:26:36Z")
> [@PierreZ](#): > > Funny story, I’m also [experiencing `2131` errors during bindingTester](https://github.com/foundationdb-rs/foundationdb-rs/actions/runs/3196194750/jobs/5217799983) 🙃 > Digging 👀 I would be _really_ interested if you are able to fix this issue. So far, I’ve had no luck. > [@PierreZ](#): > > @rajivr, did you disable some tests on your side? The only test that I’ve disabled is versionstamp v1 format as that is not supported in my bindings. It is documented [here](https://github.com/fdb-rs/fdb/tree/fdb-0.3.1/fdb-stacktester/fdb-stacktester-710/bindingtester). ---
**Author:** ![PierreZ](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/pierrez/32/866_2.png) [@PierreZ](https://forums.foundationdb.org/u/PierreZ)\ **Post date:** [October 7, 2022, 2:36pm UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/9 "2022-10-07T14:36:32Z")
Okay, after some digging, here’s what I found: I’m experiencing many tenant-related error on the Rust-bindings. I decided to dig on the seed `3181802154` on FoundationDB (7.1.23). BindingTester is the latest commit on the `release-7.1`. The seed is passing on my laptop running Linux, and failing on Github Actions: ```auto Incorrect result: rust - ('tester_output', 'stack', 1174, 19426) = b'\x01\x01ERROR\x00\xff\x011025\x00\xff\x00' python - ('tester_output', 'stack', 1174, 19426) = b'\x01\x01ERROR\x00\xff\x012131\x00\xff\x00' Test with seed 3181802154 and concurrency 1 had 1 incorrect result(s) and 0 error(s) at API version 710 Completed api test with random seed 3181802154 and 1000 operations ``` We have error 1025(`transaction_cancelled`) on Rust whereas we have 2131(`tenant_not_found`) on operation `19426`. I forked my branch, and start hacking. I managed to reduce the scope of the problem to two jobs in the same job [run](https://github.com/foundationdb-rs/foundationdb-rs/actions/runs/3204829394): - one that is [failing](https://github.com/foundationdb-rs/foundationdb-rs/actions/runs/3204829394/jobs/5236591311), - one that is [succeeding](https://github.com/foundationdb-rs/foundationdb-rs/actions/runs/3204829394/jobs/5236591311). They are both trying to run 50 iterations of the same seed. The only difference is that I’ve added [an ugly sleep](https://github.com/foundationdb-rs/foundationdb-rs/blob/5f355582c474ecfef2cb2d62a58d54bf7c2cc229/foundationdb-bindingtester/src/main.rs#L2753-L2757) of 4ms between each op near `19426` to make it work. I know tenants are an experimental features, but I have the feeling that the Rust code is executing faster than Python, causing a race-condition somewhere 🤔 Following this debug, I have some questions: - On the official CI, how many cores are used during `bindingTester` tests? Github Actions runners have only 2-core CPU. - are tenant-operations async internally somehwere? - I cannot see any tenant op in the Flow bindings, is it planned? I could use some help or advices to fix that issue 👀 ---
**Author:** ![rajivr](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/rajivr/32/1100_2.png) [@rajivr](https://forums.foundationdb.org/u/rajivr)\ **Post date:** [October 8, 2022, 2:04am UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/10 "2022-10-08T02:04:19Z")
> [@PierreZ](#): > > I managed to reduce the scope of the problem to two jobs in the same job [run](https://github.com/foundationdb-rs/foundationdb-rs/actions/runs/3204829394): > > - one that is [failing](https://github.com/foundationdb-rs/foundationdb-rs/actions/runs/3204829394/jobs/5236591311), > - one that is [succeeding](https://github.com/foundationdb-rs/foundationdb-rs/actions/runs/3204829394/jobs/5236591311). > > They are both trying to run 50 iterations of the same seed. The only difference is that I’ve added [an ugly sleep](https://github.com/foundationdb-rs/foundationdb-rs/blob/5f355582c474ecfef2cb2d62a58d54bf7c2cc229/foundationdb-bindingtester/src/main.rs#L2753-L2757) of 4ms between each op near `19426` to make it work. > > I know tenants are an experimental features, but I have the feeling that the Rust code is executing faster than Python, causing a race-condition somewhere 🤔 Thanks @PierreZ for the awesome work in helping to reproduce this issue. The CI for my bindings is on a previous version (7.1.12), and I too [regularly](https://github.com/fdb-rs/fdb/actions?query=is%3Afailure) see this error. Other than this one error, the binding tester is very stable. ---
**Author:** ![ajbeamon](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/ajbeamon/32/13_2.png) [@ajbeamon](https://forums.foundationdb.org/u/ajbeamon)\ **Post date:** [October 8, 2022, 3:07am UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/11 "2022-10-08T03:07:29Z")
My usual questions for starting an investigation into an issue like this are: 1. Does the test always fail? If so, then that’s usually the easier case and we’re mainly need to find out where the two errors are coming from. 2. If not, is one of the binding testers producing a stable result? For example, do we most of the time get error 2131 in both bindings but occasionally 1025 in rust (or the opposite)? Or maybe both bindings occasionally give 1025 while usually giving 2131? If only rust gives the 1025 error and then only some of the time, then it could be a subtle behavior difference in the bindings. That doesn’t necessarily mean that they binding implementation is to blame, but it could be revealing a non-determinism in the client behavior. This is of course harder to debug because of the difficulty in reproduction, and I’ll sometimes turn on more verbose logging and as some extra instrumentation before sending it off to try a bunch of runs. 3. What are the operations being run when the failure happens? The specific operation is useful, as well as any others in the same or concurrent transactions. Some of the times I’ve seen cases where the same operation has generated 2 different errors, both errors are valid in the context and which you get depends on which one you hit first. Still there can often be managed, and the first step is understanding why the operation would generate the errors. ---
**Author:** ![ajbeamon](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/ajbeamon/32/13_2.png) [@ajbeamon](https://forums.foundationdb.org/u/ajbeamon)\ **Post date:** [October 8, 2022, 3:11am UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/12 "2022-10-08T03:11:35Z")
I’ll add that I don’t think I’ve seen this problem (though I haven’t run the binding tester on 7.1 in a while, maybe something has been fixed since). If I had a reproduction I could play with using the standard bindings, I would try to lend a hand tracking it down, but otherwise I can try to offer suggestions based on any findings you have. ---
**Author:** ![PierreZ](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/pierrez/32/866_2.png) [@PierreZ](https://forums.foundationdb.org/u/PierreZ)\ **Post date:** [October 10, 2022, 8:45am UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/13 "2022-10-10T08:45:48Z")
Thanks a lot @ajbeamon for your suggestions 😄 I will try to answer them the best way I can: > [@ajbeamon](#): > > Does the test always fail? If so, then that’s usually the easier case and we’re mainly need to find out where the two errors are coming from. The test is always failing on Github Actions. I’ve just tested 200 iterations of [the same seed](https://github.com/foundationdb-rs/foundationdb-rs/pull/74/commits/1274be3dbdf1225d21366b533603801d9c166f07). [The lastest run](https://github.com/foundationdb-rs/foundationdb-rs/actions/runs/3217600052) is: - failing without sleep at the very first iteration, - succeedding with a sleep of 4ms on 200 iterations. > [@ajbeamon](#): > > If not, is one of the binding testers producing a stable result? For example, do we most of the time get error 2131 in both bindings but occasionally 1025 in rust (or the opposite)? Or maybe both bindings occasionally give 1025 while usually giving 2131? If only rust gives the 1025 error and then only some of the time, then it could be a subtle behavior difference in the bindings. That doesn’t necessarily mean that they binding implementation is to blame, but it could be revealing a non-determinism in the client behavior. This is of course harder to debug because of the difficulty in reproduction, and I’ll sometimes turn on more verbose logging and as some extra instrumentation before sending it off to try a bunch of runs. It’s an hardware-based stable result 🙈 For the `3181802154` seed on operation `19426`: - in Python, I’m always experiencing 2131 - in Rust, I’m experiencing either: - 2131 on a local, more beefy machine, - 2131 on Github Actions with a 4ms sleep after each op between 18900 and 1950, - 1025 on Github Actions without a sleep. > [@rajivr](#): > > Recently I encountered an [unusual failure](https://github.com/fdb-rs/fdb/runs/6340413041) with FDB version 7.1.3 and API version 710. > > The failing seed according to CI is `1191235632` and it fails with the following error message > > ```auto > Incorrect result: > rust - ('tester_output', 'stack', 630, 24440) = b'\x01GOT_RANGE_SPLIT_POINTS\x00' > python - ('tester_output', 'stack', 630, 24440) = b'\x01\x01ERROR\x00\xff\x012131\x00\xff\x00' > > Test with seed 1191235632 and concurrency 1 had 1 incorrect result(s) and 0 error(s) at API version 710 > > ``` > > From the failure, it looks like Python bindings detected a `2131` (`tenant_not_found`) error, whereas the Rust bindings was able to complete the `get_range_split_points` instruction successfully. I’m seeing also this error on previous runs on other seeds. The similarity are quite high: - Same low-level rust librairies, - CI both based on Github Actions, - python bindings experiencing `2131`, - rust binding experiencing another behavior, from errors to a succeeding transaction. > [@ajbeamon](#): > > What are the operations being run when the failure happens? The specific operation is useful, as well as any others in the same or concurrent transactions. I’m not sure what you mean by operations being run. As far as I know: - I’m not running operations other than the [previous operations](https://gist.github.com/PierreZ/e12548442392c58fc67099b8c7387bef), - I have no parallelism enabled in `./bindings/bindingtester/bindingtester.py --num-ops 1000 --api-version $fdb_api_version --test-name api --compare python rust --seed 3181802154` ---
**Author:** ![ajbeamon](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/ajbeamon/32/13_2.png) [@ajbeamon](https://forums.foundationdb.org/u/ajbeamon)\ **Post date:** [October 10, 2022, 1:45pm UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/14 "2022-10-10T13:45:15Z")
> [@PierreZ](#): > > I’m not sure what you mean by operations being run. I meant to say the sequence of instructions run by the binding tester. You can use the `--print` option to print the sequence of instructions for a seed (and add `--all` I believe to include even the less interesting instructions). In this output: ```auto rust - ('tester_output', 'stack', 1174, 19426) ``` The 19426 refers to the instruction number, so you can track it back down to the particular instruction that failed and look at what ran leading up to it. This doesn’t always point you to the most relevant place, so it’s also helpful if you have a stable result to use `--bisect`. This will run the test repeatedly with different numbers of instructions until it finds the minimum number that produces your error. Then you pass that number into `--num-ops` and rerun the smaller reproduction and/or print the test instructions and see how it ends. ---
**Author:** ![PierreZ](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/pierrez/32/866_2.png) [@PierreZ](https://forums.foundationdb.org/u/PierreZ)\ **Post date:** [October 12, 2022, 9:08am UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/15 "2022-10-12T09:08:36Z")
> [@ajbeamon](#): > > I meant to say the sequence of instructions run by the binding tester. You can use the `--print` option to print the sequence of instructions for a seed (and add `--all` I believe to include even the less interesting instructions). Thanks for the tips, it will help me display relevant operations. > [@ajbeamon](#): > > This doesn’t always point you to the most relevant place, so it’s also helpful if you have a stable result to use `--bisect`. This will run the test repeatedly with different numbers of instructions until it finds the minimum number that produces your error. Then you pass that number into `--num-ops` and rerun the smaller reproduction and/or print the test instructions and see how it ends. Running [–bisect](https://github.com/foundationdb-rs/foundationdb-rs/actions/runs/3233184084/jobs/5294707898) is confirming that something strange is going on, here’s an extract of the logs: ```auto Test with seed 3181802154 and concurrency 1 had 0 incorrect result(s) and 0 error(s) at API version 710 Completed api test with random seed 3181802154 and 500 operations Test with seed 3181802154 and concurrency 1 had 0 incorrect result(s) and 0 error(s) at API version 710 Completed api test with random seed 3181802154 and 750 operations Test with seed 3181802154 and concurrency 1 had 1 incorrect result(s) and 0 error(s) at API version 710 Completed api test with random seed 3181802154 and 875 operations Test with seed 3181802154 and concurrency 1 had 0 incorrect result(s) and 0 error(s) at API version 710 Completed api test with random seed 3181802154 and 813 operations # Same logs with 0 errors and operations {844, 860, 852, 848, 846, 845} Error finding minimal failing test for seed 3181802154. The failure may not be deterministic ``` We also started running integrations tests (which are starting an fdb testcontainer) on our layers with tenants enabled, and we are also hitting the same `tenant_not_found` error, even if it has been created. I’m not sure why, but sleeping before running the tests seems to fix the issue. I will keep digging, much faster now that I can reproduce locally through our integration tests. ---
**Author:** ![PierreZ](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/pierrez/32/866_2.png) [@PierreZ](https://forums.foundationdb.org/u/PierreZ)\ **Post date:** [October 13, 2022, 9:08am UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/16 "2022-10-13T09:08:09Z")
To add more details, on our integrations tests, we are spinning up an fdb container running `7.1.23`. From several tests, I discovered that tests are always failing if I’m starting my tests right after `configure new single memory tenant_mode=optional_experimental;createtenant test` with a `tenant_not_found` error. Waiting for database to be healthy before starting the test fixed the issue 🙈 I tried adding some sleep on the bindingTester, with no success. ---
**Author:** ![PierreZ](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/pierrez/32/866_2.png) [@PierreZ](https://forums.foundationdb.org/u/PierreZ)\ **Post date:** [October 19, 2022, 8:35am UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/17 "2022-10-19T08:35:27Z")
I didn’t have time to look at the issue, but is there some tenants-caching involved internally in fdbclient/fdb? ### EDIT 17 of november 2022 I finally had the time to dig a bit more: - my assumption that I can reproduce it locally is wrong, it was another issue on our side 🙈 - we have not encountered the bug in our layers, which are using the tenant branch, - It is still failling on CI. I added more pipelines to try to retrieve more patterns: - `./bindings/bindingtester/bindingtester.py --num-ops 1000 --api-version $fdb_api_version --test-name api --compare python rust --seed 3181802154` is failing without a sleep and succeeds with a sleep([Exhibit A](https://github.com/foundationdb-rs/foundationdb-rs/actions/runs/3489980557/jobs/5840803261) and [B](https://github.com/foundationdb-rs/foundationdb-rs/actions/runs/3489980557/jobs/5840803505), code difference is [here](https://github.com/foundationdb-rs/foundationdb-rs/blob/be156847b0e36ee050c18a11ef6e0ee4c040832a/foundationdb-bindingtester/src/main.rs#L2764-L2771)) - [brute-forcing --bisect](https://github.com/foundationdb-rs/foundationdb-rs/actions/runs/3489980560) on multiple fdb versions is showing that: - it fails randomly during bisect when sleep is disabled, regardless of fdb’s version(`Error finding minimal failing test for seed 3181802154. The failure may not be deterministic`) - it always succeeds when sleep is enabled, regardless of fdb’s version(`No failing test found for seed 3181802154 with 1000 ops. Try specifying a larger --num-ops parameter.`) I’m not sure on how I could debug more this issue, any ideas @ajbeamon ? My question above still remains, is there some tenant-caching in libfdb/fdbserver? ---
**Author:** ![ajbeamon](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/ajbeamon/32/13_2.png) [@ajbeamon](https://forums.foundationdb.org/u/ajbeamon)\ **Post date:** [November 18, 2022, 11:47pm UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/18 "2022-11-18T23:47:49Z")
I spent a little bit of time digging into the get range split points operation and what might go wrong with it. I don’t have an exact answer yet, but there are a couple things that seemed interesting. First, are you running your test against a cluster that has more than one process in it? I think that all of our binding tester runs involve only one process in the cluster, and if you are doing something different it could represent something worth exploring. The other thing is that the `getRangeSplitPoints` function does not actually get a read version on the client to send to the cluster for this request. Instead, it gets answered based on the most recent data on the server process it talks to. That means that if you delete a tenant and then succeed in sending a `getRangeSplitPoints` request to a storage server for that tenant, that server may get the request before it learns of the deletion. It would therefore not actually fail. Running more than one process in your cluster could make this scenario more likely, as there would be a longer delay between data being committed and getting sent to the storage server. The last relevant bit involves what the client does when it wants to use a tenant as part of an operation. It needs to look up some details about the tenant, which it either learns from the commit proxy or gets locally from cache. Ordinarily reading the local cache would have been fine because the server process should reject the request if the cache was stale, but as mentioned above that isn’t happening here with an unversioned request. That means it is also possible that there is some race involving this entry showing up in your client cache. This seems less likely (I think it would require that no successful operation on this tenant has been completed yet and that one is outstanding), but it may also be possible. As a side note, some of what I described above (in particular, the caching behavior on the client) is likely going to change soon. ---
**Author:** ![PierreZ](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/pierrez/32/866_2.png) [@PierreZ](https://forums.foundationdb.org/u/PierreZ)\ **Post date:** [November 21, 2022, 4:02pm UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/19 "2022-11-21T16:02:46Z")
> [@ajbeamon](#): > > I spent a little bit of time digging into the get range split points operation and what might go wrong with it. I don’t have an exact answer yet, but there are a couple things that seemed interesting. Thanks a lot for spending time on it 😄 > [@ajbeamon](#): > > I think that all of our binding tester runs involve only one process in the cluster, and if you are doing something different it could represent something worth exploring. I’m not doing something different. > [@ajbeamon](#): > > The other thing is that the `getRangeSplitPoints` function does not actually get a read version on the client to send to the cluster for this request. Instead, it gets answered based on the most recent data on the server process it talks to. > > That means that if you delete a tenant and then succeed in sending a `getRangeSplitPoints` request to a storage server for that tenant, that server may get the request before it learns of the deletion. It would therefore not actually fail. Running more than one process in your cluster could make this scenario more likely, as there would be a longer delay between data being committed and getting sent to the storage server. > > The last relevant bit involves what the client does when it wants to use a tenant as part of an operation. It needs to look up some details about the tenant, which it either learns from the commit proxy or gets locally from cache. Ordinarily reading the local cache would have been fine because the server process should reject the request if the cache was stale, but as mentioned above that isn’t happening here with an unversioned request. > > That means it is also possible that there is some race involving this entry showing up in your client cache. This seems less likely (I think it would require that no successful operation on this tenant has been completed yet and that one is outstanding), but it may also be possible. > > As a side note, some of what I described above (in particular, the caching behavior on the client) is likely going to change soon. That could explains the error when combining `getRangeSplitPoints` and `tenants`, thanks for digging that out. If I put aside those types of errors, I’m oftenly seeing a transaction cancelled in Rust where it should be `tenant_not_found`: ```auto Incorrect result: rust - ('tester_output', 'stack', 1308, 26689) = b'\x01\x01ERROR\x00\xff\x011025\x00\xff\x00' python - ('tester_output', 'stack', 1308, 26689) = b'\x01\x01ERROR\x00\xff\x012131\x00\xff\x00' Test with seed 2834048320 and concurrency 1 had 1 incorrect result(s) and 0 error(s) at API version 710 Completed api test with random seed 2834048320 and 1000 operations ``` Those errors are only appearing on the CI, and I can’t reproduce the error locally. I will try to add more a more beefy CI server, because I have no idea how reliable those Github Actions VMs are 🙈 Also, could you share how the bindingTester is runned on the official CI? I’m mostly looking for information like: - how many ops and which scenarios are run, - how many core and ram are available, - how the loop is handled. - Is there a retry strategy on a seed? - do you fail on each errors? My goal is to be more closer to what you are using 😄 ---
**Author:** ![ajbeamon](https://sea1.discourse-cdn.com/foundationdb/user_avatar/forums.foundationdb.org/ajbeamon/32/13_2.png) [@ajbeamon](https://forums.foundationdb.org/u/ajbeamon)\ **Post date:** [November 22, 2022, 12:36am UTC](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306/20 "2022-11-22T00:36:05Z")
I’m not really sure what kind of hardware we use, but I can point you to the scripts that we use to run the binding tester. I’m not super familiar with what the details of what these scripts do, but I can give a summary from my understanding. The basic idea is that for a given run, we start with [bindingTest.sh](https://github.com/apple/foundationdb/blob/main/contrib/Joshua/scripts/bindingTest.sh), which does a little setup and then runs [bindingTestScript.sh](https://github.com/apple/foundationdb/blob/main/contrib/Joshua/scripts/bindingTestScript.sh). This creates a local cluster (using [localClusterStart.sh](https://github.com/apple/foundationdb/blob/main/contrib/Joshua/scripts/localClusterStart.sh)) and then starts [run\_binding\_tester.sh](https://github.com/apple/foundationdb/blob/main/bindings/bindingtester/run_binding_tester.sh) to actually run the binding tester. This last script has some logic to choose a particular set of arguments for the test and runs it. We basically package all of this up and run it across a test framework that executes this whole process a bunch of times (with random seeds, etc., each time). I believe each run only does one run of the binding tester, and if the binding tester reports that the run failed (I think by exit code), then we will consider the test failed. We don’t really retry the same set of arguments in any automated way, but when we get reports of failures we would re-run the test manually. [Next page](https://forums.foundationdb.org/t/binding-tester-heisenbug-with-api-version-710-and-tenant/3306.md?page=2)