[2.19.4] Sporadic test failure with `_GLIBCXX_ASSERTIONS`

thesamesam commented 7 months ago

Hi all!

When running tests for Botan 2.19.4 when packaging for Gentoo, I got:

bcrypt:
bcrypt ran 380 tests in 2.33 sec all ok
bcrypt_pbkdf:
/usr/lib/gcc/x86_64-pc-linux-gnu/14/include/g++-v14/bits/stl_vector.h:1127: std::vector<_Tp, _Alloc>::reference std::vector<_Tp, _Alloc>::operator[](size_type) [with _Tp = unsigned char; _Alloc = Botan::secure_allocator<unsigned char>; reference = unsigned char&; size_type = long unsigned int]: Assertion '__n < this->size()' failed.
Aborted (core dumped)

It only happens on some runs, unfortunately.

Backtraces (hit this with gcc 13 too):

Core was generated by `./botan-test2 --test-threads=32'.
Program terminated with signal SIGABRT, Aborted.
#0  0x00007f403f2bec7c in ?? () from /usr/lib64/libc.so.6
[Current thread is 1 (Thread 0x7f4032a136c0 (LWP 2878430))]
(gdb) bt
#0  0x00007f403f2bec7c in ?? () from /usr/lib64/libc.so.6
#1  0x00007f403f268fc2 in raise () from /usr/lib64/libc.so.6
#2  0x00007f403f2514f2 in abort () from /usr/lib64/libc.so.6
#3  0x00007f403f4e4dfb in std::__glibcxx_assert_fail (file=file@entry=0x7f403fdac4f0 "/usr/lib/gcc/x86_64-pc-linux-gnu/14/include/g++-v14/bits/stl_vector.h", line=line@entry=1127,
    function=function@entry=0x7f403fdacee0 "std::vector<_Tp, _Alloc>::reference std::vector<_Tp, _Alloc>::operator[](size_type) [with _Tp = unsigned char; _Alloc = Botan::secure_allocator<unsigned char>; reference = unsigned char&; size_type = "..., condition=condition@entry=0x7f403fda401a "__n < this->size()")
    at /usr/src/debug/sys-devel/gcc-14.0.9999/gcc-14.0.9999/libstdc++-v3/src/c++11/assert_fail.cc:41
#4  0x00007f403fca9eff in std::vector<unsigned char, Botan::secure_allocator<unsigned char> >::operator[] (this=<optimized out>, __n=<optimized out>)
    at /usr/lib/gcc/x86_64-pc-linux-gnu/14/include/g++-v14/bits/stl_vector.h:1127
#5  Botan::TLS::TLS_CBC_HMAC_AEAD_Encryption::finish (this=0x7f3fc804b580, buffer=std::vector of length 0, capacity 0, offset=5) at src/lib/tls/tls_cbc/tls_cbc.cpp:207
#6  0x000055b54d1981c0 in ?? ()
#7  0x00007f4032a136c0 in ?? ()
#8  0x0000000000000001 in ?? ()
#9  0x0000000000000000 in ?? ()

#0  0x00007f2c660bec7c in ?? () from /usr/lib64/libc.so.6
#1  0x00007f2c66068fc2 in raise () from /usr/lib64/libc.so.6
#2  0x00007f2c660514f2 in abort () from /usr/lib64/libc.so.6
#3  0x00007f2c662e4dfb in std::__glibcxx_assert_fail (file=file@entry=0x7f2c66ba7578 "/usr/lib/gcc/x86_64-pc-linux-gnu/13/include/g++-v13/bits/stl_vector.h", line=line@entry=1125,
    function=function@entry=0x7f2c66ba7f68 "std::vector<_Tp, _Alloc>::reference std::vector<_Tp, _Alloc>::operator[](size_type) [with _Tp = unsigned char; _Alloc = Botan::secure_allocator<unsigned char>; reference = unsigned char&; size_type = "..., condition=condition@entry=0x7f2c66b9f000 "__n < this->size()")
    at /usr/src/debug/sys-devel/gcc-14.0.9999/gcc-14.0.9999/libstdc++-v3/src/c++11/assert_fail.cc:41
#4  0x00007f2c66a9f0df in std::vector<unsigned char, Botan::secure_allocator<unsigned char> >::operator[] (__n=<optimized out>, this=<optimized out>)
    at /usr/lib/gcc/x86_64-pc-linux-gnu/13/include/g++-v13/bits/stl_vector.h:1125
#5  Botan::TLS::TLS_CBC_HMAC_AEAD_Encryption::finish (this=0x7f2c661f7b50, buffer=std::vector of length 5, capacity 10240 = {...}, offset=5) at src/lib/tls/tls_cbc/tls_cbc.cpp:207
#6  0x000055e4428366f0 in ?? ()
#7  0x00007f2c5f01e6c0 in ?? ()
#8  0x0000000000000001 in ?? ()
#9  0x0000000000000000 in ?? ()

thesamesam commented 7 months ago

My memory of those bugs from last year is completely gone, but wonder if a fix needed to be backported to 2.19.x from 3.x?

randombit commented 7 months ago

Replicated here

#0  0x00007ffff72ab32c in ?? () from /usr/lib/libc.so.6
#1  0x00007ffff725a6c8 in raise () from /usr/lib/libc.so.6
#2  0x00007ffff72424b8 in abort () from /usr/lib/libc.so.6
#3  0x00007ffff74dd3b2 in std::__glibcxx_assert_fail (file=file@entry=0x7ffff7d574f0 "/usr/include/c++/13.2.1/bits/stl_vector.h",
    line=line@entry=1125,
    function=function@entry=0x7ffff7d57de0 "std::vector<_Tp, _Alloc>::reference std::vector<_Tp, _Alloc>::operator[](size_type) [with _Tp = unsigned char; _Alloc = Botan::secure_allocator<unsigned char>; reference = unsigned char&; size_type = "...,
    condition=condition@entry=0x7ffff7d4f000 "__n < this->size()") at /usr/src/debug/gcc/gcc/libstdc++-v3/src/c++11/debug.cc:61
#4  0x00007ffff7c5d28f in std::vector<unsigned char, Botan::secure_allocator<unsigned char> >::operator[] (__n=<optimized out>,
    this=<optimized out>) at /usr/include/c++/13.2.1/bits/stl_vector.h:1125
#5  Botan::TLS::TLS_CBC_HMAC_AEAD_Encryption::finish (this=0x7fffec04ee00, buffer=std::vector of length 5, capacity 10240 = {...}, offset=5)
    at src/lib/tls/tls_cbc/tls_cbc.cpp:207
#6  0x00007ffff7c8a51e in Botan::TLS::write_record (output=std::vector of length 5, capacity 10240 = {...}, record_type=<optimized out>,
    version=..., record_sequence=<optimized out>, message=0x7fffec05c46e "\211\301\264o\267ɡ3\370<\221\002", message_len=0, cs=..., rng=...)
    at src/lib/tls/tls_record.cpp:260
#7  0x00007ffff7c5fcd4 in Botan::TLS::Channel::write_record (this=this@entry=0x7fffec0406c0, cipher_state=0x7fffec0412b0, epoch=epoch@entry=1,
    record_type=record_type@entry=23 '\027', input=input@entry=0x7fffec05c46e "\211\301\264o\267ɡ3\370<\221\002", length=length@entry=0)
    at src/lib/tls/tls_channel.cpp:570
#8  0x00007ffff7c63b3e in Botan::TLS::Channel::send_record_array (this=0x7fffec0406c0, epoch=<optimized out>, type=type@entry=23 '\027',
    input=0x7fffec05c46e "\211\301\264o\267ɡ3\370<\221\002", length=<optimized out>) at /usr/include/c++/13.2.1/bits/shared_ptr_base.h:1665
#9  0x00007ffff7c63f2d in Botan::TLS::Channel::send (this=<optimized out>, buf=<optimized out>, buf_size=<optimized out>)
    at src/lib/tls/tls_channel.cpp:642

randombit commented 7 months ago

Can you try this

diff --git a/src/lib/tls/tls_cbc/tls_cbc.cpp b/src/lib/tls/tls_cbc/tls_cbc.cpp
index 3e3e4c2df..bdf8f2e00 100644
--- a/src/lib/tls/tls_cbc/tls_cbc.cpp
+++ b/src/lib/tls/tls_cbc/tls_cbc.cpp
@@ -204,7 +204,9 @@ void TLS_CBC_HMAC_AEAD_Encryption::finish(secure_vector<uint8_t>& buffer, size_t

    buffer.reserve(offset + msg_size + padding_length + tag_size());
    buffer.resize(offset + msg_size);
-   copy_mem(&buffer[offset], msg().data(), msg_size);
+   if(msg_size > 0) {
+      copy_mem(&buffer[offset], msg().data(), msg_size);
+   }

    mac().update(assoc_data());

randombit commented 7 months ago

The same expression appears on master

   copy_mem(&buffer[offset], msg().data(), msg_size);

So I don't know why you wouldn't be able to repro it in 3.3 as well. (Unless GCC's iterator debugging behavior depends on C++ version in use, which seems possible but not something I have knowledge of.)

thesamesam commented 7 months ago

Trying it now. It's possible I was just very unlucky. I can't hit it very often, and when I ran in a loop, for 3.3, all I hit was the other bug.

thesamesam commented 7 months ago

No luck! I double checked the patch was applied.

Test run 7/100000 complete ran 6959 tests in 1.76 sec all tests ok
tls:
/usr/lib/gcc/x86_64-pc-linux-gnu/13/include/g++-v13/bits/stl_vector.h:1125: std::vector<_Tp, _Alloc>::reference std::vector<_Tp, _Alloc>::operator[](size_type) [with _Tp = unsigned char; _Alloc = Botan::secure_allocator<unsigned char>; reference = unsigned char&; size_type = long unsigned int]: Assertion '__n < this->size()' failed.
Aborted (core dumped)

(gdb) bt
#0  0x00007f1025cbec7c in ?? () from /usr/lib64/libc.so.6
#1  0x00007f1025c68fc2 in raise () from /usr/lib64/libc.so.6
#2  0x00007f1025c514f2 in abort () from /usr/lib64/libc.so.6
#3  0x00007f1025ee4dfb in std::__glibcxx_assert_fail (file=file@entry=0x7f10266ac128 "/usr/lib/gcc/x86_64-pc-linux-gnu/13/include/g++-v13/bits/stl_vector.h", line=line@entry=1125,
    function=function@entry=0x7f10266ac9e8 "std::vector<_Tp, _Alloc>::reference std::vector<_Tp, _Alloc>::operator[](size_type) [with _Tp = unsigned char; _Alloc = Botan::secure_allocator<unsigned char>; reference = unsigned char&; size_type = "..., condition=condition@entry=0x7f10266c7c2f "__n < this->size()")
    at /usr/src/debug/sys-devel/gcc-14.0.9999/gcc-14.0.9999/libstdc++-v3/src/c++11/assert_fail.cc:41
#4  0x00007f10265d416f in std::vector<unsigned char, Botan::secure_allocator<unsigned char> >::operator[] (this=0x7f1025df7b50, __n=5)
    at /usr/lib/gcc/x86_64-pc-linux-gnu/13/include/g++-v13/bits/stl_vector.h:1123
#5  std::vector<unsigned char, Botan::secure_allocator<unsigned char> >::operator[] (__n=<optimized out>, this=<optimized out>)
    at /usr/lib/gcc/x86_64-pc-linux-gnu/13/include/g++-v13/bits/stl_vector.h:1123
#6  Botan::TLS::TLS_CBC_HMAC_AEAD_Encryption::finish (this=0x7f1026808580, buffer=std::vector of length 0, capacity 0, offset=5) at src/lib/tls/tls_cbc/tls_cbc.cpp:209
#7  0x00007f10265f81f4 in Botan::TLS::write_record (output=std::vector of length 5, capacity 10240 = {...}, record_type=<optimized out>, version=..., record_sequence=<optimized out>,
    message=0x56014694d551 "\315\034\252M\026/T\371i\206;(\364ɶZN5*!f\002KH\364\322?e!d\302)\226\313W\243\031\315\315\310\3362]5c\242\346\233_\344\tU_\334\327\020~bx\364\aO\n\017^\3728\206\247\220/\r,\317\002\300\262_\333W\222a\255\242\377+B\213\tlJ_\255\225\263\272\204\253`&@\315\270\016\037\314χ\204\303\364\377}}mo\3006cwLqw\234&\323?\326\t\213\202\234Io\177\374\303\350\264\366\263%U\021\200\357\343'Y\267\306\037e<.\370\217\227?7ۮ\232\265\311f\373~3\343\026¿\246+\003\240\026z{G9\220\a\373\342/F˪7\353W\314\334\0360L\304Z"..., message_len=0,
    cs=..., rng=...) at src/lib/tls/tls_record.cpp:260
