проблемы с авторизацией

От: Oleg Shumsky <CGatePro_at_mx_ru>
Дата: Mon 06 Nov 2006 - 12:21:19 MSK


Здравствуйте.

Всем спасибо за ответ на сообщение про нокию.

Теперь есть следующая проблема. В нашей системе настроено все таким образом, что обычно в коммунигейте не присутствуют пользователи и аккаунт создается при приходе REGISTER от нужного пользователя. Все замечательно работает, но есть одно но...

Есть такой юзер kalinova. Почему-то коммунигейт каждый раз считает, что именно этого юзера (20 других пользователей работают и заводятся в системе нормально) нет и каждый раз присылает внешнему хелперу SASL сообщение. Каждый раз внешний хелпер честно пытается создать этого пользователя, т.к. считается, что если уж прислали SASL, то этого пользователся нет и обламывается, потому что он есть в системе. В конечном итоге внешний хелпер почему-то затыкается, непонятно почему, как будто просто зависает т.к. в логи не пишет вообще ничего. А коммунигейт все никак не может найти этого пользователя в системе и за ночь набегает немеряное количество висящих процессов, в итоге коммунигейт вообще перестает отвечать на любые сип-запросы из внешнего мира.

Плохо, в общем. Лечится ситуация следующим образом. Можно убить этого пользователя. И всем становится хорошо, а можно грохнуть внешний хелпер. Тогда все пробуждается до поры до времени.

Хотелось бы понять, что же именно с этим юзером не так. в Domain Settings стоит Consult external authenticators На unknown names, и calls to unknown стоит reroute to на пользователя, от имени которого производится запуск хелпера на авторизацию

Теперь логи:

В коммунигейте (юзер kalinova в системе уже есть):

11:49:02.880 5 SIP [0.0.0.0]:5060 <- [85.140.138.88]:5060 inp(421): REGISTER sip:sip.corbina.ru SIP/2.0\r\nVia: SIP/2.0/UDP
192.168.1.11;rport;branch=z9hG4bKc0a8010b0000000b454ef7090000592a0000024c\r\nContent-Length: 0\r\nContact: <sip:kalinova@192.168.1.11:5060>\r\nCall-ID: 72890EC7-4751-4F64-A626-
11:49:02.880 2 SIPDATA-000310 inp: req [0.0.0.0]:5060 <- udp [85.140.138.88]:5060 REGISTER(421 bytes) sip:sip.corbina.ru
11:49:02.880 5 SIPDATA-000310 inp: REGISTER sip:sip.corbina.ru SIP/2.0
11:49:02.880 5 SIPDATA-000310 inp: Via: SIP/2.0/UDP 192.168.1.11;rport;branch=z9hG4bKc0a8010b0000000b454ef7090000592a0000024c 11:49:02.880 5 SIPDATA-000310 inp: Content-Length: 0 11:49:02.880 5 SIPDATA-000310 inp: Contact: <sip:kalinova@192.168.1.11:5060>
11:49:02.880 5 SIPDATA-000310 inp: Call-ID: 72890EC7-4751-4F64-A626-CC97BB136A28@192.168.1.11 11:49:02.880 5 SIPDATA-000310 inp: CSeq: 112 REGISTER 11:49:02.880 5 SIPDATA-000310 inp: From: <sip:kalinova@sip.corbina.ru>;tag=537687112315 11:49:02.880 5 SIPDATA-000310 inp: Max-Forwards: 70 11:49:02.880 5 SIPDATA-000310 inp: To:
<sip:kalinova@sip.corbina.ru>
11:49:02.880 5 SIPDATA-000310 inp: User-Agent: SJphone/1.60.289a (SJ Labs)
11:49:02.880 5 SIPDATA-000310 inp:
11:49:02.880 4 SIPDATA-000310 NATed [192.168.1.11]:5060 via [85.140.138.88]:5060

