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