ASTERISK-16133: [patch] Notify event keep-alive is responded with bad event

[Home]

Summary: ASTERISK-16133: [patch] Notify event keep-alive is responded with bad event

Reporter: rsw686 (rsw686) Labels:

Date Opened: 2010-05-23 21:19:08 Date Closed: 2011-08-30 16:54:32

Priority: Minor Regression? No

Status: Closed/Complete Components: Channels/chan_sip/General

Versions: Frequency of
Occurrence

Related
Issues:

Environment: Attachments: ( 0) asterisk-1.6.2.9-keep-alive.patch
( 1) debug.txt

Description: Looking through chan_sip.c I see that there is support for returning a 200 OK for a notify keep-alive event. However Asterisk is sending a Bad event response complaining about the call-id.

[May 23 22:07:39] DEBUG[6668]: chan_sip.c:22046 handle_request_do: Invalid SIP message - rejected , no callid, len 313
<--- SIP read from UDP:10.10.5.128:5060 --->
NOTIFY sip:10.10.5.16 SIP/2.0
Via: SIP/2.0/UDP 10.10.5.128:5060;branch=z9hG4bK-5f632398
From: <sip:110@10.10.5.16>;tag=a05c065adebc52bco0
To: <sip:10.10.5.16>
Call-ID: 57768572-7ae21e84@10.10.5.128
CSeq: 322 NOTIFY
Max-Forwards: 70
Event: keep-alive
User-Agent: Linksys/SPA941-5.1.8
Content-Length: 0

<------------->
--- (10 headers 0 lines) ---
[May 23 22:07:40] DEBUG[6668]: acl.c:506 ast_ouraddrfor: Found IP address for this socket
[May 23 22:07:40] DEBUG[6668]: chan_sip.c:3682 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.10.5.16:5060

<--- Transmitting (no NAT) to 10.10.5.128:5060 --->
SIP/2.0 489 Bad event
Via: SIP/2.0/UDP 10.10.5.128:5060;branch=z9hG4bK-5f632398;received=10.10.5.128
From: <sip:110@10.10.5.16>;tag=a05c065adebc52bco0
To: <sip:10.10.5.16>;tag=as4cad60c7
Call-ID: 57768572-7ae21e84@10.10.5.128
CSeq: 322 NOTIFY
Server: Asterisk PBX 1.6.2.8-rc1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Content-Length: 0

<------------>
[May 23 22:07:40] DEBUG[6668]: chan_sip.c:3561 __sip_xmit: Trying to put 'SIP/2.0 489' onto UDP socket destined for 10.10.5.128 :5060

Comments: By: Paul Belanger (pabelanger) 2010-05-24 14:43:16

Could you capture a debug log (see below) of you issue? Thanks.

---
We require a complete debug log to help triage the issue.

This document will provide instructions on how to collect debugging logs from an Asterisk machine for the purpose of helping bug marshals troubleshoot an issue:

http://svn.digium.com/svn/asterisk/trunk/doc/HOWTO_collect_debug_information.txt
By: rsw686 (rsw686) 2010-05-24 15:04:49

I posted the debug output in the original message. The phones send out a NAT keep alive packet which Asterisk response Bad event to. If you want I can let it collect a bunch of these packets in a log file, but they all look the same.
By: Paul Belanger (pabelanger) 2010-05-24 15:21:38

We just want to get a full debug output from your issue. Following the document just tells you how to do this.

Thanks
By: Paul Belanger (pabelanger) 2010-06-03 20:56:46

Suspended due to lack of activity. Please request a bug marshal in #asterisk-bugs on the IRC network irc.freenode.net to reopen the issue should you have the additional information requested.

Further information can be found at http://www.asterisk.org/developers/bug-guidelines
By: rsw686 (rsw686) 2010-06-22 18:28:38

I attached the requested debug log for this issue.

By: Leif Madsen (lmadsen) 2010-06-23 11:21:38

I think I'd like to see the SIP history attached as well which can be enabled in sip.conf. This is all per the bug guidelines when debugging SIP issues.
By: rsw686 (rsw686) 2010-06-23 12:26:25

James Lamanna on the Asterisk user's mailing list had a patch for Asterisk 1.4. With his permission I have attached the modified version for 1.6.2. Since 1.6.2 already had support for notify keep-alive all that was necessary was allow the packet to be out of dialog.
By: rsw686 (rsw686) 2010-06-26 10:05:39

Since patches are provided can this be marked ready for testing?
By: Paul Belanger (pabelanger) 2010-06-26 13:05:58

Promoted to 'Ready for Testing'. If you can round up a few more testers we can continue to triage this issue.
By: rsw686 (rsw686) 2010-06-26 14:43:56

Thanks I'll see if I can get a few testers from the mailing list. Here is the sip debug output from a patched install.

<--- SIP read from UDP:10.10.5.129:5060 --->
NOTIFY sip:10.10.5.16 SIP/2.0
Via: SIP/2.0/UDP 10.10.5.129:5060;branch=z9hG4bK-88b0451d
From: <sip:114@10.10.5.16>;tag=18b75b1137a2abfbo0
To: <sip:10.10.5.16>
Call-ID: f6217a89-691652e3@10.10.5.129
CSeq: 4147 NOTIFY
Max-Forwards: 70
Event: keep-alive
User-Agent: Linksys/SPA941-5.1.8
Content-Length: 0

