capture and handle logging messages from Binary Ninja backend

[williballenthin]

as first described and triaged in the thread here: #1343 (comment)
Binary Ninja emits logging messages to stdout/stderr directly, which doesn't give Python a chance to handle/format/suppress messages. When they add support for registering a logging listener, we should use it to improve the user and tester experience of capa.

[williballenthin]

@xusheng6 for awareness of tracking issue

[xusheng6]

Noted with thanks! This one should be pretty easy. My colleague has already written the code for the Python binding of the log listener and I just need to steal it. Though I will have to get back to it at a later moment because we are working on a new BN release. Best, Xusheng

…

On Wed, Mar 29, 2023 at 9:36 PM Willi Ballenthin ***@***.***> wrote: @xusheng6 <https://github.com/xusheng6> for awareness of tracking issue — Reply to this email directly, view it on GitHub <#1413 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AWRACE5SPDRVPVOGWJHLXNDW6Q3GTANCNFSM6AAAAAAWL7V73Y> . You are receiving this because you were mentioned.Message ID: ***@***.***>

[xusheng6]

I just realized that I should better fix the issue on our end before the new release. So that when we release it, we can update capa to utilize it. Otherwise, since capa CI uses the stable build of BN, we will have to wait longer.

[xusheng6]

I notice a BN bug while dealing with this: Vector35/binaryninja-api#4205

Update: I have pushed a fix for it. Once we release the new stable, we should see far less warn messages

[xusheng6]

I tried to understand why the BN logs are even printed at all. I checked our code and did some experiment, I figured that if we do not do anything, logs would not be printed to stdout/stderr by default. We must call log_to_stdout first so the logs would be printed to stdout. For example, see the code snippet in our API docs:

https://github.com/Vector35/binaryninja-api/blob/85e782ad57f27c753364faeaead01522982a12ec/python/log.py#L142-L144

[xusheng6]

Oh nvm, I figured out. The output is dumped to stderr by default: https://github.com/Vector35/binaryninja-api/blob/94391b2730dcc2e6cfe9f26d13569b15c6d1a0ad/python/__init__.py#L168. So we would not be able to see it if we run something directly, but it can be captured by things like pytest.

[xusheng6]

So we have decided to not merge the branch that fixes this issue Vector35/binaryninja-api#4156, primarily because of a performance consideration. It could become a footgun and slow down the analysis speed if the user uses in a wrong way.

This means we would not be able to fix this issue in a perfect way. However, I propose we solve it like this:

1. Disable the default log by calling disable_default_log https://github.com/Vector35/binaryninja-api/blob/5721a4177f651a9d518f1a3b74caca450061e05c/python/__init__.py#L179
2. Configure BN to log to a file, and then either inform the user the existence of the BN log file, or replay it at the end of analysis using Python's logging infra

[xusheng6]

Not requiring the Python LogListener means this does not need to be completed before the next BN stable release. All the infra mentioned above is already existing