dagent problem

bbc

Hello!
Help me please with problem circular mails via distribution groups. I’ve installed kopano on Ubuntu 20.04 with postfix. Connected to AD.

kopano-server-packages: 11.0.1.101.66a6a5219-0+584.1
kopano-webapp: 6.0.0.22+2006.1
z-push-kopano: 2.6.2+0-0

When someone sends email to distribution group postfix sets them into queue for delivering and gets following error:

May 17 10:34:42 srv-cl-mail-be1 postfix/lmtp[1700746]: 97B9513E5D2: to=<email1@example.com>, orig_to=<group@example.com>, relay=127.0.0.1[127.0.0.1]:2003, delay=7118, delays=6492/9.1/2/614, dsn=4.4.2, status=deferred (conversation with 127.0.0.1[127.0.0.1] timed out while sending end of data -- message may be sent more than once)
May 17 10:34:42 srv-cl-mail-be1 postfix/lmtp[1700746]: 97B9513E5D2: to=<email2@example.com>, orig_to=<group@example.com>, relay=127.0.0.1[127.0.0.1]:2003, delay=7118, delays=6492/9.1/2/614, dsn=4.4.2, status=deferred (conversation with 127.0.0.1[127.0.0.1] timed out while sending end of data -- message may be sent more than once)
May 17 10:34:42 srv-cl-mail-be1 postfix/lmtp[1700746]: 97B9513E5D2: to=<email3@example.com>, orig_to=<group@example.com>, relay=127.0.0.1[127.0.0.1]:2003, delay=7118, delays=6492/9.1/2/614, dsn=4.4.2, status=deferred (conversation with 127.0.0.1[127.0.0.1] timed out while sending end of data -- message may be sent more than once)

Users receive this mail multiple times. Deleting duplicated messages from queue and restart kopano-dagent fix the problem. Until new message to distribution group.
I found similar old post https://forum.kopano.io/topic/805/circular-mail-will-be-send-dublicated, but not the same and without solution.
dagent config:

lmtp_listen = *:2003
log_method = file
log_level = 6
log_file = /var/log/kopano/dagent.log

Postfix:

virtual_mailbox_domains = example.com
virtual_mailbox_maps = ldap:/etc/postfix/ldap-users.cf
virtual_transport = lmtp:127.0.0.1:2003
virtual_alias_maps = ldap:/etc/postfix/ldap-groups.cf hash:/etc/postfix/aliases hash:/etc/postfix/rule_forward_email hash:/etc/postfix/domains

How can I fix it? Is there dagent bug?

Also found in dagent.log when problem occurs:

2021-05-17T08:47:31.633746: [kopano-dagent|T1672773] [error  ] LMTP write error: network error (80040115)
2021-05-17T09:03:05.450998: [kopano-dagent|T1676031] [error  ] Previous message logged 10 times

externa1

@bbc said in dagent problem:

lmtp_listen = *:2003

Did you already try this with lmtp_listen = 127.0.0.1:2003 ?

rg
Christian

bbc

@externa1 No, i did’nt. All works well exept sending to distibution groups. Tried configured

lmtp_listen = 127.0.0.1:2003

and restarted dagent. Whait for users action.

I’ve measured how fast postfix gets group memebers emails (about 100):

time postmap -q group@example.com ldap:/etc/postfix/ldap-groups.cf
real    0m9,839s
user    0m0,023s
sys     0m0,023s

It is not critical I think. All emails are valid.

fbartels

Hi @bbc,

you said that you raised logging of kopano-dagent to 6, but did not provide any logging from the service in question (apart from the network error). Are there any other messages in the logs?

Generally speaking its the job of the mta to resolve your group and then pass the message along for the individual recipients to dagent.

Regarding

@bbc said in dagent problem:

group memebers emails (about 100)

and

@bbc said in dagent problem:

kopano-server-packages: 11.0.1.101.66a6a5219-0+584.1

I would not really recommend to use the nightly builds for production setups. Packages that have completed testing are available for customers with a valid subscription. If you are still testing out Kopano the recommendation is to request a trial key from https://kopano.com/downloads-demo/ instead of using the nightlies.

bbc

@fbartels Thank you for answer.

@fbartels said in dagent problem:

you said that you raised logging of kopano-dagent to 6, but did not provide any logging from the service in question (apart from the network error). Are there any other messages in the logs?

