Jepsen: lost write due to intersecting transactions both committing #2885

snaury · 2024-03-18T11:47:52Z

I've been running Jepsen over the weekend, and got a couple of weird failures. I've tried to investigate this case so far, formatted for readability:

G-single-item-realtime #0
Let:
  T1 = {:index 307889, :time 309547049652, :type :ok, :process 193, :f :txn,
    :value [
        [:append 198 986]
        [:r 198 [2 5 6 7 11 12 15 21 27 31 32 35 49 53 57 61 68 70 76 80 81 87 89 94 95 96 99 101 108 109 113 114 123 126 141 144 145 154 155 163 166 174 175 176 185 186 187 193 200 210 215 225 231 240 242 245 252 254 262 263 268 281 284 289 297 305 309 310 313 314 321 322 326 334 341 346 352 354 362 386 387 393 398 407 423 428 433 439 445 460 466 467 470 476 482 489 490 502 503 508 513 523 531 534 535 538 546 553 564 571 576 586 597 607 608 609 630 637 639 645 646 649 651 658 660 666 670 680 685 693 710 724 733 744 751 756 775 781 782 784 786 798 800 801 812 823 824 830 837 840 852 853 861 867 871 872 906 924 926 927 937 940 947 948 953 963 964 968 969 986]]],
    :modified-txn [
        [:commit nil [:batch nil [[:append 198 986] [:r 198 nil]]]]],
    :debug-info [
        [
            {:tablet 72075186227119711, :acquired-locks [{:lock-id 844432915039999, :counter 10019}], :gen 1, :read-version "v1710698143592/18446744073709551615", :op "read", :finished true, :node 50001, :keys 0, :seqno 1, :read-id 1, :ranges 1, :snapshot-repeatable true, :lock-tx-id 844432915039999, :read-rows 169}
            {:tablet 72075186227119711, :acquired-locks [{:lock-id 844432915039999, :counter 10019, :has-writes true}], :gen 1, :op "kqp-tx", :node 50001, :snapshot "v1710698143592/18446744073709551615", :tx-id 844432915040058, :snapshot-repeatable true, :lock-tx-id 844432915039999}
            {:tablet 72075186227119711, :acquired-locks [{:lock-id 844432915039999, :counter 10019, :has-writes true}], :gen 1, :read-version "v1710698143592/18446744073709551615", :op "read", :finished true, :node 50001, :keys 0, :seqno 1, :read-id 0, :ranges 1, :snapshot-repeatable true, :lock-tx-id 844432915039999, :read-rows 170}
            {:tablet 72075186227119711, :gen 1, :op "kqp-tx", :node 50001, :locks-op "commit", :tx-id 844432915040112, :version "v1710698143605/0", :validate-locks [{:lock-id 844432915039999, :counter 10019, :has-writes true}]}]]}
  T2 = {:index 306836, :time 308975535691, :type :ok, :process 10, :f :txn,
    :value [
        [:append 198 667]],
    :modified-txn [
        [:commit nil [:batch nil [[:append 198 667]]]]],
    :debug-info [
        [
            {:tablet 72075186227119711, :acquired-locks [{:lock-id 281482960303871, :counter 9189}], :gen 1, :read-version "v1710698143031/18446744073709551615", :op "read", :finished true, :node 50001, :keys 0, :seqno 1, :read-id 1, :ranges 1, :snapshot-repeatable true, :lock-tx-id 281482960303871, :read-rows 125}
            {:tablet 72075186227119711, :gen 1, :op "kqp-tx", :node 50001, :locks-op "commit", :tx-id 281482960303890, :version "v1710698143041/18446744073709551615", :validate-locks [{:lock-id 281482960303871, :counter 9189}]}]]}
  T3 = {:index 306920, :time 309027458496, :type :ok, :process 276, :f :txn,
    :value [
        [:append 144 414]
        [:r 169 [1 4 5 6 8 11 13 15 24 33 38 41 42 43 45 47 49 51 52 54 57 65 72 74 75 77 78 80 82 91 98 100 102 104 108 109 114 118 119 120 123 128 132 135 137 138 140 146 147 152 154 158 161 163 165 166 173 175 176 180 181 183 184 186 187 190 193 194 195 200 206 210 212 214 215 216 221 223 225 230 231 235 238 242 244 245 253 254 256 257 261 263 266 270 271 273 274 278 286 287 290 293 294 300 302 303 304 305 307 309 311 312 313 316 317 318 319 329 330 331 333 335 339 343 346 348 349 351 352 354 360 362 363 367 368 369 379 387 389 394 395 400 402 403 404 406 407 408 409 417 419 420 421 422 424 425 426 430 434 435 437 438 441 443 445 446 450 454 455 457 466 468 472 473 475 476 479 481 485 488 495 498 502 504 505 508 511 512 514 515 517 518 519 523 525 527 528 529 530 535 537 538 541 551 552 555 557 560 563 567 568 569 570 574 575 576 582 584 589 591 596 598 605 613 618 619 626 627 633 635 641 642 647 648 649 651 654 656 658 662 671 674 677 680 683 686 687 689 691 693 700 702 704 712 716 717 725 726 730 736 737 741 742 746 751 754 755 756 758 759 764 767 770 773 774 777 781 787 790 795 810 812 813 815 817 819 820 822 825 828 829 834 836 841 843 846 847 852 854 857 863 864 866 871 872 874 875 878 879 881 886 888 897 898 900 914 915 916 920 924 928 933 937 939 941 944 945 962 966 969]]
        [:append 198 685]],
    :modified-txn [
        [:commit nil [:batch nil [[:append 144 414] [:r 169 nil] [:append 198 685]]]]],
    :debug-info [
        [
            {:tablet 72075186227119617, :acquired-locks [{:lock-id 281482960304100, :counter 116}], :gen 3, :read-version "v1710698143062/18446744073709551615", :op "read", :finished true, :node 50008, :keys 0, :seqno 1, :read-id 1, :ranges 1, :snapshot-repeatable true, :lock-tx-id 281482960304100, :read-rows 125}
            {:tablet 72075186227119617, :acquired-locks [{:lock-id 281482960304100, :counter 116, :has-writes true}], :gen 3, :op "kqp-tx", :node 50008, :snapshot "v1710698143062/18446744073709551615", :tx-id 281482960304112, :snapshot-repeatable true, :lock-tx-id 281482960304100}
            {:tablet 72075186227119711, :acquired-locks [{:lock-id 281482960304100, :counter 9237}], :gen 1, :read-version "v1710698143062/18446744073709551615", :op "read", :finished true, :node 50001, :keys 0, :seqno 1, :read-id 1, :ranges 1, :snapshot-repeatable true, :lock-tx-id 281482960304100, :read-rows 128}
            {:tablet 72075186227119710, :acquired-locks [{:lock-id 281482960304100, :counter 241}], :gen 3, :read-version "v1710698143062/18446744073709551615", :op "read", :finished true, :node 50005, :keys 0, :seqno 1, :read-id 0, :ranges 1, :snapshot-repeatable true, :lock-tx-id 281482960304100, :read-rows 330}
            {:tablet 72075186227119710, :gen 3, :op "kqp-tx", :node 50005, :locks-op "commit", :tx-id 281482960304209, :version "v1710698143075/281482960304209", :step 1710698143075, :validate-locks [{:lock-id 281482960304100, :counter 241}]}
            {:tablet 72075186227119711, :gen 1, :op "kqp-tx", :node 50001, :locks-op "commit", :tx-id 281482960304209, :version "v1710698143075/281482960304209", :step 1710698143075, :validate-locks [{:lock-id 281482960304100, :counter 9237}]}
            {:tablet 72075186227119617, :gen 3, :op "kqp-tx", :node 50008, :locks-op "commit", :tx-id 281482960304209, :version "v1710698143075/281482960304209", :step 1710698143075, :validate-locks [{:lock-id 281482960304100, :counter 116, :has-writes true}]}]]}
  T4 = {:index 307116, :time 309137635732, :type :ok, :process 372, :f :txn,
    :value [
        [:r 169 [1 4 5 6 8 11 13 15 24 33 38 41 42 43 45 47 49 51 52 54 57 65 72 74 75 77 78 80 82 91 98 100 102 104 108 109 114 118 119 120 123 128 132 135 137 138 140 146 147 152 154 158 161 163 165 166 173 175 176 180 181 183 184 186 187 190 193 194 195 200 206 210 212 214 215 216 221 223 225 230 231 235 238 242 244 245 253 254 256 257 261 263 266 270 271 273 274 278 286 287 290 293 294 300 302 303 304 305 307 309 311 312 313 316 317 318 319 329 330 331 333 335 339 343 346 348 349 351 352 354 360 362 363 367 368 369 379 387 389 394 395 400 402 403 404 406 407 408 409 417 419 420 421 422 424 425 426 430 434 435 437 438 441 443 445 446 450 454 455 457 466 468 472 473 475 476 479 481 485 488 495 498 502 504 505 508 511 512 514 515 517 518 519 523 525 527 528 529 530 535 537 538 541 551 552 555 557 560 563 567 568 569 570 574 575 576 582 584 589 591 596 598 605 613 618 619 626 627 633 635 641 642 647 648 649 651 654 656 658 662 671 674 677 680 683 686 687 689 691 693 700 702 704 712 716 717 725 726 730 736 737 741 742 746 751 754 755 756 758 759 764 767 770 773 774 777 781 787 790 795 810 812 813 815 817 819 820 822 825 828 829 834 836 841 843 846 847 852 854 857 863 864 866 871 872 874 875 878 879 881 886 888 897 898 900 914 915 916 920 924 928 933 937 939 941 944 945 962 966 969]]
        [:append 169 976]],
    :modified-txn [
        [:batch nil [[:r 169 nil] [:append 169 976]]]],
    :debug-info [
        [
            {:tablet 72075186227119710, :acquired-locks [{:lock-id 281482960305138, :counter 246}], :gen 3, :read-version "v1710698143181/18446744073709551615", :op "read", :finished true, :node 50005, :keys 0, :seqno 1, :read-id 1, :ranges 1, :snapshot-repeatable true, :lock-tx-id 281482960305138, :read-rows 330}
            {:tablet 72075186227119710, :acquired-locks [{:lock-id 281482960305138, :counter 246}], :gen 3, :read-version "v1710698143181/18446744073709551615", :op "read", :finished true, :node 50005, :keys 0, :seqno 1, :read-id 0, :ranges 1, :snapshot-repeatable true, :lock-tx-id 281482960305138, :read-rows 330}]
        [
            {:tablet 72075186227119710, :gen 3, :op "kqp-tx", :node 50005, :locks-op "commit", :tx-id 281482960305294, :version "v1710698143202/0", :validate-locks [{:lock-id 281482960305138, :counter 246}]}]]}
  T5 = {:index 307638, :time 309412303749, :type :ok, :process 318, :f :txn,
    :value [
        [:append 193 985]
        [:append 169 985]],
    :modified-txn [
        [:batch nil [[:append 193 985] [:append 169 985]]]],
    :debug-info [
        [
            {:tablet 72075186227119710, :acquired-locks [{:lock-id 281482960313928, :counter 257}], :gen 3, :read-version "v1710698143462/18446744073709551615", :op "read", :finished true, :node 50005, :keys 0, :seqno 1, :read-id 1, :ranges 1, :snapshot-repeatable true, :lock-tx-id 281482960313928, :read-rows 331}
            {:tablet 72075186227119711, :acquired-locks [{:lock-id 281482960313928, :counter 9821}], :gen 1, :read-version "v1710698143462/18446744073709551615", :op "read", :node 50001, :keys 0, :seqno 1, :read-id 2, :ranges 1, :snapshot-repeatable true, :lock-tx-id 281482960313928, :read-rows 66}
            {:tablet 72075186227119711, :gen 1, :read-version "v1710698143462/18446744073709551615", :op "read", :finished true, :node 50001, :keys 0, :seqno 2, :read-id 2, :ranges 1, :snapshot-repeatable true, :lock-tx-id 281482960313928, :read-rows 177}]
        [
            {:tablet 72075186227119710, :gen 3, :op "kqp-tx", :node 50005, :locks-op "commit", :tx-id 281482960313998, :version "v1710698143472/281482960313998", :step 1710698143472, :validate-locks [{:lock-id 281482960313928, :counter 257}]}
            {:tablet 72075186227119711, :gen 1, :op "kqp-tx", :node 50001, :locks-op "commit", :tx-id 281482960313998, :version "v1710698143472/281482960313998", :step 1710698143472, :validate-locks [{:lock-id 281482960313928, :counter 9821}]}]]}
  T6 = {:index 307744, :time 309465926073, :type :ok, :process 32, :f :txn,
    :value [
        [:r 198 [2 5 6 7 11 12 15 21 27 31 32 35 49 53 57 61 68 70 76 80 81 87 89 94 95 96 99 101 108 109 113 114 123 126 141 144 145 154 155 163 166 174 175 176 185 186 187 193 200 210 215 225 231 240 242 245 252 254 262 263 268 281 284 289 297 305 309 310 313 314 321 322 326 334 341 346 352 354 362 386 387 393 398 407 423 428 433 439 445 460 466 467 470 476 482 489 490 502 503 508 513 523 531 534 535 538 546 553 564 571 576 586 597 607 608 609 630 637 639 645 646 649 651 658 660 666 670 680 685 693 710 724 733 744 751 756 775 781 782 784 786 798 800 801 812 823 824 830 837 840 852 853 861 867 871 872 906 924]]
        [:r 198 [2 5 6 7 11 12 15 21 27 31 32 35 49 53 57 61 68 70 76 80 81 87 89 94 95 96 99 101 108 109 113 114 123 126 141 144 145 154 155 163 166 174 175 176 185 186 187 193 200 210 215 225 231 240 242 245 252 254 262 263 268 281 284 289 297 305 309 310 313 314 321 322 326 334 341 346 352 354 362 386 387 393 398 407 423 428 433 439 445 460 466 467 470 476 482 489 490 502 503 508 513 523 531 534 535 538 546 553 564 571 576 586 597 607 608 609 630 637 639 645 646 649 651 658 660 666 670 680 685 693 710 724 733 744 751 756 775 781 782 784 786 798 800 801 812 823 824 830 837 840 852 853 861 867 871 872 906 924]]
        [:r 193 [2 5 13 17 21 25 26 28 29 35 36 37 38 42 43 45 48 51 54 56 58 59 60 61 64 67 68 70 72 76 77 80 81 87 88 96 98 99 100 103 111 113 115 117 120 136 141 143 147 149 150 151 152 154 158 160 161 167 174 178 179 185 186 188 189 193 195 198 203 206 211 220 222 225 232 233 240 243 248 256 258 259 260 264 269 275 280 281 283 288 299 301 312 313 321 322 332 338 341 343 346 349 352 354 359 363 373 377 386 392 394 398 399 403 407 417 423 424 428 432 449 455 465 468 461 473 475 478 483 490 492 493 495 496 497 502 504 505 508 511 512 514 515 518 522 523 525 527 528 530 532 539 543 546 551 553 556 560 561 563 567 569 570 572 578 579 582 586 587 593 594 598 599 604 606 608 609 613 616 621 626 628 629 630 633 649 657 663 665 674 676 683 694 697 709 726 736 741 745 746 754 761 764 778 788 794 795 798 799 800 813 822 842 846 850 858 863 867 871 884 885 889 890 892 895 898 899 904 909 911 920 921 925 927 934 944 952 955 959 963 970 974 977 985 987]]],
    :modified-txn [
        [:commit nil [:batch nil [[:r 198 nil] [:r 198 nil] [:r 193 nil]]]]],
    :debug-info [
        [
            {:tablet 72075186227119711, :gen 1, :read-version "v1710698143505/18446744073709551615", :op "read", :finished true, :node 50001, :keys 0, :seqno 1, :read-id 0, :ranges 1, :snapshot-repeatable true, :read-rows 245}
            {:tablet 72075186227119711, :gen 1, :read-version "v1710698143505/18446744073709551615", :op "read", :node 50001, :keys 0, :seqno 1, :read-id 0, :ranges 1, :snapshot-repeatable true, :read-rows 1}
            {:tablet 72075186227119711, :gen 1, :read-version "v1710698143505/18446744073709551615", :op "read", :node 50001, :keys 0, :seqno 2, :read-id 0, :ranges 1, :snapshot-repeatable true, :read-rows 27}
            {:tablet 72075186227119711, :gen 1, :read-version "v1710698143505/18446744073709551615", :op "read", :finished true, :node 50001, :keys 0, :seqno 3, :read-id 0, :ranges 1, :snapshot-repeatable true, :read-rows 130}
            {:tablet 72075186227119711, :gen 1, :read-version "v1710698143505/18446744073709551615", :op "read", :node 50001, :keys 0, :seqno 1, :read-id 0, :ranges 1, :snapshot-repeatable true, :read-rows 1}
            {:tablet 72075186227119711, :gen 1, :read-version "v1710698143505/18446744073709551615", :op "read", :node 50001, :keys 0, :seqno 2, :read-id 0, :ranges 1, :snapshot-repeatable true, :read-rows 27}
            {:tablet 72075186227119711, :gen 1, :read-version "v1710698143505/18446744073709551615", :op "read", :finished true, :node 50001, :keys 0, :seqno 3, :read-id 0, :ranges 1, :snapshot-repeatable true, :read-rows 130}]]}
  T7 = {:index 307798, :time 309498438771, :type :ok, :process 145, :f :txn,
    :value [
        [:r 198 [2 5 6 7 11 12 15 21 27 31 32 35 49 53 57 61 68 70 76 80 81 87 89 94 95 96 99 101 108 109 113 114 123 126 141 144 145 154 155 163 166 174 175 176 185 186 187 193 200 210 215 225 231 240 242 245 252 254 262 263 268 281 284 289 297 305 309 310 313 314 321 322 326 334 341 346 352 354 362 386 387 393 398 407 423 428 433 439 445 460 466 467 470 476 482 489 490 502 503 508 513 523 531 534 535 538 546 553 564 571 576 586 597 607 608 609 630 637 639 645 646 649 651 658 660 666 670 680 685 693 710 724 733 744 751 756 775 781 782 784 786 798 800 801 812 823 824 830 837 840 852 853 861 867 871 872 906 924 926 927 937 940]]
        [:r 198 [2 5 6 7 11 12 15 21 27 31 32 35 49 53 57 61 68 70 76 80 81 87 89 94 95 96 99 101 108 109 113 114 123 126 141 144 145 154 155 163 166 174 175 176 185 186 187 193 200 210 215 225 231 240 242 245 252 254 262 263 268 281 284 289 297 305 309 310 313 314 321 322 326 334 341 346 352 354 362 386 387 393 398 407 423 428 433 439 445 460 466 467 470 476 482 489 490 502 503 508 513 523 531 534 535 538 546 553 564 571 576 586 597 607 608 609 630 637 639 645 646 649 651 658 660 666 670 680 685 693 710 724 733 744 751 756 775 781 782 784 786 798 800 801 812 823 824 830 837 840 852 853 861 867 871 872 906 924 926 927 937 940]]
        [:r 197 [7 9 15 16 19 21 23 26 29 30 33 35 37 41 43 44 52 64 65 72 79 83 85 88 91 92 94 98 102 104 106 109 110 113 114 116 119 129 139 155 165 166 169 175 183 184 188 193 202 203 208 214 229 235 241 243 249 252 238 263 265 271 274 278 283 290 292 300 307 309 312 320 323 324 343 347 355 359 365 375 381 384 390 392 394 395 399 400 401 409 413 419 428 429 430 435 443 451 455 456 465 469 470 473 479 480 486 492 503 506 512 514 515 519 527 529 538 542 548 554 555 558 565 566 569 575 580 586 590 598 611 626 629 640 649 658 662 677 683 692 697 704 705 707 713 719 723 732 742 743 751 756 757 765 779 792 800 804 813 816 821 825 828 829 836 840 841 844 854]]],
    :modified-txn [
        [:batch nil [[:r 198 nil]]]
        [:commit nil [:batch nil [[:r 198 nil] [:r 197 nil]]]]],
    :debug-info [
        [
            {:tablet 72075186227119711, :gen 1, :read-version "v1710698143541/18446744073709551615", :op "read", :finished true, :node 50001, :keys 0, :seqno 1, :read-id 0, :ranges 1, :snapshot-repeatable true, :broken-locks [{:lock-id 844432915039567, :counter 18446744073709551612N}], :lock-tx-id 844432915039567, :read-rows 162}]
        [
            {:tablet 72075186227119711, :gen 1, :read-version "v1710698143541/18446744073709551615", :op "read", :finished true, :node 50001, :keys 0, :seqno 1, :read-id 0, :ranges 1, :snapshot-repeatable true, :read-rows 169}
            {:tablet 72075186227119711, :gen 1, :read-version "v1710698143541/18446744073709551615", :op "read", :finished true, :node 50001, :keys 0, :seqno 1, :read-id 0, :ranges 1, :snapshot-repeatable true, :read-rows 162}]]}

