[Home]

Summary:ASTERISK-09043: Improper response on receiving duplicated packets
Reporter:Dan Lukes (dan_lukes)Labels:
Date Opened:2007-03-18 17:23:05Date Closed:2011-06-07 14:08:06
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/Registration
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) asterisk-debuglog.txt
( 1) verbosedebug2.txt
Description:SIP protocol handler improperly handle the REGISTER message that has been duplicated in transmit.
The "Additional Information" section contain the dump od debug messages. I attached the timestamps related to each packet (obtained from tcpdump).

The Asterisk sends REGISTER. Server responds "401 Unauthorized". Unfortunately, this packet arrived three times (it has been replicated somewhere on the network).
In my humble opinion, Asterisk shall respond to the first then ignore replicants (resending the same response as in the first case). Unfortunatelly, it doesn't. It respond to every of them using separate response (different CSeq). In advance, it can't handle three "OK" that arrive later claiming he got OK/REGISTER to nonregister request which is not true (the reauest has been REGISTER request).


****** ADDITIONAL INFORMATION ******

REGISTER attempt 1 to 222360743@hlas6.802.cz
Reliably Transmitting (no NAT) to 212.71.146.183:5060:
--> Timestamp: 22:46:08.601593
REGISTER sip:hlas6.802.cz SIP/2.0
Via: SIP/2.0/UDP 62.209.200.25:5060;branch=z9hG4bK24b955a3;rport
From: <sip:222360743@hlas6.802.cz>;tag=as01be7452
To: <sip:222360743@hlas6.802.cz>
Call-ID: 11118530153f1b11620a03fc7f8bc7ac@62.209.200.25
CSeq: 117 REGISTER
User-Agent: Asterisk PBX
Max-Forwards: 70
Expires: 150
Contact: <sip:222360743@62.209.200.25>
Event: registration
Content-Length: 0


---

<-- SIP read from 212.71.146.183:5060:
<-- Timestamp: 22:46:08.612689
SIP/2.0 401 Unauthorized
Call-ID: 11118530153f1b11620a03fc7f8bc7ac@62.209.200.25
CSeq: 117 REGISTER
From: <sip:222360743@hlas6.802.cz>;tag=as01be7452
To: <sip:222360743@hlas6.802.cz>
Via: SIP/2.0/UDP 62.209.200.25:5060;branch=z9hG4bK24b955a3;rport
WWW-Authenticate: Digest realm="212.71.146.183", algorithm=MD5, nonce="15a06a58443d322b2b0f1c171a100a0e"
Content-Length:0


--- (8 headers 0 lines) ---
Responding to challenge, registration to domain/host name hlas6.802.cz
REGISTER 13 headers, 0 lines
REGISTER attempt 2 to 222360743@hlas6.802.cz
Reliably Transmitting (no NAT) to 212.71.146.183:5060:
--> Timestamp: 22:46:08.614105
REGISTER sip:hlas6.802.cz SIP/2.0
Via: SIP/2.0/UDP 62.209.200.25:5060;branch=z9hG4bK2dc0e407;rport
From: <sip:222360743@hlas6.802.cz>;tag=as58870964
To: <sip:222360743@hlas6.802.cz>
Call-ID: 11118530153f1b11620a03fc7f8bc7ac@62.209.200.25
CSeq: 118 REGISTER
User-Agent: Asterisk PBX
Max-Forwards: 70
Authorization: Digest username="<removed>", realm="212.71.146.183", algorithm=MD5, uri="sip:hlas6.802.cz", nonce="15a06a58443d322b2b0f1c171a100a0e", response="<removed>", opaque=""
Expires: 150
Contact: <sip:222360743@62.209.200.25>
Event: registration
Content-Length: 0


---

<-- SIP read from 212.71.146.183:5060:
<-- Timestamp: 22:46:08.612960
SIP/2.0 401 Unauthorized
Call-ID: 11118530153f1b11620a03fc7f8bc7ac@62.209.200.25
CSeq: 117 REGISTER
From: <sip:222360743@hlas6.802.cz>;tag=as01be7452
To: <sip:222360743@hlas6.802.cz>
Via: SIP/2.0/UDP 62.209.200.25:5060;branch=z9hG4bK24b955a3;rport
WWW-Authenticate: Digest realm="212.71.146.183", algorithm=MD5, nonce="15a06a58443d322b2b0f1c171a100a0e"
Content-Length:0


--- (8 headers 0 lines) ---
Responding to challenge, registration to domain/host name hlas6.802.cz
REGISTER 13 headers, 0 lines
REGISTER attempt 3 to 222360743@hlas6.802.cz
Reliably Transmitting (no NAT) to 212.71.146.183:5060:
--> Timestamp: 22:46:08.615051
REGISTER sip:hlas6.802.cz SIP/2.0
Via: SIP/2.0/UDP 62.209.200.25:5060;branch=z9hG4bK63264601;rport
From: <sip:222360743@hlas6.802.cz>;tag=as3e26756a
To: <sip:222360743@hlas6.802.cz>
Call-ID: 11118530153f1b11620a03fc7f8bc7ac@62.209.200.25
CSeq: 119 REGISTER
User-Agent: Asterisk PBX
Max-Forwards: 70
Authorization: Digest username="<removed>", realm="212.71.146.183", algorithm=MD5, uri="sip:hlas6.802.cz", nonce="15a06a58443d322b2b0f1c171a100a0e", response="<removed>", opaque=""
Expires: 150
Contact: <sip:222360743@62.209.200.25>
Event: registration
Content-Length: 0