#8  0x00007f10265d6694 in Botan::TLS::Channel::write_record (this=this@entry=0x5601469bf5e0, cipher_state=0x5601469b02d0, epoch=epoch@entry=1, record_type=record_type@entry=23 '\027',
    input=input@entry=0x56014694d551 "\315\034\252M\026/T\371i\206;(\364ɶZN5*!f\002KH\364\322?e!d\302)\226\313W\243\031\315\315\310\3362]5c\242\346\233_\344\tU_\334\327\020~bx\364\aO\n\017^\3728\206\247\220/\r,\317\002\300\262_\333W\222a\255\242\377+B\213\tlJ_\255\225\263\272\204\253`&@\315\270\016\037\314χ\204\303\364\377}}mo\3006cwLqw\234&\323?\326\t\213\202\234Io\177\374\303\350\264\366\263%U\021\200\357\343'Y\267\306\037e<.\370\217\227?7ۮ\232\265\311f\373~3\343\026¿\246+\003\240\026z{G9\220\a\373\342/F˪7\353W\314\334\0360L\304Z"...,
    length=length@entry=0) at src/lib/tls/tls_channel.cpp:570
#9  0x00007f10265d9ecc in Botan::TLS::Channel::send_record_array (this=0x5601469bf5e0, epoch=<optimized out>, type=type@entry=23 '\027',
    input=0x56014694d551 "\315\034\252M\026/T\371i\206;(\364ɶZN5*!f\002KH\364\322?e!d\302)\226\313W\243\031\315\315\310\3362]5c\242\346\233_\344\tU_\334\327\020~bx\364\aO\n\017^\3728\206\247\220/\r,\317\002\300\262_\333W\222a\255\242\377+B\213\tlJ_\255\225\263\272\204\253`&@\315\270\016\037\314χ\204\303\364\377}}mo\3006cwLqw\234&\323?\326\t\213\202\234Io\177\374\303\350\264\366\263%U\021\200\357\343'Y\267\306\037e<.\370\217\227?7ۮ\232\265\311f\373~3\343\026¿\246+\003\240\026z{G9\220\a\373\342/F˪7\353W\314\334\0360L\304Z"...,
    length=<optimized out>) at /usr/lib/gcc/x86_64-pc-linux-gnu/13/include/g++-v13/bits/shared_ptr_base.h:1665
