How to read Valgrind's output

Every semester, a surprising amount of our students have trouble reading Valgrind's output. To this end, I decided to write this short post.

First, some background: in a series of homework, our students incrementally implement a rudimentary version of trie. The students are in their 3rd semester and should have previous experience programming in Java and Python.

This experience means that I would expect them to be familiar with the concept of a stack trace, and thus be able to read Valgrind's output with only a modicum of difficulty. For some reason though, this is often not true.

Let's use an example output that was shown to our student^[1]:

==23556== Conditional jump or move depends on uninitialised value(s)
==23556==    at 0x46EA5B: insert(trie_node&, char const*) (trie.cpp:13)
==23556==    by 0x46EBC5: insert(trie&, std::__cxx11::basic_string, std::allocator > const&) (trie.cpp:50)
==23556==    by 0x46EE08: insert_all(trie&, std::vector, std::allocator >, std::allocator, std::allocator > > > const&) (trie.cpp:108)
==23556==    by 0x4657A2: ____C_A_T_C_H____T_E_S_T____7() (trie-tests.cpp:35)
==23556==  Uninitialised value was created by a heap allocation
==23556==    at 0x4C2A16F: operator new(unsigned long) (vg_replace_malloc.c:333)
==23556==    by 0x41BCE6: __gnu_cxx::new_allocator, std::allocator > >::allocate(unsigned long, void const*) (in /local/brute/ae/432123/trie-1-debug)
==23556==    by 0x41BC8B: std::allocator_traits, std::allocator > > >::allocate(std::allocator, std::allocator > >&, unsigned long) (in /local/brute/ae/432123/trie-1-debug)
==23556==    by 0x41BC32: std::_Vector_base, std::allocator >, std::allocator, std::allocator > > >::_M_allocate(unsigned long) (in /local/brute/ae/432123/trie-1-debug)
==23556==    by 0x46E6AC: void std::vector, std::allocator >, std::allocator, std::allocator > > >::_M_range_initialize, std::allocator > const*>(std::__cxx11::basic_string, std::allocator > const*, std::__cxx11::basic_string, std::allocator > const*, std::forward_iterator_tag) (stl_vector.h:1287)
==23556==    by 0x46DF77: std::vector, std::allocator >, std::allocator, std::allocator > > >::vector(std::initializer_list, std::allocator > >, std::allocator, std::allocator > > const&) (stl_vector.h:377)
==23556==    by 0x46578D: ____C_A_T_C_H____T_E_S_T____7() (trie-tests.cpp:35)

First of all, the ==<num>== part of every line is the PID (process ID) and usually does not matter. Similarly, the address parts (by 0xFFFF and at 0xFFFF) are usually not important.

Now onto the rest of the message: the first line of the error is the error type itself. In this case, it is that our code reads from an uninitialized memory. The following lines show call stack when the error occurred, with the deepest level being first. Some errors, including this one, also have a second part of the report, where additional information is provided. For this error, it is where the uninitialized memory came from.

Knowing this, let us look at the cleaned up error call stack:

Conditional jump or move depends on uninitialised value(s)
  : insert(trie_node&, char const*) (trie.cpp:13)
  : insert(trie&, std::__cxx11::basic_string, std::allocator > const&) (trie.cpp:50)
  : insert_all(trie&, std::vector, std::allocator >, std::allocator, std::allocator > > > const&) (trie.cpp:108)
  : ____C_A_T_C_H____T_E_S_T____7() (trie-tests.cpp:35)

Much better!
We can also clean up the other part of the report, but it does not tell us much, except that the uninitialized memory was allocated dynamically using new when constructing a vector:

Uninitialised value was created by a heap allocation
  : operator new(unsigned long) (vg_replace_malloc.c:333)
  : __gnu_cxx::new_allocator, std::allocator > >::allocate(unsigned long, void const*) (in /local/brute/ae/432123/trie-1-debug)
  : std::allocator_traits, std::allocator > > >::allocate(std::allocator, std::allocator > >&, unsigned long) (in /local/brute/ae/432123/trie-1-debug)
  : std::_Vector_base, std::allocator >, std::allocator, std::allocator > > >::_M_allocate(unsigned long) (in /local/brute/ae/432123/trie-1-debug)
  : void std::vector, std::allocator >, std::allocator, std::allocator > > >::_M_range_initialize, std::allocator > const*>(std::__cxx11::basic_string, std::allocator > const*, std::__cxx11::basic_string, std::allocator > const*, std::forward_iterator_tag) (stl_vector.h:1287)
  : std::vector, std::allocator >, std::allocator, std::allocator > > >::vector(std::initializer_list, std::allocator > >, std::allocator, std::allocator > > const&) (stl_vector.h:377)
  : ____C_A_T_C_H____T_E_S_T____7() (trie-tests.cpp:35)

The error happens inside function insert(trie_node&, char const *), at line 13 of trie.cpp, so lets look there.

bool insert(trie_node& node, const char* str)
{
    if (node.children[(int)*str] == nullptr)
    {
        char c = *str;
        node.children[(int)c] = new trie_node();
        (*node.children[(int)c]).payload = c;
        (*node.children[(int)c]).parent = &node;
 
        str++;
        if (*str && c != '\0') // <--- Line 13 in the original file

    // -------------------------------
    // The rest of the code is omitted
}

At line 13 we read from 2 locations, c and str. c is a local variable and we know that the initialised memory was dynamically allocated, leaving us with *str causing the error.

However, why and when?

We need to take a look at how we got the pointer insert is working with and from the Valgrind output we have 3 more places of interest:

• trie-tests.cpp line 35
• insert_all(trie&, std::vector<std::string> const&>, trie.cpp line 108
• insert(trie&, std::string const&), trie.cpp line 50

If we look at line 35 of trie-tests.cpp, we find this:

insert_all(trie, {"abc", "bc", "a", "bc", "d", "", "d", "abcd", "abc"});

We insert a number of strings into the trie, using initializer list of C style strings.
Let's look at insert_all:

void insert_all(trie& trie, const std::vector<std::string>& items) {
    for (auto it = items.begin(); it != items.end(); ++it)
    {
        insert(trie, *it); // <--- Line 108 in the original file
    }
}

Nothing interesting happens here -> every std::string inside the std::vector passed to insert_all is passed to insert(trie&, std::string const&) as is. When we look at insert, we see nothing too interesting either:

bool insert(trie& trie, const std::string& str) {
    if (str.c_str())
    {
        if (insert(*trie.root, str.c_str())) // <--- Line 50 in the original file
        {
            trie.size++;
            return true;
        }
        return false;
    }
    else
    {
        return false;
    }
}

A pointer to std::string's internal data is passed to insert(trie_node&, char const *) without any modifications. Armed with this knowledge, we now know that the error we are diagnosing is due to logic bug inside insert(trie_node& char const*).

Let us look at it again:

bool insert(trie_node& node, const char* str)
{
    if (node.children[(int)*str] == nullptr)
    {
        char c = *str;         // <---
        node.children[(int)c] = new trie_node();
        (*node.children[(int)c]).payload = c;
        (*node.children[(int)c]).parent = &node;
 
        str++;                 // <---
        if (*str && c != '\0') // <--- Line 13 in the original file

    // -------------------------------
    // The rest of the code is omitted
}

What happens when we pass an empty string "" to insert? First, we read the null terminator ('\0') and save it in c. Then we increment str, making it point behind the null terminator, into invalid memory^[2]. Then, when we dereference str again, we access invalid (and thus uninitialised) piece of memory.

Interestingly, the student's code had the right idea in checking c against '\0', but since the dereference is always performed first, it was still wrong.