[Home]

Summary:ASTERISK-07413: Notifications sent with wrong Content-Type
Reporter:Jeff Siddall (jsiddall)Labels:
Date Opened:2006-07-28 10:58:29Date Closed:2011-06-07 14:02:38
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/Subscriptions
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) full
( 1) full-1.2SVN
( 2) full-1.2SVN-2
( 3) full-SVN-branch-1.2-r46406
( 4) full-SVN-branch-1.2-r46406-2
Description:After a successful subscribe transaction subsequent notifications are sent with Content-Type: unknown even though the subscription specified Accept: application/dialog-info+xml.  Notifications with the incorrect Content-Type result in SIP/2.0 415 Unacceptable Content-Type messages back from the subscriber.

It is interesting to note that this problem does not occur on all subscriptions.  There are usually a number of successful subscriptions in place at any given time, but as shown in the sib debug log attached below this particular resubscribe seems to cause the wrong content type to be sent, at which point the subscription is removed.

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

Reproducible with significant regularity using Grandstream GXP-2000 phones running firmware 1.1.0.16.  Below is a SIP debug log:

<-- SIP read from 192.168.3.46:5060:
SUBSCRIBE sip:14@server;user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.3.46:5060;branch=z9hG4bK509f29dac594a9f8
From: "User <13>"
<sip:user@server>;tag=c2b860d13462b60b
To: <sip:14@server;user=phone>
Contact: <sip:user@192.168.3.46:5060>
Call-ID: 9f7a88cff8da06f1@192.168.3.46
CSeq: 2244 SUBSCRIBE
User-Agent: Grandstream GXP2000 1.1.0.16
Max-Forwards: 70
Allow:
INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK
Event: dialog
Expires: 3600
Accept: application/dialog-info+xml
Content-Length: 0


Jul 19 11:54:04 VERBOSE[18606] logger.c: --- (14 headers 0 lines)Jul 19
11:54:04 VERBOSE[18606] logger.c: --- (14 headers 0 lines)---
Jul 19 11:54:04 DEBUG[18606] chan_sip.c: Got a re-subscribe on existing
subscription 9f7a88cff8da06f1@192.168.3.46
Jul 19 11:54:04 DEBUG[18606] chan_sip.c: Adding subscription for
extension 14 context outgoing-unrestricted for peer user
Jul 19 11:54:04 VERBOSE[18606] logger.c: Scheduling destruction of call
'9f7a88cff8da06f1@192.168.3.46' in 3610000 ms
Jul 19 11:54:04 VERBOSE[18606] logger.c: Transmitting (no NAT) to
192.168.3.46:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP
192.168.3.46:5060;branch=z9hG4bK509f29dac594a9f8;received=192.168.3.46
From: "User <13>"
<sip:user@server>;tag=c2b860d13462b60b
To: <sip:14@server;user=phone>;tag=as1404a059
Call-ID: 9f7a88cff8da06f1@192.168.3.46
CSeq: 2244 SUBSCRIBE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Expires: 3600
Contact: <sip:14@192.168.3.1>;expires=3600
Content-Length: 0

---
Jul 19 11:54:04 VERBOSE[18606] logger.c: Reliably Transmitting (no NAT)
to 192.168.3.46:5060:
NOTIFY sip:user@192.168.3.46:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.1:5060;branch=z9hG4bK2542863c;rport
From: <sip:14@server;user=phone>;tag=as1404a059
To: "User <13>"
<sip:user@server>;tag=c2b860d13462b60b
Contact: <sip:14@192.168.3.1>
Call-ID: 9f7a88cff8da06f1@192.168.3.46
CSeq: 112 NOTIFY
User-Agent: Asterisk PBX
Max-Forwards: 70
Event: -
Content-Type: unknown
Subscription-State: active
Content-Length: 0
Comments:By: ajmahler (diver) 2006-08-16 12:08:45

I See this message on a 1.2.10 with GXP-2000 firmware code 1.1.1.9 and an extension unit.  I did not see this error message on firmware code 1.1.1.7 and below.
By: Joshua C. Colp (jcolp) 2006-08-16 12:24:30

What does sip show subscriptions come up with? is the type unknown for it?
By: ajmahler (diver) 2006-08-16 12:50:14

