Mailman 3.3.4 logging behaviour, mixed log formats, and REST API error
Hello,
I have been chatting with Copilot AI for some days to get help investigating some logging-related issues in a Mailman 3.3.4 Docker installation and, so I would appreciate any guidance.
We are working on a long needed upgrade, but for now I need the logs in Elasticsearch, and they are aweful.
Environment
- GNU Mailman 3.3.4 (Tom Sawyer)
- Python 3.8.10
- Docker-based installation
- Test environment with a single mailing list: listname@example.com<mailto:listname@example.com>
Logging configuration
I've configured dedicated log files for most logging channels. For example, [logging.http] is configured with format: %(asctime)s (%(process)d) %(message)s, datefmt: %Y-%m-%d %H:%M:%S.%3N, propagate: no, level: debug, and path: http.log.
All [logging.*] sections in the generated /etc/mailman-extra.cfg use the same datefmt. format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: info path: mailman.log
[logging.archiver] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: archiver.log
[logging.bounce] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: bounce.log
[logging.config] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: config.log
[logging.database] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: database.log
[logging.debug] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: debug.log
[logging.error] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: error.log
[logging.fromusenet] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: fromusenet.log
[logging.http] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: http.log
[logging.locks] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: locks.log
[logging.mischief] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: mischief.log
[logging.plugins] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: plugins.log
[logging.runner] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: info path: runner.log
[logging.smtp] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: info path: smtp.log
[logging.smtp-failure] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: smtp-failure.log
[logging.subscribe] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: subscribe.log
[logging.vette] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: vette.log
Issue 1: Mixed log formats
Despite configuring all logging sections with datefmt: %Y-%m-%d %H:%M:%S.%3N, I still see multiple timestamp formats in mailman.log, for example:
- [30/Jul/2026:12:00:03 +0000] "GET /3.1/lists?count=10&page=1 HTTP/1.1" 200 90 "-" "GNU Mailman REST client v3.3.3"
- [2026-07-30 12:32:15 +0000] [36] [INFO] Shutting down: Master
- Jul 30 12:32:14 2026 (1) Master watcher caught SIGTERM. Exiting
This suggests that multiple logging systems may be writing to the same log file.
Issue 2: Runner debug noise
With logging level set to debug, mailman.log contains a large number of entries such as:
- Jul 31 07:58:12 2026 (33) [PipelineRunner] starting oneloop
- Jul 31 07:58:12 2026 (33) [PipelineRunner] ending oneloop: 0
- Jul 31 07:58:12 2026 (26) [ArchiveRunner] starting oneloop
- Jul 31 07:58:12 2026 (26) [ArchiveRunner] ending oneloop: 0
- Jul 31 07:58:12 2026 (29) [IncomingRunner] starting oneloop
- Jul 31 07:58:12 2026 (29) [IncomingRunner] ending oneloop: 0
- Jul 31 07:58:13 2026 (28) [CommandRunner] starting oneloop
- Jul 31 07:58:13 2026 (36) [VirginRunner] starting oneloop
- Jul 31 07:58:13 2026 (36) [VirginRunner] ending oneloop: 0
- Jul 31 07:58:13 2026 (28) [CommandRunner] ending oneloop: 0
- Jul 31 07:58:13 2026 (37) [DigestRunner] starting oneloop
- Jul 31 07:58:13 2026 (37) [DigestRunner] ending oneloop: 0
- Jul 31 07:58:13 2026 (31) [NNTPRunner] starting oneloop
- Jul 31 07:58:13 2026 (32) [OutgoingRunner] starting oneloop
- Jul 31 07:58:13 2026 (31) [NNTPRunner] ending oneloop: 0
- Jul 31 07:58:13 2026 (32) [OutgoingRunner] ending oneloop: 0
Is there a recommended way to suppress these internal runner loop messages while retaining useful operational logging?
Issue 3: HTTP request logging
I intentionally keep [logging.http] at level: debug because I want to see which REST endpoints are called. Examples:
- [2026-08-03 12:10:28 +0000] [51] [DEBUG] GET /3.1/lists/listname@example.com<mailto:/3.1/lists/listname@example.com>
- [2026-08-03 12:15:29 +0000] [52] [DEBUG] GET /3.1/lists/listname@example.com<mailto:/3.1/lists/listname@example.com>
- [2026-08-03 13:00:03 +0000] [53] [DEBUG] GET /3.1/lists
My goal is to keep these request entries.
Issue 4: Falcon tracebacks in http.log
The same http.log also contains Falcon tracebacks. One example is:
2026-08-03 12:10:29 [FALCON] [ERROR] GET /3.1/lists/listname@example.com/config<mailto:/3.1/lists/listname@example.com/config> => Traceback (most recent call last):
File "/usr/lib/python3.8/site-packages/sqlalchemy/engine/result.py", line 779, in _getter getter = self._metadata._getter
AttributeError: 'NoneType' object has no attribute '_getter'
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/lib/python3.8/site-packages/falcon/app.py", line 361, in call responder(req, resp, **params)
File "/usr/lib/python3.8/site-packages/mailman/rest/listconf.py", line 282, in on_get value = getter.get(self._mlist, attribute)
File "/usr/lib/python3.8/site-packages/mailman/rest/listconf.py", line 52, in get return sorted(aliases.aliases)
File "/usr/lib/python3.8/site-packages/mailman/model/mailinglist.py", line 565, in aliases for alias in aliases
File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/loading.py", line 100, in instances cursor.close()
File "/usr/lib/python3.8/site-packages/sqlalchemy/util/langhelpers.py", line 68, in exit compat.raise_(
File "/usr/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 182, in raise_ raise exception
File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/loading.py", line 58, in instances *[
File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/loading.py", line 59, in query_entity.row_processor(query, context, cursor)
File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/query.py", line 4422, in row_processor _instance = loading._instance_processor(
File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/loading.py", line 421, in _instance_processor getter = result._getter(col, False)
File "/usr/lib/python3.8/site-packages/sqlalchemy/engine/result.py", line 781, in _getter return self._non_result(None, err)
File "/usr/lib/python3.8/site-packages/sqlalchemy/engine/result.py", line 1236, in non_result util.raise(
File "/usr/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 182, in raise_ raise exception
sqlalchemy.exc.ResourceClosedError: This result object does not return rows. It has been closed automatically.
Is it possible to:
- Continue logging HTTP GET requests to http.log
- Send Falcon tracebacks and REST API errors to a separate log file
At the moment, both request logging and tracebacks appear in the same file.
Issue 5: Worker timeout
After the traceback above, I consistently see:
- [2026-08-03 12:21:29 +0000] [34] [CRITICAL] WORKER TIMEOUT (pid:52)
- [2026-08-03 12:21:30 +0000] [53] [INFO] Booting worker with pid: 53
This appears to indicate that the worker handling GET /3.1/lists/listname@example.com/config<mailto:/3.1/lists/listname@example.com/config> times out and is restarted.
Additional observations
error.log contains Mailman Core exceptions such as:
(52) deque: subscribe_from_restored
Traceback (most recent call last):
File "/usr/lib/python3.8/site-packages/mailman/app/workflow.py", line 69, in next return step()
File "/usr/lib/python3.8/site-packages/mailman/app/subscriptions.py", line 341, in _step_get_moderator_approval raise StopIteration
StopIteration
However, the Falcon/REST traceback shown above does not appear in error.log.
This suggests that:
- error.log receives Mailman Core exceptions.
- http.log receives REST API/Falcon exceptions.
- The two do not appear to be linked.
Questions
- Is the mixed timestamp formatting expected in Mailman 3.3.4 Docker deployments?
- Which component produces the starting oneloop / ending oneloop runner messages?
- Can HTTP request logging and Falcon tracebacks be directed to separate log files?
- Is ResourceClosedError when accessing GET /3.1/lists/listname@example.com/config<mailto:/3.1/lists/listname@example.com/config> a known Mailman 3.3.4 issue?
- Is there a recommended logging configuration that preserves REST API access logging while reducing runner/debug noise?
Thanks in advance.
Best regards, Henrik
Henrik Rasmussen via Mailman-users writes:
I have been chatting with Copilot AI
Be careful with that. I can't speak to Copilot, but I assure you that Gemini and Claude both gave a lot of crappy advice about Mailman 3 over the last couple of years (the latest most expensive versions may be better). There was a lot of confusion among Mailman 2 and Mailman 3.
for some days to get help investigating some logging-related issues in a Mailman 3.3.4 Docker installation
We are working on a long needed upgrade,
I assume you intend to continue with a containerized Mailman 3. In that case, my understanding is that you want to upgrade Python to 3.13 right now. But once a couple of dependencies that don't work with Python 3.14 are upgraded upstream, 3.14 is probably the way to go (you may be more conservative than that though). I don't know how likely 3.3.11 is to support 3.14. Experience suggests we surely won't be able to support 3.15 for a couple of releases.
but for now I need the logs in Elasticsearch,
You mean dumping the Mailman logs into Elasticsearch, not using Elasticsearch for the archives, right?
and they are aweful.
I don't know any logs produced by concurrent server systems that aren't, to be honest. Even Postfix, which seems to be a pretty well- designed logging system, is a real pain to analyze, especially if you enable debug output. I sympathize with your desire for a consistent date format, but to get that you probably need to conform Mailman's logging to gunicorn's. Gunicorn (the WSGI server for the REST API) allows much flexibility in selecting different information to add to each log message, but I don't recall any in formatting the individual fields.
Environment
- GNU Mailman 3.3.4 (Tom Sawyer)
- Python 3.8.10
- Docker-based installation
- Test environment with a single mailing list: listname@example.com<mailto:listname@example.com>
Logging configuration
I've configured dedicated log files for most logging channels. For example, [logging.http] is configured with format: %(asctime)s (%(process)d) %(message)s, datefmt: %Y-%m-%d %H:%M:%S.%3N, propagate: no, level: debug, and path: http.log.
You can configure all configurable logging to defaults, then override only the non-default attributes (I didn't look carefully, but it seems like all of your settings are identical except for path and level). Using the [logging.template] section described below (mailman/config/schema.cfg has more details) may give you a little more consistency in date formatting. From schema.cfg:
[logging.template] # This defines various log settings. The options available are: # # - level -- Overrides the default level; this may be any of the # standard Python logging levels, case insensitive. # - format -- Overrides the default format string # - datefmt -- Overrides the default date format string # - path -- Overrides the default logger path. This may be a relative # path name, in which case it is relative to Mailman's LOG_DIR, # or it may be an absolute path name. You cannot change the # handler class that will be used. # - propagate -- Boolean specifying whether to propagate log message from this # logger to the root "mailman" logger. You cannot override # settings for the root logger. # # In this section, you can define defaults for all loggers, which will be # prefixed by 'mailman.'.
I guess your logging.template would look like
[logging.template] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug # some sections should override to "info"
Then use subsections as in your current configuration to override the path, and occasionally level, settings for specific loggers.
Somebody added a [logging.gunicorn] section, but did not add it to that list. The date format is gunicorn-specific. I don't know if there's a way to change it, there's no documentation beyond the default setting itself in schema.cfg for logging.gunicorn. (Gunicorn's own documentation is quite good, though.) The log message format (the syntax is also gunicorn-specific, and not generic logging format syntax) is
[logging.gunicorn] format: %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"
That won't help in 3.3.4, though.
Issue 1: Mixed log formats
This suggests that multiple logging systems may be writing to the same log file.
Pretty sure all Mailman modules use the stdlib logging module, but I'm not sure about gunicorn. Four possibilities for inconsistency:
- You missed configuring some particular logger (unlikely but possible)
- Date format is hard-coded in some module
- Bug in parsing the config file or updating the config object
- REST API logging comes from gunicorn. You may need to configure this in gunicorn.conf (in the same place as mailman.cfg).
Issue 2: Runner debug noise
With logging level set to debug, mailman.log contains a large number of entries such as: [omitted] Is there a recommended way to suppress these internal runner loop messages while retaining useful operational logging?
"level: info" is the only standard way. If that is not detailed enough, you'll need to customize the code or filter using "grep -v" or similar.
Issue 3: HTTP request logging
I intentionally keep [logging.http] at level: debug because I want to see which REST endpoints are called. My goal is to keep these request entries.
I don't understand where the problem for your current 3.3.4 lies. Just keep "level: debug", no? For current 3.3.10, [logging.http] has "level: info" and generates all API requests like
[24/Sep/2025:00:00:10 +0000] "GET /3.1/lists/testlist@turnbull.jp HTTP/1.1" 200 368 "-" "GNU Mailman REST client v3.3.5"
Pretty sure the slashes and the brackets come from gunicorn's "%(t)s" format.
Issue 4: Falcon tracebacks in http.log
The same http.log also contains Falcon tracebacks. One example is: Is it possible to:
- Continue logging HTTP GET requests to http.log
- Send Falcon tracebacks and REST API errors to a separate log file
For 3.3.4, you'll have to customize the relevant loggers, but I don't think there is provision for this in the config module. You can reconfigure Falcon once and for all using standard logging APIs. Splitting GET requests from REST API debugging would need to be done at the call sites.
For 3.3.10, you can't split, but you can inhibit debug output. I'm not sure what happens with "level: info" when an exception is raised. Probably that goes to the [logging.http] file, though, as exceptions are high priority events.
At the moment, both request logging and tracebacks appear in the same file.
Are you sure you want to split them? Since Mailman usually works OK, generally we want to know what requests cause exceptions and tracebacks.
Issue 5: Worker timeout
After the traceback above, I consistently see:
- [2026-08-03 12:21:29 +0000] [34] [CRITICAL] WORKER TIMEOUT (pid:52)
- [2026-08-03 12:21:30 +0000] [53] [INFO] Booting worker with pid: 53
This appears to indicate that the worker handling GET /3.1/lists/listname@example.com/config<mailto:/3.1/lists/listname@example.com/config> times out and is restarted.
Yes. That's by design, since the workers are a different process from where the exception is raised, and the IPC socket is supposed to be persistent for the whole session, but it goes idle without being closed.
However, the Falcon/REST traceback shown above does not appear in error.log.
This suggests that:
- error.log receives Mailman Core exceptions.
- http.log receives REST API/Falcon exceptions.
- The two do not appear to be linked.
That is correct. The REST API runs in a gunicorn process, separate from the other Mailman core runners.
Questions
- Is the mixed timestamp formatting expected in Mailman 3.3.4 Docker deployments?
Yes. This is a bug, but it's not high priority.
- Which component produces the starting oneloop / ending oneloop runner messages?
mailman/core/runner.py
- Can HTTP request logging and Falcon tracebacks be directed to separate log files?
See above.
- Is ResourceClosedError when accessing GET /3.1/lists/listname@example.com/config<mailto:/3.1/lists/listname@example.com/config> a known Mailman 3.3.4 issue?
That error is not raised by Mailman, but by some other package. Mailman 3.3.4 is over 5 years old now. It is quite likely it has been fixed either by that package's maintainer, or "en passant" in some Mailman fix.
- Is there a recommended logging configuration that preserves REST API access logging while reducing runner/debug noise?
"level: info" where "level: debug" is considered too noisy.
If you don't like that, you can submit a specific RFE, but as you can see from where I pushback on your requests, opinions vary on logging. I rather doubt that Mailman admins will fracture cleanly into two factions, one agreeing with you and the other with me. ;-) So it could be a long messy discussion about how to factor literally hundreds of individual logging calls.
Regards, Steve
-- GNU Mailman consultant (installation, migration, customization) Sirius Open Source https://www.siriusopensource.com/ Software systems consulting in Europe, North America, and Japan
participants (2)
-
Henrik Rasmussen -
Stephen J. Turnbull