<------------->
--- (10 headers 0 lines) ---

<--- Transmitting (no NAT) to 10.10.5.129:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.10.5.129:5060;branch=z9hG4bK-88b0451d;received=10.10.5.129
From: <sip:114@10.10.5.16>;tag=18b75b1137a2abfbo0
To: <sip:10.10.5.16>;tag=as4d751a17
Call-ID: f6217a89-691652e3@10.10.5.129
CSeq: 4147 NOTIFY
Server: Asterisk PBX 1.6.2.9
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Content-Length: 0
By: John Covert (jcovert) 2010-07-21 20:18:13

That patch certainly isn't going to solve the problem below. Here we have an asterisk running 1.6.2.9 registered as a station with another asterisk. The 1.6.2.9 system shouldn't send the Bad Events.

Separately from the bug, it would also be a nice feature to have the NOTIFY do something useful in the 1.6.2.9 asterisk so that it could handle the event. Maybe if an extension named "Notify" existed in the incoming context, an application could be called that would be able to read and process the NOTIFY.

<--- SIP read from UDP:192.168.32.26:5060 --->
NOTIFY sip:s@192.168.44.10:5062 SIP/2.0
Via: SIP/2.0/UDP 192.168.32.26:5060;branch=z9hG4bK5c3ebc52;rport
From: "asterisk" <sip:asterisk@192.168.32.26>;tag=as70e4560c
To: <sip:s@192.168.44.10:5062>
Contact: <sip:asterisk@192.168.32.26>
Call-ID: 2c9e33a164dc6a2d2bbd8ece78577e8f@192.168.32.26
CSeq: 102 NOTIFY
User-Agent: Asterisk PBX
Max-Forwards: 70
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 93

Messages-Waiting: no
Message-Account: sip:asterisk@192.168.32.26
Voice-Message: 0/0 (0/0)

<------------->
--- (12 headers 3 lines) ---

<--- Transmitting (no NAT) to 192.168.32.26:5060 --->
SIP/2.0 489 Bad event
Via: SIP/2.0/UDP 192.168.32.26:5060;branch=z9hG4bK5c3ebc52;received=192.168.32.26;rport=5060
From: "asterisk" <sip:asterisk@192.168.32.26>;tag=as70e4560c
To: <sip:s@192.168.44.10:5062>;tag=as527899de
Call-ID: 2c9e33a164dc6a2d2bbd8ece78577e8f@192.168.32.26
CSeq: 102 NOTIFY
Server: Asterisk PBX 1.6.2.9
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Content-Length: 0
By: James Lamanna (jlamanna) 2010-07-22 04:59:13

I would say in that case, Asterisk is doing the right thing in sending a Bad Event reply.
The NOTIFY that is being sent is for message-summary, which is the message for communicating if there are voicemails present. Since this is not being sent to a phone, but instead to another Asterisk box, Bad Event seems like an appropriate reply.

Is there a reason why you are registering Asterisk as a station to another Asterisk and not using IAX?
By: John Covert (jcovert) 2010-07-22 06:18:53

I'm emulating a station with a personal Asterisk instance which registers with every station assigned to me, with every upstream provider I obtain service from, with every telecommunications provider I do business with.

I don't control what protocol the upstream provider chooses to use. Quite possibly, the upstream provider, or the corporation, has decided that due to the current problems with IAX stability (see issue 0017521 for example), only SIP is allowed for the safety of the corporate PBX.

According to the Asterisk training materials (Bootcamp slides) Asterisk is supposed to be a building block which can be embedded in such things as phones.

Asterisk is the PBX which does what YOU want it to do, not what some PBX manufacturer wants it to do.

What possible goodness is provided by sending "Bad Event"?

By: Paul Belanger (pabelanger) 2010-07-22 08:50:45

Goodness? We send '483 Bad Event' because asterisk does not understand the previous event (see below).

---
7.3.2. "489 Bad Event" Response Code

The 489 event response is added to the "Client-Error" header field
definition. "489 Bad Event" is used to indicate that the server did
not understand the event package specified in a "Event" header field.
---

That said, your NOTIFY event is different. This patch is to help handle keep-alive message (for NATs), your events seems to notify you about voicemail.

So your statement is correct, this patch will not help you in this situation because you and the reporter are doing 2 different things.
By: John Covert (jcovert) 2010-07-22 09:04:15

Just because asterisk doesn't understand a valid event does not make that event a bad event.

It would be good for a single patch to fix both "Bad Event" problems.

Reporting "Bad Event" for something which would better be ignored is certainly a problem.

/john
By: David Vossel (dvossel) 2010-08-30 13:00:35

I think this may work in 1.6.2.12-rc1. I noticed this code changed to allow out of dialog NOTIFY messages to create a dialog. Please test this.
By: rsw686 (rsw686) 2010-08-31 07:09:40

I just looked at the 1.6.2.12-rc1 code and it looks unchanged to me. The 1.8 code is changed and looks to have support for NOTIFY messages. I will try and test this out in the next couple of days.
By: shmaize (shmaize) 2010-11-24 03:33:58.000-0600

1.8.0 answers with 200 OK and 1.6.2.14 keep answering with 489 Bad event