Peer             User        Call ID      Extension        Last state     Type
192.168.168.201  201         c067de2e80c  217              Idle           dialog-info+xml
192.168.168.201  201         7d4004fb2dd  216              Idle           dialog-info+xml
192.168.168.201  201         b889558c157  215              Idle           dialog-info+xml
192.168.168.201  201         84f6228bb58  214              Idle           dialog-info+xml
192.168.168.201  201         45d13826da7  213              Idle           dialog-info+xml
192.168.168.201  201         973d3a1bc4c  212              Idle           dialog-info+xml
192.168.168.201  201         7a613d4bfaa  211              Idle           dialog-info+xml
192.168.168.201  201         81f8aa94941  210              Idle           dialog-info+xml
192.168.168.201  201         02dd5ebcb8a  209              Idle           dialog-info+xml
192.168.168.201  201         505525e3428  208              Idle           dialog-info+xml
192.168.168.201  201         740b7ba1be5  207              Idle           dialog-info+xml
192.168.168.201  201         4c86cf20ab2  206              Idle           dialog-info+xml
192.168.168.201  201         be929c64335  205              Idle           dialog-info+xml
192.168.168.201  201         fedee1368ce  203              Idle           dialog-info+xml
192.168.168.201  201         58cfac62c81  261              Idle           dialog-info+xml
192.168.168.201  201         926cb320641  260              Idle           dialog-info+xml
192.168.168.201  201         372f42e3b5b  259              Idle           dialog-info+xml
192.168.168.201  201         2b184676384  258              Idle           dialog-info+xml
192.168.168.201  201         9380e305c69  257              Idle           dialog-info+xml
192.168.168.201  201         61c954d3584  256              Idle           dialog-info+xml
192.168.168.201  201         b7d7d3e2122  255              Idle           dialog-info+xml
192.168.168.201  201         33d7b349dd1  254              Idle           dialog-info+xml
192.168.168.201  201         35e7bce85b1  253              Idle           dialog-info+xml
192.168.168.201  201         05900784d43  252              Idle           dialog-info+xml
192.168.168.201  201         2f0c22268a9  251              Idle           dialog-info+xml
192.168.168.201  201         e21eb9aebaa  250              Idle           dialog-info+xml
192.168.168.201  201         c949870e0b2  237              Idle           dialog-info+xml
192.168.168.201  201         614fdb927e9  236              InUse          dialog-info+xml
192.168.168.201  201         9d8235b3367  235              Idle           dialog-info+xml
192.168.168.201  201         051ce7ddbef  232              Idle           dialog-info+xml
192.168.168.201  201         5700bfbf65a  231              Idle           dialog-info+xml
192.168.168.201  201         b670a74ba8f  230              Idle           dialog-info+xml
192.168.168.201  201         0665ae4e408  229              Idle           dialog-info+xml
192.168.168.201  201         1d0adf28347  228              Idle           dialog-info+xml
192.168.168.201  201         49941a3c1b3  223              Idle           dialog-info+xml
192.168.168.201  201         1858371793f  222              Idle           dialog-info+xml
192.168.168.201  201         484afdea494  221              Idle           dialog-info+xml
192.168.168.201  201         876c882309a  220              Idle           dialog-info+xml
192.168.168.201  201         ca24e883b0e  219              Idle           dialog-info+xml
192.168.168.201  201         bda2e1926e1  218              Idle           dialog-info+xml
By: Jeff Siddall (jsiddall) 2006-08-16 12:56:16

All _active_ subscriptions show type dialog-info+xml.  It appears that whenever a phone responds with a "SIP/2.0 415 Unacceptable Content-Type" to a notification with a content type of "unknown" that Asterisk removes the subscription.
By: ajmahler (diver) 2006-08-16 12:59:30

I tried to roll back to 1.1.1.7 of the firmware, but the messages continue.  Perhaps I changed something in the config file with this upgrade that I didn't notice.  I will check
By: Serge Vecher (serge-v) 2006-08-16 13:07:28

I think we need to see a complete SIP debug trace showing the problem, not just the snippets. Also, if downgrading firmware works, then perhaps it is the Grandstream firmware problem, not Asterisk.

Please do the following:
1) Prepare test environment (reduce the ammount of unrelated traffic on the server);
2) Make sure your logger.conf has the following line:
  console => notice,warning,error,debug
3) restart Asterik.
4) Enable SIP transaction logging with the following CLI commands:
set debug 4
set verbose 4
sip debug
5) Save complete console log to file and _attach_ said file to the bug.
By: Joshua C. Colp (jcolp) 2006-08-16 13:07:38

The question though, is why is it being generated as "unknown"? It's weird, chan_sip has a listing internally of all the different types... when the subscription comes in it records the subscription time numerically, when it goes to make the NOTIFY it uses that numerical value to search for the subscription type information (content type for example). The only time unknown should be returned is if the type wasn't found. I'd like to get in and add some debug information if possible.
By: ajmahler (diver) 2006-08-16 13:17:30

