[Home]

Summary:ASTERISK-11778: Asterisk crash and receive lot of 'Bad request protocol' error
Reporter:Joel Vandal (jvandal)Labels:
Date Opened:2008-04-03 11:55:02Date Closed:2008-04-30 12:00:58
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) gdb.txt
( 1) valgrind.txt
Description:Hi,

I have a server that have been updated to Asterisk 1.4.19 and since yesterday, it crashed about each hour.

Not sure if this can be related, but I see this warning on CLI, not sure if this can be related, but 1st time I see this, using a Mediatrix 2102 ATA.

[Apr  3 12:55:03] WARNING[7832]: chan_sip.c:6772 determine_firstline_parts: Bad request protocol Method Not Allowed
[Apr  3 12:56:35] WARNING[7832]: chan_sip.c:6772 determine_firstline_parts: Bad request protocol OK
[Apr  3 12:56:35] WARNING[7832]: chan_sip.c:6772 determine_firstline_parts: Bad request protocol OK


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

(gdb) bt
#0  0x0052a97b in strlen () from /lib/tls/libc.so.6
#1  0x004fe731 in vfprintf () from /lib/tls/libc.so.6
#2  0x0051bf86 in vsnprintf () from /lib/tls/libc.so.6
#3  0x0810670c in ast_dynamic_str_thread_build_va ()
#4  0x080b9b21 in ast_log ()
ASTERISK-1  0x002bce00 in __sip_destroy (p=0xb78d9b30, lockowner=1) at chan_sip.c:3161
ASTERISK-2  0x002bde28 in sip_destroy (p=0xb78d9b30) at chan_sip.c:3315
ASTERISK-3  0x002f58b6 in sip_poke_noanswer (data=0x96698a8) at chan_sip.c:15793
ASTERISK-4  0x080f59b7 in ast_sched_runq ()
ASTERISK-5  0x002f534c in do_monitor (data=0x0) at chan_sip.c:15718
ASTERISK-6 0x08105a04 in dummy_start ()
ASTERISK-7 0x006613cc in start_thread () from /lib/tls/libpthread.so.0
ASTERISK-8 0x0058a1ae in clone () from /lib/tls/libc.so.6

Will post full gdb output (bt full, thread apply all bt)
Comments:By: Mark Michelson (mmichelson) 2008-04-03 13:21:04

Regarding the "Bad request protocol" messages, what this means is that chan_sip thinks that the first line of the SIP request sent does not contain the string "SIP/2.0" after the request type.

What seems odd from the output you have given is that it appears that chan_sip thinks that it has received a request when it has actually received a response. Those "OK's" are most likely part of a "200 OK" response. A SIP debug of the packets that cause the problem would be helpful in determining why this is happening.

As for the crash, I would suggest that p->callid is NULL, but this is unlikely since stringfield parameters should never be NULL. Instead, I would bet that this is an issue of memory corruption. The best way to fix such issues is to run Asterisk under valgrind as described in doc/valgrind.txt
By: Joel Vandal (jvandal) 2008-04-22 08:14:35

Please note that I'm unable to reproduce this problem on others server, only on a specific customer, at random interval (ex. worked ok since last 5 days but yesterday it crashed each 30 minutes)...

We run valgrind this morning to try to capture some data, but server has been very very slow and 'unusable' so we stopped valgrind, have some 'write' error, hope this can help.
By: Mark Michelson (mmichelson) 2008-04-22 17:43:43

Thanks very much for the valgrind output on this. What was the svn revision being used on this system when the valgrind output was taken? The line numbers from the valgrind output don't appear to line up properly with 1.4.19 or the latest 1.4 SVN.
By: Joel Vandal (jvandal) 2008-04-25 08:19:17

Hi,

If I look on chan_sip.c, the revision is 113348 but we use a ~23 line patch for a custom application (custom CoutactRoute INFO Message) but I'm sure that this patch is unrelated to the crash.

I have copy the chan_sip.c to :

http://www.scopserv.com/private/chan_sip.c


Now, if I check on this file, I think line match with valgrind.

By example :

