[sr-dev] presence notify packet garbage with latest 4.0
Juha Heinanen
jh at tutpro.com
Mon Mar 11 04:03:36 CET 2013
i tested my presence server using the latest 4.0 branch and noticed that
some notify requests generated by presence server over tcp cannot be
interpreted by my sip proxy.
here is working example using version 4.0.0-pre1 when presence server is
sending notify request to sip proxy over tcp to port 5070:
Mar 11 04:06:15 sip /usr/sbin/pres-serv[6837]: INFO: Routing locally generated NOTIFY <sip:jh_test_fi at 192.98.102.10:5074;alias=192.98.102.10~46961~2;transport=tcp> to <sip:jh at test.fi> from <sip:jh at test.fi>
Mar 11 04:06:15 sip /usr/sbin/sip-proxy[6473]: INFO: Routing in-dialog NOTIFY <sip:jh_test_fi at 192.98.102.10:5074;transport=tcp> from <sip:jh at test.fi> to <sip:192.98.102.10:46961;transport=tcp>
No. Time Source Destination Protocol Info
242 04:06:15.847426 127.0.0.1 127.0.0.1 SIP Request: NOTIFY sip:jh_test_fi at 192.98.102.10:5074;alias=192.98.102.10~46961~2;transport=tcp
Frame 242 (707 bytes on wire, 707 bytes captured)
Linux cooked capture
Internet Protocol, Src: 127.0.0.1 (127.0.0.1), Dst: 127.0.0.1 (127.0.0.1)
Transmission Control Protocol, Src Port: 40580 (40580), Dst Port: vtsas (5070), Seq: 1, Ack: 1, Len: 639
Session Initiation Protocol
Request-Line: NOTIFY sip:jh_test_fi at 192.98.102.10:5074;alias=192.98.102.10~46961~2;transport=tcp SIP/2.0
Message Header
Via: SIP/2.0/TCP 127.0.0.1:5080;branch=z9hG4bK582b.bbb468a4000000000000000000000000.0
To: sip:jh at test.fi;tag=xohct
From: sip:jh at test.fi;tag=2c15998813993a5f2698a8693042e46f-d0d1
CSeq: 2 NOTIFY
Call-ID: kblivgathfumnxl at sip.test.fi
Route: <sip:127.0.0.1:5070;transport=tcp;r2=on;lr>, <sip:192.98.102.10;transport=tcp;r2=on;lr>
Content-Length: 0
User-Agent: OpenXg Presence/XCAP Server (4.0.0-pre1 (i386/linux))
Max-Forwards: 70
Event: message-summary
Contact: <sip:127.0.0.1:5080;transport=tcp>
Subscription-State: active;expires=900
0000 00 00 03 04 00 06 00 00 00 00 00 00 00 00 08 00 ................
0010 45 10 02 b3 e5 4d 40 00 40 06 54 e5 7f 00 00 01 E....M at .@.T.....
0020 7f 00 00 01 9e 84 13 ce 2b 73 81 d2 25 bd 9e 17 ........+s..%...
0030 80 18 02 01 00 a8 00 00 01 01 08 0a 00 3b 64 9e .............;d.
0040 00 3b 64 9d 4e 4f 54 49 46 59 20 73 69 70 3a 6a .;d.NOTIFY sip:j
0050 68 5f 74 65 73 74 5f 66 69 40 31 39 32 2e 39 38 h_test_fi at 192.98
0060 2e 31 30 32 2e 31 30 3a 35 30 37 34 3b 61 6c 69 .102.10:5074;ali
0070 61 73 3d 31 39 32 2e 39 38 2e 31 30 32 2e 31 30 as=192.98.102.10
0080 7e 34 36 39 36 31 7e 32 3b 74 72 61 6e 73 70 6f ~46961~2;transpo
0090 72 74 3d 74 63 70 20 53 49 50 2f 32 2e 30 0d 0a rt=tcp SIP/2.0..
00a0 56 69 61 3a 20 53 49 50 2f 32 2e 30 2f 54 43 50 Via: SIP/2.0/TCP
00b0 20 31 32 37 2e 30 2e 30 2e 31 3a 35 30 38 30 3b 127.0.0.1:5080;
00c0 62 72 61 6e 63 68 3d 7a 39 68 47 34 62 4b 35 38 branch=z9hG4bK58
00d0 32 62 2e 62 62 62 34 36 38 61 34 30 30 30 30 30 2b.bbb468a400000
00e0 30 30 30 30 30 30 30 30 30 30 30 30 30 30 30 30 0000000000000000
00f0 30 30 30 2e 30 0d 0a 54 6f 3a 20 73 69 70 3a 6a 000.0..To: sip:j
0100 68 40 74 65 73 74 2e 66 69 3b 74 61 67 3d 78 6f h at test.fi;tag=xo
0110 68 63 74 0d 0a 46 72 6f 6d 3a 20 73 69 70 3a 6a hct..From: sip:j
0120 68 40 74 65 73 74 2e 66 69 3b 74 61 67 3d 32 63 h at test.fi;tag=2c
0130 31 35 39 39 38 38 31 33 39 39 33 61 35 66 32 36 15998813993a5f26
0140 39 38 61 38 36 39 33 30 34 32 65 34 36 66 2d 64 98a8693042e46f-d
0150 30 64 31 0d 0a 43 53 65 71 3a 20 32 20 4e 4f 54 0d1..CSeq: 2 NOT
0160 49 46 59 0d 0a 43 61 6c 6c 2d 49 44 3a 20 6b 62 IFY..Call-ID: kb
0170 6c 69 76 67 61 74 68 66 75 6d 6e 78 6c 40 73 69 livgathfumnxl at si
0180 70 2e 74 65 73 74 2e 66 69 0d 0a 52 6f 75 74 65 p.test.fi..Route
0190 3a 20 3c 73 69 70 3a 31 32 37 2e 30 2e 30 2e 31 : <sip:127.0.0.1
01a0 3a 35 30 37 30 3b 74 72 61 6e 73 70 6f 72 74 3d :5070;transport=
01b0 74 63 70 3b 72 32 3d 6f 6e 3b 6c 72 3e 2c 20 3c tcp;r2=on;lr>, <
01c0 73 69 70 3a 31 39 32 2e 39 38 2e 31 30 32 2e 31 sip:192.98.102.1
01d0 30 3b 74 72 61 6e 73 70 6f 72 74 3d 74 63 70 3b 0;transport=tcp;
01e0 72 32 3d 6f 6e 3b 6c 72 3e 0d 0a 43 6f 6e 74 65 r2=on;lr>..Conte
01f0 6e 74 2d 4c 65 6e 67 74 68 3a 20 30 0d 0a 55 73 nt-Length: 0..Us
0200 65 72 2d 41 67 65 6e 74 3a 20 4f 70 65 6e 58 67 er-Agent: OpenXg
0210 20 50 72 65 73 65 6e 63 65 2f 58 43 41 50 20 53 Presence/XCAP S
0220 65 72 76 65 72 20 20 28 34 2e 30 2e 30 2d 70 72 erver (4.0.0-pr
0230 65 31 20 28 69 33 38 36 2f 6c 69 6e 75 78 29 29 e1 (i386/linux))
0240 0d 0a 4d 61 78 2d 46 6f 72 77 61 72 64 73 3a 20 ..Max-Forwards:
0250 37 30 0d 0a 45 76 65 6e 74 3a 20 6d 65 73 73 61 70..Event: messa
0260 67 65 2d 73 75 6d 6d 61 72 79 0d 0a 43 6f 6e 74 ge-summary..Cont
0270 61 63 74 3a 20 3c 73 69 70 3a 31 32 37 2e 30 2e act: <sip:127.0.
0280 30 2e 31 3a 35 30 38 30 3b 74 72 61 6e 73 70 6f 0.1:5080;transpo
0290 72 74 3d 74 63 70 3e 0d 0a 53 75 62 73 63 72 69 rt=tcp>..Subscri
02a0 70 74 69 6f 6e 2d 53 74 61 74 65 3a 20 61 63 74 ption-State: act
02b0 69 76 65 3b 65 78 70 69 72 65 73 3d 39 30 30 0d ive;expires=900.
02c0 0a 0d 0a ...
and here is failing example using version 4.0.0-rc1:
Mar 11 04:02:12 sip /usr/sbin/pres-serv[5879]: INFO: Routing locally generated NOTIFY <sip:jh_test_fi at 192.98.102.10:5074;alias=192.98.102.10~46955~2;transport=tcp> to <sip:jh at test.fi> from <sip:jh at test.fi>
Mar 11 04:02:12 sip /usr/sbin/sip-proxy[6463]: INFO: Routing in-dialog ##### here is $rm
Mar 11 04:02:12 sip /usr/sbin/sip-proxy[6463]: INFO: <core> [parser/parse_fline.c:145]: ERROR:parse_first_line: method not followed by SP
Mar 11 04:02:12 sip /usr/sbin/sip-proxy[6463]: INFO: <core> [parser/parse_fline.c:242]: ERROR:parse_first_line: bad message
Mar 11 04:02:12 sip /usr/sbin/sip-proxy[6463]: INFO: <core> [parser/parse_fline.c:90]: ERROR: parse_first_line: message too short: 7
Mar 11 04:02:12 sip /usr/sbin/sip-proxy[6463]: INFO: <core> [parser/parse_fline.c:242]: ERROR:parse_first_line: bad message
Mar 11 04:02:12 sip /usr/sbin/sip-proxy[6463]: ERROR: <core> [parser/msg_parser.c:705]: ERROR: parse_msg: message=<out#015#012#015#012>
Mar 11 04:02:12 sip /usr/sbin/sip-proxy[6463]: ERROR: <core> [receive.c:146]: ERROR: receive_msg: parse_msg failed
Frame 31 (724 bytes on wire, 724 bytes captured)
Linux cooked capture
Internet Protocol, Src: 127.0.0.1 (127.0.0.1), Dst: 127.0.0.1 (127.0.0.1)
Transmission Control Protocol, Src Port: 40567 (40567), Dst Port: vtsas (5070), Seq: 1, Ack: 1, Len: 656
Session Initiation Protocol
Request-Line: NOTIFY sip:jh_test_fi at 192.98.102.10:5074;alias=192.98.102.10~46955~2;transport=tcp SIP/2.0
Message Header
Via: SIP/2.0/TCP 127.0.0.1:5080;branch=z9hG4bK84cf.d6d935d2000000000000000000000000.0
To: sip:jh at test.fi;tag=zrrmw
From: sip:jh at test.fi;tag=2c15998813993a5f2698a8693042e46f-d351
CSeq: 2 NOTIFY
Call-ID: jcgampqtrnzphwb at sip.test.fi
Route: <sip:127.0.0.1:5070;transport=tcp;r2=on;lr>, <sip:192.98.102.10;transport=tcp;r2=on;lr>
Content-Length: 0
User-Agent: OpenXg Presence/XCAP Server (4.0.0-rc1 (i386/linux))
Max-Forwards: 70
Event: message-summary
Contact: <sip:127.0.0.1:5080;transport=tcp>
Subscription-State: active;expires=900
Data (656 bytes)
Data: 4E4F54494659207369703A6A685F746573745F6669403139...
[Length: 656]
0000 00 00 03 04 00 06 00 00 00 00 00 00 00 00 08 00 ................
0010 45 10 02 c4 6f 27 40 00 40 06 ca fa 7f 00 00 01 E...o'@. at .......
0020 7f 00 00 01 9e 77 13 ce 1f 95 60 1b 27 89 f5 cc .....w....`.'...
0030 80 18 02 55 00 b9 00 00 01 01 08 0a 00 3a 76 a3 ...U.........:v.
0040 00 3a 61 7f 4e 4f 54 49 46 59 20 73 69 70 3a 6a .:a.NOTIFY sip:j
0050 68 5f 74 65 73 74 5f 66 69 40 31 39 32 2e 39 38 h_test_fi at 192.98
0060 2e 31 30 32 2e 31 30 3a 35 30 37 34 3b 61 6c 69 .102.10:5074;ali
0070 61 73 3d 31 39 32 2e 39 38 2e 31 30 32 2e 31 30 as=192.98.102.10
0080 7e 34 36 39 35 35 7e 32 3b 74 72 61 6e 73 70 6f ~46955~2;transpo
0090 72 74 3d 74 63 70 20 53 49 50 2f 32 2e 30 0d 0a rt=tcp SIP/2.0..
00a0 56 69 61 3a 20 53 49 50 2f 32 2e 30 2f 54 43 50 Via: SIP/2.0/TCP
00b0 20 31 32 37 2e 30 2e 30 2e 31 3a 35 30 38 30 3b 127.0.0.1:5080;
00c0 62 72 61 6e 63 68 3d 7a 39 68 47 34 62 4b 38 34 branch=z9hG4bK84
00d0 63 66 2e 64 36 64 39 33 35 64 32 30 30 30 30 30 cf.d6d935d200000
00e0 30 30 30 30 30 30 30 30 30 30 30 30 30 30 30 30 0000000000000000
00f0 30 30 30 2e 30 0d 0a 54 6f 3a 20 73 69 70 3a 6a 000.0..To: sip:j
0100 68 40 74 65 73 74 2e 66 69 3b 74 61 67 3d 7a 72 h at test.fi;tag=zr
0110 72 6d 77 0d 0a 46 72 6f 6d 3a 20 73 69 70 3a 6a rmw..From: sip:j
0120 68 40 74 65 73 74 2e 66 69 3b 74 61 67 3d 32 63 h at test.fi;tag=2c
0130 31 35 39 39 38 38 31 33 39 39 33 61 35 66 32 36 15998813993a5f26
0140 39 38 61 38 36 39 33 30 34 32 65 34 36 66 2d 64 98a8693042e46f-d
0150 33 35 31 0d 0a 43 53 65 71 3a 20 32 20 4e 4f 54 351..CSeq: 2 NOT
0160 49 46 59 0d 0a 43 61 6c 6c 2d 49 44 3a 20 6a 63 IFY..Call-ID: jc
0170 67 61 6d 70 71 74 72 6e 7a 70 68 77 62 40 73 69 gampqtrnzphwb at si
0180 70 2e 74 65 73 74 2e 66 69 0d 0a 52 6f 75 74 65 p.test.fi..Route
0190 3a 20 3c 73 69 70 3a 31 32 37 2e 30 2e 30 2e 31 : <sip:127.0.0.1
01a0 3a 35 30 37 30 3b 74 72 61 6e 73 70 6f 72 74 3d :5070;transport=
01b0 74 63 70 3b 72 32 3d 6f 6e 3b 6c 72 3e 2c 20 3c tcp;r2=on;lr>, <
01c0 73 69 70 3a 31 39 32 2e 39 38 2e 31 30 32 2e 31 sip:192.98.102.1
01d0 30 3b 74 72 61 6e 73 70 6f 72 74 3d 74 63 70 3b 0;transport=tcp;
01e0 72 32 3d 6f 6e 3b 6c 72 3e 0d 0a 43 6f 6e 74 65 r2=on;lr>..Conte
01f0 6e 74 2d 4c 65 6e 67 74 68 3a 20 30 0d 0a 55 73 nt-Length: 0..Us
0200 65 72 2d 41 67 65 6e 74 3a 20 4f 70 65 6e 58 67 er-Agent: OpenXg
0210 20 50 72 65 73 65 6e 63 65 2f 58 43 41 50 20 53 Presence/XCAP S
0220 65 72 76 65 72 20 20 28 34 2e 30 2e 30 2d 72 63 erver (4.0.0-rc
0230 31 20 28 69 33 38 36 2f 6c 69 6e 75 78 29 29 0d 1 (i386/linux)).
0240 0a 4d 61 78 2d 46 6f 72 77 61 72 64 73 3a 20 37 .Max-Forwards: 7
0250 30 0d 0a 45 76 65 6e 74 3a 20 6d 65 73 73 61 67 0..Event: messag
0260 65 2d 73 75 6d 6d 61 72 79 0d 0a 43 6f 6e 74 61 e-summary..Conta
0270 63 74 3a 20 3c 73 69 70 3a 31 32 37 2e 30 2e 30 ct: <sip:127.0.0
0280 2e 31 3a 35 30 38 30 3b 74 72 61 6e 73 70 6f 72 .1:5080;transpor
0290 74 3d 74 63 70 3e 0d 0a 53 75 62 73 63 72 69 70 t=tcp>..Subscrip
02a0 74 69 6f 6e 2d 53 74 61 74 65 3a 20 61 63 74 69 tion-State: acti
02b0 76 65 3b 65 78 70 69 72 65 73 3d 39 30 30 0d 0a ve;expires=900..
02c0 0d 0a 6f 75 74 0d 0a 0d 0a 00 00 00 00 00 00 00 ..out...........
02d0 00 00 00 00 ....
notice that wireshark in the failing case shows that notify request is
followed by data, which it is not doing in the working example.
i have tried this on two hosts with equal result. in both cases the
config files, amount of memory, etc. are the same.
this looks like a show stopper grade problem to me. what has changed
between 4.0.0-pre1 and 4.0.0-rc1 that could explain this?
-- juha
More information about the sr-dev
mailing list