---

<-- SIP read from 212.71.146.183:5060:
<-- Timestamp: 22:46:08.613191
SIP/2.0 401 Unauthorized
Call-ID: 11118530153f1b11620a03fc7f8bc7ac@62.209.200.25
CSeq: 117 REGISTER
From: <sip:222360743@hlas6.802.cz>;tag=as01be7452
To: <sip:222360743@hlas6.802.cz>
Via: SIP/2.0/UDP 62.209.200.25:5060;branch=z9hG4bK24b955a3;rport
WWW-Authenticate: Digest realm="212.71.146.183", algorithm=MD5, nonce="15a06a58443d322b2b0f1c171a100a0e"
Content-Length:0


--- (8 headers 0 lines) ---
Responding to challenge, registration to domain/host name hlas6.802.cz
REGISTER 13 headers, 0 lines
REGISTER attempt 4 to 222360743@hlas6.802.cz
Reliably Transmitting (no NAT) to 212.71.146.183:5060:
--> Timestamp: 22:46:08.615654
REGISTER sip:hlas6.802.cz SIP/2.0
Via: SIP/2.0/UDP 62.209.200.25:5060;branch=z9hG4bK4765d6e3;rport
From: <sip:222360743@hlas6.802.cz>;tag=as6338c5d2
To: <sip:222360743@hlas6.802.cz>
Call-ID: 11118530153f1b11620a03fc7f8bc7ac@62.209.200.25
CSeq: 120 REGISTER
User-Agent: Asterisk PBX
Max-Forwards: 70
Authorization: Digest username="<removed>", realm="212.71.146.183", algorithm=MD5, uri="sip:hlas6.802.cz", nonce="15a06a58443d322b2b0f1c171a100a0e", response="<removed>", opaque=""
Expires: 150
Contact: <sip:222360743@62.209.200.25>
Event: registration
Content-Length: 0


---

<-- SIP read from 212.71.146.183:5060:
<-- Timestamp: 22:46:08.624683
SIP/2.0 200 OK
Call-ID: 11118530153f1b11620a03fc7f8bc7ac@62.209.200.25
Contact: <sip:222360743@62.209.200.25>;expires=102
CSeq: 118 REGISTER
From: <sip:222360743@hlas6.802.cz>;tag=as58870964
To: <sip:222360743@hlas6.802.cz>
Via: SIP/2.0/UDP 62.209.200.25:5060;branch=z9hG4bK2dc0e407;rport
Content-Length:0


--- (8 headers 0 lines) ---
Scheduling destruction of call '11118530153f1b11620a03fc7f8bc7ac@62.209.200.25' in 32000 ms
Mar 18 22:46:08 NOTICE[19289]: chan_sip.c:9955 handle_response_register: Outbound Registration: Expiry for hlas6.802.cz is 102 sec (Scheduling reregistration in 87 s)

<-- SIP read from 212.71.146.183:5060:
<-- Timestamp: 22:46:08.628929
SIP/2.0 200 OK
Call-ID: 11118530153f1b11620a03fc7f8bc7ac@62.209.200.25
Contact: <sip:222360743@62.209.200.25>;expires=102
CSeq: 119 REGISTER
From: <sip:222360743@hlas6.802.cz>;tag=as3e26756a
To: <sip:222360743@hlas6.802.cz>
Via: SIP/2.0/UDP 62.209.200.25:5060;branch=z9hG4bK63264601;rport
Content-Length:0


--- (8 headers 0 lines) ---
Mar 18 22:46:08 WARNING[19289]: chan_sip.c:9895 handle_response_register: Got 200 OK on REGISTER that isn't a register

<-- SIP read from 212.71.146.183:5060:
<-- Timestamp: 22:46:08.631572
SIP/2.0 200 OK
Call-ID: 11118530153f1b11620a03fc7f8bc7ac@62.209.200.25
Contact: <sip:222360743@62.209.200.25>;expires=102
CSeq: 120 REGISTER
From: <sip:222360743@hlas6.802.cz>;tag=as6338c5d2
To: <sip:222360743@hlas6.802.cz>
Via: SIP/2.0/UDP 62.209.200.25:5060;branch=z9hG4bK4765d6e3;rport
Content-Length:0