#10 0x00007f10265da2cd in Botan::TLS::Channel::send (this=<optimized out>, buf=<optimized out>, buf_size=<optimized out>) at src/lib/tls/tls_channel.cpp:642
#11 0x0000560146350453 in Botan_Tests::(anonymous namespace)::TLS_Handshake_Test::go (this=this@entry=0x7ffe130c1840) at src/tests/unit_tls.cpp:727
#12 0x0000560146351bd1 in Botan_Tests::(anonymous namespace)::TLS_Unit_Tests::test_with_policy (test_descr=..., results=std::vector of length 51, capacity 64 = {...}, client_ses=...,
    server_ses=..., creds=..., versions=..., policy=..., client_auth=<optimized out>, this=<optimized out>) at src/tests/unit_tls.cpp:895
#13 0x00005601463529f4 in Botan_Tests::(anonymous namespace)::TLS_Unit_Tests::test_all_versions (test_descr="3DES ECDH", results=std::vector of length 51, capacity 64 = {...},
    client_ses=..., server_ses=..., creds=..., kex_policy="ECDH", cipher_policy="3DES", mac_policy="SHA-1", etm_policy="false", client_auth=false, this=<optimized out>)
    at src/tests/unit_tls.cpp:944
#14 0x000056014635361f in Botan_Tests::(anonymous namespace)::TLS_Unit_Tests::run (this=<optimized out>) at src/tests/unit_tls.cpp:1114
#15 0x00005601462d1113 in Botan_Tests::(anonymous namespace)::run_a_test (test_name="tls") at src/tests/test_runner.cpp:256
#16 0x00005601462d1f0b in Botan_Tests::Test_Runner::run_tests (this=this@entry=0x7ffe130c2790, tests_to_run=std::vector of length 1, capacity 1 = {...}, test_threads=<optimized out>,
    test_run=test_run@entry=7, tot_test_runs=100000) at src/tests/test_runner.cpp:389
