Add Thread ID to all BIH log messages

[svenseeberg]

• This PR adds the thread id to all log messages of the BIH. Most Deliverable log messages already contained the thread id.
• Partially fixes Create Individual Log Files for Each Build Thread #98

[tomschr]

@svenseeberg Thanks for the PR! 👍

Actually, the thread_id is not really necessary. 😉 The logging module does that for you automatically. You only need to pass the correct format string (%(thread)d), see the table about available attribute names.

In your case, you need to change docserv.py#L396 and add %(thread)d string wherever you like it. That should work.

I think, it has a some advantages to do it with the right formatter. For example, you don't have to pass the thread ID to your logging output. Plus you can change the position of the thread ID at one location and not in each function you need it.

---

One final idea (and to play devil's advocate): Do you think the ID is really useful? Does it really help to debug it?

The threading.Thread class allows you to assign a name for a thread, for example Thread(target=..., name="Bla") . The name can be set, for example, to a deliverable or something with a reasonable name. 😉 In that case, use %(threadName)s instead of %(thread_id)s.

Could the 2nd solution be more useful?

[svenseeberg]

Using the thread ID from logging is a good idea.

Regarding the necessity: in some cases definitely yes. But only if there is a problem with threading itself. Its probably not required for finding bugged configuration files or DocBook XML.

[svenseeberg]

We can probably close this PR?

[ghost]

Why do you think we should close it? I still think it is indeed rather useful to have thread IDs in messages.

My initial criticism (which I kept to myself because I suck) of this PR was just that it was never clear when the main thread did stuff, so I would add annotations for that as well. I had started on a commit to that end which I have now pushed here: 1dfbb46 (not editing your branch; not finished but you should get the idea).

I don't think I have quite understood Tom's comment -- in any case, however you do it is fine with me, as long as we have the proper associations between thread name + message on the command line (and potentially in a log file).

Finally, I am really sorry for the lack of answers from me here.

[tomschr]

@sknorr

[...]
I don't think I have quite understood Tom's comment -- in any case, however you do it is fine with me, as long as we have the proper associations between thread name + message on the command line (and potentially in a log file).

That's what my initial comment was aiming for: to preserve a unique thread name for logging output. To make each threads distinguishable, you need these two steps:

1. Pass a name when you call the Thread(name='some unique name', ...) class. Probably you need to add this in file docserv.py, line 338 and 343 (master).
2. Insert the thread name placeholder (%(threadName)s) into your log formatter docserv.py (line 296).

Whenever you call log.debug() or any of the other functions, you should see the unique name in the logger output. Here is a small example:

import logging
import threading

format = "%(asctime)s [%(threadName)s]: %(message)s"
logging.basicConfig(
    format=format,
    level=logging.DEBUG,
)


def worker():
    """thread worker function"""
    logging.debug('doing some work')


threads = []
for i in range(5):
    t = threading.Thread(target=worker, name="MyThread-%s" % i)
    threads.append(t)
    t.start()

gives the following output:

2019-04-25 21:07:00,531 [MyThread-0]: doing some work
2019-04-25 21:07:00,532 [MyThread-1]: doing some work
2019-04-25 21:07:00,532 [MyThread-2]: doing some work
2019-04-25 21:07:00,532 [MyThread-3]: doing some work
2019-04-25 21:07:00,532 [MyThread-4]: doing some work

Hope that clarifies it.

[tomschr]

Oh, one additional comment from me.

Looking at Stefan's commit 1dfbb46, I think it isn't necessary to pass the thread name for each and every .debug() call.

I haven't tried it yet, but if you apply the two steps from my last comment, the output will be changed accordingly, containing a unique thread name. Makes the code a little bit easier to read and maintain I suppose.