2021-05-18T14:29:29.084706: [kopano-dagent|T2478154] [info   ] LMTP thread exiting
2021-05-18T14:29:42.695647: [kopano-dagent|T2315553] [info   ] Accepted connection from 127.0.0.1:59616
2021-05-18T14:29:42.695739: [kopano-dagent|T2478185] [info   ] Starting worker for LMTP request pid 2315553
2021-05-18T14:29:42.723514: [kopano-dagent|T2315553] [info   ] Accepted connection from 127.0.0.1:59620
2021-05-18T14:29:42.723613: [kopano-dagent|T2478186] [info   ] Starting worker for LMTP request pid 2315553
2021-05-18T14:29:42.731259: [kopano-dagent|T2478185] [debug  ] Initializing provider "Kopano Directory Service"
2021-05-18T14:29:42.731290: [kopano-dagent|T2478185] [debug  ] Initializing provider "Private Folders"
2021-05-18T14:29:42.755980: [kopano-dagent|T2478186] [debug  ] Initializing provider "Kopano Directory Service"
2021-05-18T14:29:42.756032: [kopano-dagent|T2478186] [debug  ] Initializing provider "Private Folders"
2021-05-18T14:29:42.780124: [kopano-dagent|T2478185] [debug  ] Initializing provider "Public Folders"
2021-05-18T14:29:42.802927: [kopano-dagent|T2315553] [info   ] Accepted connection from 127.0.0.1:59622
2021-05-18T14:29:42.803070: [kopano-dagent|T2478187] [info   ] Starting worker for LMTP request pid 2315553
2021-05-18T14:29:42.815756: [kopano-dagent|T2478186] [debug  ] Initializing provider "Public Folders"
2021-05-18T14:29:42.836238: [kopano-dagent|T2478187] [debug  ] Initializing provider "Kopano Directory Service"
2021-05-18T14:29:42.836280: [kopano-dagent|T2478187] [debug  ] Initializing provider "Private Folders"
2021-05-18T14:29:42.887950: [kopano-dagent|T2478187] [debug  ] Initializing provider "Public Folders"
2021-05-18T14:29:43.060718: [kopano-dagent|T2478185] [debug  ] < 220 2.1.5 LMTP server is ready
2021-05-18T14:29:43.060924: [kopano-dagent|T2478185] [debug  ] > LHLO srv-cl-mail-be1.voda.local
2021-05-18T14:29:43.060942: [kopano-dagent|T2478185] [debug  ] LHLO ID: srv-cl-mail-be1.voda.local
2021-05-18T14:29:43.060948: [kopano-dagent|T2478185] [debug  ] < 250-SERVER ready
2021-05-18T14:29:43.060968: [kopano-dagent|T2478185] [debug  ] < 250-PIPELINING
2021-05-18T14:29:43.060992: [kopano-dagent|T2478185] [debug  ] < 250-8BITMIME
2021-05-18T14:29:43.061016: [kopano-dagent|T2478185] [debug  ] < 250-ENHANCEDSTATUSCODE
2021-05-18T14:29:43.061039: [kopano-dagent|T2478185] [debug  ] < 250-RSET
2021-05-18T14:29:43.061070: [kopano-dagent|T2478185] [debug  ] < 250 SMTPUTF8
2021-05-18T14:29:43.061174: [kopano-dagent|T2478185] [debug  ] > MAIL FROM:<g.aksenova@example.com>
2021-05-18T14:29:43.061200: [kopano-dagent|T2478185] [debug  ] < 250 2.1.0 Ok
2021-05-18T14:29:43.061242: [kopano-dagent|T2478185] [debug  ] > RCPT TO:<v.korushev@example.com>
2021-05-18T14:29:43.061252: [kopano-dagent|T2478185] [debug  ] Resolved command "RCPT TO:<v.korushev@example.com>" to recipient address "v.korushev@example.com"
2021-05-18T14:29:43.096167: [kopano-dagent|T2478186] [debug  ] < 220 2.1.5 LMTP server is ready
2021-05-18T14:29:43.096342: [kopano-dagent|T2478186] [debug  ] > LHLO srv-cl-mail-be1.local
2021-05-18T14:29:43.096358: [kopano-dagent|T2478186] [debug  ] LHLO ID: srv-cl-mail-be1.local
2021-05-18T14:29:43.096363: [kopano-dagent|T2478186] [debug  ] < 250-SERVER ready
2021-05-18T14:29:43.096380: [kopano-dagent|T2478186] [debug  ] < 250-PIPELINING
2021-05-18T14:29:43.096401: [kopano-dagent|T2478186] [debug  ] < 250-8BITMIME
2021-05-18T14:29:43.096418: [kopano-dagent|T2478186] [debug  ] < 250-ENHANCEDSTATUSCODE
2021-05-18T14:29:43.096435: [kopano-dagent|T2478186] [debug  ] < 250-RSET
2021-05-18T14:29:43.096445: [kopano-dagent|T2478186] [debug  ] < 250 SMTPUTF8
2021-05-18T14:29:43.096527: [kopano-dagent|T2478186] [debug  ] > MAIL FROM:<kazakov@example.com>
2021-05-18T14:29:43.096538: [kopano-dagent|T2478186] [debug  ] < 250 2.1.0 Ok
2021-05-18T14:29:43.096597: [kopano-dagent|T2478186] [debug  ] > RCPT TO:<d.firsova@example.com>
2021-05-18T14:29:43.096609: [kopano-dagent|T2478186] [debug  ] Resolved command "RCPT TO:<d.firsova@example.com>" to recipient address "d.firsova@example.com"
2021-05-18T14:29:43.166173: [kopano-dagent|T2478187] [debug  ] < 220 2.1.5 LMTP server is ready
2021-05-18T14:29:43.166405: [kopano-dagent|T2478187] [debug  ] > LHLO srv-cl-mail-be1.local
2021-05-18T14:29:43.166423: [kopano-dagent|T2478187] [debug  ] LHLO ID: srv-cl-mail-be1.local
2021-05-18T14:29:43.166428: [kopano-dagent|T2478187] [debug  ] < 250-SERVER ready
2021-05-18T14:29:43.166446: [kopano-dagent|T2478187] [debug  ] < 250-PIPELINING
2021-05-18T14:29:43.166459: [kopano-dagent|T2478187] [debug  ] < 250-8BITMIME
2021-05-18T14:29:43.166472: [kopano-dagent|T2478187] [debug  ] < 250-ENHANCEDSTATUSCODE
2021-05-18T14:29:43.166485: [kopano-dagent|T2478187] [debug  ] < 250-RSET
2021-05-18T14:29:43.166498: [kopano-dagent|T2478187] [debug  ] < 250 SMTPUTF8
2021-05-18T14:29:43.166607: [kopano-dagent|T2478187] [debug  ] > MAIL FROM:<g.aksenova@example.com>
2021-05-18T14:29:43.166631: [kopano-dagent|T2478187] [debug  ] < 250 2.1.0 Ok
2021-05-18T14:29:43.166669: [kopano-dagent|T2478187] [debug  ] > RCPT TO:<v.korushev@example.com>
2021-05-18T14:29:43.166680: [kopano-dagent|T2478187] [debug  ] Resolved command "RCPT TO:<v.korushev@example.com>" to recipient address "v.korushev@example.com"
2021-05-18T14:29:43.214199: [kopano-dagent|T2478185] [notice ] Resolved recipient v.korushev@example.com as user v.korushev
2021-05-18T14:29:43.214236: [kopano-dagent|T2478185] [debug  ] < 250 2.1.5 Ok
2021-05-18T14:29:43.214291: [kopano-dagent|T2478185] [debug  ] > DATA
2021-05-18T14:29:43.214342: [kopano-dagent|T2478185] [debug  ] < 354 2.1.5 Start mail input; end with <CRLF>.<CRLF>
2021-05-18T14:29:43.248248: [kopano-dagent|T2478186] [notice ] Resolved recipient d.firsova@example.com as user d.firsova
2021-05-18T14:29:43.248294: [kopano-dagent|T2478186] [debug  ] < 250 2.1.5 Ok
2021-05-18T14:29:43.248355: [kopano-dagent|T2478186] [debug  ] > DATA
2021-05-18T14:29:43.248406: [kopano-dagent|T2478186] [debug  ] < 354 2.1.5 Start mail input; end with <CRLF>.<CRLF>
2021-05-18T14:29:43.332834: [kopano-dagent|T2478187] [notice ] Resolved recipient v.korushev@example.com as user v.korushev
2021-05-18T14:29:43.332883: [kopano-dagent|T2478187] [debug  ] < 250 2.1.5 Ok
2021-05-18T14:29:43.332953: [kopano-dagent|T2478187] [debug  ] > DATA
2021-05-18T14:29:43.333026: [kopano-dagent|T2478187] [debug  ] < 354 2.1.5 Start mail input; end with <CRLF>.<CRLF>
2021-05-18T14:29:43.335296: [kopano-dagent|T2478185] [debug  ] Initializing provider "Kopano Directory Service"
2021-05-18T14:29:43.335331: [kopano-dagent|T2478185] [debug  ] Initializing provider "Private Folders"
2021-05-18T14:29:43.412605: [kopano-dagent|T2478185] [debug  ] Initializing provider "Public Folders"
2021-05-18T14:29:43.427691: [kopano-dagent|T2478187] [debug  ] Initializing provider "Kopano Directory Service"
2021-05-18T14:29:43.427744: [kopano-dagent|T2478187] [debug  ] Initializing provider "Private Folders"
2021-05-18T14:29:43.428236: [kopano-dagent|T2478186] [debug  ] Initializing provider "Kopano Directory Service"
2021-05-18T14:29:43.428275: [kopano-dagent|T2478186] [debug  ] Initializing provider "Private Folders"
2021-05-18T14:29:43.483042: [kopano-dagent|T2478187] [debug  ] Initializing provider "Public Folders"
2021-05-18T14:29:43.724730: [kopano-dagent|T2478185] [debug  ] Initializing provider "Kopano Directory Service"
2021-05-18T14:29:43.724782: [kopano-dagent|T2478185] [debug  ] Initializing provider "Private Folders"
2021-05-18T14:29:43.770022: [kopano-dagent|T2478186] [debug  ] Initializing provider "Kopano Directory Service"
2021-05-18T14:29:43.770060: [kopano-dagent|T2478186] [debug  ] Initializing provider "Private Folders"
2021-05-18T14:29:43.770335: [kopano-dagent|T2478187] [debug  ] Initializing provider "Kopano Directory Service"
2021-05-18T14:29:43.770366: [kopano-dagent|T2478187] [debug  ] Initializing provider "Private Folders"
2021-05-18T14:29:43.772257: [kopano-dagent|T2478185] [debug  ] Initializing provider "Public Folders"
2021-05-18T14:29:44.263762: [kopano-dagent|T2478186] [debug  ] Previous message logged 2 times
2021-05-18T14:29:44.263808: [kopano-dagent|T2478186] [info   ] Mail will be delivered in Inbox
2021-05-18T14:29:44.820602: [kopano-dagent|T2478185] [info   ] Previous message logged 2 times
2021-05-18T14:29:44.820665: [kopano-dagent|T2478185] [debug  ] Parsing MIME part 1
2021-05-18T14:29:44.821029: [kopano-dagent|T2478185] [debug  ] HTML4 meta tag found: charset="text/html; charset=utf-8"
2021-05-18T14:29:44.821048: [kopano-dagent|T2478185] [debug  ] HTML charset adjusted to "utf-8"
2021-05-18T14:29:44.821148: [kopano-dagent|T2478185] [debug  ] renovate_encoding: reading data using charset "utf-8" succeeded.
2021-05-18T14:29:44.878387: [kopano-dagent|T2478186] [debug  ] Parsing MIME part 0.1
2021-05-18T14:29:44.878620: [kopano-dagent|T2478186] [debug  ] HTML4 meta tag found: charset="text/html; charset=utf-8"
2021-05-18T14:29:44.878659: [kopano-dagent|T2478186] [debug  ] HTML charset adjusted to "utf-8"
2021-05-18T14:29:44.878698: [kopano-dagent|T2478186] [debug  ] renovate_encoding: reading data using charset "utf-8" succeeded.
2021-05-18T14:29:44.950212: [kopano-dagent|T2478185] [debug  ] Initializing provider "Kopano Directory Service"
2021-05-18T14:29:44.950283: [kopano-dagent|T2478185] [debug  ] Initializing provider "Private Folders"
2021-05-18T14:29:45.004570: [kopano-dagent|T2478187] [debug  ] Parsing MIME part 1
2021-05-18T14:29:45.004987: [kopano-dagent|T2478187] [debug  ] HTML4 meta tag found: charset="text/html; charset=utf-8"
2021-05-18T14:29:45.005015: [kopano-dagent|T2478187] [debug  ] HTML charset adjusted to "utf-8"
2021-05-18T14:29:45.005100: [kopano-dagent|T2478187] [debug  ] renovate_encoding: reading data using charset "utf-8" succeeded.
2021-05-18T14:29:45.024847: [kopano-dagent|T2478186] [debug  ] Initializing provider "Kopano Directory Service"
2021-05-18T14:29:45.024900: [kopano-dagent|T2478186] [debug  ] Initializing provider "Private Folders"
2021-05-18T14:29:45.042384: [kopano-dagent|T2478185] [debug  ] Initializing provider "Public Folders"
2021-05-18T14:29:45.105215: [kopano-dagent|T2478187] [debug  ] Initializing provider "Kopano Directory Service"
2021-05-18T14:29:45.105284: [kopano-dagent|T2478187] [debug  ] Initializing provider "Private Folders"
2021-05-18T14:29:45.165548: [kopano-dagent|T2478185] [debug  ] Target user has OOF inactive
2021-05-18T14:29:45.171779: [kopano-dagent|T2478187] [debug  ] Initializing provider "Public Folders"
2021-05-18T14:29:45.241717: [kopano-dagent|T2478186] [debug  ] Target user has OOF inactive
2021-05-18T14:29:45.329769: [kopano-dagent|T2478185] [debug  ] Send 'New Mail' notification
2021-05-18T14:29:45.329829: [kopano-dagent|T2478185] [info   ] Delivered message to "v.korushev", Subject: "FW: Amount", Message-Id: <kcEE.TcqYhNE/SYWVI0H2/YxjOg.AFdlGNlL1wE@srv-cl-mail-be1.local>, size 22182
2021-05-18T14:29:45.331847: [kopano-dagent|T2478186] [debug  ] Send 'New Mail' notification
2021-05-18T14:29:45.331910: [kopano-dagent|T2478186] [info   ] Delivered message to "d.firsova", Subject: "с", Message-Id: <kcEE.ILRjT/uHSuaJoNNwaXq30A.AFdlGNlL1wE@srv-cl-mail-be1.local>, size 348259
2021-05-18T14:29:45.400156: [kopano-dagent|T2478185] [info   ] Finished processing message
2021-05-18T14:29:45.406528: [kopano-dagent|T2478187] [debug  ] Send 'New Mail' notification
2021-05-18T14:29:45.406573: [kopano-dagent|T2478187] [info   ] Delivered message to "v.korushev", Subject: "FW: Amount", Message-Id: <kcEE.TcqYhNE/SYWVI0H2/YxjOg.AFdlGNlL1wE@srv-cl-mail-be1.local>, size 22182
2021-05-18T14:29:45.459986: [kopano-dagent|T2478185] [debug  ] < 250 2.1.5 v.korushev@example.com Ok
2021-05-18T14:29:45.460122: [kopano-dagent|T2478185] [debug  ] > QUIT
2021-05-18T14:29:45.460140: [kopano-dagent|T2478185] [debug  ] < 221 2.0.0 Bye
2021-05-18T14:29:45.460155: [kopano-dagent|T2478185] [info   ] LMTP thread exiting
2021-05-18T14:29:45.462425: [kopano-dagent|T2478186] [debug  ] < 250 2.1.5 d.firsova@example.com Ok
2021-05-18T14:29:45.462549: [kopano-dagent|T2478186] [debug  ] > QUIT
2021-05-18T14:29:45.462564: [kopano-dagent|T2478186] [debug  ] < 221 2.0.0 Bye
2021-05-18T14:29:45.462588: [kopano-dagent|T2478186] [info   ] LMTP thread exiting
2021-05-18T14:29:45.475511: [kopano-dagent|T2478187] [info   ] Finished processing message
2021-05-18T14:29:45.531806: [kopano-dagent|T2478187] [debug  ] < 250 2.1.5 v.korushev@example.com Ok
2021-05-18T14:29:45.531935: [kopano-dagent|T2478187] [debug  ] > QUIT
2021-05-18T14:29:45.531951: [kopano-dagent|T2478187] [debug  ] < 221 2.0.0 Bye
2021-05-18T14:29:45.531975: [kopano-dagent|T2478187] [info   ] LMTP thread exiting