11:49:02.880 4 SIPDATA-000310 Hash=1343397018
11:49:02.880 5 SIPS 186: enqueued
11:49:02.880 2 SIPS-000186 enqueued
11:49:02.880 5 SIPS-000186 INITIAL posted
11:49:02.880 2 SIPDATA-000310 created SIPS-000186
11:49:02.880 5 SIPS(55) 186: processing INITIAL
11:49:02.880 2 SIPS-000186 [000310] REGISTER 
sip:sip.corbina.ru from udp [85.140.138.88]:5060
11:49:02.880 2 SIGNAL-000178 enqueued
11:49:02.880 2 SIPS-000186 created SIGNAL-000178
11:49:02.880 5 SIPS(55) 186: idling
11:49:02.880 2 SIGNAL-000178 SIPS-000186: REGISTER 
sip:sip.corbina.ru
11:49:02.880 2 SIGNAL-000178 REGISTER sip:sip.corbina.ru via sip:sip.corbina.ru
11:49:02.880 2 SIGNAL-000178 401 relaying
11:49:02.880 5 SIPS-000186 FINAL posted
11:49:02.880 2 SIGNAL-000178 dequeued
11:49:02.880 5 SIPS(22) 186: processing FINAL
11:49:02.880 2 SIPDATA-000311 out: rsp [0.0.0.0]:5060 -> 
udp [85.140.138.88]:5060 401-REGISTER(577 bytes) 11:49:02.880 5 SIPDATA-000311 out: SIP/2.0 401 Authentication required
11:49:02.880 5 SIPDATA-000311 out: Via: SIP/2.0/UDP 192.168.1.11;rport=5060;branch=z9hG4bKc0a8010b0000000b454ef7090000592a0000024c;received=85.140.138.88 11:49:02.880 5 SIPDATA-000311 out: Path: <sip:85.140.138.88-5060.nat.cgatepro;lr> 11:49:02.880 5 SIPDATA-000311 out: From: <sip:kalinova@sip.corbina.ru>;tag=537687112315 11:49:02.880 5 SIPDATA-000311 out: To:
<sip:kalinova@sip.corbina.ru>;tag=FC0CFDFCA75B2284 11:49:02.880 5 SIPDATA-000311 out: Call-ID: 72890EC7-4751-4F64-A626-CC97BB136A28@192.168.1.11 11:49:02.880 5 SIPDATA-000311 out: CSeq: 112 REGISTER 11:49:02.880 5 SIPDATA-000311 out: WWW-Authenticate: Digest
realm="sip.corbina.ru",nonce="4C39CD972A5F0E8232CC",opaque="opaqueData",qop="auth",algorithm=MD5 11:49:02.880 5 SIPDATA-000311 out: Server: CommuniGatePro/5.1.0 _trial_
11:49:02.880 5 SIPDATA-000311 out: Content-Length: 0
11:49:02.880 5 SIPDATA-000311 out:
11:49:02.880 5 SIP [0.0.0.0]:5060 -> [85.140.138.88]:5060 
out(577): SIP/2.0 401 Authentication required\r\nVia: SIP/2.0/UDP
192.168.1.11;rport=5060;branch=z9hG4bKc0a8010b0000000b454ef7090000592a0000024c;received=85.140.138.88\r\nPath: <sip:85.140.138.88-5060.nat.cgatepro;lr>\r\nFrom: <sip:kalinova@s
11:49:02.880 2 SIPS-000186 [000311] 401-REGISTER(final) sent to udp [85.140.138.88]:5060
11:49:02.880 4 SIPS-000186 completed
11:49:02.880 5 SIPS-000186 timeout set for 32 secs
11:49:02.880 5 SIPS(22) 186: enqueued (32 secs)
11:49:02.933 5 SIP [0.0.0.0]:5060 <- [85.140.138.88]:5060 
inp(668): REGISTER sip:sip.corbina.ru SIP/2.0\r\nVia: SIP/2.0/UDP
192.168.1.11;rport;branch=z9hG4bKc0a8010b0000000b454ef709000020b70000024e\r\nContent-Length: 0\r\nContact: <sip:kalinova@192.168.1.11:5060>\r\nCall-ID: 72890EC7-4751-4F64-A626-
11:49:02.933 2 SIPDATA-000312 inp: req [0.0.0.0]:5060 <- udp [85.140.138.88]:5060 REGISTER(668 bytes) sip:sip.corbina.ru
11:49:02.933 5 SIPDATA-000312 inp: REGISTER sip:sip.corbina.ru SIP/2.0
11:49:02.933 5 SIPDATA-000312 inp: Via: SIP/2.0/UDP 192.168.1.11;rport;branch=z9hG4bKc0a8010b0000000b454ef709000020b70000024e 11:49:02.933 5 SIPDATA-000312 inp: Content-Length: 0 11:49:02.933 5 SIPDATA-000312 inp: Contact: <sip:kalinova@192.168.1.11:5060>
11:49:02.933 5 SIPDATA-000312 inp: Call-ID: 72890EC7-4751-4F64-A626-CC97BB136A28@192.168.1.11 11:49:02.933 5 SIPDATA-000312 inp: CSeq: 113 REGISTER 11:49:02.933 5 SIPDATA-000312 inp: From: <sip:kalinova@sip.corbina.ru>;tag=537691129449 11:49:02.933 5 SIPDATA-000312 inp: Max-Forwards: 70 11:49:02.933 5 SIPDATA-000312 inp: To:
<sip:kalinova@sip.corbina.ru>

