| commit | author | age | ||
| 1ae7af | 1 | .. _logging_chapter: |
| CM | 2 | |
| 3 | Logging | |
| 4 | ======= | |
| 5 | ||
| 6 | :app:`Pyramid` allows you to make use of the Python standard library | |
| 274412 | 7 | :mod:`logging` module. This chapter describes how to configure logging and how |
| SP | 8 | to send log messages to loggers that you've configured. |
| 1ae7af | 9 | |
| 012b97 | 10 | .. warning:: |
| M | 11 | |
| 2d35e2 | 12 | This chapter assumes you've used a :term:`cookiecutter` to create a project |
| 274412 | 13 | which contains ``development.ini`` and ``production.ini`` files which help |
| 2d35e2 | 14 | configure logging. All of the Pyramid cookiecutters provided by the Pylons Project do |
| SP | 15 | this. If you're not using a cookiecutter, or if you've used a third-party |
| 16 | cookiecutter which does not create these files, the configuration information in | |
| 274412 | 17 | this chapter may not be applicable. |
| 1ae7af | 18 | |
| 8197f1 | 19 | .. index:: |
| 4a63f6 | 20 | pair: settings; logging |
| KOP | 21 | pair: .ini; logging |
| 22 | pair: logging; configuration | |
| 23 | ||
| d3ce2b | 24 | .. _logging_config: |
| CM | 25 | |
| 1ae7af | 26 | Logging Configuration |
| CM | 27 | --------------------- |
| 28 | ||
| 2d35e2 | 29 | A :app:`Pyramid` project created from a :term:`cookiecutter` is configured to allow |
| 274412 | 30 | you to send messages to :mod:`Python standard library logging package |
| SP | 31 | <logging>` loggers from within your application. In particular, the |
| 32 | :term:`PasteDeploy` ``development.ini`` and ``production.ini`` files created | |
| 2d35e2 | 33 | when you use a cookiecutter include a basic configuration for the Python |
| 274412 | 34 | :mod:`logging` package. |
| 1ae7af | 35 | |
| 32c508 | 36 | PasteDeploy ``.ini`` files use the Python standard library :mod:`ConfigParser |
| 274412 | 37 | format <ConfigParser>`. This is the same format used as the Python |
| 32c508 | 38 | :ref:`logging module's Configuration file format <logging-config-fileformat>`. |
| TL | 39 | The application-related and logging-related sections in the configuration file |
| 1ae7af | 40 | can coexist peacefully, and the logging-related sections in the file are used |
| cfb2b5 | 41 | from when you run ``pserve``. |
| 1ae7af | 42 | |
| 274412 | 43 | The ``pserve`` command calls the :func:`pyramid.paster.setup_logging` function, |
| SP | 44 | a thin wrapper around the :func:`logging.config.fileConfig` using the specified |
| 45 | ``.ini`` file, if it contains a ``[loggers]`` section (all of the | |
| 2d35e2 | 46 | cookiecutter-generated ``.ini`` files do). ``setup_logging`` reads the logging |
| 274412 | 47 | configuration from the ini file upon which ``pserve`` was invoked. |
| 1ae7af | 48 | |
| CM | 49 | Default logging configuration is provided in both the default |
| 2d35e2 | 50 | ``development.ini`` and the ``production.ini`` files. If you use ``pyramid-cookiecutter-starter`` to generate a Pyramid project with the name of the package as ``hello_world``, then the logging configuration |
| 274412 | 51 | in the ``development.ini`` file is as follows: |
| 1ae7af | 52 | |
| fb77c9 | 53 | .. literalinclude:: myproject/development.ini |
| 2d35e2 | 54 | :language: ini |
| SP | 55 | :lineno-match: |
| 56 | :lines: 29- | |
| 1ae7af | 57 | |
| CM | 58 | The ``production.ini`` file uses the ``WARN`` level in its logger |
| 2d35e2 | 59 | configuration instead of ``DEBUG``, but it is otherwise identical. |
| 1ae7af | 60 | |
| CM | 61 | In this logging configuration: |
| 62 | ||
| 274412 | 63 | - a logger named ``root`` is created that logs messages at a level above or |
| SP | 64 | equal to the ``INFO`` level to stderr, with the following format: |
| 1ae7af | 65 | |
| 274412 | 66 | .. code-block:: text |
| 1ae7af | 67 | |
| 274412 | 68 | 2007-08-17 15:04:08,704 INFO [packagename] Loading resource, id: 86 |
| 1ae7af | 69 | |
| CM | 70 | - a logger named ``myapp`` is configured that logs messages sent at a level |
| 274412 | 71 | above or equal to ``DEBUG`` to stderr in the same format as the root logger. |
| 1ae7af | 72 | |
| CM | 73 | The ``root`` logger will be used by all applications in the Pyramid process |
| 274412 | 74 | that ask for a logger (via ``logging.getLogger``) that has a name which begins |
| SP | 75 | with anything except your project's package name (e.g., ``myapp``). The logger |
| 76 | with the same name as your package name is reserved for your own usage in your | |
| 77 | :app:`Pyramid` application. Its existence means that you can log to a known | |
| 2d35e2 | 78 | logging location from any :app:`Pyramid` application generated via a cookiecutter. |
| 1ae7af | 79 | |
| 274412 | 80 | :app:`Pyramid` and many other libraries (such as Beaker, SQLAlchemy, Paste) log |
| SP | 81 | a number of messages to the root logger for debugging purposes. Switching the |
| 1ae7af | 82 | root logger level to ``DEBUG`` reveals them: |
| CM | 83 | |
| 274412 | 84 | .. code-block:: ini |
| 1ae7af | 85 | |
| 274412 | 86 | [logger_root] |
| SP | 87 | #level = INFO |
| 88 | level = DEBUG | |
| 89 | handlers = console | |
| 1ae7af | 90 | |
| 2d35e2 | 91 | Some cookiecutters configure additional loggers for additional subsystems they use |
| 274412 | 92 | (such as SQLALchemy). Take a look at the ``production.ini`` and |
| 2d35e2 | 93 | ``development.ini`` files rendered when you create a project from a cookiecutter. |
| 1ae7af | 94 | |
| CM | 95 | Sending Logging Messages |
| 96 | ------------------------ | |
| 97 | ||
| 98 | Python's special ``__name__`` variable refers to the current module's fully | |
| 274412 | 99 | qualified name. From any module in a package named ``myapp``, the ``__name__`` |
| SP | 100 | builtin variable will always be something like ``myapp``, or |
| 1ae7af | 101 | ``myapp.subpackage`` or ``myapp.package.subpackage`` if your project is named |
| CM | 102 | ``myapp``. Sending a message to this logger will send it to the ``myapp`` |
| 103 | logger. | |
| 104 | ||
| 105 | To log messages to the package-specific logger configured in your ``.ini`` | |
| 106 | file, simply create a logger object using the ``__name__`` builtin and call | |
| 107 | methods on it. | |
| 108 | ||
| 274412 | 109 | .. code-block:: python |
| 392a6c | 110 | :linenos: |
| 1ae7af | 111 | |
| 274412 | 112 | import logging |
| SP | 113 | log = logging.getLogger(__name__) |
| 1ae7af | 114 | |
| CM | 115 | def myview(request): |
| 274412 | 116 | content_type = 'text/plain' |
| SP | 117 | content = 'Hello World!' |
| 118 | log.debug('Returning: %s (content-type: %s)', content, content_type) | |
| 119 | request.response.content_type = content_type | |
| 1ae7af | 120 | return request.response |
| CM | 121 | |
| 274412 | 122 | This will result in the following printed to the console, on ``stderr``: |
| 1ae7af | 123 | |
| 274412 | 124 | .. code-block:: text |
| 1ae7af | 125 | |
| CM | 126 | 16:20:20,440 DEBUG [myapp.views] Returning: Hello World! |
| 274412 | 127 | (content-type: text/plain) |
| 1ae7af | 128 | |
| CM | 129 | Filtering log messages |
| 130 | ---------------------- | |
| 131 | ||
| 274412 | 132 | Often there's too much log output to sift through, such as when switching the |
| SP | 133 | root logger's level to ``DEBUG``. |
| 1ae7af | 134 | |
| 274412 | 135 | For example, you're diagnosing database connection issues in your application |
| 1ae7af | 136 | and only want to see SQLAlchemy's ``DEBUG`` messages in relation to database |
| CM | 137 | connection pooling. You can leave the root logger's level at the less verbose |
| 138 | ``INFO`` level and set that particular SQLAlchemy logger to ``DEBUG`` on its | |
| 139 | own, apart from the root logger: | |
| 140 | ||
| 274412 | 141 | .. code-block:: ini |
| 1ae7af | 142 | |
| 274412 | 143 | [logger_sqlalchemy.pool] |
| SP | 144 | level = DEBUG |
| 145 | handlers = | |
| 146 | qualname = sqlalchemy.pool | |
| 1ae7af | 147 | |
| 274412 | 148 | then add it to the list of loggers: |
| 1ae7af | 149 | |
| 274412 | 150 | .. code-block:: ini |
| 1ae7af | 151 | |
| 274412 | 152 | [loggers] |
| SP | 153 | keys = root, myapp, sqlalchemy.pool |
| 1ae7af | 154 | |
| 274412 | 155 | No handlers need to be configured for this logger as by default non-root |
| SP | 156 | loggers will propagate their log records up to their parent logger's handlers. |
| 157 | The root logger is the top level parent of all loggers. | |
| 1ae7af | 158 | |
| CM | 159 | This technique is used in the default ``development.ini``. The root logger's |
| 160 | level is set to ``INFO``, whereas the application's log level is set to | |
| 161 | ``DEBUG``: | |
| 162 | ||
| 274412 | 163 | .. code-block:: ini |
| 1ae7af | 164 | |
| 274412 | 165 | # Begin logging configuration |
| 1ae7af | 166 | |
| 274412 | 167 | [loggers] |
| 1ae7af | 168 | keys = root, myapp |
| CM | 169 | |
| 274412 | 170 | [logger_myapp] |
| SP | 171 | level = DEBUG |
| 172 | handlers = | |
| 173 | qualname = myapp | |
| 1ae7af | 174 | |
| CM | 175 | All of the child loggers of the ``myapp`` logger will inherit the ``DEBUG`` |
| 176 | level unless they're explicitly set differently. Meaning the ``myapp.views``, | |
| 274412 | 177 | ``myapp.models``, and all your app's modules' loggers by default have an |
| 1ae7af | 178 | effective level of ``DEBUG`` too. |
| CM | 179 | |
| 0e4dcf | 180 | For more advanced filtering, the logging module provides a |
| SP | 181 | :class:`logging.Filter` object; however it cannot be used directly from the |
| 182 | configuration file. | |
| 1ae7af | 183 | |
| 0e4dcf | 184 | Advanced Configuration |
| 1ae7af | 185 | ---------------------- |
| CM | 186 | |
| 0e4dcf | 187 | To capture log output to a separate file, use :class:`logging.FileHandler` (or |
| SP | 188 | :class:`logging.handlers.RotatingFileHandler`): |
| 1ae7af | 189 | |
| 274412 | 190 | .. code-block:: ini |
| 1ae7af | 191 | |
| 274412 | 192 | [handler_filelog] |
| SP | 193 | class = FileHandler |
| 194 | args = ('%(here)s/myapp.log','a') | |
| 195 | level = INFO | |
| 196 | formatter = generic | |
| 1ae7af | 197 | |
| 274412 | 198 | Before it's recognized, it needs to be added to the list of handlers: |
| 1ae7af | 199 | |
| 274412 | 200 | .. code-block:: ini |
| 1ae7af | 201 | |
| 274412 | 202 | [handlers] |
| 1ae7af | 203 | keys = console, myapp, filelog |
| CM | 204 | |
| 274412 | 205 | and finally utilized by a logger. |
| 1ae7af | 206 | |
| 274412 | 207 | .. code-block:: ini |
| 1ae7af | 208 | |
| 274412 | 209 | [logger_root] |
| SP | 210 | level = INFO |
| 1ae7af | 211 | handlers = console, filelog |
| CM | 212 | |
| 274412 | 213 | These final three lines of configuration direct all of the root logger's output |
| 1ae7af | 214 | to the ``myapp.log`` as well as the console. |
| CM | 215 | |
| bfdbcf | 216 | Logging Exceptions |
| CM | 217 | ------------------ |
| 218 | ||
| 274412 | 219 | To log or email exceptions generated by your :app:`Pyramid` application, use |
| SP | 220 | the :term:`pyramid_exclog` package. Details about its configuration are in its |
| 1cb30e | 221 | `documentation |
| 19d341 | 222 | <https://docs.pylonsproject.org/projects/pyramid_exclog/en/latest/>`_. |
| bfdbcf | 223 | |
| ad76ef | 224 | .. index:: |
| KOP | 225 | single: TransLogger |
| 226 | single: middleware; TransLogger | |
| 227 | pair: configuration; middleware | |
| 228 | single: settings; middleware | |
| 229 | pair: .ini; middleware | |
| 230 | ||
| 231 | .. _request_logging_with_pastes_translogger: | |
| 232 | ||
| 274412 | 233 | Request Logging with Paste's TransLogger |
| 1ae7af | 234 | ---------------------------------------- |
| CM | 235 | |
| 274412 | 236 | The :term:`WSGI` design is modular. Waitress logs error conditions, debugging |
| SP | 237 | output, etc., but not web traffic. For web traffic logging, Paste provides the |
| dcc6b4 | 238 | `TransLogger <http://pythonpaste.org/modules/translogger.html>`_ |
| KOP | 239 | :term:`middleware`. TransLogger produces logs in the `Apache Combined Log |
| 240 | Format <http://httpd.apache.org/docs/2.2/logs.html#combined>`_. But | |
| 274412 | 241 | TransLogger does not write to files; the Python logging system must be |
| SP | 242 | configured to do this. The Python :class:`logging.FileHandler` logging handler |
| 243 | can be used alongside TransLogger to create an ``access.log`` file similar to | |
| 244 | Apache's. | |
| 1ae7af | 245 | |
| 37607c | 246 | Like any standard :term:`middleware` with a Paste entry point, TransLogger can |
| 274412 | 247 | be configured to wrap your application using ``.ini`` file syntax. First |
| 3d338e | 248 | rename your Pyramid ``.ini`` file's ``[app:main]`` section to |
| 274412 | 249 | ``[app:mypyramidapp]``, then add a ``[filter:translogger]`` section, then use a |
| SP | 250 | ``[pipeline:main]`` section file to form a WSGI pipeline with both the |
| 3d338e | 251 | translogger and your application in it. For instance, change from this: |
| 1ae7af | 252 | |
| 274412 | 253 | .. code-block:: ini |
| 3d338e | 254 | |
| CM | 255 | [app:main] |
| fb77c9 | 256 | use = egg:myproject |
| 3d338e | 257 | |
| CM | 258 | To this: |
| 259 | ||
| 274412 | 260 | .. code-block:: ini |
| 3d338e | 261 | |
| CM | 262 | [app:mypyramidapp] |
| fb77c9 | 263 | use = egg:myproject |
| 1ae7af | 264 | |
| 274412 | 265 | [filter:translogger] |
| SP | 266 | use = egg:Paste#translogger |
| 1ae7af | 267 | setup_console_handler = False |
| CM | 268 | |
| 269 | [pipeline:main] | |
| 270 | pipeline = translogger | |
| 3d338e | 271 | mypyramidapp |
| 1ae7af | 272 | |
| 3d338e | 273 | Using PasteDeploy this way to form and serve a pipeline is equivalent to |
| ea8798 | 274 | wrapping your app in a TransLogger instance via the bottom of the ``main`` |
| 3d338e | 275 | function of your project's ``__init__`` file: |
| 1ae7af | 276 | |
| 274412 | 277 | .. code-block:: python |
| 1ae7af | 278 | |
| CM | 279 | ... |
| 280 | app = config.make_wsgi_app() | |
| 274412 | 281 | from paste.translogger import TransLogger |
| SP | 282 | app = TransLogger(app, setup_console_handler=False) |
| 283 | return app | |
| dcc6b4 | 284 | |
| KOP | 285 | .. note:: |
| 286 | TransLogger will automatically setup a logging handler to the console when | |
| 274412 | 287 | called with no arguments, so it "just works" in environments that don't |
| SP | 288 | configure logging. Since our logging handlers are configured, we disable |
| dcc6b4 | 289 | the automation via ``setup_console_handler = False``. |
| 1ae7af | 290 | |
| 780805 | 291 | With the filter in place, TransLogger's logger (named the ``wsgi`` logger) will |
| 274412 | 292 | propagate its log messages to the parent logger (the root logger), sending its |
| SP | 293 | output to the console when we request a page: |
| 1ae7af | 294 | |
| 274412 | 295 | .. code-block:: text |
| 1ae7af | 296 | |
| CM | 297 | 00:50:53,694 INFO [myapp.views] Returning: Hello World! |
| 274412 | 298 | (content-type: text/plain) |
| 1ae7af | 299 | 00:50:53,695 INFO [wsgi] 192.168.1.111 - - [11/Aug/2011:20:09:33 -0700] "GET /hello |
| 274412 | 300 | HTTP/1.1" 404 - "-" |
| 1ae7af | 301 | "Mozilla/5.0 (Macintosh; U; Intel Mac OS X; en-US; rv:1.8.1.6) Gecko/20070725 |
| 274412 | 302 | Firefox/2.0.0.6" |
| 1ae7af | 303 | |
| dcc6b4 | 304 | To direct TransLogger to an ``access.log`` FileHandler, we need the following |
| KOP | 305 | to add a FileHandler (named ``accesslog``) to the list of handlers, and ensure |
| 306 | that the ``wsgi`` logger is configured and uses this handler accordingly: | |
| 1ae7af | 307 | |
| 274412 | 308 | .. code-block:: ini |
| 1ae7af | 309 | |
| 274412 | 310 | # Begin logging configuration |
| 1ae7af | 311 | |
| 780805 | 312 | [loggers] |
| DB | 313 | keys = root, myapp, wsgi |
| 314 | ||
| 315 | [handlers] | |
| 316 | keys = console, accesslog | |
| 1ae7af | 317 | |
| 274412 | 318 | [logger_wsgi] |
| SP | 319 | level = INFO |
| 7dd856 | 320 | handlers = accesslog |
| 274412 | 321 | qualname = wsgi |
| SP | 322 | propagate = 0 |
| 1ae7af | 323 | |
| 274412 | 324 | [handler_accesslog] |
| SP | 325 | class = FileHandler |
| 326 | args = ('%(here)s/access.log','a') | |
| 327 | level = INFO | |
| 328 | formatter = generic | |
| 1ae7af | 329 | |
| 274412 | 330 | As mentioned above, non-root loggers by default propagate their log records to |
| SP | 331 | the root logger's handlers (currently the console handler). Setting |
| 332 | ``propagate`` to ``0`` (``False``) here disables this; so the ``wsgi`` logger | |
| 780805 | 333 | directs its records only to the ``accesslog`` handler. |
| 1ae7af | 334 | |
| CM | 335 | Finally, there's no need to use the ``generic`` formatter with TransLogger as |
| 274412 | 336 | TransLogger itself provides all the information we need. We'll use a formatter |
| SP | 337 | that passes through the log messages as is. Add a new formatter called |
| 338 | ``accesslog`` by including the following in your configuration file: | |
| 1ae7af | 339 | |
| 274412 | 340 | .. code-block:: ini |
| 1ae7af | 341 | |
| 274412 | 342 | [formatters] |
| SP | 343 | keys = generic, accesslog |
| 1ae7af | 344 | |
| 274412 | 345 | [formatter_accesslog] |
| SP | 346 | format = %(message)s |
| 1ae7af | 347 | |
| 274412 | 348 | Finally alter the existing configuration to wire this new ``accesslog`` |
| SP | 349 | formatter into the FileHandler: |
| dcc6b4 | 350 | |
| 274412 | 351 | .. code-block:: ini |
| 1ae7af | 352 | |
| 274412 | 353 | [handler_accesslog] |
| SP | 354 | class = FileHandler |
| 355 | args = ('%(here)s/access.log','a') | |
| 356 | level = INFO | |
| 357 | formatter = accesslog | |