Delivering works well. I noticed today, dagent delivers about 1 email from maling list in 2-3 seconds. It just not finished when postfix sent new equal email to user list. It looks like send timeout in postfix.
Is there way to speed up dagent? Rise number of threads to deliver?

@fbartels said in dagent problem:

I would not really recommend to use the nightly builds for production setups. Packages that have completed testing are available for customers with a valid subscription. If you are still testing out Kopano the recommendation is to request a trial key from https://kopano.com/downloads-demo/ instead of using the nightlies.

I’ll try, thank you. There is some user data to transfer. And it is a problem. Out of the scoupe of this topic :)

fbartels

@bbc said in dagent problem:

dagent delivers about 1 email from maling list in 2-3 seconds

I had a look at your logging, but did not really manage to spot an error. But 2-3 seconds per mail sounds like an underperforming database.

There is however a way to influence how many threads are used at max for delivering messages from the mta to dagent. The setting is called lmtp_max_threads and can be found at https://stash.kopano.io/projects/KC/repos/kopanocore/browse/installer/linux/dagent.cfg?at=9f839209662#31-33

bbc

@fbartels Thanks. It is good idea about DB. I’ve changed

lmtp_data_done_timeout = 1200s

in postfix config for now. Because I tried to send emails to about 400 test users, it took over 10 minutes to deliver and close connection.

