Re[2]: неудавшийся апгрейд на 5.0.12

От: Varinov Nicolay <CGatePro_at_mx_ru>
Дата: Fri 27 Oct 2006 - 12:08:17 MSD

День добрый Dmitry,

Thursday, October 26, 2006, 8:43:52 PM, Вы пишете:

DA> Здравствуйте,

DA> Varinov Nicolay wrote:
>> День добрый
>>
>> Решил я проапгрейдиться на 5.0.12 с 5.0.11 и получил проблему на свою
>> голову. За 10 мин. работы сервера около 2000 входящих SMTP соединяй
>> так мило висящих и нечего не делающих, больше 2000 тредов в состоянии:
>>
>> VSMTPInput 2827 checking the source network address wait(DNR Limit)
>> VSMTPInput 1308 checking the source network address wait(DNR)
>>
>> Танцы с бубном на подобие отключения BL, проверки SPF, R-C, R-P, HELLO
>> ни к чему не привели.

DA> Detect Client by DNS Name - используется? Нет

DA> В логах записи о проблемах с DNS есть? Что есть в логах по поводу этих Вроде не нашел только после 64 запроса начинают расти задержки

18:18:40.23 4 DNR-00064(164.223.216.60.IN-ADDR.ARPA) PTR-request
18:18:40.46 4 DNR-00064(164.223.216.60.IN-ADDR.ARPA) request sent to [127.0.0.1]
18:18:40.59 3 DNR-00064(164.223.216.60.IN-ADDR.ARPA) PTR:host name is unknown
18:18:40.61 4 DNR-00065(dp38.lookwhois.com) A-request
18:18:40.96 4 DNR-00065(dp38.lookwhois.com) request sent to [127.0.0.1]
18:18:42.36 4 DNR-00065(dp38.lookwhois.com) A-response[0]: dp38.lookwhois.com=[66.109.117.9]
а после 75 ответов нет вообще, хотя наймед замечательно в это время работает
18:18:42.76 4 DNR-00074(32.90.92.72.IN-ADDR.ARPA) PTR-request
18:18:42.76 4 DNR-00074(32.90.92.72.IN-ADDR.ARPA) request sent to [127.0.0.1]
18:19:08.93 4 DNR-00074(32.90.92.72.IN-ADDR.ARPA) PTR-response: 32.90.92.72.IN-ADDR.ARPA -> pool-72-92-90-32.phlapa.fios.verizon.net
18:18:42.78 4 DNR-00075(|http://mail.oldartero.com:8888/cgi-bin/put) A-request
18:18:42.81 4 DNR-00075(|http://mail.oldartero.com:8888/cgi-bin/put) request sent to [127.0.0.1]
18:19:19.94 3 DNR-00075(|http://mail.oldartero.com:8888/cgi-bin/put) A:host name is unknown
18:18:42.93 4 DNR-00076(19.207.190.194.IN-ADDR.ARPA) PTR-request
18:18:43.10 4 DNR-00076(19.207.190.194.IN-ADDR.ARPA) request sent to [127.0.0.1]
18:21:09.44 4 DNR-00076(19.207.190.194.IN-ADDR.ARPA) request sent to [80.72.112.2]
18:23:27.51 4 DNR-00076(19.207.190.194.IN-ADDR.ARPA) request sent to [80.72.114.2]
18:40:55.07 4 DNR-00076(19.207.190.194.IN-ADDR.ARPA) request sent to [127.0.0.1]
...
18:44:46.68 4 DNR-00876(178.93.26.195.IN-ADDR.ARPA) PTR-request 18:44:52.31 4 DNR-00876(178.93.26.195.IN-ADDR.ARPA) request sent to [127.0.0.1]

DA> конкретно SMTPI сессий?
это:

18:27:12.74 4 SMTPI-01308([83.222.5.153]) got connection on [80.72.112.9:25](mx.sotcom.ru) from [83.222.5.153:64112]
18:27:18.54 4 SMTPI-01308([83.222.5.153]) rsp: 220 mx.sotcom.ru ESMTP CommuniGate Pro 5.0.12
18:27:20.13 4 SMTPI-01308([83.222.5.153]) cmd: HELO relay-vand.mybsd.ru
18:40:29.02 4 SMTPI-02827([81.176.77.82]) got connection on [80.72.112.9:25](mx.sotcom.ru) from [81.176.77.82:2070]
18:40:33.87 4 SMTPI-02827([81.176.77.82]) rsp: 220 mx.sotcom.ru ESMTP CommuniGate Pro 5.0.12
18:40:37.14 4 SMTPI-02827([81.176.77.82]) cmd: EHLO www.computerra.ru
18:40:40.11 4 SMTPI-02827([81.176.77.82]) rsp: 250-mx.sotcom.ru we trust you www.computerra.ru\r\n250-DSN\r\n250-SIZE\r\n250-STARTTLS\r\n250-AUTH LOGIN PLAIN CRAM-MD5 DIGEST-MD5 GSSAPI MSN\r\n250-ETRN\r\n250-TURN\r\n250-ATRN\r\n250-NO-SOLICITING\r\n250-8BITMIME\r\n250-HELP\r\n250-PIPELINING\r\n250 E
18:40:42.47 4 SMTPI-02827([81.176.77.82]) cmd: MAIL From:<mailrobot@www.computerra.ru> SIZE=18501
18:40:45.01 4 SMTPI-02827([81.176.77.82]) rsp: 250 mailrobot@www.computerra.ru sender accepted
18:40:48.96 4 SMTPI-02827([81.176.77.82]) cmd: RCPT To:<aga@rbd.rzn.ru>
18:40:52.56 4 SMTPI-02827([81.176.77.82]) checking MX-record for rbd.rzn.ru


Но с SMTPI все плохо в общем случае письма проходят, но как

18:18:37.82 4 SMTPI-00002(gato55.subscribe.ru) rsp: 250 20960001 message accepted for delivery
18:21:20.52 4 SMTPI-00152([80.72.124.142]) rsp: 250 20960014 message accepted for delivery
18:28:38.45 4 SMTPI-01415([80.72.113.101]) rsp: 250 20960055 message accepted for delivery
18:30:01.25 4 SMTPI-01522([195.218.170.2]) rsp: 250 20960076 message accepted for delivery
18:30:08.86 4 SMTPI-01523([84.252.142.19]) rsp: 250 20960077 message accepted for delivery
18:30:15.13 4 SMTPI-01475([80.72.117.58]) rsp: 250 20960056 message accepted for delivery
это записи с начала его работы

Вот первые несколько сессий из лога

18:18:30.97 4 SMTPI-00001([81.106.62.178]) got connection on [80.72.112.9:25](mx.sotcom.ru) from [81.106.62.178:3826]
18:18:36.17 4 SMTPI-00001([81.106.62.178]) rsp: 220 mx.sotcom.ru ESMTP CommuniGate Pro 5.0.12
18:18:42.64 4 SMTPI-00001([81.106.62.178]) cmd: EHLO HOME-NDUF357T0X.o3ea1d8.org
18:19:30.30 3 SMTPI-00001(HOME-NDUF357T0X.o3ea1d8.org) failed to resolve HELO parameter: host name is unknown. Real address is [81.106.62.178]
18:19:31.90 4 SMTPI-00001([81.106.62.178]) rsp: 250-mx.sotcom.ru host name is unknown HOME-NDUF357T0X.o3ea1d8.org\r\n250-DSN\r\n250-SIZE\r\n250-STARTTLS\r\n250-AUTH LOGIN PLAIN CRAM-MD5 DIGEST-MD5 GSSAPI MSN\r\n250-ETRN\r\n250-TURN\r\n250-ATRN\r\n250-NO-SOLICITING\r\n250-8BITMIME\r\n250-HELP\r\n250-
18:19:34.30 3 SMTPI-00001([81.106.62.178]) read failed. Error Code=connection closed by peer
18:19:37.34 4 SMTPI-00001([81.106.62.178]) closing connection
18:19:41.75 4 SMTPI-00001([81.106.62.178]) releasing stream
18:18:32.08 4 SMTPI-00002([81.222.129.55]) got connection on [80.72.112.16:25](rzpost.ru) from [81.222.129.55:60810]
18:18:37.13 4 SMTPI-00002([81.222.129.55]) rsp: 220 mx.sotcom.ru ESMTP CommuniGate Pro 5.0.12
18:18:37.15 4 SMTPI-00002([81.222.129.55]) cmd: EHLO gato55.subscribe.ru
18:18:37.21 4 SMTPI-00002(gato55.subscribe.ru) rsp: 250-mx.sotcom.ru is pleasedto meet you\r\n250-DSN\r\n250-SIZE\r\n250-STARTTLS\r\n250-AUTH LOGIN PLAIN CRAM-MD5 DIGEST-MD5 GSSAPI MSN\r\n250-ETRN\r\n250-TURN\r\n250-ATRN\r\n250-NO-SOLICITING\r\n250-8BITMIME\r\n250-HELP\r\n250-PIPELINING\r\n250 EHLO
18:18:37.23 4 SMTPI-00002(gato55.subscribe.ru) cmd: MAIL FROM:<gluck@mail.subscribe.ru> SIZE=80158 BODY=8BITMIME ENVID=3696FB505D RET=HDRS
18:18:37.25 4 SMTPI-00002(gato55.subscribe.ru) checking relay smtp1.mail.subscribe.ru
18:18:37.27 4 SMTPI-00002(gato55.subscribe.ru) rsp: 250 gluck@mail.subscribe.rusender accepted
18:18:37.27 4 SMTPI-00002(gato55.subscribe.ru) cmd: RCPT TO:<fixel@rzpost.ru> NOTIFY=FAILURE
18:18:37.27 4 SMTPI-00002(gato55.subscribe.ru) rsp: 250 fixel@rzpost.ru will leave the Internet
18:18:37.27 4 SMTPI-00002(gato55.subscribe.ru) cmd: DATA
18:18:37.27 4 SMTPI-00002(gato55.subscribe.ru) rsp: 354 Enter mail, end with "." on a line by itself
18:18:37.82 2 SMTPI-00002(gato55.subscribe.ru) [20960001] received, 79346 bytes
18:18:37.82 4 SMTPI-00002(gato55.subscribe.ru) rsp: 250 20960001 message accepted for delivery
18:18:37.82 4 SMTPI-00002(gato55.subscribe.ru) cmd: QUIT
18:18:37.82 4 SMTPI-00002(gato55.subscribe.ru) rsp: 221 mx.sotcom.ru CommuniGate Pro SMTP closing connection
18:18:37.82 4 SMTPI-00002(gato55.subscribe.ru) closing connection
18:18:37.82 4 SMTPI-00002(gato55.subscribe.ru) releasing stream
18:18:32.11 4 SMTPI-00003([222.252.228.98]) got connection on [80.72.112.9:25](mx.sotcom.ru) from [222.252.228.98:41818]
18:18:37.66 4 SMTPI-00003([222.252.228.98]) rsp: 220 mx.sotcom.ru ESMTP CommuniGate Pro 5.0.12
18:18:38.53 4 SMTPI-00003([222.252.228.98]) cmd: EHLO UYEN.jugo.net
18:18:39.22 3 SMTPI-00003(UYEN.jugo.net) failed to resolve HELO parameter: hostname is unknown. Real address is [222.252.228.98]
18:18:39.22 4 SMTPI-00003([222.252.228.98]) rsp: 250-mx.sotcom.ru host name is unknown UYEN.jugo.net\r\n250-DSN\r\n250-SIZE\r\n250-STARTTLS\r\n250-AUTH LOGIN PLAIN CRAM-MD5 DIGEST-MD5 GSSAPI MSN\r\n250-ETRN\r\n250-TURN\r\n250-ATRN\r\n250-NO-SOLICITING\r\n250-8BITMIME\r\n250-HELP\r\n250-PIPELINING\r\
18:18:42.76 4 SMTPI-00003([222.252.228.98]) cmd: MAIL FROM: <bunyanbroadside@roteshaus-musik.de>
18:18:42.76 4 SMTPI-00003([222.252.228.98]) SPF(roteshaus-musik.de) checking
18:18:32.50 4 SMTPI-00004([88.155.207.218]) got connection on [80.72.112.9:25](mx.sotcom.ru) from [88.155.207.218:3633]
18:18:37.82 4 SMTPI-00004([88.155.207.218]) rsp: 220 mx.sotcom.ru ESMTP CommuniGate Pro 5.0.12
18:18:38.54 4 SMTPI-00004([88.155.207.218]) cmd: HELO bzq-88-155-207-218.red.bezeqint.net
18:18:38.87 4 SMTPI-00004(bzq-88-155-207-218.red.bezeqint.net) rsp: 250 mx.sotcom.ru is pleased to meet you
18:18:39.53 4 SMTPI-00004(bzq-88-155-207-218.red.bezeqint.net) cmd: MAIL FROM: <info@chandar.com>
18:18:39.53 4 SMTPI-00004(bzq-88-155-207-218.red.bezeqint.net) SPF(chandar.com)checking
18:18:44.86 1 SMTPI-00004(bzq-88-155-207-218.red.bezeqint.net) Return-Path 'info@chandar.com' rejected: sender domain does not match SPF records
18:18:46.87 4 SMTPI-00004(bzq-88-155-207-218.red.bezeqint.net) rsp: 587 info@chandar.com sender domain does not match SPF records
18:18:48.65 4 SMTPI-00004(bzq-88-155-207-218.red.bezeqint.net) cmd: RSET
18:18:48.65 4 SMTPI-00004(bzq-88-155-207-218.red.bezeqint.net) rsp: 250 SMTP state reset
18:18:49.13 4 SMTPI-00004(bzq-88-155-207-218.red.bezeqint.net) cmd: MAIL FROM: <info@cathaus.com>
18:18:52.12 4 SMTPI-00004(bzq-88-155-207-218.red.bezeqint.net) SPF(cathaus.com)checking

по большинству в логах только это

18:28:07.82 4 SMTPI-01441([201.250.3.156]) got connection on [80.72.112.9:25](mx.sotcom.ru) from [201.250.3.156:24599]
18:28:12.65 4 SMTPI-01441([201.250.3.156]) closing connection
18:28:13.25 4 SMTPI-01441([201.250.3.156]) releasing stream

grep SMTPI | grep -c 'message accepted for delivery'  - 924
grep SMTPI | grep -c 'got connection on' - 3414 grep SMTPI | grep -c 'releasing stream' - 1677

не маловато ли писем принялось за 26 с половиной минут работы сервера всего 924 из 3414 а еще 753 соединения были просто закрыты, а судьба еще 1737 для меня загадочна.

Могу выслать весь лог того периода на support@stalker.com, могу даже попробовать повторить попытку с вклячением всего что надо в All Info, но тогда от сталкера? что надо или что надо все в AI

>> В tope в это время наблюдалась примерно такая картина:
>> last pid: 31802; load averages: 9.29, 9.72, 8.82 up 247+00:23:20 17:54:10
>> 29 processes: 2 running, 27 sleeping
>> CPU states: 96.9% user, 0.0% nice, 2.3% system, 0.0% interrupt, 0.8% idle
>> Mem: 462M Active, 1384M Inact, 348M Wired, 97M Cache, 199M Buf, 219M Free
>> Swap: 1024M Total, 128K Used, 1024M Free
>>
>> PID USERNAME PRI NICE SIZE RES STATE TIME WCPU CPU COMMAND
>> 29320 root 56 0 379M 73640K RUN 12:06 94.34% 94.34% CGServer
>> 30640 root 2 0 84572K 76992K poll 0:24 1.56% 1.56% perl
>> 20541 root 2 0 34772K 33268K poll 2:23 0.10% 0.10% named
>>
>> Да OS FreeBSD 4.9, ветку 5.1 лицензия попробовать не позволяет,
>> Переходить на 5 или 6 FretBSD не хочу.
>>
>> Откат назад на 5.0.11 помог и вот сеже я сейчас и думаю толи я где не
>> прав, толи в 5.0.12 для FreeBSD4 что-то не так.
>>
>> Вопрос то в том что неверно мне уже ничего не светит в плане
>> обновлений или я не прав?



С наилучшими пожеланиями
Николай Варинов.
тел.+7 4912 243873
mailto:nic@sotcom.ru
Получено Fri Oct 27 08:08:19 2006

Этот архив был сгенерирован hypermail 2.1.8 : Fri 24 Apr 2015 - 16:15:10 MSK