[PATCH] Syslog Logging Not Working on FreeBSD

[david@…]

FreeBSD's syslog doesn't listen on /dev/log. It uses /var/run/log. Attached is a patch that allows you to specify the path to the UNIX socket instead of hardcoding it. It basically uses the logfile parameter, if it's None use /dev/log otherwise use it.

This bug affects all versions of Trac since about 0.7 it looks like.

[david@…]

Patch for 0.10-stable and trunk. Overrides handling of UNIX socket path via logfile parameter.

[david@…]

It's also possible to just remove the explicit path, and everything Just Works(tm) (at least on Python 2.5.2).

[Christian Boos]

My preference goes to attachment:syslog-removepath.patch​.

Moving to 0.13 so that we don't have to bother with Python 2.3.

Should be verified for 2.4 as well, and on other platforms if needed (MacOS X?)

[george@…]

Yes, this works for OS 10.6 with the built-in Python 2.6.

[Remy Blank]

According to the Python documentation:

• Passing no argument to SysLogHandler connects to the syslog via UDP port 514 on localhost.
• Specifying a string argument to SysLogHandler is only documented since 2.5, but is actually supported earlier (2.3 is the oldest I checked), and connects to a UNIX socket.

Considering this, we could support both variants, which comes closer to the first patch:

• Add a new parameter logdest.
• If logdest starts with UDP:, we pass the remaining string as a hostname and log via UDP to that host (which could be localhost). This would also allow logging remotely.
• Otherwise, logdest is passed as a string and we log to a UNIX socket.

Re-using logfile for this purpose is probably a bad idea, as the default value is trac.log.

[Remy Blank]

Oops, wrong field :)

[Ryan J Ollos]

#11216 closed as a duplicate, additionally requesting the ability to set the syslog facility. ticket:11216:logging_config.patch​ adds a log_config option which points to a dedicated logging configuration file.

[Sebastian Klemke <packet@…>]

Updated logging config patch. Adds the path, basename, project log format substitutions.

[Sebastian Klemke <packet@…>]

Logging config ini file to log to syslog on FreeBSD

[Sebastian Klemke <packet@…>]

Patch to the admin panel to add log_config support.

[Ryan J Ollos]

The patch looks pretty good. The biggest thing that will delay getting this committed is the lack of unit tests. If some unit tests were added this could be included in milestone:1.2.

[Ryan J Ollos]

See also #11874. The proposed changes in that ticket would be a good follow-on to this ticket.

[Ryan J Ollos]

Minor refactorings in [14333:14336].

Revised changes in log:rjollos.git:t7820_logging_config. The revised changes avoid API changes that were present in attachment:logging_config.patch​. Some of those changes have been deferred to #11874 (comment:10:ticket:11874).

I'll do more testing and add unit tests.

[Ryan J Ollos]

TODO Add documentation to TracLogging.

[Jun Omae]

At least, we should use disable_existing_loggers=False for the logging.config.fileConfig(). I guess that call of the fileConfig() would stop loggers of other environments with multiple projects.

See:

• ​https://docs.python.org/2/library/logging.config.html#logging.config.fileConfig
• ​https://docs.python.org/3/howto/logging.html#configuring-logging

[Ryan J Ollos]

Proposed changes in log:rjollos.git:t7820_logging_config.1.

[Jun Omae]

The resource of the logging handler isn't closed even though calling Environment.shutdown().

logging.ini has the following.

[formatters]
keys=form01

[logger_root]
level=NOTSET
handlers=hand01

[handler_hand01]
class=FileHandler
level=NOTSET
formatter=form01
args=('/tmp/trac.log',)

[formatter_form01]
class=logging.Formatter
format=Trac %(asctime)s %(levelname)s %(message)s

After constructing Environment object, the logger is initialized and the /tmp/trac.log is opened.

>>> from trac.env import Environment
>>> env = Environment('/home/jun66j5/var/trac/1.3dev-sqlite')
>>> import os
>>> os.getpid()
4625
>>> os.system('lsof -p 4625 | tail -4')
python  4625 jun66j5    0u   CHR  136,0      0t0       3 /dev/pts/0
python  4625 jun66j5    1u   CHR  136,0      0t0       3 /dev/pts/0
python  4625 jun66j5    2u   CHR  136,0      0t0       3 /dev/pts/0
python  4625 jun66j5    3w   REG    8,1    14517  268820 /tmp/trac.log
0

However, the /tmp/trac.log is still opened after call of Environment.shutdown(). No way to close the resource.