Also tuned my MariaDB with

innodb_buffer_pool_size = 1G
innodb_log_file_size    = 250M
innodb_log_buffer_size  = 32M
innodb_file_per_table   = 1

And add cache tunning in server.cfg

cache_cell_size = 1024M
cache_object_size = 10M
cache_indexedobject_size = 50M

Watching for result.

fbartels

@bbc said in dagent problem:

I tried to send emails to about 400 test users

Are you using the ldap backend of Kopano? If so then the delay could also be related to missing indexes.

bbc

@fbartels Yep, I do. LDAP user plugin. How can I check it?

fbartels

@bbc said in dagent problem:

How can I check it?

I cannot find an example log line right now, but in the past OpenLDAP logged when it encountered a query that would benefit from additional indexed attributes.

bbc

@fbartels Hi. Problem occured again. With cache settings delivering duration ~10min:

2021-05-20T07:20:08.519098: [kopano-dagent|T3594108] [info   ] Starting worker for LMTP request pid 3343371
...
2021-05-20T07:20:08.527422: [kopano-dagent|T3594108] [debug  ] Resolved command "RCPT TO:<user1@example.com>" to recipient address "user1@example.com"
2021-05-20T07:20:08.680410: [kopano-dagent|T3594108] [notice ] Resolved recipient user1@example.com as user user1
...
2021-05-20T07:29:39.995770: [kopano-dagent|T3594108] [info   ] LMTP thread exiting

