PowerPC Boost Logging displays linux thread ids as all 0s

[John Coffey]

I recently posted a question on StackOverflow to resolve an issue with ThreadIDs. I am logging on an embedded target using the latest 1.57.0 version of boost and unfortunately I cannot reproduce the problem on Coliru via a live example. The problem is that the logger works fine on windows - displaying correctly formatted Thread-IDs in the position expected, but on the target power-PC platform all the other fields (severity etc) are displayed correctly but the thread ID field is filled with 8 zeros - even the leading 0x is missing. I looked through the source code in Boost.Log but its a bit beyond my ability to see exactly where the thread IDs might be going astray. Any help would be greatly appreciated.

Here is a link to my question on StackOverflow

http://stackoverflow.com/questions/26939047/boost-logging-displays-linux-thread-ids-as-all-0s

and here is my coliru live demo demonstrating it working fine on the coliru server (displaying thread IDs) however the exact same code does not work on the target - you can see the output on the target in the original question.

http://coliru.stacked-crooked.com/a/55e4b334188c978d

I'm not sure if this is a bug, my compiler on teh target platform is gcc 4.8.3 using the Mentor Graphics' CodeSourcery GNU tool-chain.

[John Coffey]

Per a reply I received directly from Andrey in this bug or my misuse of the API - its looking more like a bug. Anyway on the target platform I printed out the following details that apparently affect the logging of the thread ID

On Tue, Nov 18, 2014 at 5:27 AM, andysem@users.sf.net wrote:

In POSIX, there is no portable notion of a thread id, so Boost.Log
attempts to come up with some close equivalent. Basically, it takes
sizeof(uintmax_t) first bytes of pthread_t, whatever it is. It is possible
that on some platform pthread_t is a structure, and its first bytes don't
uniquely identify a thread. I don't know if that is your case, and I don't
have access to a ppc platform to check. You'll have to debug it. See
boost/log/detail/thread_id.hpp and libs/log/src/thread_id.cpp.

As for formatting, this code is not platform-specific (well, at least, in
Boost.Log side), so if it doesn't output 0x on your platform then there's
probably some problem with your compiler or STL. The lack of 0x may be the
indication of the source of the problem (i.e. that the issue is actually
not with ids but with their formatting).

In any case, if you figure out what the problem is, feel free to send a
patch.

---

I don't know if this is helpful, but I dumped it from my target application

if defined (GNUC)

std::thread::id this_id = std::this_thread::get_id();
std::cout << "threadID[" << std::hex << this_id << std::dec
    << "], sizeof(std::thread::id)[" << sizeof(std::thread::id)
    << " bytes], sizeof(pthread_t)[" << sizeof(pthread_t)
    << " bytes], sizeof(uintmax_t)[" << sizeof(uintmax_t);

endif

threadID[b79c6210], sizeof(std::thread::id)[4 bytes], sizeof(pthread_t)[4 bytes], sizeof(uintmax_t)[8 bytes]

my logging entries always have 10 zeros in the place of the thread ID

13:43:49.191856 [warning] tid[0000000000] module[N/A] [>TIMEOUT<]

do you think that the above values could possibly explain the zeros in the thread IDs for this platform? Also where in the code does the 0x prefixing occur, I can see where space is made available for the 2 extra characters.

Thanks in advance

[Andrey Semashev]

Yes, that's probably a bug in the thread id formatting code.

[John Coffey]

Any idea which block of code the bug could be in? I can probably code up a fix for it but its not really obvious where that formatting code is? Seems like the problem is I am taking first 8 bytes from a 4 byte pthrad_t. Sorry just saw this new markdown format and I'm not sure how to quote code blocks.

John

It looks like

enum { tid_size = sizeof(pthread_t) > sizeof(uintmax_t) ? sizeof(uintmax_t) : sizeof(pthread_t) }; 

in line 103 of thread_id.cpp is going to give a tid_size of 4 bytes in my case.

Then in the block of code - it all depends on the size parameter - and I'm not sure where that is being called from. Anyways the bug lurks here somewhere.

// Used in default_sink.cpp
void format_thread_id(char* buf, std::size_t size, thread::id tid)
{
    static const char char_table[] = "0123456789abcdef";

    // Input buffer is assumed to be always larger than 2 chars
    *buf++ = '0';
    *buf++ = 'x';

    size -= 3; // reserve space for the terminating 0
    thread::id::native_type id = tid.native_id();
    unsigned int i = 0;
    const unsigned int n = (size > (tid_size * 2u)) ? static_cast< unsigned int >(tid_size * 2u) : static_cast< unsigned int >(size);
    for (unsigned int shift = n * 4u; i < n; ++i, shift -= 4u)
    {
        buf[i] = char_table[(id >> shift) & 15u];
    }

    buf[i] = '\0';
}

[Andrey Semashev]

Sorry for the delay. I think it should be fixed in https://github.com/boostorg/log/commit/45a91ff2bec11a9a64352d4b02b9a54d201a925d.

[John Coffey]

Sorry to report that the fix is not quite working yet. I can see that the 0x makes it into the logs now though, here is an old log entry:
22:22:29.092947 [info] tid[0000000000] module[proc1] .....

and here are the entries after applying the patch

12:03:44.035735 [info] tid[0x00000000] module[dmu] ....

Again note that in my case I showed the sizes of various types on my target platform, let me know if there is any other info I can get from my platform for you.

[John Coffey]

Andrey, looks like there is an endianizaion issue, the native thread id is 8 bytes, however you are only showing the first 4 - which happen to be all zeros, what you probably needed to do (given that it is PowerPC is revere endianize the 8 bytes and display them using 18 characters - including the leading [Ox.....]

Anyways here is my hack around this by simply shifting the zeroed out word right 32 bits - nasty but seems to work for my purposes.

All the best, looking forward to getting a proper fix.

John

template< typename CharT >
inline void format_thread_id_impl(CharT* buf, std::size_t size, thread::id tid, const CharT (&char_table)[18])
{
    // Input buffer is assumed to be always larger than 2 chars
    *buf++ = char_table[0];  // '0'
    *buf++ = char_table[16]; // 'x'

    size -= 3; // reserve space for the terminating 0
    thread::id::native_type id = tid.native_id() >> 32;
    std::cout << "tid.native_id() " << tid.native_id() << " sizeof(tid.native_id()) " << sizeof(tid.native_id()) << std::endl;
    unsigned int i = 0;
    const unsigned int n = (size > (tid_size * 2u)) ? static_cast< unsigned int >(tid_size * 2u) : static_cast< unsigned int >(size);
    for (unsigned int shift = n * 4u - 4u; i < n; ++i, shift -= 4u)
    {
        buf[i] = char_table[(id >> shift) & 15u];
    }

    buf[i] = '\0';
}

Here is the printout from the above hack

tid.native_id() 13257227380210008064 sizeof(tid.native_id()) 8

[Andrey Semashev]

You are quite right. I've committed a fix for this: https://github.com/boostorg/log/commit/66e7ade8eceb5d8d60eb72baabd25a9c536b22da