Please note that rolling back to firmware 1.1.1.7 did not clear the problem.  I did make several small changes to the config including changing the dns from 0.0.0.0 to 4.2.2.2 but nothing I can see that was significant.
By: ajmahler (diver) 2006-08-16 13:18:09

I will setup the debug for tonight.  I cannot give you an isolated trace during business hours.  This actually a production environment.
By: ajmahler (diver) 2006-08-16 13:50:20

OK...this is weird.  I re-updated the phone to 1.1.1.9 from 1.1.1.7 and the problem went away.  Go figure...
By: Joshua C. Colp (jcolp) 2006-08-16 13:52:26

How very very strange... I guess the moral of this story is to... reflash your phone 42 times to be sure? :D would you be okay with closing the bug since it appears to have been your phone?
By: ajmahler (diver) 2006-08-16 13:55:07

I didn't open this bug, I just was adding information.  I have Grandstream looking at it also, I will update you when they give me  more information.
By: Joshua C. Colp (jcolp) 2006-08-16 13:57:39

Ah, I got mixed up. I will await a reply from the original poster as well and we can go from there!
By: ajmahler (diver) 2006-08-16 14:08:37

Spoke too soon, its baaaaacccccckkkkk! :(
By: Jeff Siddall (jsiddall) 2006-08-16 15:07:09

I can attest to the intermittentness of the problem.  Sometimes everything will be good for an hour or two.

Also, from the SIP debug log I included in "Additional Information" above (sorry about the attach thing, but there were only three messages), you can see the SUBSCRIBE has the correct "Accept: application/dialog-info+xml" field, and then immediately (within the same second) a 200 OK reply and a NOTIFY from Asterisk with the content type "unknown".  Clearly not a phone issue.
By: Serge Vecher (serge-v) 2006-08-16 15:18:40

Maybe these lines have something to do with it.
Jul 19 11:54:04 DEBUG[18606] chan_sip.c: Got a re-subscribe on existing
subscription 9f7a88cff8da06f1@192.168.3.46
Jul 19 11:54:04 DEBUG[18606] chan_sip.c: Adding subscription for
extension 14 context outgoing-unrestricted for peer user

Jsiddall: we still need to see a full debug, not just a snippet.
By: Jeff Siddall (jsiddall) 2006-08-16 15:35:12

Yeah, I'll work on the debug log, but this is a production system so it'll have to be after hours sometime.  I'll see if I can do it tonight.

The evidence does seem to indicate that the problem happens after a re-subscribe of a previously successful subscription.  IIRC the phones do this every hour by default.
By: ajmahler (diver) 2006-08-18 07:59:55

I was doing testing on this phone and discovered the cat5 patch cord was bad from the phone to the wall jack.  Replacing the cable made the problem go away.
By: Serge Vecher (serge-v) 2006-09-06 11:59:30

jsidall: gentle reminder on those logs
By: Jeff Siddall (jsiddall) 2006-09-06 13:48:15

Sorry, grabbing the logs got put on the back burner.  Attached is a log which includes a REGISTER followed by a bunch of SUBSCRIBE and NOTIFYs.  This is actually a re-register and re-subscribes as this user has been logged in for a long time and nothing has been changed recently.
By: Olle Johansson (oej) 2006-10-25 14:18:20

Think I fixed this in svn trunk 1.4. Need to check 1.2 too.
Rev 46252 - can you please try this version?
By: Olle Johansson (oej) 2006-10-25 14:28:06

Added a new debug line to chan_sip.c in 1.2. Can you please test with latest svn in the 1.2 branch and capture the output? I don't see the same problem in the 1.2 code base as I found in 1.4.
By: Jeff Siddall (jsiddall) 2006-10-27 23:24:44

I installed the latest 1.2 branch SVN tonight and am waiting for the problem to occur.  I'll upload the logs if/when it does.
By: Olle Johansson (oej) 2006-10-28 10:35:30

Thanks for helping, waiting for results... :-)
By: Jeff Siddall (jsiddall) 2006-10-28 14:12:47

Good news/bad news: it still happens.  Hopefully the attached snip from the debug log full-1.2SVN will help pinpoint the problem.


By: Jeff Siddall (jsiddall) 2006-10-28 14:56:44

I did some more looking through the logs to try to find the last successful NOTIFY, and found something that looked strange to me.  I attached the logs for this as full-1.2SVN-2.  Keep in mind I did a sip debug ip 192.168.3.45 (the subscriber I picked to monitor) to keep the SIP debugging to a dull roar so there is no sip debug for other subscribers.

