0

i run a wsgi application under debian 8.9 / apache2 and the app (LinOTP) is not writing logfiles. I'm not shure if this is a problem of the app or from setup. I see errors in the apache error.log

 root@host:/var/log/apache2# tail -f /var/log/apache2/error.log
[Fri Jul 06 15:56:29.537409 2018] [wsgi:warn] [pid 2050:tid 140694121756544] mod_wsgi: Compiled for Python/2.7.8.
[Fri Jul 06 15:56:29.537461 2018] [wsgi:warn] [pid 2050:tid 140694121756544] mod_wsgi: Runtime using Python/2.7.9.
[Fri Jul 06 15:56:29.538373 2018] [mpm_event:notice] [pid 2050:tid 140694121756544] AH00489: Apache/2.4.10 (Debian) OpenSSL/1.0.1t mod_wsgi/4.3.0 Python/2.7.9 configured -- resuming normal operations
[Fri Jul 06 15:56:29.538395 2018] [core:notice] [pid 2050:tid 140694121756544] AH00094: Command line: '/usr/sbin/apache2'
[Fri Jul 06 15:57:32.234197 2018] [wsgi:error] [pid 2053:tid 140693997573888] Traceback (most recent call last):
[Fri Jul 06 15:57:32.234447 2018] [wsgi:error] [pid 2053:tid 140693997573888]   File "/usr/lib/python2.7/logging/handlers.py", line 76, in emit
[Fri Jul 06 15:57:32.234832 2018] [wsgi:error] [pid 2053:tid 140693997573888]     if self.shouldRollover(record):
[Fri Jul 06 15:57:32.234926 2018] [wsgi:error] [pid 2053:tid 140693997573888]   File "/usr/lib/python2.7/logging/handlers.py", line 156, in shouldRollover
[Fri Jul 06 15:57:32.235037 2018] [wsgi:error] [pid 2053:tid 140693997573888]     msg = "%s\\n" % self.format(record)
[Fri Jul 06 15:57:32.235127 2018] [wsgi:error] [pid 2053:tid 140693997573888]   File "/usr/lib/python2.7/logging/__init__.py", line 732, in format
[Fri Jul 06 15:57:32.235546 2018] [wsgi:error] [pid 2053:tid 140693997573888]     return fmt.format(record)
[Fri Jul 06 15:57:32.235628 2018] [wsgi:error] [pid 2053:tid 140693997573888]   File "/usr/lib/python2.7/logging/__init__.py", line 474, in format
[Fri Jul 06 15:57:32.235711 2018] [wsgi:error] [pid 2053:tid 140693997573888]     s = self._fmt % record.__dict__
[Fri Jul 06 15:57:32.235793 2018] [wsgi:error] [pid 2053:tid 140693997573888] KeyError: 'request_id'
[Fri Jul 06 15:57:32.235886 2018] [wsgi:error] [pid 2053:tid 140693997573888] Logged from file SCIMIdResolver.py, line 45
[Fri Jul 06 15:57:32.236087 2018] [wsgi:error] [pid 2053:tid 140693997573888] Traceback (most recent call last):
[Fri Jul 06 15:57:32.236182 2018] [wsgi:error] [pid 2053:tid 140693997573888]   File "/usr/lib/python2.7/logging/handlers.py", line 76, in emit
[Fri Jul 06 15:57:32.236271 2018] [wsgi:error] [pid 2053:tid 140693997573888]     if self.shouldRollover(record):
[Fri Jul 06 15:57:32.236340 2018] [wsgi:error] [pid 2053:tid 140693997573888]   File "/usr/lib/python2.7/logging/handlers.py", line 156, in shouldRollover
[Fri Jul 06 15:57:32.236402 2018] [wsgi:error] [pid 2053:tid 140693997573888]     msg = "%s\\n" % self.format(record)
[Fri Jul 06 15:57:32.236451 2018] [wsgi:error] [pid 2053:tid 140693997573888]   File "/usr/lib/python2.7/logging/__init__.py", line 732, in format
[Fri Jul 06 15:57:32.236583 2018] [wsgi:error] [pid 2053:tid 140693997573888]     return fmt.format(record)
[Fri Jul 06 15:57:32.236657 2018] [wsgi:error] [pid 2053:tid 140693997573888]   File "/usr/lib/python2.7/logging/__init__.py", line 474, in format
[Fri Jul 06 15:57:32.236733 2018] [wsgi:error] [pid 2053:tid 140693997573888]     s = self._fmt % record.__dict__
[Fri Jul 06 15:57:32.236808 2018] [wsgi:error] [pid 2053:tid 140693997573888] KeyError: 'request_id'
[Fri Jul 06 15:57:32.236879 2018] [wsgi:error] [pid 2053:tid 140693997573888] Logged from file __init__.py, line 118
[Fri Jul 06 15:57:33.173087 2018] [wsgi:error] [pid 2053:tid 140693997573888] /usr/lib/python2.7/dist-packages/urllib3/contrib/socks.py:31: DependencyWarning: SOCKS support in urllib3 requires the installation of optional dependencies: specifically, PySocks.  For more information, see https://urllib3.readthedocs.io/en/latest/contrib.html#socks-proxies
[Fri Jul 06 15:57:33.173278 2018] [wsgi:error] [pid 2053:tid 140693997573888]   DependencyWarning
[Fri Jul 06 15:57:33.301962 2018] [wsgi:error] [pid 2053:tid 140693997573888] Traceback (most recent call last):
[Fri Jul 06 15:57:33.302145 2018] [wsgi:error] [pid 2053:tid 140693997573888]   File "/usr/lib/python2.7/logging/handlers.py", line 76, in emit
[Fri Jul 06 15:57:33.302238 2018] [wsgi:error] [pid 2053:tid 140693997573888]     if self.shouldRollover(record):
[Fri Jul 06 15:57:33.302333 2018] [wsgi:error] [pid 2053:tid 140693997573888]   File "/usr/lib/python2.7/logging/handlers.py", line 156, in shouldRollover
[Fri Jul 06 15:57:33.302412 2018] [wsgi:error] [pid 2053:tid 140693997573888]     msg = "%s\\n" % self.format(record)
[Fri Jul 06 15:57:33.302479 2018] [wsgi:error] [pid 2053:tid 140693997573888]   File "/usr/lib/python2.7/logging/__init__.py", line 732, in format
[Fri Jul 06 15:57:33.302554 2018] [wsgi:error] [pid 2053:tid 140693997573888]     return fmt.format(record)
[Fri Jul 06 15:57:33.302620 2018] [wsgi:error] [pid 2053:tid 140693997573888]   File "/usr/lib/python2.7/logging/__init__.py", line 474, in format
[Fri Jul 06 15:57:33.302693 2018] [wsgi:error] [pid 2053:tid 140693997573888]     s = self._fmt % record.__dict__
[Fri Jul 06 15:57:33.302767 2018] [wsgi:error] [pid 2053:tid 140693997573888] KeyError: 'request_id'
[Fri Jul 06 15:57:33.302833 2018] [wsgi:error] [pid 2053:tid 140693997573888] Logged from file base.py, line 52
[Fri Jul 06 15:57:33.365593 2018] [wsgi:error] [pid 2053:tid 140693997573888] /usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py:573: SAWarning: Unicode type received non-unicode bind param value
[Fri Jul 06 15:57:33.365787 2018] [wsgi:error] [pid 2053:tid 140693997573888]   param.append(processors[key](compiled_params[key]))