No errors in dagent log, and no speed gain.
Today kopano server crushed unexpectedly:

2021-05-21T09:01:03.485594: [crit   ] ----------------------------------------------------------------------
2021-05-21T09:01:03.485626: [crit   ] Fatal error detected. Please report all following information.
2021-05-21T09:01:03.485629: [crit   ] kopano-server 11.0.1
2021-05-21T09:01:03.485634: [crit   ] OS: Ubuntu 20.04.2 LTS (Linux 5.4.0-73-generic x86_64)
2021-05-21T09:01:03.485651: [crit   ] Thread name: kopano-server
2021-05-21T09:01:03.485675: [crit   ] Peak RSS: 1236372
2021-05-21T09:01:03.485681: [crit   ] Pid 274086 caught SIGABRT (6), out of memory or unhandled exception, traceback:
2021-05-21T09:01:03.485683: [crit   ] Backtrace:
2021-05-21T09:01:03.485982: [crit   ] f0. /lib/x86_64-linux-gnu/libkcutil.so.0(+0x50fa4) [0x7f9fefedbfa4]
2021-05-21T09:01:03.485987: [crit   ] f1. /lib/x86_64-linux-gnu/libkcutil.so.0(+0x374e6) [0x7f9fefec24e6]
2021-05-21T09:01:03.485990: [crit   ] f2. /lib/x86_64-linux-gnu/libkcutil.so.0(+0x38f24) [0x7f9fefec3f24]
2021-05-21T09:01:03.485992: [crit   ] f3. /lib/x86_64-linux-gnu/libpthread.so.0(+0x153c0) [0x7f9feebb33c0]
2021-05-21T09:01:03.485995: [crit   ] f4. /lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcb) [0x7f9fee7f418b]
2021-05-21T09:01:03.485997: [crit   ] f5. /lib/x86_64-linux-gnu/libc.so.6(abort+0x12b) [0x7f9fee7d3859]
2021-05-21T09:01:03.486000: [crit   ] f6. /lib/x86_64-linux-gnu/libc.so.6(+0x25729) [0x7f9fee7d3729]
2021-05-21T09:01:03.486002: [crit   ] f7. /lib/x86_64-linux-gnu/libc.so.6(+0x36f36) [0x7f9fee7e4f36]
2021-05-21T09:01:03.486004: [crit   ] f8. /lib/x86_64-linux-gnu/libldap_r-2.4.so.2(ldap_sasl_bind+0x175) [0x7f9fec4edb75]
2021-05-21T09:01:03.486007: [crit   ] f9. /lib/x86_64-linux-gnu/libldap_r-2.4.so.2(ldap_sasl_bind_s+0x8e) [0x7f9fec4edf4e]
2021-05-21T09:01:03.486009: [crit   ] f10. /lib/x86_64-linux-gnu/libldap_r-2.4.so.2(ldap_simple_bind_s+0x65) [0x7f9fec4eff35]
2021-05-21T09:01:03.486020: [crit   ] f11. /usr/lib/x86_64-linux-gnu/kopano/libkcserver-ldap.so(+0x20394) [0x7f9fb5197394]
2021-05-21T09:01:03.486022: [crit   ] f12. /usr/lib/x86_64-linux-gnu/kopano/libkcserver-ldap.so(+0x20733) [0x7f9fb5197733]
2021-05-21T09:01:03.486024: [crit   ] f13. /lib/x86_64-linux-gnu/libkcserver.so.0(+0x119be3) [0x7f9fefd85be3]
2021-05-21T09:01:03.486027: [crit   ] f14. /lib/x86_64-linux-gnu/libkcserver.so.0(+0xd968c) [0x7f9fefd4568c]
2021-05-21T09:01:03.486029: [crit   ] f15. /lib/x86_64-linux-gnu/libkcserver.so.0(+0xe9939) [0x7f9fefd55939]
2021-05-21T09:01:03.486031: [crit   ] f16. /lib/x86_64-linux-gnu/libkcserver.so.0(_ZN11KCmdService5logonEPKcS1_S1_S1_jjRK17xsd__base64BinarymS1_S1_S1_P13logonResponse+0x23f) [0x7f9fefdb0c6f]
2021-05-21T09:01:03.486034: [crit   ] f17. /lib/x86_64-linux-gnu/libkcserver.so.0(+0x1ae280) [0x7f9fefe1a280]
2021-05-21T09:01:03.486036: [crit   ] f18. /lib/x86_64-linux-gnu/libkcserver.so.0(_ZN11KCmdService8dispatchEP4soap+0x6a) [0x7f9fefe2c2da]
2021-05-21T09:01:03.486039: [crit   ] f19. /usr/sbin/kopano-server(+0x157c1) [0x556440cde7c1]
2021-05-21T09:01:03.486041: [crit   ] f20. /lib/x86_64-linux-gnu/libkcutil.so.0(+0x3fba2) [0x7f9fefecaba2]
2021-05-21T09:01:03.486044: [crit   ] f21. /lib/x86_64-linux-gnu/libpthread.so.0(+0x9609) [0x7f9feeba7609]
2021-05-21T09:01:03.486046: [crit   ] f22. /lib/x86_64-linux-gnu/libc.so.6(clone+0x43) [0x7f9fee8d0293]
2021-05-21T09:01:03.486059: [crit   ] Signal errno: Выполнено, signal code: -6
2021-05-21T09:01:03.486062: [crit   ] Sender pid: 274086, sender uid: 997, si_status: 0
2021-05-21T09:01:03.486065: [crit   ] Signal value: 0, faulting address: 0x3e500042ea6
2021-05-21T09:03:52.685801: [info   ] Audit logging not enabled.