Then:
  - T1 < T2, because T2 appended 667 after T1 appended 986 to 198.
  - T2 < T3, because T2 completed at index 306836, 0.017 seconds before the invocation of T3, at index 306874.
  - T3 < T4, because T3 did not observe T4's append of 976 to 169.
  - T4 < T5, because T5 appended 985 after T4 appended 976 to 169.
  - T5 < T6, because T5 completed at index 307638, 0.023 seconds before the invocation of T6, at index 307674.
  - T6 < T7, because T6 completed at index 307744, 0.004 seconds before the invocation of T7, at index 307753.
  - However, T7 < T1, because T7 completed at index 307798, 0.023 seconds before the invocation of T1, at index 307828: a contradiction!

Here's the max suffix read of the key 198:

[:r 198 [2 5 6 7 11 12 15 21 27 31 32 35 49 53 57 61 68 70 76 80 81 87 89 94 95 96 99 101 108 109 113 114 123 126 141 144 145 154 155 163 166 174 175 176 185 186 187 193 200 210 215 225 231 240 242 245 252 254 262 263 268 281 284 289 297 305 309 310 313 314 321 322 326 334 341 346 352 354 362 386 387 393 398 407 423 428 433 439 445 460 466 467 470 476 482 489 490 502 503 508 513 523 531 534 535 538 546 553 564 571 576 586 597 607 608 609 630 637 639 645 646 649 651 658 660 666 670 680 685 693 710 724 733 744 751 756 775 781 782 784 786 798 800 801 812 823 824 830 837 840 852 853 861 867 871 872 906 924 926 927 937 940 947 948 953 963 964 968 969 986]]

