drweb maild.ipc ERROR
#21
Отправлено 05 Октябрь 2008 - 14:13
#22
Отправлено 06 Октябрь 2008 - 09:59
#23
Отправлено 06 Октябрь 2008 - 10:25
Oct 6 11:14:39 mail sendmail[20987]: m967Ed3f020987: --- 220 mail.grena.ge ESMTP Sendmail 8.13.8/8.13.8; Mon, 6 Oct 2008 11:14:39 +0400
Oct 6 11:14:39 mail sendmail[20987]: m967Ed3f020987: Milter: connect to filters
Oct 6 11:14:39 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=connect, continue
Oct 6 11:14:39 mail sendmail[20987]: m967Ed3f020987: Milter (drweb-filter): init success to negotiate
Oct 6 11:14:44 mail sendmail[20987]: m967Ed3f020987: --- 250-mail.grena.ge Hello [217.147.227.47], pleased to meet you
Oct 6 11:14:44 mail sendmail[20987]: m967Ed3f020987: <-- EHLO ubuntu.local
Oct 6 11:14:44 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=helo, continue
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250-8BITMIME
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250-DELIVERBY
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250-DSN
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250-ENHANCEDSTATUSCODES
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250-ETRN
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250 HELP
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250-PIPELINING
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250-SIZE 10485760
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250-STARTTLS
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: <-- MAIL FROM:
Oct 6 11:14:46 mail sendmail[20987]: m967Ed3f020987: --- 250 2.1.0
Oct 6 11:14:46 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=mail, continue
Oct 6 11:14:46 mail sendmail[20987]: m967Ed3f020987: Milter: senders:
Oct 6 11:14:46 mail sendmail[20987]: m967Ed3f020987: <-- RCPT TO:
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: --- 250 2.1.5
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: --- 354 Enter mail, end with "." on a line by itself
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: <-- DATA
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: from=
ay=[217.147.227.47]
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=rcpt, continue
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: Milter: rcpts:
Oct 6 11:14:56 mail drweb-milter: [2746125216] milter INFO [m967Ed3f020987]: success save mail to /var/drweb/msgs/in/8/000378E8/
Oct 6 11:14:56 mail drweb-milter: [2746125216] milter INFO drweb-maild return pass action for msg 000378E8
Oct 6 11:14:56 mail drweb-milter: [2746125216] milter INFO [m967Ed3f020987]: processing message from
Oct 6 11:14:56 mail sendmail[20987]: m967Ed3f020987: Milter accept: message
Oct 6 11:14:56 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=body, continue
Oct 6 11:14:56 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=eoh, continue
Oct 6 11:14:56 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:56 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:56 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:56 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:56 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:57 mail sendmail[20987]: m967Ed3f020987: --- 250 2.0.0 m967Ed3f020987 Message accepted for delivery
Oct 6 11:15:14 mail sendmail[21026]: m967Ed3f020987: SMTP outgoing connect on mail.grena.ge
Oct 6 11:15:16 mail sendmail[21026]: m967Ed3f020987: done; delay=00:00:21, ntries=1
Oct 6 11:15:16 mail sendmail[21026]: m967Ed3f020987: to=
gmail-smtp-in.l.google.com. [74.125.79.27], dsn=2.0.0, stat=Sent (OK 1223277307 20si11148126eyk.4)
#24
Отправлено 06 Октябрь 2008 - 10:48
Oct 6 11:14:46 mail sendmail[20987]: m967Ed3f020987: <-- RCPT TO:
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: --- 250 2.1.5
this delay due to MTA rcpt checking
Oct 6 11:14:57 mail sendmail[20987]: m967Ed3f020987: --- 250 2.0.0 m967Ed3f020987 Message accepted for delivery
Oct 6 11:15:14 mail sendmail[21026]: m967Ed3f020987: SMTP outgoing connect on mail.grena.ge
this delay due to gmail-smtp-in.l.google.com sever delay.
To say more, please, attach some log with Logging/Level = debug for MailD.
#25
Отправлено 06 Октябрь 2008 - 14:49
#26
Отправлено 06 Октябрь 2008 - 15:12
#27
Отправлено 06 Октябрь 2008 - 16:26
#28
Отправлено 06 Октябрь 2008 - 17:23
Oct 6 17:19:54 mail sendmail[14812]: AUTH: available mech=ANONYMOUS, allowed mech=LOGIN PLAIN
Oct 6 17:19:53 mail drweb-maild: [615201696] maild DEBUG FileList::insert_file(/var/drweb/msgs/in/5/00037B45/.p2.p1.epi) was called
Oct 6 17:19:28 mail drweb-milter: [1697139616] milter DEBUG end of a SMTP session
Oct 6 17:19:54 mail sendmail[14239]: m96DGt8P014239: milter=drweb-filter, action=header, continue
maybe this is because very big system loading?
#29
Отправлено 06 Октябрь 2008 - 17:55
as you can see load is not big, just iowait is big
[root@mail mail]# sar
Linux 2.6.17-1.2187_FC5smp (mail.grena.ge) 10/06/2008
12:00:01 AM CPU %user %nice %system %iowait %idle
12:10:02 AM all 3.10 0.00 1.94 20.33 74.64
12:20:01 AM all 2.33 0.00 1.27 21.54 74.87
12:30:01 AM all 1.75 0.00 0.90 18.50 78.85
12:40:01 AM all 0.95 0.00 0.45 9.80 88.80
12:50:01 AM all 0.70 0.00 0.42 11.19 87.69
01:00:01 AM all 0.91 0.00 0.49 11.42 87.18
01:10:01 AM all 0.79 0.00 0.41 9.76 89.04
01:20:01 AM all 0.83 0.00 0.42 9.36 89.39
01:30:01 AM all 0.81 0.00 0.42 8.24 90.54
01:40:01 AM all 0.73 0.00 0.45 9.26 89.56
01:50:01 AM all 0.62 0.00 0.39 9.32 89.67
02:00:01 AM all 0.69 0.00 0.41 9.03 89.88
02:10:01 AM all 0.75 0.00 0.48 11.87 86.90
02:20:01 AM all 0.71 0.00 0.42 9.34 89.53
02:30:01 AM all 0.72 0.00 0.49 10.64 88.15
02:40:01 AM all 0.80 0.00 0.50 10.96 87.75
02:50:01 AM all 0.71 0.00 0.46 10.74 88.08
03:00:01 AM all 0.71 0.00 0.41 9.16 89.72
03:10:01 AM all 0.82 0.00 0.52 10.24 88.42
03:20:01 AM all 0.72 0.00 0.47 11.65 87.16
03:30:01 AM all 1.12 0.00 0.55 12.49 85.84
03:40:01 AM all 0.85 0.00 0.58 13.61 84.95
03:50:01 AM all 0.66 0.00 0.41 10.25 88.68
04:00:01 AM all 0.65 0.00 0.49 14.04 84.82
04:10:01 AM all 0.71 0.00 0.46 10.73 88.11
04:20:01 AM all 0.81 0.00 0.53 13.16 85.49
04:30:01 AM all 10.60 0.00 2.25 15.60 71.55
04:40:01 AM all 19.34 0.41 1.12 16.66 62.48
04:50:01 AM all 0.83 0.00 0.58 13.52 85.07
05:00:01 AM all 0.73 0.00 0.55 16.70 82.02
05:10:01 AM all 0.77 0.00 0.58 17.80 80.85
05:20:01 AM all 1.01 0.00 0.73 18.99 79.27
05:30:01 AM all 0.82 0.00 0.60 17.69 80.89
05:40:01 AM all 0.80 0.00 0.54 14.33 84.33
05:50:01 AM all 0.90 0.00 0.66 15.80 82.64
06:00:01 AM all 0.76 0.00 0.48 12.67 86.08
06:10:02 AM all 0.86 0.00 0.58 13.84 84.72
06:20:01 AM all 0.91 0.00 0.61 14.33 84.15
06:30:01 AM all 1.17 0.00 0.69 12.59 85.55
06:40:01 AM all 0.64 0.00 0.44 12.17 86.75
06:50:01 AM all 0.63 0.00 0.39 11.02 87.97
07:00:01 AM all 0.64 0.00 0.41 12.51 86.44
07:10:01 AM all 0.59 0.00 0.48 13.85 85.08
07:20:01 AM all 0.70 0.00 0.51 13.33 85.47
07:30:01 AM all 0.56 0.00 0.38 10.39 88.67
07:40:01 AM all 6.93 0.00 4.57 12.87 75.63
07:50:01 AM all 13.04 0.00 8.58 13.07 65.31
08:00:01 AM all 12.43 0.00 8.16 15.55 63.85
08:10:01 AM all 12.28 0.00 8.18 19.09 60.45
08:20:01 AM all 11.34 0.00 7.30 20.13 61.23
08:30:01 AM all 14.43 0.00 9.64 15.27 60.66
08:40:01 AM all 7.02 0.00 4.70 11.55 76.73
08:50:01 AM all 1.99 0.00 1.01 17.95 79.05
09:00:01 AM all 1.14 0.00 0.62 9.31 88.93
09:10:01 AM all 0.85 0.00 0.36 2.11 96.68
09:20:01 AM all 1.90 0.00 0.96 16.52 80.62
09:30:01 AM all 1.57 0.00 0.88 20.01 77.54
09:30:01 AM CPU %user %nice %system %iowait %idle
09:40:01 AM all 1.31 0.00 0.80 18.37 79.52
09:50:01 AM all 1.58 0.00 0.85 17.13 80.44
10:00:01 AM all 1.78 0.00 0.83 16.30 81.10
10:10:01 AM all 2.14 0.00 1.01 21.34 75.51
10:20:01 AM all 2.69 0.00 1.05 17.97 78.30
10:30:01 AM all 2.34 0.00 0.94 19.59 77.13
10:40:03 AM all 1.72 0.00 0.91 24.55 72.82
10:50:01 AM all 2.27 0.00 1.15 22.86 73.72
11:00:01 AM all 1.96 0.00 1.08 22.12 74.83
11:10:01 AM all 2.54 0.00 1.24 23.88 72.34
11:20:01 AM all 1.78 0.00 0.78 24.80 72.65
11:30:02 AM all 0.80 0.00 0.65 24.76 73.79
11:40:01 AM all 1.48 0.00 0.83 24.59 73.10
11:50:01 AM all 1.57 0.00 0.91 25.25 72.28
12:00:01 PM all 0.88 0.00 0.74 24.81 73.57
12:10:01 PM all 1.24 0.00 0.79 24.90 73.08
12:20:01 PM all 1.04 0.00 0.73 24.80 73.43
12:30:01 PM all 1.66 0.00 0.70 24.83 72.80
12:40:02 PM all 1.16 0.00 0.65 24.86 73.34
12:50:01 PM all 0.99 0.00 0.76 24.79 73.46
01:00:01 PM all 1.00 0.00 0.62 24.79 73.59
01:10:01 PM all 0.82 0.00 0.58 24.85 73.75
01:20:01 PM all 0.85 0.00 0.65 24.78 73.72
01:30:01 PM all 0.92 0.00 0.78 24.83 73.47
01:40:01 PM all 0.80 0.00 0.75 24.75 73.69
01:50:01 PM all 0.86 0.00 0.67 24.69 73.78
02:00:01 PM all 1.03 0.00 0.59 24.82 73.56
02:10:01 PM all 1.87 0.00 0.75 23.69 73.69
02:20:01 PM all 2.03 0.00 1.14 17.17 79.66
02:30:02 PM all 1.45 0.00 1.01 16.02 81.52
02:40:01 PM all 1.40 0.00 0.89 13.01 84.70
02:50:01 PM all 1.53 0.00 1.10 21.22 76.15
03:00:02 PM all 1.99 0.00 0.98 24.40 72.63
03:10:01 PM all 3.35 0.00 1.07 24.49 71.09
03:20:02 PM all 1.52 0.00 0.96 24.11 73.42
03:30:01 PM all 2.91 0.00 1.22 17.21 78.67
03:40:01 PM all 2.18 0.00 1.11 16.60 80.11
03:50:02 PM all 1.42 0.00 0.98 22.17 75.44
04:00:02 PM all 1.31 0.00 0.84 17.60 80.26
04:10:01 PM all 1.92 0.00 1.05 19.13 77.90
04:20:01 PM all 1.47 0.00 0.90 18.49 79.14
04:30:01 PM all 1.11 0.00 0.80 17.04 81.05
04:40:01 PM all 1.22 0.00 0.82 21.17 76.79
04:50:01 PM all 1.23 0.00 0.89 18.50 79.38
05:00:01 PM all 1.25 0.00 0.96 22.26 75.52
05:10:01 PM all 1.60 0.00 1.01 19.31 78.08
05:20:01 PM all 1.80 0.00 0.96 23.20 74.03
05:30:02 PM all 1.42 0.00 0.97 24.64 72.97
05:40:02 PM all 1.19 0.00 0.88 24.61 73.32
05:50:02 PM all 1.12 0.00 0.88 24.79 73.22
06:00:02 PM all 1.22 0.00 0.88 24.69 73.21
06:10:01 PM all 1.31 0.00 0.89 23.27 74.52
06:20:01 PM all 1.15 0.00 0.81 18.43 79.61
06:30:01 PM all 1.06 0.00 0.78 18.18 79.98
06:40:01 PM all 0.93 0.00 0.77 18.37 79.93
06:50:01 PM all 1.01 0.00 0.91 20.55 77.53
Average: all 2.10 0.00 1.16 17.47 79.26
#30
Отправлено 07 Октябрь 2008 - 08:53
2. Move all plugins from BeforeQueueFilters to AfterQueueFilters - this must remove timeouts between drweb-milter and drweb-maild (but this is does not increase total speed of msgs checking)
#31
Отправлено 07 Октябрь 2008 - 09:43
Oct 7 10:30:50 mail drweb-maild: [652827552] maild INFO start processing msg 0003A9B7 ...
Oct 7 10:30:50 mail drweb-maild: [652827552] maild INFO put msg 0003A9B7 to queue for processing
Oct 7 10:38:10 mail drweb-maild: [652827552] maild INFO start processing msg 0003AA45 ...
Oct 7 10:39:14 mail drweb-maild: [652827552] maild INFO put msg 0003AA45 to queue for processing
Oct 7 10:40:15 mail drweb-maild: [652827552] maild.ipc ERROR Socket::Send(4) to connection (fd->342, local->local:/var/drweb/ipc/.db, client->local:) failed becasue Broken pipe
Oct 7 10:41:25 mail drweb-maild: [652827552] maild.ipc ERROR Session::Execute - error for address(es) [local:/var/drweb/ipc/.db]: Socket::Send: [32] Broken pipe
Oct 7 10:34:36 mail drweb-milter: [2545773472] milter INFO [m976XguR020642]: success save mail to /var/drweb/msgs/in/4/0003AA04/
Oct 7 10:35:31 mail drweb-milter: [2545773472] milter INFO success send msg 0003AA04 to drweb-maild component
Oct 7 10:36:13 mail drweb-milter: [2545773472] milter INFO [m976XguR020642]: can not find action for msg after 40 sec; discard it (it may be send by drweb-sender process)
Oct 7 10:36:13 mail drweb-milter: [2545773472] milter INFO [m976XguR020642]: processing message from
Oct 7 10:36:42 mail drweb-milter: [2545773472] milter INFO [m976aIu5021117]: success save mail to /var/drweb/msgs/in/1/0003AA31/
Oct 7 10:38:38 mail drweb-milter: [2545773472] milter INFO success send msg 0003AA31 to drweb-maild component
Oct 7 10:39:19 mail drweb-milter: [2545773472] milter INFO [m976aIu5021117]: can not find action for msg after 40 sec; discard it (it may be send by drweb-sender process)
Oct 7 10:39:24 mail drweb-milter: [2545773472] milter INFO [m976aIu5021117]: processing message from
Oct 7 10:41:30 mail drweb-milter: [2545773472] milter INFO [m976eOVo021842]: success save mail to /var/drweb/msgs/in/D/0003AA6D/
Oct 7 10:43:36 mail drweb-milter: [2545773472] milter.ipc ERROR is timed out (timeout= 1 m 119 s 119741 ms)!
Oct 7 10:44:16 mail drweb-milter: [2545773472] milter.ipc ERROR Session::Execute - error for address(es) [local:/var/drweb/ipc/.db]: a waiting of Socket::IsReady(0x1) for connection (fd->482, local->local:, server->local:/var/drweb/ipc/.db): timed out (timeout= 1 m 119 s 119741 ms)
Oct 7 10:44:17 mail drweb-milter: [2545773472] milter ERROR error in send request to drweb-maild: a waiting of Socket::IsReady(0x1) for connection (fd->482, local->local:, server->local:/var/drweb/ipc/.db): timed out (timeout= 1 m 119 s 119741 ms)
#32
Отправлено 07 Октябрь 2008 - 10:29
Oct 7 10:38:10 mail drweb-maild: [652827552] maild INFO start processing msg 0003AA45 ...
Oct 7 10:39:14 mail drweb-maild: [652827552] maild INFO put msg 0003AA45 to queue for processing
this is strange because only msg parsing and saving to disk executing during this operatoin. Please, show your hardware configuration and output of commands:
vmstat -s
free
#33
Отправлено 07 Октябрь 2008 - 10:33
2075192 total memory
1966472 used memory
1090996 active memory
666332 inactive memory
108720 free memory
240372 buffer memory
1331604 swap cache
4209020 total swap
74828 used swap
4134192 free swap
43811576 non-nice user cpu ticks
192011 nice user cpu ticks
19451988 system cpu ticks
2020430801 idle cpu ticks
289394665 IO-wait cpu ticks
178463 IRQ cpu ticks
2075388 softirq cpu ticks
0 stolen cpu ticks
417023574 pages paged in
1360785008 pages paged out
2814869 pages swapped in
3873276 pages swapped out
3211395722 interrupts
3878242764 CPU context switches
1217422738 boot time
13197275 forks
[root@mail ~]# free
total used free shared buffers cached
Mem: 2075192 1971556 103636 0 240412 1331564
-/+ buffers/cache: 399580 1675612
Swap: 4209020 74828 4134192
#34
Отправлено 07 Октябрь 2008 - 11:05
Читают тему: 1
0 пользователей, 1 гостей, 0 скрытых