Out of Memory.
My VM has 6 cpu and 12G RAM.

fbartels

@bbc said in dagent problem:

No errors in dagent log, and no speed gain.

Then it is indeed most likely missing ldap tuning. What is logged between 07:20:08 and 07:29:39 more of the “resolved recipient” messages?

bbc

I found strange behavior. Message to mailing list sent triple time. It appears in Outbox for a long time. Then in SENT multiply times. From 2 to 7 times. Thus I can make desision - something wrong in webapp.
Postfix and dagent deliver this multiple mail.
From server log in time when the second email forming appears:

2021-05-21T12:16:19.438546: [warning] K-1515: Object not found unknown user "Group1": Group1 not found in LDAP

But in GAL this group and its members persist and I can choose it for sending mail.

Step by step representation:

New mail, to Group1 (from GAL)
Insert to email body text and picture.
Click Send.
Email apperas in Outbox for a long time.
In Sent appears multiple emalis have been sent in the same time.

fbartels

@bbc said in dagent problem:

I found strange behavior. Message to mailing list sent triple time

That works just fine here with your steps from below.

bbc

@bbc Looks good:

2021-05-20T07:20:08.680410: [kopano-dagent|T3594108] [notice ] Resolved recipient user1@example.com as user user1
2021-05-20T07:20:08.805199: [kopano-dagent|T3594108] [notice ] Resolved recipient user2@example.com as user user2
2021-05-20T07:20:08.930680: [kopano-dagent|T3594108] [notice ] Resolved recipient user3@example.com as user user3
2021-05-20T07:20:09.056292: [kopano-dagent|T3594108] [notice ] Resolved recipient user4@example.com as user user4
2021-05-20T07:20:09.162755: [kopano-dagent|T3594108] [notice ] Resolved recipient user5@example.com as user user5
2021-05-20T07:20:09.291722: [kopano-dagent|T3594108] [notice ] Resolved recipient user6@example.com as user user6
2021-05-20T07:20:09.412437: [kopano-dagent|T3594108] [notice ] Resolved recipient user7@example.com as user user7
2021-05-20T07:20:09.546712: [kopano-dagent|T3594108] [notice ] Resolved recipient user8@example.com as user user8
2021-05-20T07:20:09.655315: [kopano-dagent|T3594108] [notice ] Resolved recipient user9@example.com as user user9
2021-05-20T07:20:09.761158: [kopano-dagent|T3594108] [notice ] Resolved recipient user10@example.com as user user10
2021-05-20T07:20:09.893580: [kopano-dagent|T3594108] [notice ] Resolved recipient user11@example.com as user user11
2021-05-20T07:20:10.017800: [kopano-dagent|T3594108] [notice ] Resolved recipient user12@example.com as user user12
2021-05-20T07:20:10.133228: [kopano-dagent|T3594108] [notice ] Resolved recipient user13@example.com as user user13
2021-05-20T07:20:10.236180: [kopano-dagent|T3594108] [notice ] Resolved recipient user14@example.com as user user14
2021-05-20T07:20:10.340550: [kopano-dagent|T3594108] [notice ] Resolved recipient user15@example.com as user user15
2021-05-20T07:20:10.456775: [kopano-dagent|T3594108] [notice ] Resolved recipient user16@example.com as user user16
2021-05-20T07:20:10.569905: [kopano-dagent|T3594108] [notice ] Resolved recipient user17@example.com as user user17
2021-05-20T07:20:10.678748: [kopano-dagent|T3594108] [notice ] Resolved recipient user18@example.com as user user18
2021-05-20T07:20:10.792431: [kopano-dagent|T3594108] [notice ] Resolved recipient user19@example.com as user user19
2021-05-20T07:20:10.932309: [kopano-dagent|T3594108] [notice ] Resolved recipient user20@example.com as user user20
2021-05-20T07:20:11.075832: [kopano-dagent|T3594108] [notice ] Resolved recipient user21@example.com as user user21
2021-05-20T07:20:11.222666: [kopano-dagent|T3594108] [notice ] Resolved recipient user22@example.com as user user22
2021-05-20T07:20:11.338868: [kopano-dagent|T3594108] [notice ] Resolved recipient user23@example.com as user user23
2021-05-20T07:20:11.480295: [kopano-dagent|T3594108] [notice ] Resolved recipient user24@example.com as user user24
2021-05-20T07:20:11.598774: [kopano-dagent|T3594108] [notice ] Resolved recipient user25@example.com as user user25
2021-05-20T07:20:11.711734: [kopano-dagent|T3594108] [notice ] Resolved recipient user26@example.com as user user26
2021-05-20T07:20:11.851958: [kopano-dagent|T3594108] [notice ] Resolved recipient user27@example.com as user user27
2021-05-20T07:20:11.968343: [kopano-dagent|T3594108] [notice ] Resolved recipient user28@example.com as user user28
2021-05-20T07:20:12.084134: [kopano-dagent|T3594108] [notice ] Resolved recipient user29@example.com as user user29
2021-05-20T07:20:12.217297: [kopano-dagent|T3594108] [notice ] Resolved recipient user30@example.com as user user30
2021-05-20T07:20:12.326252: [kopano-dagent|T3594108] [notice ] Resolved recipient user31@example.com as user user31
2021-05-20T07:20:12.437458: [kopano-dagent|T3594108] [notice ] Resolved recipient user32@example.com as user user32
2021-05-20T07:20:12.582123: [kopano-dagent|T3594108] [notice ] Resolved recipient user33@example.com as user user33
2021-05-20T07:20:12.689722: [kopano-dagent|T3594108] [notice ] Resolved recipient user34@example.com as user user34
2021-05-20T07:20:12.795292: [kopano-dagent|T3594108] [notice ] Resolved recipient user35@example.com as user user35
2021-05-20T07:20:12.930133: [kopano-dagent|T3594108] [notice ] Resolved recipient user36@example.com as user user36
2021-05-20T07:20:13.035372: [kopano-dagent|T3594108] [notice ] Resolved recipient user37@example.com as user user37
2021-05-20T07:20:13.139240: [kopano-dagent|T3594108] [notice ] Resolved recipient user38@example.com as user user38
2021-05-20T07:20:13.281658: [kopano-dagent|T3594108] [notice ] Resolved recipient user39@example.com as user user39
2021-05-20T07:20:13.395122: [kopano-dagent|T3594108] [notice ] Resolved recipient user40@example.com as user user40
2021-05-20T07:20:13.518676: [kopano-dagent|T3594108] [notice ] Resolved recipient user41@example.com as user user41
2021-05-20T07:20:13.647601: [kopano-dagent|T3594108] [notice ] Resolved recipient user42@example.com as user user42
2021-05-20T07:20:13.761206: [kopano-dagent|T3594108] [notice ] Resolved recipient user43@example.com as user user43
2021-05-20T07:20:13.880314: [kopano-dagent|T3594108] [notice ] Resolved recipient user44@example.com as user user44
2021-05-20T07:20:13.999268: [kopano-dagent|T3594108] [notice ] Resolved recipient user45@example.com as user user45
2021-05-20T07:20:14.106302: [kopano-dagent|T3594108] [notice ] Resolved recipient user46@example.com as user user46
2021-05-20T07:20:14.216822: [kopano-dagent|T3594108] [notice ] Resolved recipient user47@example.com as user user47
2021-05-20T07:20:14.334523: [kopano-dagent|T3594108] [notice ] Resolved recipient user48@example.com as user user48
2021-05-20T07:20:14.459130: [kopano-dagent|T3594108] [notice ] Resolved recipient user49@example.com as user user49
2021-05-20T07:20:14.563643: [kopano-dagent|T3594108] [notice ] Resolved recipient user50@example.com as user user50