Not exactly sure why but the state of the subscriber I was monitoring goes state 5 (Unavailable) in line 2, but then two NOTIFYs go out in rapid succession (within a second).  Look at line 6, then 96.  Line 96 and onward all have invalid content type.

Not sure if anyone can make sense of all this, but since it seems odd I thought I'd throw it in.


By: Olle Johansson (oej) 2006-10-29 12:56:48.000-0600

Finally found the bug. Thanks for following up! Please test the latest 1.2 from subversion.

The phone obviously does not re-subscribe in time, so the subscription expires.
By: Olle Johansson (oej) 2006-10-29 12:57:25.000-0600

Please re-open if the issue remains.
By: Olle Johansson (oej) 2006-10-29 13:04:23.000-0600

Fix committed to 1.2 rev 46402
By: Olle Johansson (oej) 2006-10-29 13:16:52.000-0600

Asterisk 1.4, rev 46403, svn trunk rev 46405
By: Jeff Siddall (jsiddall) 2006-10-30 19:45:07.000-0600

D'oooh,.. still getting 415's.  I re-enabled debug logging and will attach updated logs once I have them.  Show version says:

Asterisk SVN-branch-1.2-r46406


By: Jeff Siddall (jsiddall) 2006-10-30 19:55:30.000-0600

I attached logs as full-SVN-branch-1.2-r46406.  Not sure that this shows anything new though, so let me know if you want me to watch for something specific.
By: Olle Johansson (oej) 2006-10-31 02:25:38.000-0600

Hmm. At least this is a different message. I need you to capture what goes on before the bad message too, at least one successful NOTIFY before the bad one - that's what caught my eye on the other issue.

Thanks.
By: Jeff Siddall (jsiddall) 2006-10-31 11:15:39.000-0600

I attached an "interesting" bit of log as full-SVN-branch-1.2-r46406-2.  In this snip the monitored user (192.168.3.45) hangs up a call to another user, then gets a successful NOTIFY in line 84, followed by unsuccessful ones in lines 116, 142, and 184.  Let me know if that helps.
By: Olle Johansson (oej) 2006-11-12 14:02:44.000-0600

From reading the source this is impossible. Guess I have to read again... :-)
By: Jeff Siddall (jsiddall) 2006-11-19 20:47:31.000-0600

Anything else I can do to help get this resolved?  If you know what is triggering this bug I will also ask Grandstream to fix the problem.
By: Olle Johansson (oej) 2007-02-14 10:55:33.000-0600

This bug still boggles my mind.
By: John Coleman (ninthclowd) 2007-03-07 16:51:58.000-0600

Any word on whether or not this is a Grandstream issue?
By: Olle Johansson (oej) 2007-05-16 03:54:39

Let's take this bull by the horns. First, I need to know if the problem exists in the latest asterisk versions?
By: Michel Belleau (malaiwah) 2007-05-24 11:17:37

I'm on Asterisk 1.2.17, Gentoo distro and I have Grandstream GXP-2000 phones that do the same trick mentionned here every once in a while, as this is a production environnement I'll try to get some logs outside usage hours:

May 24 11:09:19 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
May 24 11:09:19 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
May 24 11:09:19 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
May 24 11:09:19 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
May 24 11:09:19 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
May 24 11:09:19 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
May 24 11:09:20 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
May 24 11:09:20 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
May 24 11:09:27 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
May 24 11:09:27 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
May 24 11:32:12 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
May 24 11:32:55 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
May 24 11:37:32 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
May 24 12:07:12 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
May 24 12:09:48 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
May 24 12:09:48 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
May 24 12:09:49 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
May 24 12:09:49 VERBOSE[4118] logger.c:     -- Incoming call: Got SIP response 415 "Unacceptable Content-Type" back from 70.82.177.77
By: Wolfgang Liegel (wliegel) 2007-05-25 04:56:32

I have this problem with Asterisk Version 1.2.18

You can solve this problem temporarly by rebooting all GXP2000 Phones.

You can solve this problem permanently by upgrading to 1.1.2.23 or later.
According to http://www.voip-info.org/wiki/view/GXP-2000 this issue is fixed in GXP-2000 Firmware 1.1.2.23
> Fixed we send 415 response for NOTIFY when no Content-Type header is present
By: Joshua C. Colp (jcolp) 2007-06-27 18:33:33

Since this seems to have been a Grandstream issue I'm closing this out... everyone update their firmware!