>>> env.shutdown()
>>> os.system('lsof -p 4625 | tail -4')
python  4625 jun66j5    0u   CHR  136,0      0t0       3 /dev/pts/0
python  4625 jun66j5    1u   CHR  136,0      0t0       3 /dev/pts/0
python  4625 jun66j5    2u   CHR  136,0      0t0       3 /dev/pts/0
python  4625 jun66j5    3w   REG    8,1    14517  268820 /tmp/trac.log
0
>>> del env
>>> env
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
NameError: name 'env' is not defined
>>> import gc
>>> gc.collect()
732
>>> gc.collect()
0
>>> os.system('lsof -p 4625 | tail -4')
python  4625 jun66j5    0u   CHR  136,0      0t0       3 /dev/pts/0
python  4625 jun66j5    1u   CHR  136,0      0t0       3 /dev/pts/0
python  4625 jun66j5    2u   CHR  136,0      0t0       3 /dev/pts/0
python  4625 jun66j5    3w   REG    8,1    14517  268820 /tmp/trac.log
0

[Ryan J Ollos]

Replying to Jun Omae:

The resource of the logging handler isn't closed even though calling Environment.shutdown().

Thanks for noticing. I have a possible solution for that issue, but there are a few related issues to work through. Handling multiple environments, each with their own logger, may be tricky. I'll post some more changes and comments soon.

[Ryan J Ollos]

There are numerous issues that need to be worked out, the first of which is for the Environment to get the name of the logger to use, as pointed out in comment:18. I considered a few ways to approach this:

• Add a [logging] configuration option, logger_name. This seems like a redundant specification since the logger name is specified in the logging.ini file, but it could be useful in the case that logging.ini defined loggers for several environments, and each environment pointed to the same logging.ini (which itself presents issues, to be discussed).
• Parse logging.ini to get the logger name before calling fileConfig. An imposed constraint would be that logging.ini can only contain the configuration for single logger, and possibly the root logger as well. Python 3.4 allows an instance derived from RawConfigParser to be ​passed as fname, which would fit this pattern.
• Reimplement fileConfig in trac.log, returning the name of the logger. The constraint of one logger per configuration file (not including root), would need to be imposed.

I'm inclined to go with the last solution because the implementation of fileConfig has several issues that could be solved with a rewrite.

• fileConfig calls ​_install_loggers, which removes all handlers for the root logger. With multiple environments we might want to use the root logger to share configuration across all the environments, but we don't want the root logger to be reset each time an environment reads its logging.ini.
• The internal list of handlers ​is cleared each time a logging config file is read. fileConfig doesn't support ​incremental configuration. DictConfig does support incremental configuration, but I'm not sure the implementation is quite what we want.

The way fileConfig is implemented, I'm inclined to think that the expected use would be to load logging.ini at application scope, then have a logger_name configuration option so that each Environment knows which logger to use. However, Trac doesn't have an application scope configuration whereby we could load the logging configuration at application startup. Or, maybe I'm wrong about this, and Trac's means of application-scope configuration is to use environment variables, which might work in this case.

Side note: the Python documentation recommends using dictConfig rather than fileConfig, but I think fileConfig is pretty close to what we want with Trac since we already use the ini file format for trac.ini. I've studied the source code for logging.config and there are other warts, which I won't go into because I think I see a path to a reasonable solution.

I don't want to overcomplicate the implementation prior to getting feedback on use cases, so I'm suggesting the following constraints:

• Each environment should have its own logging.ini file and that file should define the name of a single logger that is used only by that environment.
• To share a configuration among multiple environments (e.g. have them all log to the same file), the root logger should be configured.

The re-implementation of fileConfig will return the name of the logger that has been read from logging.ini and the Trac environment will clean up the handlers for its loggers on shutdown.

I'm not quite sure how to handle configuring the root logger in a multi-environment configuration. If the root logger is configured in logging.ini for every environment, then it will be recreated when each Environment is created. It's also not clear to me which Environment should be responsible for cleaning up the handlers for the root logger. Maybe that would be accomplished by a ​shutdown function called by atexit.

On the other hand, if we make a single environment responsible for configuration and cleaning up the root logger, then we need to make sure that environment is started first.

I'm considering something like the following as a solution. Store the logger config in its own file, or use a prefix like file:// (inspired by ​cfg://), to point to the root config file from every logging.ini. With the logging config in its own file, we could store the timestamp of that file and only reload the root configuration file when the timestamp has changed. I'm assuming we could use a class or module scope variable to store the timestamp so that the timestamp would be seen by all environments running in the same process. However, it's possible I don't understand all the possible runtime configurations that need to be accounted for. I'm assuming that under any configuration, we only need to account for multiple environments running in the same process, and that the state of class or module scope variables will be shared across all environments running in the same process, but no environments running outside the process. I'm also assuming we may need to put a lock on any such variables since they could be written to from multiple threads running in the process.

Another possible solution, mentioned earlier, would be to configure the root logger at application scope.

[Christian Boos]

Moving to some later 1.3.x version.

[Ryan J Ollos]

Milestone renamed

[Ryan J Ollos]

Milestone renamed