It is kinda visible, that the append of 667 in T2 was lost, even though ydb replied with success.

I searched the history and found these appends surrounding 667, sorted by commit timestamp:

{:index 306838, :time 308976215025, :type :ok, :process 88, :f :txn,
    :value [
        [:append 198 666]
        [:append 140 961]],
    :modified-txn [
        [:batch nil [[:append 198 666] [:append 140 961]]]],
    :debug-info [
        [
            {:tablet 72075186227119617, :acquired-locks [{:lock-id 281482960303854, :counter 113}], :gen 3, :read-version "v1710698143031/18446744073709551615", :op "read", :finished true, :node 50008, :keys 0, :seqno 1, :read-id 1, :ranges 1, :snapshot-repeatable true, :lock-tx-id 281482960303854, :read-rows 334}
            {:tablet 72075186227119711, :acquired-locks [{:lock-id 281482960303854, :counter 9183}], :gen 1, :read-version "v1710698143031/18446744073709551615", :op "read", :node 50001, :keys 0, :seqno 1, :read-id 2, :ranges 1, :snapshot-repeatable true, :lock-tx-id 281482960303854, :read-rows 1}
            {:tablet 72075186227119711, :gen 1, :read-version "v1710698143031/18446744073709551615", :op "read", :finished true, :node 50001, :keys 0, :seqno 2, :read-id 2, :ranges 1, :snapshot-repeatable true, :lock-tx-id 281482960303854, :read-rows 124}]
        [
            {:tablet 72075186227119711, :gen 1, :op "kqp-tx", :node 50001, :locks-op "commit", :tx-id 281482960303899, :version "v1710698143041/281482960303899", :step 1710698143041, :validate-locks [{:lock-id 281482960303854, :counter 9183}]}
            {:tablet 72075186227119617, :gen 3, :op "kqp-tx", :node 50008, :locks-op "commit", :tx-id 281482960303899, :version "v1710698143041/281482960303899", :step 1710698143041, :validate-locks [{:lock-id 281482960303854, :counter 113}]}]]}
{:index 306836, :time 308975535691, :type :ok, :process 10, :f :txn,
    :value [
        [:append 198 667]],
    :modified-txn [
        [:commit nil [:batch nil [[:append 198 667]]]]],
    :debug-info [
        [
            {:tablet 72075186227119711, :acquired-locks [{:lock-id 281482960303871, :counter 9189}], :gen 1, :read-version "v1710698143031/18446744073709551615", :op "read", :finished true, :node 50001, :keys 0, :seqno 1, :read-id 1, :ranges 1, :snapshot-repeatable true, :lock-tx-id 281482960303871, :read-rows 125}
            {:tablet 72075186227119711, :gen 1, :op "kqp-tx", :node 50001, :locks-op "commit", :tx-id 281482960303890, :version "v1710698143041/18446744073709551615", :validate-locks [{:lock-id 281482960303871, :counter 9189}]}]]}
{:index 306864, :time 308987322000, :type :ok, :process 13, :f :txn,
    :value [
        [:append 198 670]
        [:append 199 81]],
    :modified-txn [
        [:commit nil [:batch nil [[:append 198 670] [:append 199 81]]]]],
    :debug-info [
        [
            {:tablet 72075186227119711, :acquired-locks [{:lock-id 844432915030958, :counter 9195}], :gen 1, :read-version "v1710698143041/18446744073709551615", :op "read", :node 50001, :keys 0, :seqno 1, :read-id 1, :ranges 2, :snapshot-repeatable true, :lock-tx-id 844432915030958, :read-rows 127}
            {:tablet 72075186227119711, :gen 1, :read-version "v1710698143041/18446744073709551615", :op "read", :finished true, :node 50001, :keys 0, :seqno 2, :read-id 1, :ranges 2, :snapshot-repeatable true, :lock-tx-id 844432915030958, :read-rows 24}
            {:tablet 72075186227119711, :gen 1, :op "kqp-tx", :node 50001, :locks-op "commit", :tx-id 844432915031077, :version "v1710698143052/0", :validate-locks [{:lock-id 844432915030958, :counter 9195}]}]]}

