[Serusers] pa module presence windows messenger 5 header parse error

[Morten Kuehl]

Hello list,

I cannot get the presence module to work. It seems like the pa module does
not like Windows Messenger 5 SUBSCRIBE requests. ser is 0.8.14. Any
help???

Cheers
Morten

The SIP dump looks as follows:

U 192.168.1.10:33831 -> 192.168.1.1:5060
  SUBSCRIBE sip:usera at mck.li SIP/2.0..Via: SIP/2.0/UDP
192.168.1.20:8148..From: "Morten.Kuehl"
<sip:userb at mck.li>;tag=60111e38-e275-4e2d-8c30-9e0c25850673..To: <si
  p:usera at mck.li>..Call-ID:
5158ee48-5662-4a93-9994-11ed9d24e70f at 192.168.1.20..CSeq: 1
SUBSCRIBE..Contact: <sip:192.168.1.20:8148>..User-Agent: Windows
RTC/1.0..Expires: 1
  800..Content-Length: 0....

U 192.168.1.1:5060 -> 192.168.1.10:8148
  SIP/2.0 400 Bad Request..Via: SIP/2.0/UDP
192.168.1.20:8148;received=192.168.1.10..From: "Morten.Kuehl"
<sip:userb at mck.li>;tag=60111e38-e275-4e2d-8c30-9e0c25850673..To:
  <sip:usera at mck.li>;tag=0889e34f0f1bf5e510f3e8bae6892393-bfb5..Call-ID:
5158ee48-5662-4a93-9994-11ed9d24e70f at 192.168.1.20..CSeq: 1
SUBSCRIBE..Error while parsing headersS
  erver: Sip EXpress router (0.8.14 (i386/linux))..Content-Length:
0..Warning: 392 192.168.1.1:5060 "Noisy feedback tells:  pid=6118
req_src_ip=192.168.1.10 req_src_port=33831
   in_uri=sip:usera at mck.li out_uri=sip:usera at mck.li via_cnt==1"....

Debug from ser looks like this:

Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: SIP Request:
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]:  method:  <SUBSCRIBE>
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]:  uri:     <sip:usera at mck.li>
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]:  version: <SIP/2.0>
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: parse_headers: flags=1
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: end of header reached, state=5
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: parse_headers: Via found, flags=1
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: parse_headers: this is the
first via
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: After parse_msg...
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: preparing to run routing
scripts...
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: DEBUG : is_maxfwd_present:
searching for max_forwards header
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: parse_headers: flags=128
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: end of header reached, state=9
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: DEBUG: get_hdr_field: <To>
[29]; uri=[sip:usera at mck.li]
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: DEBUG: to body
[<sip:usera at mck.li>^M ]
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: get_hdr_field: cseq <CSeq>: <2>
<SUBSCRIBE>
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: DEBUG: get_hdr_body :
content_length=0
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: found end of header
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: DEBUG: is_maxfwd_present:
max_forwards header not found!
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: DEBUG: add_param:
tag=60eb5347-331a-4548-9761-e5ca8818e699
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: end of header reached, state=29
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: parse_headers: flags=256
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: find_first_route(): No Route
headers found
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: loose_route(): There is no
Route HF
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: check_self - checking if
host==us: 7==15 &&  [whu.edu] == [192.168.1.1]
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: check_self - checking if port
5060 matches port 5060
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: Subscribe
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: DEBUG: t_addifnew: msg id=3 ,
global msg id=2 , T on entrance=0xffffffff
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: parse_headers: flags=-1
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: parse_headers: flags=60
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: t_lookup_request: start
searching: hash=18509, isACK=0
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: DEBUG: proceeding to
pre-RFC3261 transaction matching
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: DEBUG: t_lookup_request: no
transaction found
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: Registrar
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: parse_headers: flags=1581064
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: parse_hfs(): Error while
parsing headers
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: handle_subscription(): Error
while parsing message header
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: DEBUG: t_check: msg id=3 global
id=3 T start=0x402d1d28
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: DEBUG: t_check: T alredy found!
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: parse_headers: flags=-1
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: WARNING:vqm_resize: resize(0)
called
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: DEBUG: cleanup_uacs: RETR/FR
timers reset
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: DEBUG: add_to_tail_of_timer[2]:
0x402d1d70
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: DEBUG: reply sent out.
buf=0x80dd610: SIP/2.0 4..., shmem=0x402d32b0: SIP/2.0 4
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: DEBUG: t_reply: finished
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: DEBUG:destroy_avp_list:
destroing list (nil)
Sep 25 16:00:39 sip01 /usr/sbin/ser[6117]: receive_msg: cleaning up

ser.cfg part looks like this:

                if (method=="SUBSCRIBE")
                {
                        log(1, "Subscribe\n");
                        if (t_newtran())
                        {
                                log(1, "Registrar\n");
                                handle_subscription("registrar");
                        };
                        break;                                            
                                                  
                                                  
                            };