Page MenuHomekolab.org

wallaced not starting after reboot
Open, Needs TriagePublic

Description

Hi.

I am using the latest version of the Community Edition on CentOS 7 and after a reboot I am suddenly having the problem that wallaced appears not to start properly and listen on port 10026 anymore.
(Before, the last configuration changes and server reboot were in September, the issue persists after updating to the latest version.)

Postfix is now giving me lots of errors like these:
Dec 18 10:46:02 myserver01 postfix/error[3542]: 6F7F9176: to=<root@mydomain.local>, relay=none, delay=0.13, delays=0.07/0.04/0/0.03, dsn=4.4.1, status=deferred (delivery temporarily suspended: connect to 127.0.0.1[127.0.0.1]:10026: Connection refused)

In the pykolab.log I see these messages:
2021-12-18 08:55:27,028 pykolab.wallace/modules ERROR [1588] tmpvFcc0A SMTP Recipient(s) Refused, SMTPRecipientsRefused({'root@mydomain.local': (451, '4.3.0 <root@mydomain.local>: Temporary lookup failure')},)

The login with roundcubemail, etc is still working, but no e-mails can be received.

I really do not know how to properly troubleshoot the issue and if it is a bug, but the debug output of wallaced included below is telling me to report a bug...

I would very much appreciate your help.

[]# /usr/sbin/wallaced -l debug -d 9

