jupyter-server / jupyter_server

The backend—i.e. core services, APIs, and REST endpoints—to Jupyter web applications.
https://jupyter-server.readthedocs.io
BSD 3-Clause "New" or "Revised" License
486 stars 302 forks source link

Don't use F-string in log.level(...) #1186

Open Carreau opened 1 year ago

Carreau commented 1 year ago

the is a number os places using f-string in log methods:

$ rg self.log | grep "f[\"|']"
jupyter_server/gateway/handlers.py:        self.log.info(f"Connecting to {ws_url}")
jupyter_server/gateway/handlers.py:            self.log.debug(f"Connection is ready: ws: {self.ws}")
jupyter_server/gateway/handlers.py:            self.log.debug(f"_disconnect: future cancelled, disconnected: {self.disconnected}")
jupyter_server/gateway/handlers.py:                        self.log.warning(f"Lost connection to Gateway: {self.kernel_id}")
jupyter_server/gateway/handlers.py:            self.log.error(f"Exception writing message to websocket: {e}")  # , exc_info=True)
jupyter_server/gateway/managers.py:        self.log.info(f"Request start kernel: kernel_id={kernel_id}, path='{path}'")
jupyter_server/gateway/managers.py:        self.log.debug(f"Request list kernels: {self.kernels_url}")
jupyter_server/gateway/managers.py:        self.log.debug(f"Request list kernel specs at: {kernel_spec_url}")
jupyter_server/gateway/managers.py:        self.log.debug(f"Request kernel spec at: {kernel_spec_url}")
jupyter_server/gateway/managers.py:        self.log.debug(f"Request kernel spec resource '{path}' at: {kernel_spec_resource_url}")
jupyter_server/gateway/managers.py:            self.log.info(f"GatewayKernelManager started kernel: {self.kernel_id}, args: {kwargs}")
jupyter_server/gateway/managers.py:            self.log.info(f"GatewayKernelManager using existing kernel: {self.kernel_id}")
jupyter_server/gateway/managers.py:                self.log.warning(f"Unexpected exception encountered ({be})")
jupyter_server/services/sessions/sessionmanager.py:                self.log.warning(f"{msg}  Continuing...")
jupyter_server/services/contents/largefilemanager.py:                self.log.debug(f"Saving last chunk of file {os_path}")
jupyter_server/services/contents/largefilemanager.py:                self.log.debug(f"Saving chunk {chunk} of file {os_path}")
jupyter_server/services/contents/largefilemanager.py:                self.log.debug(f"Saving last chunk of file {os_path}")
jupyter_server/services/contents/largefilemanager.py:                self.log.debug(f"Saving chunk {chunk} of file {os_path}")
jupyter_server/services/kernels/websocket.py:        self.log.info(f"Connecting to kernel {self.kernel_id}.")
jupyter_server/serverapp.py:                f"Customizing authentication via ServerApp.login_handler_class={self.login_handler_class}"
jupyter_server/serverapp.py:                f"Ignoring deprecated config ServerApp.login_handler_class={self.login_handler_class}."
jupyter_server/auth/identity.py:                self.log.warning(f"Clearing invalid/expired login cookie {cookie_name}")
jupyter_server/auth/identity.py:            self.log.debug(f"Error unpacking user from cookie: cookie={user_cookie}", exc_info=True)
jupyter_server/auth/identity.py:            self.log.error(f"Error unpacking user from cookie: {e}")
jupyter_server/auth/identity.py:                self.log.info(_i18n(f"Wrote hashed password to {config_file}"))
jupyter_server/auth/login.py:        self.log.info(f"User {user.username} logged in.")
jupyter_server/extension/serverextension.py:            self.log.info(f"{self._toggle_pre_message.capitalize()}: {import_name}")
jupyter_server/extension/serverextension.py:            self.log.info(f"- Writing config: {config_dir}")
jupyter_server/extension/serverextension.py:            self.log.info(f"    - Validating {import_name}...")
jupyter_server/extension/serverextension.py:            self.log.info(f"      {import_name} {version} {GREEN_OK}")
jupyter_server/extension/serverextension.py:            self.log.info(f"    - Extension successfully {self._toggle_post_message}.")
jupyter_server/extension/serverextension.py:            self.log.info(f"     {RED_X} Validation failed: {err}")
jupyter_server/extension/serverextension.py:            self.log.info(f"Config dir: {config_dir}")
jupyter_server/extension/serverextension.py:                self.log.info(f"    {name} {GREEN_ENABLED if enabled else RED_DISABLED}")
jupyter_server/extension/serverextension.py:                    self.log.info(f"    - Validating {name}...")
jupyter_server/extension/serverextension.py:                    self.log.info(f"      {name} {version} {GREEN_OK}")
jupyter_server/extension/serverextension.py:                    self.log.warning(f"      {RED_X} {err}", exc_info=exc_info)
tests/services/sessions/test_api.py:        self.log.debug(f"DEBUG**** calling super().restart_kernel with newports={newports}")
examples/identity/system_password/jupyter_server_config.py:            self.log.error(f"Failed login for {username}: {e}")
examples/simple/simple_ext11/application.py:        self.log.info(f"ignore_js has just changed: {change}")
examples/simple/simple_ext11/application.py:        self.log.info(f"hello: {self.hello}")
examples/simple/simple_ext11/application.py:        self.log.info(f"ignore_js: {self.ignore_js}")
examples/simple/simple_ext1/application.py:        self.log.info(f"Config {self.config}")
examples/simple/simple_ext2/application.py:        self.log.info(f"Config {self.config}")
examples/simple/simple_ext1/handlers.py:        self.log.info(f"Extension Name in {self.name} Default Handler: {self.name}")

This prevent structured logging and post-processing, as the f-string is formatted before being passed to log.

The goal of log taking parameter if for for self.log.level('format string %s, %r', param_1, param_2 ), is that you can store the log in a format where you you actually ask "give me all the logs which format strings are 'format string %s, %r'" without having to parse text. And this allow handler like Rich, for example to do proper syntax highlighting, or allow compressed storage of logs indexed by the message.

Carreau commented 1 year ago

See also, https://discuss.python.org/t/safer-logging-methods-for-f-strings-and-new-style-formatting/13802/2 that also discuss that f"" in logs is unsafe.

Carreau commented 1 year ago

pylint --disable=all --enable W1202 jupyter_server, seem to only find 2 out of all the above ones, but if you wish to use a linter this may help

maartenbreddels commented 1 year ago

👍 also much better for performance With parameters, if no logging is done, no string formatting is done, while with f"" it will always be done.

blink1073 commented 1 year ago

This is on the list of pylint codes not yet implemented in ruff.

minrk commented 1 year ago

FWIW, since logging in our applications is at info or debug level roughly 100% of the time, performance is actually better in practice with f-strings than format-strings for all log statements at info level or above. So this mainly describes the performance benefit of increasing the log level to unusually quiet levels, which is smaller with f-strings than lazy formatting. Still, the difference is not likely to be noticeable except for debug statements which tend to be very frequent, include a lot of to-format data, and are often not displayed.