11:49:02.933 5 SIPDATA-000312 inp: User-Agent: SJphone/1.60.289a (SJ Labs)
11:49:02.933 5 SIPDATA-000312 inp: Authorization: Digest username="kalinova",realm="sip.corbina.ru",nonce="4C39CD972A5F0E8232CC",uri="sip:sip.corbina.ru",response="15a6b84aee61c6b0cca64d41ebe1e964",algorithm="MD5",cnonce="537691113945",opaque="opaqueData",qop="auth",nc="00000001" 11:49:02.933 5 SIPDATA-000312 inp:
11:49:02.933 4 SIPDATA-000312 NATed [192.168.1.11]:5060 via [85.140.138.88]:5060
11:49:02.933 4 SIPDATA-000312 Hash=251154449
11:49:02.933 5 SIPS 188: enqueued
11:49:02.933 2 SIPS-000188 enqueued
11:49:02.933 5 SIPS-000188 INITIAL posted
11:49:02.933 2 SIPDATA-000312 created SIPS-000188
11:49:02.933 5 SIPS(89) 188: processing INITIAL
11:49:02.933 2 SIPS-000188 [000312] REGISTER 
sip:sip.corbina.ru from udp [85.140.138.88]:5060 11:49:02.934 4 EXTAUTH out(184): 14 SASL(DIGEST-HTTP) (SIP) kalinova@sip.corbina.ru
15a6b84aee61c6b0cca64d41ebe1e964
kalinova:sip.corbina.ru:4C39CD972A5F0E8232CC:00000001:537691113945:auth:REGISTER:sip:sip.corbina.ru\n 11:49:02.934 4 EXTAUTH inp(189): * RX: 14 SASL(DIGEST-HTTP) (SIP) kalinova@sip.corbina.ru 15a6b84aee61c6b0cca64d41ebe1e964
kalinova:sip.corbina.ru:4C39CD972A5F0E8232CC:00000001:537691113945:auth:REGISTER:sip:sip.corbina.ru

[some sql stuff]