3079 :  if (p->rtp && ast_rtp_get_bridged(p->rtp)) {
3084 :         if (p->vrtp && ast_rtp_get_bridged(p->vrtp)) {
3092 :       if (ast_test_flag(&p->flags[0], SIP_INC_COUNT) || ast_test_flag(&p->flags[1], SIP_PAGE2_CALL_ONHOLD)) {

3099 :      if (p->owner) {

3114 :     if (p->relatedpeer && p->relatedpeer->mwipvt)

3120 :     if (p->options)
3123 :  if (p->stateid > -1)
3125 : AST_SCHED_DEL(sched, p->initid);
3126 : AST_SCHED_DEL(sched, p->waitid);
3127 : AST_SCHED_DEL(sched, p->autokillid);
3129 :  if (p->rtp) {
....
3322 : __sip_destroy(p, 1);
By: Joel Vandal (jvandal) 2008-04-25 08:22:40

About corrupted packet, the server will start crash in 1-2 hours after receive some corrupt packet like :

#
U 192.111.226.42:5060 -> 172.16.186.49:5060
NOTIFY sip:t8885555583@172.16.186.49:5060 SIP/2.0.
Via: SIP/2.0/UDP 192.111.226.42:5060;branch=z9hG4bK4c6b082f;rport.
From: "asterisk" <sip:asterisk@192.111.226.42>;tag=as2a2e0574.
To: <sip:t8885555583@172.16.186.49:5060>.
Contact: <sip:asterisk@192.111.226.42>.
Call-ID: 088aaa476d295a7245440d90181c8942@192.111.226.42.
CSeq: 102 NOTIFY.
User-Agent: Asterisk PBX.
Max-Forwards: 70.
Event: message-summary.
Content-Type: application/simple-message-summary.
Content-Length: 96.
.
Messages-Waiting: yes.
Message-Account: sip:asterisk@192.111.226.42.
Voice-Message: 10/6 (0/0).

#
U 172.16.186.49:5060 -> 192.111.226.42:5060
SI5004P/2.0 200 OK.
Call-ID: 088aaa476d295a7245440d90181c8942@192.111.226.42.
CSeq: 102 NOTIFY.
From: "asterisk" <sip:asterisk@192.111.226.42>;tag=as2a2e0574.
To: <sip:t8885555583@172.16.186.49:5060>;tag=ba02a167407dad8.
Via: SIP/2.0/UDP 192.111.226.42:5060;branch=z9hG4bK4c6b082f;rport.
Content-Length: 4.
User-Agent: MxSipApp/5.0.23.141 MxSF/v3.2.2.4.
.


On valgrind output, some line on chan_sip.c refer to MWI, this can also be related ?
By: Olle Johansson (oej) 2008-04-30 10:56:20

Ok, we should drop the reply you have there since it's not valid. However, unfortunately the parse_request function doesn't check the result of determine_firstline_parts, so that's incorrect.

putnopvut and I have agreed on a fix that will be committed today to 1.4, 1.6 and trunk.
By: Digium Subversion (svnbot) 2008-04-30 11:17:42

Repository: asterisk
Revision: 114890

U   branches/1.4/channels/chan_sip.c

------------------------------------------------------------------------
r114890 | oej | 2008-04-30 11:17:41 -0500 (Wed, 30 Apr 2008) | 7 lines

Don't crash on bad SIP replys.
Fix created in Huntsville together with Mark M (putnopvut)

(closes issue ASTERISK-11778)
Reported by: jvandal
Tested by: putnopvut, oej

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=114890
By: Digium Subversion (svnbot) 2008-04-30 11:50:19

Repository: asterisk
Revision: 114899

_U  trunk/
U   trunk/channels/chan_sip.c

------------------------------------------------------------------------
r114899 | oej | 2008-04-30 11:50:18 -0500 (Wed, 30 Apr 2008) | 15 lines

Merged revisions 114890 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
r114890 | oej | 2008-04-30 18:23:17 +0200 (Ons, 30 Apr 2008) | 7 lines

Don't crash on bad SIP replys.
Fix created in Huntsville together with Mark M (putnopvut)

(closes issue ASTERISK-11778)
Reported by: jvandal
Tested by: putnopvut, oej

........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=114899
By: Digium Subversion (svnbot) 2008-04-30 12:00:58

Repository: asterisk
Revision: 114900

_U  branches/1.6.0/
U   branches/1.6.0/channels/chan_sip.c

------------------------------------------------------------------------
r114900 | oej | 2008-04-30 12:00:56 -0500 (Wed, 30 Apr 2008) | 23 lines

Merged revisions 114899 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
r114899 | oej | 2008-04-30 18:55:49 +0200 (Ons, 30 Apr 2008) | 15 lines

Merged revisions 114890 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
r114890 | oej | 2008-04-30 18:23:17 +0200 (Ons, 30 Apr 2008) | 7 lines

Don't crash on bad SIP replys.
Fix created in Huntsville together with Mark M (putnopvut)

(closes issue ASTERISK-11778)
Reported by: jvandal
Tested by: putnopvut, oej

........

................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=114900