--- (8 headers 0 lines) ---
Mar 18 22:46:08 WARNING[19289]: chan_sip.c:9895 handle_response_register: Got 200 OK on REGISTER that isn't a register
Destroying call '11118530153f1b11620a03fc7f8bc7ac@62.209.200.25'
Mar 18 22:46:08 NOTICE[19289]: chan_sip.c:9955 handle_response_register: Outbound Registration: Expiry for hlas2.802.cz is 102 sec (Scheduling reregistration in 87 s)

Comments:By: Serge Vecher (serge-v) 2007-03-19 09:18:13

Please read bug guidelines before reporting bugs: 1) you must be using the latest release (1.2.16 currently); 2) you need to attach a SIP debug trace illustrating the problem. Please do the following:
1) Prepare test environment (reduce the amount of unrelated traffic on the server);
2) Make sure your logger.conf has the following line:
  console => notice,warning,error,debug
3) restart Asterisk with the following command:
  'asterisk -Tvvvvvdddddngc | tee /tmp/verbosedebug.txt'
4) Enable SIP transaction logging with the following CLI commands (1.4/trunk commands in parenthesis):
set debug 4 (core set debug 4)
set verbose 4 (core set verbose 4)
sip debug (sip set debug)
5) Reproduce the problem
6) Trim startup information and attach verbosedebug.txt to the issue.
By: Dan Lukes (dan_lukes) 2007-03-19 13:03:33

I'm running the 1.2.13 because later versions are not avaiable for my OS now. I read the channel_sip.c from 1.2.16 and I'm sure it's handling of replicated packets is the same as within 1.2.13 - but I understand the rules are the rules. Althought I'm sure the bug is in 1.2.16 as well, I can't send log from it, so this problem report need's to be closed for formal deficience despite the bug still exist. I'm understand the reasons.

Let's close it. Sorry for disturbing.

If 1.2.16 become avaiable for me before the release of 1.2.17, I will report the problem again following the guidelines.

By the way, you "checklist" is more useful for bug reporting than guidelines - I did' almost everything you want with exception of "console => notice,warning,error,debug" configuration. I didn's know this statement exist.
By: Serge Vecher (serge-v) 2007-03-19 14:16:54

ok, attach the log as per my instruction then.
By: Jonathan Hunter (jmhunter) 2007-04-04 15:05:53

I have what seems to be exactly this issue, and I am running Asterisk 1.4.2.

I would concur with Dan_Lukes that Asterisk really should be ignoring the duplicate messages.. FWIW, my retransmissions come from sipgate.co.uk but I guess any SIP provider would have the potential to generate retransmissions.

Not sure if it makes a difference, but my Asterisk box registers two SIP numbers with sipgate (one for me, one for my flatmate) - this is possibly not a usual case.

I shall also upload my debug log.
By: Serge Vecher (serge-v) 2007-04-05 08:33:45

jmhunter: debug portion of the log is missing -> please redo as per my instructions.
By: Olle Johansson (oej) 2007-04-27 09:46:19

Please state clearly what the issue is - Doesn't at least one of these register messages perform a working registration for you? Or does sipgate still think you're not registered?
By: Jonathan Hunter (jmhunter) 2007-04-27 10:52:47

Hi - thanks for looking at this!

I can't speak for Dan_Lukes, but I feel that Asterisk does not behave gracefully when faced with a misbehaving or overloaded SIP peer such as whichever software sipgate uses, for example.

The attached trace was sent from a "correctly functioning" system - IMHO Asterisk should be able to receive the duplicate packets from sipgate, and realise that they are in fact retransmissions and can be ignored. The current behaviour seems to be that Asterisk moans loudly ("Got 200 OK on REGISTER that isn't a register") whereas I would expect it to understand that these packets are duplicates and can be safely ignored (i.e. don't fill the logs with warnings)

Maybe I've got the wrong end of the stick somewhere.. perhaps all that is required is to increase the debug level that these warnings are logged at?
By: Dan Lukes (dan_lukes) 2007-04-27 13:23:54

I didn't reported failing registration. The first registration is succesfull. I reported improper handling of packets duplicating somewhere on the way only. The WiFi seems to be reason of duplication. At the first - improper response may cause problem with some application firewalls (althought I there is no known case of this type), at the second, messages about "registration response to non-registration request" are anyonyng and are not true.
BTW, althought 1.2.16 is not avaiable for FreeBSD (the latest is 1.2.13 in 1.2.x branch), we have 1.4.2 online. After update I will submit the required logs.
By: Olle Johansson (oej) 2007-04-30 02:11:13

So to summarize: THis is not very elegant, but does not cause any failures in operation?

The reason I am asking is that this is deeply buried into the chan_sip source and can't be elegantly solved without a proper cleanup/rewrite, something I'm still trying to get funding for (http://www.codename-pineapple.org). I also need to prioritize bugs that cause failures in call handling.

I agree very much that this is stupid and should be fixed. I've been aware of it for a very long time...
By: Joshua C. Colp (jcolp) 2007-10-30 10:17:43

I'm suspending this since it's a 1.2 bug, plus as oej mentioned while it isn't elegant... it doesn't cause any issues and will hopefully be fixed in newer versions.