11:49:03.082 4 EXTAUTH inp(19): * Creating kalinova
11:49:03.082 5 PWD connection request from 
[127.0.0.1]:56486, socket=53
11:49:03.082 5 PWD new VStream created, n=1
11:49:03.082 5 PWD stream thread started
11:49:03.083 4 PWD-000018([127.0.0.1]) got connection on 
[127.0.0.1]:106(sip.corbina.ru) from [127.0.0.1]:56486
11:49:03.083 5 PWD-000018([127.0.0.1]) out: 200 
CommuniGate Pro PWD Server 5.1.0 ready
<18.1162802943@sip.corbina.ru>\r\n
11:49:03.083 5 PWD-000018([127.0.0.1]) inp: APOP postmaster 946ad8059f99c5d6f534d6fb897b81be 11:49:03.083 2 PWD-000018([127.0.0.1])
'postmaster@sip.corbina.ru' connected from [127.0.0.1]:56486
11:49:03.083 5 PWD-000018([127.0.0.1]) out: 200 login OK, proceed\r\n
11:49:03.083 5 PWD-000018([127.0.0.1]) inp: INLINE 11:49:03.083 5 PWD-000018([127.0.0.1]) out: 200 switched to the inline mode\r\n
11:49:03.083 5 PWD-000018([127.0.0.1]) inp: CreateAccount kalinova {}
11:49:03.083 1 DOMAIN(*) failed to create account 'kalinova'. Error Code=account with this name already exists
11:49:03.083 5 PWD-000018([127.0.0.1]) out: 520 account with this name already exists\r\n
11:49:03.083 5 PWD-000018([127.0.0.1]) inp: QUIT 11:49:03.083 5 PWD-000018([127.0.0.1]) out: 200 CommuniGate Pro PWD Server connection closed\r\n 11:49:03.084 2 PWD-000018([127.0.0.1])
'postmaster@sip.corbina.ru' disconnected ([127.0.0.1]:56486)
11:49:03.084 4 PWD-000018([127.0.0.1]) closing connection
11:49:03.084 4 PWD-000018([127.0.0.1]) releasing stream
11:49:03.084 4 EXTAUTH inp(67): * ERR: Can't create 
kalinova: account with this name already exists 11:49:03.084 4 EXTAUTH inp(28): * Updating kalinova settings
11:49:03.084 5 PWD connection request from 
[127.0.0.1]:65401, socket=31
11:49:03.084 4 PWD-000019([127.0.0.1]) got connection on 
[127.0.0.1]:106(sip.corbina.ru) from [127.0.0.1]:65401
11:49:03.084 5 PWD-000019([127.0.0.1]) out: 200 
CommuniGate Pro PWD Server 5.1.0 ready
<19.1162802943@sip.corbina.ru>\r\n
11:49:03.085 5 PWD-000019([127.0.0.1]) inp: APOP postmaster 83ecae065a37cad45bb54e2d754af18f 11:49:03.085 2 PWD-000019([127.0.0.1])
'postmaster@sip.corbina.ru' connected from [127.0.0.1]:65401
11:49:03.085 5 PWD-000019([127.0.0.1]) out: 200 login OK, proceed\r\n
11:49:03.085 5 PWD-000019([127.0.0.1]) inp: INLINE 11:49:03.085 5 PWD-000019([127.0.0.1]) out: 200 switched to the inline mode\r\n
11:49:03.085 5 PWD-000019([127.0.0.1]) inp: UpdateAccountSettings kalinova {Password=xxxxx;}
11:49:03.108 2 ACCOUNT(kalinova) settings updated
11:49:03.108 5 PWD-000019([127.0.0.1]) out: 200 OK\r\n
11:49:03.108 5 PWD-000019([127.0.0.1]) inp: 
SetAccountAliases kalinova ()
11:49:03.108 2 DOMAIN(*) kalinova aliases(0) updated by postmaster
11:49:03.108 5 PWD-000019([127.0.0.1]) out: 200 OK\r\n
11:49:03.108 5 PWD-000019([127.0.0.1]) inp: QUIT
11:49:03.108 5 PWD-000019([127.0.0.1]) out: 200 
CommuniGate Pro PWD Server connection closed\r\n 11:49:03.109 2 PWD-000019([127.0.0.1])
'postmaster@sip.corbina.ru' disconnected ([127.0.0.1]:65401)
11:49:03.109 4 PWD-000019([127.0.0.1]) closing connection 11:49:03.109 4 EXTAUTH inp(43): 14 REJECTED please try again 1 minute later
11:49:03.109 4 PWD-000019([127.0.0.1]) releasing stream 11:49:03.109 4 EXTAUTH inp(49): * TX: 14 REJECTED please try again 1 minute later Получено Mon Nov 06 09:21:21 2006

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