Alot of logs for delivering mail from 07:20:14 to 07:29 with subject and debug info. This tread T3594108 has 50 recipients. The group1 maling list consits of 400 recipients.

fbartels

@bbc said in dagent problem:

Looks good

so issue resolved?

bbc

@fbartels Not yet. I am trying fix ldap latency. Chache doesn’t help.
i’ve installed one more test kopano with ldap on the same VM. And have’nt such problem. I think the webapp ask ldap for data to make email, didnt get it before timeout. Again make new mail and so on and so on. With fast ldap I cant reproduce it. Working to find out the source of this problem.
Also i’ve there is problem no even with groups, but fit many recicpients >10. Mails arrive twice.

bbc

@fbartels So, I did it. With local ldap replica works fine.

Webapp make more than 1 message, when ldap response too slow. I think it is special bug of webapp.

bbc

Today occured problem. Webapp made 2 mails with 1 recepient and send it to postfix. I dont know what is it. And why.

Jun  1 08:25:18 srv-cl-mail-be1 postfix/smtpd[3709007]: 9E9C213EA71: client=localhost[127.0.0.1]
Jun  1 08:25:18 srv-cl-mail-be1 postfix/cleanup[3696710]: 9E9C213EA71: message-id=<kcEE.b7se5azhQvO3WhQE7mQ3ZQ.ADM4gqZW1wE@srv-cl-mail-be1.voda.local>
Jun  1 08:25:18 srv-cl-mail-be1 postfix/qmgr[1076776]: 9E9C213EA71: from=<KAM01@example.com>, size=55919, nrcpt=1 (queue active)
Jun  1 08:25:19 srv-cl-mail-be1 postfix/smtpd[3709007]: 29F1F13EA74: client=localhost[127.0.0.1]
Jun  1 08:25:19 srv-cl-mail-be1 postfix/cleanup[3696710]: 29F1F13EA74: message-id=<kcEE.b7se5azhQvO3WhQE7mQ3ZQ.gMnQgqZW1wE@srv-cl-mail-be1.voda.local>
Jun  1 08:25:19 srv-cl-mail-be1 postfix/qmgr[1076776]: 29F1F13EA74: from=<KAM01@example.com>, size=55919, nrcpt=1 (queue active)
Jun  1 08:25:20 srv-cl-mail-be1 postfix/lmtp[3705216]: 9E9C213EA71: to=<oleg@example.com>, relay=127.0.0.1[127.0.0.1]:2003, delay=2, delays=0.01/0/0.01/2, dsn=2.1.5, status=sent (250 2.1.5 oleg@example.com Ok)
Jun  1 08:25:20 srv-cl-mail-be1 postfix/qmgr[1076776]: 9E9C213EA71: removed
Jun  1 08:25:21 srv-cl-mail-be1 postfix/lmtp[3710929]: 29F1F13EA74: to=<oleg@example.com>, relay=127.0.0.1[127.0.0.1]:2003, delay=2.3, delays=0.01/0.01/0/2.3, dsn=2.1.5, status=sent (250 2.1.5 oleg@example.com Ok)
Jun  1 08:25:21 srv-cl-mail-be1 postfix/qmgr[1076776]: 29F1F13EA74: removed