[Home]

Summary:ASTERISK-16500: [patch] Missing semicolon in SIP-Notify
Reporter:Sebastian Denz (denzs)Labels:
Date Opened:2010-08-04 04:01:36Date Closed:2010-08-27 15:32:20
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/Subscriptions
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 17790-chunky.diff
( 1) ast_full.log
( 2) bug_17790.pcap
( 3) r283495_asterisk_-c_with_verbose_and_debug_in_cli.conf.log
Description:I see a lots of messages like this in the CLI...

It seems like there is a semicolon missing?

NOTIFY sip:1686@192.168.51.201:5060user=phone
shouldn it be
NOTIFY sip:1686@192.168.51.201:5060;user=phone


Sending to 192.168.51.201:5060 (no NAT)
[Aug  4 11:29:07] ERROR[486]: netsock2.c:245 ast_sockaddr_resolve: getaddrinfo("192.168.51.201", "5060user=phone", ...): Servname not supported for ai_socktype
[Aug  4 11:29:07] WARNING[486]: chan_sip.c:12820 __set_address_from_contact: Invalid host name in Contact: (can't resolve in DNS) : '192.168.51.201:5060user=phone'
Scheduling destruction of SIP dialog '66e9b8d9258832ce00d06b607e0243e3@192.168.51.123:5060' in 32000 ms (Method: NOTIFY)
Reliably Transmitting (no NAT) to 192.168.51.201:5060:
NOTIFY sip:1686@192.168.51.201:5060user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.51.123:5060;branch=z9hG4bK08321305
Max-Forwards: 70
From: "asterisk" <sip:asterisk@192.168.51.123>;tag=as59f03aba
To: <sip:1686@192.168.51.201:5060user=phone>
Contact: <sip:asterisk@192.168.51.123:5060>
Call-ID: 66e9b8d9258832ce00d06b607e0243e3@192.168.51.123:5060
CSeq: 102 NOTIFY
User-Agent: Asterisk PBX SVN-trunk-r280810
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 99

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

---

<--- Transmitting (no NAT) to 192.168.51.201:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.51.201:5060;branch=z9hG4bK1523223228;received=192.168.51.201;rport=5060
From: <sip:1686@poc.lvmtest.ar.intranet.gonicus.de;user=phone>;tag=766983564
To: <sip:1686@poc.lvmtest.ar.intranet.gonicus.de;user=phone>;tag=as5a5cd7fd
Call-ID: 117896864-5060-1@192.168.51.201
CSeq: 4420 REGISTER
Server: Asterisk PBX SVN-trunk-r280810
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Expires: 300
Contact: <sip:1686@192.168.51.201:5060;user=phone>;expires=300
Date: Wed, 04 Aug 2010 09:29:07 GMT
Content-Length: 0


<------------>
Scheduling destruction of SIP dialog '117896864-5060-1@192.168.51.201' in 32000 ms (Method: REGISTER)
[Aug  4 11:29:07] ERROR[459]: netsock2.c:245 ast_sockaddr_resolve: getaddrinfo("192.168.51.201", "5060user=phone", ...): Servname not supported for ai_socktype
[Aug  4 11:29:07] WARNING[459]: chan_sip.c:12820 __set_address_from_contact: Invalid host name in Contact: (can't resolve in DNS) : '192.168.51.201:5060user=phone'
Retransmitting #1 (no NAT) to 192.168.51.201:5060:
NOTIFY sip:1686@192.168.51.201:5060user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.51.123:5060;branch=z9hG4bK074f9545
Max-Forwards: 70
From: "asterisk" <sip:asterisk@192.168.51.123>;tag=as626d156f
To: <sip:1686@192.168.51.201:5060user=phone>
Contact: <sip:asterisk@192.168.51.123:5060>
Call-ID: 5c08a9c229b34d5a23e3183c58953d48@192.168.51.123:5060
CSeq: 102 NOTIFY
User-Agent: Asterisk PBX SVN-trunk-r280810
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 99

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

---
Retransmitting #1 (no NAT) to 192.168.51.201:5060:
NOTIFY sip:1686@192.168.51.201:5060user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.51.123:5060;branch=z9hG4bK08321305
Max-Forwards: 70
From: "asterisk" <sip:asterisk@192.168.51.123>;tag=as59f03aba
To: <sip:1686@192.168.51.201:5060user=phone>
Contact: <sip:asterisk@192.168.51.123:5060>
Call-ID: 66e9b8d9258832ce00d06b607e0243e3@192.168.51.123:5060
CSeq: 102 NOTIFY
User-Agent: Asterisk PBX SVN-trunk-r280810
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 99

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

Comments:By: Paul Belanger (pabelanger) 2010-08-04 09:51:56

Going to see if I can track this down.  Mind providing a full debug log?
---
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: Markus Lindenberg (mli) 2010-08-09 08:14:43

It's not visible from the log denz provided that there's a different character in place of the ';' visible in the asterisk console. Copy&Paste of console output to vim suggests it's a ^C (i guess that's a ASCII #3 ETX?).

I guess the given SIP URI is not parsed correctly. If you look at chan_sip.c, in __set_address_from_contact there's a call to parse_uri, which somehow puts "5060^Cuser=phone" in the domain variable.

[Aug  6 11:43:40] ERROR[10364]: netsock2.c:245 ast_sockaddr_resolve: getaddrinfo("192.168.51.200", "5060^Cuser=phone", ...): Servname not supported for ai_socktype
[Aug  6 11:43:40] WARNING[10364]: chan_sip.c:12820 __set_address_from_contact: Invalid host name in Contact: (can't resolve in DNS) : '192.168.51.200:5060^Cuser=phone'
By: David Vossel (dvossel) 2010-08-09 12:45:46

I'm confused, Is Asterisk generating the malformed URI (without the ';' after the port for the parameters) or is this something Asterisk is receiving?  Can you provide a packet trace please.
By: Jason Parker (jparker) 2010-08-23 13:58:28

Would it be possible to start asterisk under the `script` command, reproduce this issue, and attach the log file it creates here?

Can you also confirm that you still see this in the latest revision?
By: Sebastian Denz (denzs) 2010-08-25 09:50:18

In ast_full.log you can see a snippet from the full log which should provide some debug information.
first i thought the problem would occur after registration of a peer,
but during a test it occured after restarting the asterisk while the appropriate phone was offline.

right now iam checkin out the latest trunk and will do some further tests...
By: Sebastian Denz (denzs) 2010-08-25 10:25:28

Tested with latest svn revision 283495:

In r283495_asterisk_-c_with_verbose_and_debug_in_cli.conf.log you can see the output from "asterisk -c" with
---
sip set debug on = yes
core set verbose 15 = yes
core set debug 15 = yes
---
in cli.conf
but that doesnt seem to be so relevant for this?!

Can it be something with the saved ipaddr in the realtime mysql table or is there any other location where the ipaddr is cached?!
I think asterisk should be aware of the IP after restart while the corresponding device is offline istn it?


By: Jason Parker (jparker) 2010-08-25 10:38:58

It could very well be a realtime issue.  Would it be possible to check the contents of the fullcontact field in your realtime table, immediately after this error occurs?
By: Sebastian Denz (denzs) 2010-08-25 10:45:47

mysql> select fullcontact from ast_sipfriends_gs where ipaddr like "192%";
+----------------------------------------------+
| fullcontact                                  |
+----------------------------------------------+
| sip:1683@192.168.51.224:5060^3Btransport=udp |
+----------------------------------------------+
1 row in set (0.01 sec)

mysql> describe ast_sipfriends_gs;
+------------------+------------------------------+------+-----+---------------------+-------+
| Field            | Type                         | Null | Key | Default             | Extra |
+------------------+------------------------------+------+-----+---------------------+-------+
| _user_id         | int(10) unsigned             | NO   |     | 0                   |       |
| name             | varchar(30)                  | NO   |     |                     |       |
| secret           | varchar(20)                  | NO   |     | 1234                |       |
| type             | enum('friend','user','peer') | NO   |     | friend              |       |
| host             | varchar(50)                  | NO   |     | dynamic             |       |
| defaultip        | varchar(15)                  | YES  |     | NULL                |       |
| context          | varchar(50)                  | NO   |     | from-internal-users |       |
| callerid         | varchar(80)                  | NO   |     |                     |       |
| mailbox          | varchar(25)                  | NO   |     |                     |       |
| callgroup        | varchar(20)                  | NO   |     | 1                   |       |
| pickupgroup      | varchar(20)                  | NO   |     | 1                   |       |
| setvar           | varchar(50)                  | NO   |     |                     |       |
| call-limit       | tinyint(3) unsigned          | NO   |     | 20                  |       |
| subscribecontext | varchar(50)                  | NO   |     | default             |       |
| regcontext       | varchar(50)                  | YES  |     | NULL                |       |
| ipaddr           | varchar(15)                  | YES  |     | NULL                |       |
| port             | varchar(5)                   | YES  |     | NULL                |       |
| regseconds       | int(11)                      | NO   |     | 0                   |       |
| username         | varchar(25)                  | YES  |     | NULL                |       |
| regserver        | varchar(50)                  | YES  |     | NULL                |       |
| fullcontact      | varchar(100)                 | YES  |     | NULL                |       |
| canreinvite      | char(8)                      | NO   |     | no                  |       |
| nat              | char(8)                      | NO   |     | no                  |       |
| lastms           | int(11)                      | NO   |     | 0                   |       |
| defaultuser      | varchar(80)                  | NO   |     |                     |       |
| useragent        | varchar(20)                  | YES  |     | NULL                |       |
+------------------+------------------------------+------+-----+---------------------+-------+
26 rows in set (0.02 sec)

mysql>

let me know what i can do to help track this down :)


By: Sebastian Denz (denzs) 2010-08-25 10:56:08

update ast_sipfriends_gs set fullcontact='' where name=1683; (which is the relevant peer)
restarted asterisk
connected phone to network
phone has registered on asterisk
mysql> select fullcontact from ast_sipfriends_gs where ipaddr like "192%";
+----------------------------------------------+
| fullcontact                                  |
+----------------------------------------------+
| sip:1683@192.168.51.224:5060^3Btransport=udp |
+----------------------------------------------+
1 row in set (0.00 sec)

mysql>

still with "^3B" in fullcontact

see pcap trace of SIP Register as attachment
By: Sebastian Denz (denzs) 2010-08-25 11:42:00

Asterisk sends the wrong formated URI even in SIP-Notify.

See byte 0x115 which is 0x03 instead of 0x3B (;)

wireshark hexdump (Notify from asterisk to phone):

0000   00 1a e8 0c 06 12 00 16 3e 55 b7 b7 08 00 45 00  ........>U....E.
0010   02 84 11 f2 00 00 40 11 7d cb c0 a8 33 7b c0 a8  ......@.}...3{..
0020   33 e0 13 c4 13 c4 02 70 46 5b 4e 4f 54 49 46 59  3......pF[NOTIFY
0030   20 73 69 70 3a 31 36 38 33 40 31 39 32 2e 31 36   sip:1683@192.16
0040   38 2e 35 31 2e 32 32 34 3a 35 30 36 30 03 74 72  8.51.224:5060.tr
0050   61 6e 73 70 6f 72 74 3d 75 64 70 20 53 49 50 2f  ansport=udp SIP/
0060   32 2e 30 0d 0a 56 69 61 3a 20 53 49 50 2f 32 2e  2.0..Via: SIP/2.
0070   30 2f 55 44 50 20 31 39 32 2e 31 36 38 2e 35 31  0/UDP 192.168.51
0080   2e 31 32 33 3a 35 30 36 30 3b 62 72 61 6e 63 68  .123:5060;branch
0090   3d 7a 39 68 47 34 62 4b 35 61 39 35 37 62 39 38  =z9hG4bK5a957b98
00a0   0d 0a 4d 61 78 2d 46 6f 72 77 61 72 64 73 3a 20  ..Max-Forwards:
00b0   37 30 0d 0a 46 72 6f 6d 3a 20 22 61 73 74 65 72  70..From: "aster
00c0   69 73 6b 22 20 3c 73 69 70 3a 61 73 74 65 72 69  isk" <sip:asteri
00d0   73 6b 40 31 39 32 2e 31 36 38 2e 35 31 2e 31 32  sk@192.168.51.12
00e0   33 3e 3b 74 61 67 3d 61 73 36 61 33 63 36 61 66  3>;tag=as6a3c6af
00f0   39 0d 0a 54 6f 3a 20 3c 73 69 70 3a 31 36 38 33  9..To: <sip:1683
0100   40 31 39 32 2e 31 36 38 2e 35 31 2e 32 32 34 3a  @192.168.51.224:
0110   35 30 36 30 03 74 72 61 6e 73 70 6f 72 74 3d 75  5060.transport=u
0120   64 70 3e 0d 0a 43 6f 6e 74 61 63 74 3a 20 3c 73  dp>..Contact: <s
0130   69 70 3a 61 73 74 65 72 69 73 6b 40 31 39 32 2e  ip:asterisk@192.
0140   31 36 38 2e 35 31 2e 31 32 33 3a 35 30 36 30 3e  168.51.123:5060>
0150   0d 0a 43 61 6c 6c 2d 49 44 3a 20 35 38 30 34 65  ..Call-ID: 5804e
0160   61 64 61 30 37 38 63 64 30 34 36 33 37 66 66 36  ada078cd04637ff6
0170   32 36 65 32 35 35 62 39 33 38 32 40 31 39 32 2e  26e255b9382@192.
0180   31 36 38 2e 35 31 2e 31 32 33 3a 35 30 36 30 0d  168.51.123:5060.
0190   0a 43 53 65 71 3a 20 31 30 32 20 4e 4f 54 49 46  .CSeq: 102 NOTIF
01a0   59 0d 0a 55 73 65 72 2d 41 67 65 6e 74 3a 20 41  Y..User-Agent: A
01b0   73 74 65 72 69 73 6b 20 50 42 58 20 53 56 4e 2d  sterisk PBX SVN-
01c0   74 72 75 6e 6b 2d 72 32 38 33 34 39 35 0d 0a 45  trunk-r283495..E
01d0   76 65 6e 74 3a 20 6d 65 73 73 61 67 65 2d 73 75  vent: message-su
01e0   6d 6d 61 72 79 0d 0a 43 6f 6e 74 65 6e 74 2d 54  mmary..Content-T
01f0   79 70 65 3a 20 61 70 70 6c 69 63 61 74 69 6f 6e  ype: application
0200   2f 73 69 6d 70 6c 65 2d 6d 65 73 73 61 67 65 2d  /simple-message-
0210   73 75 6d 6d 61 72 79 0d 0a 43 6f 6e 74 65 6e 74  summary..Content
0220   2d 4c 65 6e 67 74 68 3a 20 39 39 0d 0a 0d 0a 4d  -Length: 99....M
0230   65 73 73 61 67 65 73 2d 57 61 69 74 69 6e 67 3a  essages-Waiting:
0240   20 6e 6f 0d 0a 4d 65 73 73 61 67 65 2d 41 63 63   no..Message-Acc
0250   6f 75 6e 74 3a 20 73 69 70 3a 61 73 74 65 72 69  ount: sip:asteri
0260   73 6b 40 31 39 32 2e 31 36 38 2e 35 31 2e 31 32  sk@192.168.51.12
0270   33 3a 35 30 36 30 0d 0a 56 6f 69 63 65 2d 4d 65  3:5060..Voice-Me
0280   73 73 61 67 65 3a 20 30 2f 30 20 28 30 2f 30 29  ssage: 0/0 (0/0)
0290   0d 0a                                            ..
By: Jason Parker (jparker) 2010-08-25 11:57:46

Just added a patch which should resolve this.  I believe the problem was how fields are retrieved from the database when they contain a semicolon (or, really, as you've discovered, an "escaped" semicolon).
By: Sebastian Denz (denzs) 2010-08-26 02:51:55

cd /usr/src/asterisk
wget 'https://issues.asterisk.org/file_download.php?file_id=27129&type=bug' -O - | patch -p0
make clean
make
make install
killall asterisk
mysql> update ast_sipfriends_gs set fullcontact='' ...
asterisk -c
plugged in phone

mysql> select fullcontact from ast_sipfriends_gs where ipaddr like "192%";
+----------------------------------------------+                                                                                                            
| fullcontact                                  |                                                                                                            
+----------------------------------------------+                                                                                                            
| sip:1683@192.168.51.224:5060^3Btransport=udp |                                                                                                            
| sip:1684@192.168.51.200:5062^3Buser=phone    |                                                                                                            
| sip:1686@192.168.51.201:5062^3Buser=phone    |                                                                                                            
+----------------------------------------------+

*CLI> core stop now
asterisk -c

pluggend phone on again
Now there are no more messages in the cli from netsock and there are no more notify pakets with the wrong character.

but in the mysql table there is still the "^3B" ?!
for me it is working but iam not sure if the database values are correct?

maybe it should be fixed when the values are written to the db and not when they are read?


By: Digium Subversion (svnbot) 2010-08-27 15:29:09

Repository: asterisk
Revision: 283880

U   branches/1.4/res/res_config_odbc.c
U   branches/1.4/res/res_config_pgsql.c

------------------------------------------------------------------------
r283880 | qwell | 2010-08-27 15:29:09 -0500 (Fri, 27 Aug 2010) | 8 lines

Fix issue with decoding ^-escaped characters in realtime.

(closes issue ASTERISK-16500)
Reported by: denzs
Patches:
     17790-chunky.diff uploaded by qwell (license 4)
Tested by: qwell, denzs

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

http://svn.digium.com/view/asterisk?view=rev&revision=283880
By: Digium Subversion (svnbot) 2010-08-27 15:30:25

Repository: asterisk
Revision: 283881

_U  branches/1.6.2/
U   branches/1.6.2/res/res_config_odbc.c
U   branches/1.6.2/res/res_config_pgsql.c

------------------------------------------------------------------------
r283881 | qwell | 2010-08-27 15:30:25 -0500 (Fri, 27 Aug 2010) | 15 lines

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

........
 r283880 | qwell | 2010-08-27 15:29:11 -0500 (Fri, 27 Aug 2010) | 8 lines
 
 Fix issue with decoding ^-escaped characters in realtime.
 
 (closes issue ASTERISK-16500)
 Reported by: denzs
 Patches:
       17790-chunky.diff uploaded by qwell (license 4)
 Tested by: qwell, denzs
........

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

http://svn.digium.com/view/asterisk?view=rev&revision=283881
By: Digium Subversion (svnbot) 2010-08-27 15:31:53

Repository: asterisk
Revision: 283882

_U  branches/1.8/
U   branches/1.8/addons/res_config_mysql.c
U   branches/1.8/main/config.c
U   branches/1.8/res/res_config_odbc.c

------------------------------------------------------------------------
r283882 | qwell | 2010-08-27 15:31:53 -0500 (Fri, 27 Aug 2010) | 22 lines

Merged revisions 283881 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.6.2

................
 r283881 | qwell | 2010-08-27 15:30:27 -0500 (Fri, 27 Aug 2010) | 15 lines
 
 Merged revisions 283880 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r283880 | qwell | 2010-08-27 15:29:11 -0500 (Fri, 27 Aug 2010) | 8 lines
   
   Fix issue with decoding ^-escaped characters in realtime.
   
   (closes issue ASTERISK-16500)
   Reported by: denzs
   Patches:
         17790-chunky.diff uploaded by qwell (license 4)
   Tested by: qwell, denzs
 ........
................

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

http://svn.digium.com/view/asterisk?view=rev&revision=283882
By: Digium Subversion (svnbot) 2010-08-27 15:32:19

Repository: asterisk
Revision: 283883

_U  trunk/
U   trunk/addons/res_config_mysql.c
U   trunk/main/config.c
U   trunk/res/res_config_odbc.c

------------------------------------------------------------------------
r283883 | qwell | 2010-08-27 15:32:19 -0500 (Fri, 27 Aug 2010) | 29 lines

Merged revisions 283882 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.8

................
 r283882 | qwell | 2010-08-27 15:31:55 -0500 (Fri, 27 Aug 2010) | 22 lines
 
 Merged revisions 283881 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.6.2
 
 ................
   r283881 | qwell | 2010-08-27 15:30:27 -0500 (Fri, 27 Aug 2010) | 15 lines
   
   Merged revisions 283880 via svnmerge from
   https://origsvn.digium.com/svn/asterisk/branches/1.4
   
   ........
     r283880 | qwell | 2010-08-27 15:29:11 -0500 (Fri, 27 Aug 2010) | 8 lines
     
     Fix issue with decoding ^-escaped characters in realtime.
     
     (closes issue ASTERISK-16500)
     Reported by: denzs
     Patches:
           17790-chunky.diff uploaded by qwell (license 4)
     Tested by: qwell, denzs
   ........
 ................
................

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

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