debug mode: more readable logging

[dalf]

What does this PR do?

• In development add a new dependency: coloredlogs (declared in requirements-dev.txt but optional in the code, see searx/__init__.py)
• Logs about an engine always use the engine logger ( one logger per engine #296 ), include log from searx.search.processors and searx.metrics.
• HTTP request are logged with the network name: a wikipedia HTTP request is logged with searx.network.wikipedia instead of httpx._client.

Make the debug log more readable:

Why is this change important?

A lot of information are logged in debug mode, which are not easy to read.

But it makes messages more difficult to find in the code:

But a git grep is easy:

$ git grep "engine time"
searx/search/__init__.py:        # max of all selected engine timeout
searx/search/__init__.py:                    PROCESSORS[th._engine_name].logger.error('engine timeout')

How to test this PR locally?

• make run
• production mode:
  • change the secret key
  • start in production mode
• check the log with uwsgi
• check the log with docker

Draft because

• HTTP redirection are not logged (fixed in Switch event hooks to also run on redirects. encode/httpx#1806 --> we need to upgrade httpx to a new version).
• HTTP timeout doesn't log the URL (it was not the case before ?).
• it may requires some adjustment (or close the PR).

Author's checklist

Related issues

[dalf]

@return42 @unixfox what are you opinions on this type of log?

[return42]

It seems coloredlogs is active in dumb terminals ...

In the lib.sh we use ..

searxng/utils/lib.sh

Lines 112 to 114 in 9ef7f38

	if [ ! -p /dev/stdout ] && [ ! "$TERM" = 'dumb' ] && [ ! "$TERM" = 'unknown' ]; then
	set_terminal_colors
	fi

to detect pipes and dumb terminals ...

Is there something similar we can do when initialize coloredlogs?

[dalf]

I can't find something about this, but this function should be enough:

import os
import sys

def is_color_terminal():
    if os.getenv('TERM', None) in ('dumb', 'unknown'):
        return False
    return sys.stdout.isatty()

[dalf]

Updated:

• make run | cat works without color.
• TERM=dumb make run works too.

[unixfox]

Looks cool, I like it.

[return42]

Tested / much better to read logs, like it .. Thanks!

[return42]

@dalf you force pushed but did not ask for a review .. can we merge this PR anyway?

For me this PR works and I like to use this logging in my development :)

[dalf]

About push force fix this method:

searxng/searx/network/network.py

Lines 137 to 147 in 6abc37e

	async def log_response(self, response: httpx.Response):
	request = response.request
	status = f"{response.status_code} {response.reason_phrase}"
	response_line = f"{response.http_version} {status}"
	if hasattr(response, "_elapsed"):
	elapsed_time = f"{response.elapsed.total_seconds()} sec"
	else:
	elapsed_time = "stream"
	self._logger.debug(
	f'HTTP Request: {request.method} {request.url} "{response_line}" ({elapsed_time})'
	)

Before the push force, the embedded image proxy didn't work because log_response was expecting a value for response.elapsed. Since the response is streamed, there is no value.

The new value takes of that.

---

About merging: everything works except one thing: HTTP redirect are not logged anymore.
See httpx PR : encode/httpx#1806
We need to upgrade to httpx 0.19.0 or later --> #261

If the missing log are not an issue (it is temporary), we can merge.

[return42]

If the missing log are not an issue (it is temporary), we can merge.

Thanks for the info, then I think it is better you decide if we should merge :)

[dalf]

Ok I'm going to merge.

---

httpx uses rich was has nice traceback logger, but it requires more configuration to fit into SearXNG.

But it is a dev dependency we can change later.