Note there have been no shard restarts or anything like that. Appends of 666 and 667 definitely intersect (read snapshot vs commit version), only one of them was supposed to succeed, yet both have :type :ok.

Even more interesting are shard logs on these operations:

append 666:
    lock 281482960303854 commit 281482960303899
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.988524Z :TX_DATASHARD DEBUG: 72075186227119711 Acquired lock# 281482960303854, counter# 9183 for [OwnerId: 72075186224037889, LocalPathId: 13244]
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.992288Z :TX_DATASHARD DEBUG: Prepared DataTx transaction txId 281482960303899 at tablet 72075186227119711
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.993632Z :TX_DATASHARD DEBUG: Planned transaction txId 281482960303899 at step 1710698143041 at tablet 72075186227119711 { Transactions { TxId: 281482960303899 AckTo { RawX1: 7347392433000221188 RawX2: 214774134604117 } } Step: 1710698143041 MediatorID: 72075186224037895 TabletID: 72075186227119711 }
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.993651Z :TX_DATASHARD DEBUG: Receive RS at 72075186227119711 source 72075186227119617 dest 72075186227119711 producer 72075186227119617 txId 281482960303899
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.993659Z :TX_DATASHARD DEBUG: TTxReadSet::Execute at 72075186227119711 got read set: {TEvReadSet step# 1710698143041 txid# 281482960303899 TabletSource# 72075186227119617 TabletDest# 72075186227119711 SetTabletProducer# 72075186227119617 ReadSet.Size()# 0 Seqno# 0 Flags# 7}
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.994301Z :TX_DATASHARD DEBUG: Found ready operation [1710698143041:281482960303899] in PlanQueue unit at 72075186227119711
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.994305Z :TX_DATASHARD DEBUG: LoadTxDetails at 72075186227119711 got data tx from cache 1710698143041:281482960303899
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.994421Z :TX_DATASHARD DEBUG: tx 281482960303899 released its data
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.994448Z :TX_DATASHARD DEBUG: Receive RS at 72075186227119711 source 72075186227119617 dest 72075186227119711 producer 72075186227119617 txId 281482960303899
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.994455Z :TX_DATASHARD DEBUG: TTxReadSet::Execute at 72075186227119711 got read set: {TEvReadSet step# 1710698143041 txid# 281482960303899 TabletSource# 72075186227119617 TabletDest# 72075186227119711 SetTabletProducer# 72075186227119617 ReadSet.Size()# 2 Seqno# 549 Flags# 0}
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.995264Z :TX_DATASHARD DEBUG: tx 281482960303899 at 72075186227119711 restored its data
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.995429Z :TX_DATASHARD DEBUG: Sending '{TEvPlanStepAck TabletId# 72075186227119711 step# 1710698143041 txid# 281482960303899}
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.995574Z :TX_DATASHARD DEBUG: Committing changes commitTxId# 281482960303899 in localTid# 1001 version# v1710698143041/281482960303899 while committing volatile txId# 281482960303899 shard# 72075186227119711
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.996614Z :TX_DATASHARD DEBUG: Send RS at 72075186227119711 from 72075186227119711 to 72075186227119617 txId 281482960303899
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.996630Z :TX_DATASHARD DEBUG: Complete [1710698143041 : 281482960303899] from 72075186227119711 at tablet 72075186227119711 send result to client [50004:7347392576362066415:7524], exec latency: 1 ms, propose latency: 2 ms
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.996640Z :TX_DATASHARD DEBUG: Send delayed Ack RS Ack at 72075186227119711 {TEvReadSet step# 1710698143041 txid# 281482960303899 TabletSource# 72075186227119617 TabletDest# 72075186227119711 SetTabletConsumer# 72075186227119711 Flags# 0 Seqno# 549}
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.998293Z :TX_DATASHARD DEBUG: Receive RS Ack at 72075186227119711 source 72075186227119711 dest 72075186227119617 consumer 72075186227119617 txId 281482960303899
Mar 17 20:55:43 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:43.027081Z :TX_DATASHARD DEBUG: Deleted RS at 72075186227119711 source 72075186227119711 dest 72075186227119617 consumer 72075186227119617 seqno 250 txId 281482960303899

append 667:
    lock 281482960303871 commit 281482960303890
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.990966Z :TX_DATASHARD DEBUG: 72075186227119711 Acquired lock# 281482960303871, counter# 9189 for [OwnerId: 72075186224037889, LocalPathId: 13244]
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.992014Z :TX_DATASHARD DEBUG: tx 281482960303890 released its data
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.994933Z :TX_DATASHARD DEBUG: tx 281482960303890 at 72075186227119711 restored its data

append 670:
    lock 844432915030958 commit 844432915031077
Mar 17 20:55:42 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:42.999237Z :TX_DATASHARD DEBUG: 72075186227119711 Acquired lock# 844432915030958, counter# 9195 for [OwnerId: 72075186224037889, LocalPathId: 13244]
Mar 17 20:55:43 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:43.006049Z :TX_DATASHARD DEBUG: tx 844432915031077 released its data
Mar 17 20:55:43 ydb-vla-dev03-000 kikimr_31003[3742032]: 2024-03-17T17:55:43.006361Z :TX_DATASHARD DEBUG: tx 844432915031077 at 72075186227119711 restored its data

Judging by "restored its data" timestamps we have append 667 finishing first (with write version v1710698143041/18446744073709551615), then we have append 666 finishing second (with write version v1710698143041/281482960303899), and then append 670 acquiring locks after both transactions have committed.

What we have here is append 667 (immediate) first running before append 666 (distributed) was prepared, at 992014Z (probably hit a page fault or something else). Then at 994305Z by LoadTxDetails message we can infer the distributed tx got to BuildAndWaitDependencies, and it released its data at 994421Z because it either conflicted with something, or tried executing and page faulted. Now append 667 restores its data at 994933Z and likely finishes executing. Then finally append 666 restores its data at 995264Z and succeeds as well.

Now append of 667 is supposed to break conflicting locks, it likely does so at version v1710698143041/18446744073709551615. Then append of 666 runs and sees that its lock is not broken at v1710698143041/281482960303899, so it executes as well.

What's unclear is how this reversal happened. We are supposed to choose immediate write version that sticks to the front of the next version in the transaction queue. It's possible we executed something out-of-order, but in that case we should have marked distributed transactions as "logically complete", which would in turn should have promoted immediate conflicts, and we are supposed to have had a hard dependency of 281482960303890 on 281482960303899, but it clearly didn't happen for some reason.

The text was updated successfully, but these errors were encountered:

snaury · 2024-03-18T12:30:26Z

One more clue, the distributed tx likely tried to execute before 994421Z after all, because BuildAndWaitDependencies logs an additional message when it releases tx data, so the data was released after it attempted to execute. This still doesn't explain how we could choose a version above it without it also marked logically complete or incomplete (and promoting dependencies). And step 1710698143041 had exactly one transaction at that shard.

snaury · 2024-03-18T13:14:20Z

Searched history for other operations with versions v1710698143041/*:

Found [:r 193 nil] [:append 197 713] which committed at v1710698143041/281482960303899 (just before that distributed tx)
- This would have promoted ImmediateWriteEdge to v1710698143041/281482960303899
Found [:r 198 nil] which got two read results, reading from v1710698143041/281482960303899, and it had :snapshot-repeatable true
- Since this read iterator didn't read all results at once it upgraded itself to repeatable snapshot
- This would have promoted UnprotectedReadEdge to v1710698143041/281482960303899
- New calls to GetMvccTxVersion would choose versions above 281482960303899 after this point
Found [:r 197 nil] which was reading from v1710698143041/18446744073709551615 without repeatable snapshot
- Since transaction queue was empty above 281482960303899 this is expected, we stick everything to the end of the current mediator step

Need to check whether repeatable read/write are promoted correctly in this case.

snaury · 2024-03-18T13:18:50Z

Looks like the bug is in PromoteImmediatePostExecuteEdges. It calls MarkPlannedLogicallyCompleteUpTo for the provided version, which only marks transactions below that version (non inclusive). However in RepeatableRead case all future writes must be above the given version, which means everything up to that version (inclusive) must be marked logically incomplete.

snaury · 2024-03-18T13:39:12Z

On the other hand repeatable snapshot reads are supposed to include all conflicting changes at or below the given version, so it was supposed to wait until 281482960303899 is executed (otherwise supposedly repeatable snapshot would change after it commits, it was even reading the same key). It's unclear what was the exact order though.

snaury · 2024-03-18T13:48:45Z

There could also be a race between plan step handling and plan queue starting the operation. When we choose versions we look at transaction queue, however it is possible that the front of the queue in not in active ops yet. In that case we won't be able to add a dependency to something that doesn't exist in dependency tracker yet.

This would also explain why this is relatively rare and needed many days to trigger.

snaury · 2024-03-18T16:37:34Z

A second case, where [:append 231 506] appears to have been lost. Two intersecting appends, both succeed, distributed tx "wins", and there was a repeatable snapshot read at the distributed tx version:

{:index 360873, :time 265884687662, :type :ok, :process 48, :f :txn,
    :value [
        [:r 233 [1 11 19 21 22 34 43 49 52 57 62 84 85]]
        [:append 231 506]],
    :modified-txn [
        [:batch nil [[:r 233 nil]]]
        [:commit nil [:batch nil [[:append 231 506]]]]],
    :debug-info [
        [
            {:tablet 72075186227192357, :acquired-locks [{:lock-id 844433076673900, :counter 3093}], :gen 2, :read-version "v1710723696832/18446744073709551615", :op "read", :finished true, :node 50004, :keys 0, :seqno 1, :read-id 0, :ranges 1, :snapshot-repeatable true, :lock-tx-id 844433076673900, :read-rows 13}]
        [
            {:tablet 72075186227192357, :acquired-locks [{:lock-id 844433076673900, :counter 3093}], :gen 2, :read-version "v1710723696832/18446744073709551615", :op "read", :finished true, :node 50004, :keys 0, :seqno 1, :read-id 1, :ranges 1, :snapshot-repeatable true, :lock-tx-id 844433076673900, :read-rows 57}
            {:tablet 72075186227192357, :gen 2, :op "kqp-tx", :node 50004, :locks-op "commit", :tx-id 844433076674053, :version "v1710723696852/18446744073709551615", :validate-locks [{:lock-id 844433076673900, :counter 3093}]}]]}
{:index 360883, :time 265888181362, :type :ok, :process 116, :f :txn,
    :value [
        [:append 205 976]
        [:append 231 500]],
    :modified-txn [
        [:batch nil [[:append 205 976]]]
        [:commit nil [:batch nil [[:append 231 500]]]]],
    :debug-info [
        [
            {:tablet 72075186227192356, :acquired-locks [{:lock-id 281483121537200, :counter 187}], :gen 2, :read-version "v1710723696830/18446744073709551615", :op "read", :finished true, :node 50001, :keys 0, :seqno 1, :read-id 1, :ranges 1, :snapshot-repeatable true, :lock-tx-id 281483121537200, :read-rows 303}]
        [
            {:tablet 72075186227192356, :acquired-locks [{:lock-id 281483121537200, :counter 187, :has-writes true}], :gen 2, :op "kqp-tx", :node 50001, :snapshot "v1710723696830/18446744073709551615", :tx-id 281483121537284, :snapshot-repeatable true, :lock-tx-id 281483121537200}
            {:tablet 72075186227192357, :acquired-locks [{:lock-id 281483121537200, :counter 3104}], :gen 2, :read-version "v1710723696830/18446744073709551615", :op "read", :finished true, :node 50004, :keys 0, :seqno 1, :read-id 1, :ranges 1, :snapshot-repeatable true, :lock-tx-id 281483121537200, :read-rows 57}
            {:tablet 72075186227192357, :gen 2, :op "kqp-tx", :node 50004, :locks-op "commit", :tx-id 281483121537398, :version "v1710723696852/281483121537398", :step 1710723696852, :validate-locks [{:lock-id 281483121537200, :counter 3104}]}
            {:tablet 72075186227192356, :gen 2, :op "kqp-tx", :node 50001, :locks-op "commit", :tx-id 281483121537398, :version "v1710723696852/281483121537398", :step 1710723696852, :validate-locks [{:lock-id 281483121537200, :counter 187, :has-writes true}]}]]}
{:index 360886, :time 265890293112, :type :ok, :process 144, :f :txn,
    :value [
        [:r 232 [3 4 15 20 21 22 23 27 30 34 41 46 55 57 59 62 68 69 70 75 76 85 93 94 95 102 103 107 108 114 127 128 135 148 149 156 157 165 171 172 179 180 188 189 190 195 196 227 232 233 236 237 248 249 256 262 267 275 282 291 293 294 296 299 300 308 309 313 319 321 324 338 339 354 355 364 384 385 379 380 401 409 415 421 430 434 464 468 489 490 501 502 503 509 510 523 541 550 560 567 570 573 575 586 587 588 605 608 619 628 633 644 645 646 652 669 670 671 706 707 708 709 717 723 736 741 753 754 774 780 791 801 819 825 834 862 876 901 922 928]]],
    :modified-txn [
        [:commit nil [:batch nil [[:r 232 nil]]]]],
    :debug-info [
        [
            {:tablet 72075186227192357, :gen 2, :read-version "v1710723696852/281483121537398", :op "read", :node 50004, :keys 0, :seqno 1, :read-id 0, :ranges 1, :snapshot-repeatable true, :read-rows 1}
            {:tablet 72075186227192357, :gen 2, :read-version "v1710723696852/281483121537398", :op "read", :finished true, :node 50004, :keys 0, :seqno 2, :read-id 0, :ranges 1, :snapshot-repeatable true, :read-rows 139}]]}

Notice how the read is for an unrelated key, technically it doesn't have to wait for a distributed tx with [:append 231 500] (currently it tries though).

ydb-platform#3037)

…m#2885. (ydb-platform#3074)

snaury added bug Something isn't working area/datashard Issues related to datashard tablets (relational table partitions) labels Mar 18, 2024

snaury self-assigned this Mar 18, 2024

snaury added a commit to snaury/ydb that referenced this issue Mar 21, 2024

Fix read iterator local snapshot consistency. Fixes ydb-platform#2885.

678e3ad

snaury mentioned this issue Mar 21, 2024

Fix read iterator local snapshot consistency. Fixes #2885. #3037

Merged

snaury closed this as completed in #3037 Mar 22, 2024

snaury added a commit that referenced this issue Mar 22, 2024

Fix read iterator local snapshot consistency. Fixes #2885. (#3037)

17708e5

snaury added a commit to snaury/ydb that referenced this issue Mar 22, 2024

Fix read iterator local snapshot consistency. Fixes ydb-platform#2885. (

e3630b0

ydb-platform#3037)

snaury mentioned this issue Mar 22, 2024

24-1: Fix read iterator local snapshot consistency. Fixes #2885. #3074

Merged

snaury added a commit that referenced this issue Mar 22, 2024

24-1: Fix read iterator local snapshot consistency. Fixes #2885. (#3074)

112be1a

shnikd mentioned this issue Mar 22, 2024

Support sequences backup with current value #3089

Merged

GrigoriyPA mentioned this issue Mar 26, 2024

YQ-2738 add integration tests for YT in KQP #3150

Merged

shnikd mentioned this issue Mar 26, 2024

Test temp indexes #3163

Merged

This was referenced Mar 29, 2024

Unmute kafka tests #3285

Merged

Fix kafka counters and RU #3348

Merged

StekPerepolnen mentioned this issue Apr 2, 2024

HC send whiteboard request when hive knows it's alive #3391

Merged

serbel324 mentioned this issue Apr 2, 2024

Add tracing to load actor #3395

Merged

This was referenced Apr 4, 2024

hotkeys crush on describe #3462

Merged

added QuotaStorage to tenantinfo response #3463

Merged

query stats full #3464

Merged

shnikd mentioned this issue Apr 4, 2024

Support create sequence in pg parser #3465

Merged

StekPerepolnen mentioned this issue Apr 4, 2024

hc api: updated possible problems #3482

Open

This was referenced Apr 6, 2024

Fix kafka read session verify #3522

Merged

Fix kafka read session partitions releases #3528

Merged

niksaveliev mentioned this issue Apr 8, 2024

Kafka fix verigy and partitions releases to 24-1 #3536

Closed

SammyVimes pushed a commit to SammyVimes/ydb that referenced this issue Apr 9, 2024

24-1: Fix read iterator local snapshot consistency. Fixes ydb-platfor…

40926e4

…m#2885. (ydb-platform#3074)

StekPerepolnen mentioned this issue Apr 10, 2024

hc fallback when static group has unknown status #3620

Merged

shnikd mentioned this issue Apr 11, 2024

Support create sequence #3662

Merged

This was referenced Apr 16, 2024

json_autocomplete error reports #3784

Merged

json_storage added pdiskid filter #4037

Merged

GrigoriyPA mentioned this issue Apr 24, 2024

YQ-3006 fix drop table for external entities #4063

Closed

serbel324 mentioned this issue Apr 25, 2024

Introduce local SyncLog data cutter #4124

Merged

StekPerepolnen mentioned this issue Apr 26, 2024

NBYDB 14/tenantinfo disconnected merge 24-1 #4129

Closed

mregrock mentioned this issue May 15, 2024

stable 24 1 #4538

Closed

StekPerepolnen mentioned this issue May 24, 2024

merge 24 1/hc hive sync status fix #4840

Closed

This was referenced Jun 7, 2024

Merge discarded messages sensors #5326

Closed

stable 24 1 #5327

Closed

CyberROFL mentioned this issue Jun 19, 2024

fixes #5741

Closed

CyberROFL mentioned this issue Jul 12, 2024

24-2: Fix bugs in: change exchange split, removing schema snapshots & emitting of resolved timestamps #6614

Closed

GrigoriyPA mentioned this issue Jul 15, 2024

KqpRun sync stable version with main #6670

Closed

CyberROFL mentioned this issue Jul 30, 2024

24-1-async-replication: Replicate index tables, ssl connections, connection_string in description #7242

Closed

StekPerepolnen mentioned this issue Aug 23, 2024

merge/stable 24 2/query float test asan #8196

Closed

GrigoriyPA mentioned this issue Sep 26, 2024

YQ-3684 fix screts not found error handling #9822

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Jepsen: lost write due to intersecting transactions both committing #2885

Jepsen: lost write due to intersecting transactions both committing #2885

snaury commented Mar 18, 2024

snaury commented Mar 18, 2024

snaury commented Mar 18, 2024

snaury commented Mar 18, 2024 •

edited

Loading

snaury commented Mar 18, 2024

snaury commented Mar 18, 2024

snaury commented Mar 18, 2024 •

edited

Loading

Jepsen: lost write due to intersecting transactions both committing #2885

Jepsen: lost write due to intersecting transactions both committing #2885

Comments

snaury commented Mar 18, 2024

snaury commented Mar 18, 2024

snaury commented Mar 18, 2024

snaury commented Mar 18, 2024 • edited Loading

snaury commented Mar 18, 2024

snaury commented Mar 18, 2024

snaury commented Mar 18, 2024 • edited Loading

snaury commented Mar 18, 2024 •

edited

Loading

snaury commented Mar 18, 2024 •

edited

Loading