2021-12-18 11:02:03,326 pykolab.conf DEBUG [4035] Setting kolab_default_locale to 'en_US' (from defaults)
2021-12-18 11:02:03,326 pykolab.conf DEBUG [4035] Setting mail_attributes to ['mail', 'alias'] (from defaults)
2021-12-18 11:02:03,327 pykolab.conf DEBUG [4035] Setting mailserver_attribute to 'mailhost' (from defaults)
2021-12-18 11:02:03,327 pykolab.conf DEBUG [4035] Setting loglevel to 50 (from defaults)
2021-12-18 11:02:03,327 pykolab.conf DEBUG [4035] Setting imap_virtual_domains to 'userid' (from defaults)
2021-12-18 11:02:03,327 pykolab.conf DEBUG [4035] Setting cyrus_annotations_retry_interval to 1 (from defaults)
2021-12-18 11:02:03,327 pykolab.conf DEBUG [4035] Setting ldap_unique_attribute to 'nsuniqueid' (from defaults)
2021-12-18 11:02:03,327 pykolab.conf DEBUG [4035] Setting kolab_domain_sync_interval to 600 (from defaults)
2021-12-18 11:02:03,328 pykolab.conf DEBUG [4035] Setting ldap_timeout to 10 (from defaults)
2021-12-18 11:02:03,328 pykolab.conf DEBUG [4035] Setting wallace_resource_calendar_expire_days to 100 (from defaults)
2021-12-18 11:02:03,328 pykolab.conf DEBUG [4035] Setting address_search_attrs to ['mail', 'alias'] (from defaults)
2021-12-18 11:02:03,328 pykolab.conf DEBUG [4035] Setting fork_mode to False (from the default values for CLI options)
2021-12-18 11:02:03,328 pykolab.conf DEBUG [4035] Setting config_file to '/etc/kolab/kolab.conf' (from the default values for CLI options)
2021-12-18 11:02:03,329 pykolab.conf DEBUG [4035] Setting answer_default to False (from the default values for CLI options)
2021-12-18 11:02:03,329 pykolab.conf DEBUG [4035] Setting process_groupname to 'kolab' (from the default values for CLI options)
2021-12-18 11:02:03,329 pykolab.conf DEBUG [4035] Setting loglevel to 'CRITICAL' (from the default values for CLI options)
2021-12-18 11:02:03,329 pykolab.conf DEBUG [4035] Setting wallace_port to 10026 (from the default values for CLI options)
2021-12-18 11:02:03,329 pykolab.conf DEBUG [4035] Setting answer_yes to False (from the default values for CLI options)
2021-12-18 11:02:03,329 pykolab.conf DEBUG [4035] Setting quiet to False (from the default values for CLI options)
2021-12-18 11:02:03,330 pykolab.conf DEBUG [4035] Setting wallace_bind_address to 'localhost' (from the default values for CLI options)
2021-12-18 11:02:03,330 pykolab.conf DEBUG [4035] Setting max_threads to 4 (from the default values for CLI options)
2021-12-18 11:02:03,330 pykolab.conf DEBUG [4035] Setting process_username to 'kolab' (from the default values for CLI options)
2021-12-18 11:02:03,330 pykolab.conf DEBUG [4035] Setting debuglevel to 0 (from the default values for CLI options)
2021-12-18 11:02:03,330 pykolab.conf DEBUG [4035] Setting max_tasks to None (from the default values for CLI options)
2021-12-18 11:02:03,330 pykolab.conf DEBUG [4035] Setting logfile to '/var/log/kolab/pykolab.log' (from the default values for CLI options)
2021-12-18 11:02:03,330 pykolab.conf DEBUG [4035] Setting pidfile to '/var/run/wallaced/wallaced.pid' (from the default values for CLI options)
2021-12-18 11:02:03,331 pykolab.conf DEBUG [4035] Setting options from configuration file
2021-12-18 11:02:03,331 pykolab.conf DEBUG [4035] Reading configuration file /etc/kolab/kolab.conf
2021-12-18 11:02:03,333 pykolab.conf DEBUG [4035] Setting max_threads to 4 (from CLI, not checked)
2021-12-18 11:02:03,336 pykolab.conf DEBUG [4035] Setting config_file to '/etc/kolab/kolab.conf' (from CLI, verified)
2021-12-18 11:02:03,336 pykolab.conf DEBUG [4035] Setting answer_default to False (from CLI, not checked)
2021-12-18 11:02:03,336 pykolab.conf DEBUG [4035] Setting process_groupname to 'kolab' (from CLI, not checked)
2021-12-18 11:02:03,337 pykolab.conf DEBUG [4035] Setting loglevel to 'debug' (from CLI, not checked)
2021-12-18 11:02:03,337 pykolab.conf DEBUG [4035] Setting wallace_port to 10026 (from CLI, not checked)
2021-12-18 11:02:03,337 pykolab.conf DEBUG [4035] Setting answer_yes to False (from CLI, not checked)
2021-12-18 11:02:03,337 pykolab.conf DEBUG [4035] Setting quiet to False (from CLI, not checked)
2021-12-18 11:02:03,337 pykolab.conf DEBUG [4035] Setting wallace_bind_address to 'localhost' (from CLI, not checked)
2021-12-18 11:02:03,337 pykolab.conf DEBUG [4035] Setting fork_mode to False (from CLI, not checked)
2021-12-18 11:02:03,338 pykolab.conf DEBUG [4035] Setting process_username to 'kolab' (from CLI, not checked)
2021-12-18 11:02:03,338 pykolab.conf DEBUG [4035] Setting debuglevel to 9 (from CLI, verified)
2021-12-18 11:02:03,338 pykolab.conf DEBUG [4035] Setting max_tasks to None (from CLI, not checked)
2021-12-18 11:02:03,338 pykolab.conf DEBUG [4035] Setting logfile to '/var/log/kolab/pykolab.log' (from CLI, not checked)
2021-12-18 11:02:03,338 pykolab.conf DEBUG [4035] Setting pidfile to '/var/run/wallaced/wallaced.pid' (from CLI, not checked)
2021-12-18 11:02:03,339 multiprocessing DEBUG [4035] Python multi-processing logger started
2021-12-18 11:02:03,429 pykolab.wallace DEBUG [4035] Switching real and effective group id to 412
2021-12-18 11:02:03,429 pykolab.wallace DEBUG [4035] Switching real and effective user id to 412
2021-12-18 11:02:03,436 multiprocessing DEBUG [4035] created semlock with handle 140373210562560
2021-12-18 11:02:03,436 multiprocessing DEBUG [4035] created semlock with handle 140373210558464
2021-12-18 11:02:03,436 multiprocessing DEBUG [4035] created semlock with handle 140373210554368
2021-12-18 11:02:03,437 multiprocessing DEBUG [4035] created semlock with handle 140373210550272
2021-12-18 11:02:03,438 multiprocessing DEBUG [4035] added worker
2021-12-18 11:02:03,440 multiprocessing INFO [4040] child process calling self.run()
2021-12-18 11:02:03,440 pykolab.wallace DEBUG [4040] Worker process PoolWorker-1 initializing
2021-12-18 11:02:03,440 multiprocessing DEBUG [4035] added worker
2021-12-18 11:02:03,442 multiprocessing INFO [4041] child process calling self.run()
2021-12-18 11:02:03,443 pykolab.wallace DEBUG [4041] Worker process PoolWorker-2 initializing
2021-12-18 11:02:03,443 multiprocessing DEBUG [4035] added worker
2021-12-18 11:02:03,445 multiprocessing INFO [4042] child process calling self.run()
2021-12-18 11:02:03,445 multiprocessing DEBUG [4035] added worker
2021-12-18 11:02:03,446 pykolab.wallace DEBUG [4042] Worker process PoolWorker-3 initializing
2021-12-18 11:02:03,447 multiprocessing INFO [4043] child process calling self.run()
2021-12-18 11:02:03,448 pykolab.wallace DEBUG [4043] Worker process PoolWorker-4 initializing
2021-12-18 11:02:03,449 pykolab.wallace DEBUG [4035] Wallace modules: []
2021-12-18 11:02:03,450 pykolab.wallace/footer DEBUG [4035] tmpR592MP Issuing callback after processing to stage incoming
2021-12-18 11:02:03,450 pykolab.wallace/footer DEBUG [4035] tmpR592MP Testing cb_action_incoming()
2021-12-18 11:02:03,450 pykolab.wallace/footer DEBUG [4035] tmpR592MP Executing module footer for ('/var/spool/pykolab/wallace/footer/incoming/tmpR592MP',), {'stage': 'incoming'}
2021-12-18 11:02:03,451 pykolab.wallace/footer WARNING [4035] tmpR592MP No contents configured for footer module
2021-12-18 11:02:03,452 pykolab.wallace/modules DEBUG [4035] tmpR592MP Accepting message in: '/var/spool/pykolab/wallace/footer/incoming/tmpR592MP'
2021-12-18 11:02:03,453 pykolab.wallace/modules DEBUG [4035] tmpR592MP Message-ID: <20210922024601.5F91458C@mydomain.local>, sender: ['root@mydomain.local'], recipients: ['root@mydomain.local']
2021-12-18 11:02:03,453 pykolab.wallace/modules DEBUG [4035] tmpR592MP Removed X-Kolab- headers
2021-12-18 11:02:03,459 pykolab.wallace/modules DEBUG [4035] tmpR592MP Sending email via smtplib from ['root@mydomain.local'], to ['root@mydomain.local'] (Attempt 1)
2021-12-18 11:02:03,459 pykolab.wallace/modules DEBUG [4035] tmpR592MP connect:
2021-12-18 11:02:03,459 pykolab.wallace/modules DEBUG [4035] tmpR592MP ('127.0.0.1', 10027)
2021-12-18 11:02:03,459 pykolab.wallace/modules DEBUG [4035] tmpR592MP connect:
2021-12-18 11:02:03,459 pykolab.wallace/modules DEBUG [4035] tmpR592MP ('127.0.0.1', 10027)
2021-12-18 11:02:03,485 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: '220 mydomain.local ESMTP Postfix\r\n'
2021-12-18 11:02:03,486 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: retcode (220); Msg: mydomain.local ESMTP Postfix connect:
2021-12-18 11:02:03,486 pykolab.wallace/modules DEBUG [4035] tmpR592MP mydomain.local ESMTP Postfix
2021-12-18 11:02:03,486 pykolab.wallace/modules DEBUG [4035] tmpR592MP send: 'ehlo mydomain.local\r\n'
2021-12-18 11:02:03,487 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: '250-mydomain.local\r\n'
2021-12-18 11:02:03,487 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: '250-PIPELINING\r\n'
2021-12-18 11:02:03,487 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: '250-SIZE 30720000\r\n'
2021-12-18 11:02:03,487 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: '250-VRFY\r\n'
2021-12-18 11:02:03,487 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: '250-ETRN\r\n'
2021-12-18 11:02:03,488 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: '250-STARTTLS\r\n'
2021-12-18 11:02:03,488 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: '250-XFORWARD NAME ADDR PROTO HELO SOURCE PORT IDENT\r\n'
2021-12-18 11:02:03,488 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: '250-ENHANCEDSTATUSCODES\r\n'
2021-12-18 11:02:03,488 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: '250-8BITMIME\r\n'
2021-12-18 11:02:03,488 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: '250 DSN\r\n'
2021-12-18 11:02:03,489 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: retcode (250); Msg: mydomain.local PIPELINING
2021-12-18 11:02:03,489 pykolab.wallace/modules DEBUG [4035] tmpR592MP SIZE 30720000
2021-12-18 11:02:03,489 pykolab.wallace/modules DEBUG [4035] tmpR592MP VRFY
2021-12-18 11:02:03,489 pykolab.wallace/modules DEBUG [4035] tmpR592MP ETRN
2021-12-18 11:02:03,489 pykolab.wallace/modules DEBUG [4035] tmpR592MP STARTTLS
2021-12-18 11:02:03,489 pykolab.wallace/modules DEBUG [4035] tmpR592MP XFORWARD NAME ADDR PROTO HELO SOURCE PORT IDENT
2021-12-18 11:02:03,490 pykolab.wallace/modules DEBUG [4035] tmpR592MP ENHANCEDSTATUSCODES
2021-12-18 11:02:03,490 pykolab.wallace/modules DEBUG [4035] tmpR592MP 8BITMIME
2021-12-18 11:02:03,490 pykolab.wallace/modules DEBUG [4035] tmpR592MP DSN
2021-12-18 11:02:03,491 pykolab.wallace/modules DEBUG [4035] tmpR592MP send: 'mail FROM:<root@mydomain.local> size=1262\r\n'
2021-12-18 11:02:03,496 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: '250 2.1.0 Ok\r\n'
2021-12-18 11:02:03,497 pykolab.wallace/modules DEBUG [4035] tmpR592MP send: 'rcpt TO:<root@mydomain.local>\r\n'
2021-12-18 11:02:03,511 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: '250 2.1.5 Ok\r\n'
2021-12-18 11:02:03,511 pykolab.wallace/modules DEBUG [4035] tmpR592MP send: 'data\r\n'
2021-12-18 11:02:03,512 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: '354 End data with <CR><LF>.<CR><LF>\r\n'
2021-12-18 11:02:03,512 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: retcode (354); Msg: End data with <CR><LF>.<CR><LF> data:
2021-12-18 11:02:03,512 pykolab.wallace/modules DEBUG [4035] tmpR592MP (354, 'End data with <CR><LF>.<CR><LF>')
2021-12-18 11:02:03,513 pykolab.wallace/modules DEBUG [4035] tmpR592MP send: 'X-Virus-Scanned: amavisd-new at 2help.net\r\nX-Spam-Flag: NO\r\nX-Spam-Score: -0.001\r\nX-Spam-Level: \r\nX-Spam-Status: No, score=-0.001 tagged_abov
2021-12-18 11:02:03,542 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: '250 2.0.0 Ok: queued as 7CB20184\r\n'
2021-12-18 11:02:03,543 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: retcode (250); Msg: 2.0.0 Ok: queued as 7CB20184 data:
2021-12-18 11:02:03,543 pykolab.wallace/modules DEBUG [4035] tmpR592MP (250, '2.0.0 Ok: queued as 7CB20184')
2021-12-18 11:02:03,543 pykolab.wallace/modules DEBUG [4035] tmpR592MP SMTP sendmail OK
2021-12-18 11:02:03,543 pykolab.wallace/modules DEBUG [4035] tmpR592MP send: 'quit\r\n'
2021-12-18 11:02:03,544 pykolab.wallace/modules DEBUG [4035] tmpR592MP reply: '221 2.0.0 Bye\r\n'
2021-12-18 11:02:03,545 pykolab.wallace/modules DEBUG [4035] tmpR592MP Message was sent successfully: True
2021-12-18 11:02:03,545 pykolab.wallace/modules INFO [4035] tmpR592MP Accepting message in /var/spool/pykolab/wallace/footer/incoming/tmpR592MP (by module wallace)
2021-12-18 11:02:03,545 pykolab.wallace/modules DEBUG [4035] tmpR592MP Accepting message in: '/var/spool/pykolab/wallace/footer/incoming/tmpR592MP'
2021-12-18 11:02:03,546 pykolab.wallace DEBUG [4035] Traceback (most recent call last):
2021-12-18 11:02:03,546 pykolab.wallace DEBUG [4035] File "/usr/lib/python2.7/site-packages/wallace/__init.py", line 612, in run
2021-12-18 11:02:03,546 pykolab.wallace DEBUG [4035] self.do_wallace()
2021-12-18 11:02:03,546 pykolab.wallace DEBUG [4035] File "/usr/lib/python2.7/site-packages/wallace/
init.py", line 259, in do_wallace
2021-12-18 11:02:03,547 pykolab.wallace DEBUG [4035] self.pickup_spool_messages(sync=True)
2021-12-18 11:02:03,547 pykolab.wallace DEBUG [4035] File "/usr/lib/python2.7/site-packages/wallace/
init.py", line 445, in pickup_spool_messages
2021-12-18 11:02:03,547 pykolab.wallace DEBUG [4035] pickup_message(filepath, self.modules, module=module, stage=stage)
2021-12-18 11:02:03,547 pykolab.wallace DEBUG [4035] File "/usr/lib/python2.7/site-packages/wallace/
init__.py", line 95, in pickup_message
2021-12-18 11:02:03,547 pykolab.wallace DEBUG [4035] cb_action_ACCEPT('wallace', filepath)
2021-12-18 11:02:03,548 pykolab.wallace DEBUG [4035] File "/usr/lib/python2.7/site-packages/wallace/modules.py", line 363, in cb_action_ACCEPT
2021-12-18 11:02:03,548 pykolab.wallace DEBUG [4035] message = Parser().parse(open(filepath, 'r'), True)
2021-12-18 11:02:03,548 pykolab.wallace DEBUG [4035] IOError: [Errno 2] No such file or directory: '/var/spool/pykolab/wallace/footer/incoming/tmpR592MP'
Traceback occurred, please report a bug.
2021-12-18 11:02:03,549 multiprocessing INFO [4035] process shutting down
2021-12-18 11:02:03,549 multiprocessing DEBUG [4035] running all "atexit" finalizers with priority >= 0
2021-12-18 11:02:03,549 multiprocessing DEBUG [4035] finalizing pool
2021-12-18 11:02:03,549 multiprocessing DEBUG [4035] helping task handler/workers to finish
2021-12-18 11:02:03,549 multiprocessing DEBUG [4035] removing tasks from inqueue until task handler finished
2021-12-18 11:02:03,551 multiprocessing DEBUG [4035] worker handler exiting
2021-12-18 11:02:03,551 multiprocessing DEBUG [4035] task handler got sentinel
2021-12-18 11:02:03,551 multiprocessing DEBUG [4035] task handler sending sentinel to result handler
2021-12-18 11:02:03,552 multiprocessing DEBUG [4035] task handler sending sentinel to workers
2021-12-18 11:02:03,552 multiprocessing DEBUG [4035] task handler exiting
2021-12-18 11:02:03,552 multiprocessing DEBUG [4035] result handler got sentinel
2021-12-18 11:02:03,552 multiprocessing DEBUG [4040] worker got sentinel -- exiting
2021-12-18 11:02:03,553 multiprocessing DEBUG [4040] worker exiting after 0 tasks
2021-12-18 11:02:03,553 multiprocessing DEBUG [4035] ensuring that outqueue is not full
2021-12-18 11:02:03,553 multiprocessing INFO [4040] process shutting down
2021-12-18 11:02:03,553 multiprocessing DEBUG [4035] result handler exiting: len(cache)=0, thread._state=0
2021-12-18 11:02:03,553 multiprocessing DEBUG [4040] running all "atexit" finalizers with priority >= 0
2021-12-18 11:02:03,553 multiprocessing DEBUG [4040] running the remaining "atexit" finalizers
2021-12-18 11:02:03,553 multiprocessing INFO [4040] process exiting with exitcode 0
2021-12-18 11:02:03,554 multiprocessing DEBUG [4041] worker got sentinel -- exiting
2021-12-18 11:02:03,554 multiprocessing DEBUG [4041] worker exiting after 0 tasks
2021-12-18 11:02:03,554 multiprocessing DEBUG [4042] worker got sentinel -- exiting
2021-12-18 11:02:03,554 multiprocessing INFO [4041] process shutting down
2021-12-18 11:02:03,555 multiprocessing DEBUG [4042] worker exiting after 0 tasks
2021-12-18 11:02:03,555 multiprocessing DEBUG [4041] running all "atexit" finalizers with priority >= 0
2021-12-18 11:02:03,555 multiprocessing INFO [4042] process shutting down
2021-12-18 11:02:03,555 multiprocessing DEBUG [4041] running the remaining "atexit" finalizers
2021-12-18 11:02:03,555 multiprocessing DEBUG [4042] running all "atexit" finalizers with priority >= 0
2021-12-18 11:02:03,555 multiprocessing INFO [4041] process exiting with exitcode 0
2021-12-18 11:02:03,555 multiprocessing DEBUG [4042] running the remaining "atexit" finalizers
2021-12-18 11:02:03,555 multiprocessing INFO [4042] process exiting with exitcode 0
2021-12-18 11:02:03,556 multiprocessing DEBUG [4043] worker got sentinel -- exiting
2021-12-18 11:02:03,557 multiprocessing DEBUG [4043] worker exiting after 0 tasks
2021-12-18 11:02:03,557 multiprocessing INFO [4043] process shutting down
2021-12-18 11:02:03,557 multiprocessing DEBUG [4043] running all "atexit" finalizers with priority >= 0
2021-12-18 11:02:03,557 multiprocessing DEBUG [4043] running the remaining "atexit" finalizers
2021-12-18 11:02:03,557 multiprocessing INFO [4043] process exiting with exitcode 0
2021-12-18 11:02:03,559 multiprocessing DEBUG [4035] joining worker handler
2021-12-18 11:02:03,559 multiprocessing DEBUG [4035] terminating workers
2021-12-18 11:02:03,559 multiprocessing DEBUG [4035] joining task handler
2021-12-18 11:02:03,559 multiprocessing DEBUG [4035] joining result handler
2021-12-18 11:02:03,559 multiprocessing DEBUG [4035] joining pool workers
2021-12-18 11:02:03,560 multiprocessing DEBUG [4035] running the remaining "atexit" finalizers

Details

Ticket Type
Task

Event Timeline

sicherha added a subscriber: sicherha.

Ooh, this is a subtle bug!

It can be seen from the log that the temporary file /var/spool/pykolab/wallace/footer/incoming/tmpR592MP disappeared mid-flight. Which makes sense because cb_action_ACCEPT(), called from the footer module's execute() function, has successfully sent it and then unlinked the file. cb_action_ACCEPT() is then called again from pickup_message(), by which time the file no longer exists -> everything goes boom.

There's one possible path through pickup_message() where the footer module gets invoked but its return value is not checked. That path is taken when pickup_message() gets called with module='footer'.

Suggested fix: Make the value of continue_with_accept dependent on the return values of the execute() calls that directly precede it, not only on the return values of the execute() calls in the subsequent loop.