dagent problem

fbartels

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