Kolab 16: Problems after Update

Bartosiak-Jentys, Chris chris.bartosiak-jentys at certico.co.uk
Thu Jul 7 13:11:08 CEST 2016 

Hello everyone, I am also seeing this issue on 2 CentOS 7 Kolab16 
servers since updating. Bellow is the output from my logs with Jeroen's 
suggested debug logging turned on:

Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: >>> START Data 
command RESTRICTIONS <<<
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: generic_checks: 
name=check_policy_service
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr request 
= smtpd_access_policy
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
protocol_state = DATA
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
protocol_name = ESMTP
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
client_address = ::1
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
client_name = localhost
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
reverse_client_name = localhost
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
helo_name = example.com
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr sender 
= example.example-example at example.com
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
recipient = example at example.com
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
recipient_count = 1
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
queue_id = 9AACD30833A
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
instance = 5efd.577e3657.266ae.0
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr size = 
0
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
etrn_domain =
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr stress 
=
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
sasl_method = LOGIN
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
sasl_username = example.example-example at example.com
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
sasl_sender =
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
ccert_subject =
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
ccert_issuer =
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
ccert_fingerprint =
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
ccert_pubkey_fingerprint =
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
encryption_protocol = TLSv1
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
encryption_cipher = ECDHE-RSA-AES256-SHA
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: send attr 
encryption_keysize = 256
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,663 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: request
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,663 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: protocol_state
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,664 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: protocol_name
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,664 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: client_address
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,664 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: client_name
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,664 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: reverse_client_name
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,664 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: helo_name
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,664 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: sender
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,664 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: recipient
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,665 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: recipient_count
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,665 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: queue_id
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,665 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: instance
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,665 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: size
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,665 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: etrn_domain
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,665 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: stress
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,665 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: sasl_method
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,666 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: sasl_username
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,666 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: sasl_sender
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,666 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: ccert_subject
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,666 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: ccert_issuer
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,666 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: ccert_fingerprint
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,666 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: ccert_pubkey_fingerprint
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,667 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: encryption_protocol
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,667 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: encryption_cipher
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,667 pykolab.smtp_access_policy DEBUG [24319]: 
Getting line: encryption_keysize
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,667 pykolab.smtp_access_policy DEBUG [24319]: 
End of current request
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,667 pykolab.smtp_access_policy DEBUG [24319]: 
Returning request
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,667 pykolab.smtp_access_policy DEBUG [24319]: 
Got request instance 5efd.577e3657.266ae.0
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,667 pykolab.smtp_access_policy DEBUG [24319]: 
Adding policy request to instance 5efd.577e3657.266ae.0
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,668 pykolab.smtp_access_policy DEBUG [24319]: 
Request instance 5efd.577e3657.266ae.0 is in state data
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/smtpd[24322]: connect from 
unknown[155.133.82.93]
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,670 sqlalchemy.engine.base.Engine INFO BEGIN 
(implicit)
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,673 sqlalchemy.engine.base.Engine INFO SELECT 
policy_result.id AS policy_result_id, policy_result.`key` AS 
policy_result_key, policy_result.value AS policy_result_value, 
policy_result.sender AS policy_result_sender, policy_result.recipient AS 
policy_result_recipient, policy_result.sasl_username AS 
policy_result_sasl_username, policy_result.sasl_sender AS 
policy_result_sasl_sender, policy_result.created AS 
policy_result_created, policy_result.data AS policy_result_data
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: FROM policy_result
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: WHERE policy_result.sasl_sender IS NULL AND policy_result.sender
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,673 sqlalchemy.engine.base.Engine INFO 
('example.example-example at example.com', 'verify_sender', 
'example.example-example at example.com', 'example at example.com', 
1467802841)
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,674 pykolab.smtp_access_policy ERROR Unhandled 
exception caught: OperationalError('(OperationalError) (1054, "Unknown 
column \'policy_result.data\' in \'field list\'")',)
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name: 2016-07-07 12:00:41,679 pykolab.smtp_access_policy ERROR Traceback 
(most recent call last):
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name:   File "/usr/libexec/postfix/kolab_smtp_access_policy", line 1659, 
in <module>
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name:     sender_allowed
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name:   File "/usr/libexec/postfix/kolab_smtp_access_policy", line 1053, 
in verify_sender
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name:     function
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name:   File "/usr/libexec/postfix/kolab_smtp_access_policy", line 1258, 
in cache_select
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name:     ((int)(time.time()) - cache_expire)
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name:   File 
"/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2320, 
in all
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name:     return list(self)
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name:   File 
"/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2438, 
in __iter__
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: input attribute 
name:     return self._execute_and_instances(context)
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: 
private/submission_policy: wanted attribute: action
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: warning: missing 
attribute action in input from private/submission_policy
Jul  7 12:00:41 srv01 postfix/submission/smtpd[24317]: warning: problem 
talking to server private/submission_policy: Success
Jul  7 12:00:43 srv01 postfix/submission/smtpd[24317]: warning: missing 
attribute action in input from private/submission_policy
Jul  7 12:00:43 srv01 postfix/submission/smtpd[24317]: warning: problem 
talking to server private/submission_policy: Success


Hope it helps

Chris Bartosiak-Jentys


On 2016-07-07 09:19, Jeroen van Meeuwen (Kolab Systems) wrote:
> On 2016-07-05 10:28, Paul Ryszka wrote:
>> Hi,
>> 
>> same here on ubuntu 14.04 with kolab winterfell, temporary workaround
>> is to disable sender policy:
>> comment line
>>  -o smtpd_data_restrictions=$submission_data_restrictions
>> 
> 
> I'm unable to reproduce the problem reported on a vanilla,
> next-next-finish, fresh installation of Kolab Winterfell on Enterprise
> Linux 7.
> 
> I'll do another attempt on Kolab 16, but here's the additional
> troubleshooting and information gathering you might be able to assist
> with:
> 
>   - in /etc/postfix/master.cf, add '-v' to the end of the line that
> starts with submission, so that it becomes:
> 
>>    submission          inet        n       -       n       -       -   
>>     smtpd -v
> 
>   - further down in /etc/postfix/master.cf, add '-d 9' to the
> invocations of /usr/libexec/postfix/kolab_smtp_access_policy. Strictly
> speaking, you only need the last one called submission_policy:
> 
>>    submission_policy   unix        -       n       n       -       -   
>>     spawn
>>        user=kolab-n argv=/usr/libexec/postfix/kolab_smtp_access_policy 
>> --verify-sender --verify-recipient -d 9
> 
> This will put all sorts of very verbose information in your
> /var/log/maillog, which can help us nail down to determine whether
> it's an upgrade thing or a software thing or whatnot.
> 
> Kind regards,
> 
> Jeroen van Meeuwen

More information about the users mailing list