Here is the logging configuration from the app .ini:

## Logging Configuration:
## ----------------------
## Note: For more detailed log messages change the level to INFO or DEBUG
##


## Logger configuration
## - define which modules should be logged
[loggers]
keys = root

## root module logging definition:
[logger_root]
level = DEBUG
handlers = file

[handlers]
keys = file

[handler_file]
class = handlers.RotatingFileHandler
# Make the logfiles 10 MB
#and rotate 4  files
args = ('/var/log/linotp/linotp.log','a', 10000000, 4)
level = WARN
formatter = generic

## Logging via logstash
## This is an example using the python-logstash logging library.
## If you wish to use this example, you also need to add
## logstash to handlers.keys, and add the logstash handler to
## the individual logger_* section
#[handler_logstash]
## Logging class to use
#class = logstash.UDPLogstashHandler
## Arguments as accepted by the logstash library. For more details
## see the output of 'pydoc logstash.UDPLogstashHandler'
##   ('hostname', port,  message_type, ('tag', 'tag', ...), fqdn, version)
#args = ('logstashhost', 5000, 'linotp', ('example1'), False, 1)

[formatters]
keys = generic

[formatter_generic]
## To secure your log output and prevent command escaping use the
## logger class definition linotp.lib.log.SecureFormatter by uncommenting the
## line below
##
## Caution: The SecureFormatter will only work with python >= 2.7
##
#class = linotp.lib.log.SecureFormatter
format = %(asctime)s %(levelname)-5.5s {%(request_id)s} [%(name)s][%(funcName)s #%(lineno)d] %(message)s
datefmt = %Y/%m/%d - %H:%M:%S

Has anyone any hints for me.

chewbakka
  • 401
  • 4
  • 8
  • 1
    You have defined `%(request_id)` in the format template, but the standard `LogRecord` doesn't have such field. You have to define the field either in the log method directly, for example `logger.info('spam', extra={'request_id': 'eggs'})`, or add a custom `Filter` that will implicitly add the field for each record, or use [`LoggerAdapter`](https://docs.python.org/2/library/logging.html#loggeradapter-objects) for that matter. – hoefling Jul 06 '18 at 19:13
  • so this is a problem of the app and not a problem of my installation? – chewbakka Jul 07 '18 at 20:56
  • 1
    Definitely. To test, remove `{%(request_id)s}` part from the `format =` line in the logger ini config and the error will disappear. – hoefling Jul 07 '18 at 21:26

0 Answers0