#17 0x00005601462d3c26 in Botan_Tests::Test_Runner::run (this=this@entry=0x7ffe130c2790, opts=...) at src/tests/tests.h:100
#18 0x00005601461af1d6 in main (argc=<optimized out>, argv=<optimized out>) at src/tests/main.cpp:101

thesamesam commented 7 months ago

Maybe I've made a mistake (or missing something obvious):

(gdb) frame 6
#6  Botan::TLS::TLS_CBC_HMAC_AEAD_Encryption::finish (this=0x7f1026808580, buffer=std::vector of length 0, capacity 0, offset=5) at src/lib/tls/tls_cbc/tls_cbc.cpp:209
209           copy_mem(&buffer[offset], msg().data(), msg_size);
(gdb) p msg_size
$1 = 0
(gdb) p buffer
$2 = std::vector of length 0, capacity 0
(gdb) list
204
205        buffer.reserve(offset + msg_size + padding_length + tag_size());
206        buffer.resize(offset + msg_size);
207        if(msg_size > 0)
208           {
209           copy_mem(&buffer[offset], msg().data(), msg_size);
210           }
211
212        mac().update(assoc_data());
213
(gdb)

reneme commented 7 months ago

Given that copy_mem is in line 209, I do confirm that the patch must have been applied. It would be in line 207 otherwise.

But why does it enter the if-body if msg_size is actually 0?

FWIW: We do the same &buffer[offset] thingy a few lines below.

randombit / botan

[2.19.4] Sporadic test failure with `_GLIBCXX_ASSERTIONS` #3916