[Kamailio-Users] Recording RTP session
Hector.Ortiz at swisscom.com
Hector.Ortiz at swisscom.com
Mon Mar 22 09:53:03 CET 2010
Vikram,
Yes, my server is handling SIP messages, that's why I'm able to make and receive calls. If you really need to see this info, I've activated the debug level 6 in my configuration file so I hope it helps debugging my problem.
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_msg: SIP Request:
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_msg: method: <INVITE>
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_msg: uri: <sip:0315080190 at 192.168.35.36>
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_msg: version: <SIP/2.0>
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=2
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-b562ca09>; state=16
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_via: end of header reached, state=5
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: via found, flags=2
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: this is the first via
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:receive_msg: After parse_msg...
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:receive_msg: preparing to run routing scripts...
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=100
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_to: end of header reached, state=10
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_to: display={}, ruri={sip:0315080190 at 192.168.35.36}
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: <To> [33]; uri=[sip:0315080190 at 192.168.35.36]
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: to body [<sip:0315080190 at 192.168.35.36>^M ]
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: cseq <CSeq>: <101> <INVITE>
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:maxfwd:is_maxfwd_present: value = 70
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:check_via_address: params 195.176.213.123, 195.176.213.123, 0
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=80
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:uri:has_totag: no totag
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=78
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:t_lookup_request: start searching: hash=27193, isACK=0
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:t_lookup_request: no transaction found
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: ROUTE_3^M
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_to_param: tag=40d3dff819e5d131o0
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_to: end of header reached, state=29
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_to: display={"0315080180"}, ruri={sip:0315080180 at 192.168.35.36}
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:domain:is_domain_local: Realm '192.168.35.36' is local
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:db_free_rows: freeing 1 rows
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:db_free_rows: row[0]=0x724028
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:db_free_rows: 0x724028=pkg_free() RES_ROWS
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:registrar:lookup: '0315080190' Not found in usrloc
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:domain:is_domain_local: Realm '192.168.35.36' is local
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:db_free_rows: freeing 1 rows
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:db_free_rows: row[0]=0x724028
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:db_free_rows: 0x724028=pkg_free() RES_ROWS
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: OUTGOING CALL^M
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: ROUTE 10
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: ROUTE 6
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: ROUTE 4
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: ROUTE 1
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:subst_run: running. r=1
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:subst_str: no match
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:t_newtran: transaction on entrance=(nil)
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=ffffffffffffffff
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: content_length=405
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: found end of header
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=78
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:t_lookup_request: start searching: hash=27193, isACK=0
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:t_lookup_request: no transaction found
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:run_reqin_callbacks: trans=0x7f852e6255d0, callback type 1, id 1 entered
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:run_reqin_callbacks: trans=0x7f852e6255d0, callback type 1, id 0 entered
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=ffffffffffffffff
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:check_via_address: params 195.176.213.123, 195.176.213.123, 0
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:_shm_resize: resize(0) called
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:_reply_light: reply sent out. buf=0x724860: SIP/2.0 1..., shmem=0x7f852e6282d0: SIP/2.0 1
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:_reply_light: finished
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:mk_proxy: doing DNS lookup...
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:check_via_address: params 195.176.213.123, 195.176.213.123, 0
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:set_timer: relative timeout is 500000
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:insert_timer_unsafe: [4]: 0x7f852e6257f0 (31200000)
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:set_timer: relative timeout is 30
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:insert_timer_unsafe: [0]: 0x7f852e625820 (60)
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:t_relay_to: new transaction fwd'ed
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:destroy_avp_list: destroying list (nil)
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:receive_msg: cleaning up
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_msg: SIP Reply (status):
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_msg: version: <SIP/2.0>
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_msg: status: <100>
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_msg: reason: <Trying>
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=2
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK93a6.ec962825.0>; state=6
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_via_param: found param type 234, <received> = <192.168.34.1>; state=16
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_via: end of header reached, state=5
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: via found, flags=2
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: this is the first via
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:receive_msg: After parse_msg...
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:forward_reply: found module nathelper, passing reply to it
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=4
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=6
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-b562ca09>; state=16
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_via: end of header reached, state=5
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: via found, flags=4
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: parse_headers: this is the second via
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:forward_reply: found module tm, passing reply to it
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:t_check: start=0xffffffffffffffff
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=22
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_to_param: tag=f9950f1e7f4263e3fdec46f4
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_to: end of header reached, state=29
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_to: display={}, ruri={sip:0315080190 at 192.168.35.36}
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:get_hdr_field: <To> [62]; uri=[sip:0315080190 at 192.168.35.36]
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:get_hdr_field: to body [<sip:0315080190 at 192.168.35.36>]
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:get_hdr_field: cseq <CSeq>: <101> <INVITE>
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=8
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:t_reply_matching: hash 27193 label 1384278478 branch 0
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:t_reply_matching: reply matched (T=0x7f852e6255d0)!
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:t_check: end=0x7f852e6255d0
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: ONREPLY_ROUTE
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=80
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:t_should_relay_response: T_code=100, new_code=100
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:relay_reply: branch=0, save=0, relay=-1
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:set_timer: relative timeout is 120
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:insert_timer_unsafe: [1]: 0x7f852e625820 (150)
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:destroy_avp_list: destroying list (nil)
Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:receive_msg: cleaning up
Mar 22 09:25:16 openser /usr/sbin/openser[32380]: DBG:tm:utimer_routine: timer routine:4,tl=0x7f852e6257f0 next=(nil), timeout=31200000
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_msg: SIP Reply (status):
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_msg: version: <SIP/2.0>
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_msg: status: <183>
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_msg: reason: <Session Progress>
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: flags=2
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK93a6.ec962825.0>; state=6
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_via_param: found param type 234, <received> = <192.168.34.1>; state=16
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_via: end of header reached, state=5
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: via found, flags=2
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: this is the first via
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:receive_msg: After parse_msg...
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:forward_reply: found module nathelper, passing reply to it
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: flags=4
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=6
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-b562ca09>; state=16
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_via: end of header reached, state=5
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: via found, flags=4
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: parse_headers: this is the second via
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:forward_reply: found module tm, passing reply to it
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:t_check: start=0xffffffffffffffff
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: flags=22
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_to_param: tag=f9950f1e7f4263e3fdec46f4
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_to: end of header reached, state=29
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_to: display={}, ruri={sip:0315080190 at 192.168.35.36}
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:get_hdr_field: <To> [62]; uri=[sip:0315080190 at 192.168.35.36]
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:get_hdr_field: to body [<sip:0315080190 at 192.168.35.36>]
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:get_hdr_field: cseq <CSeq>: <101> <INVITE>
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: flags=8
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:t_reply_matching: hash 27193 label 1384278478 branch 0
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:t_reply_matching: reply matched (T=0x7f852e6255d0)!
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:t_check: end=0x7f852e6255d0
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1)
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: ONREPLY_ROUTE
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: flags=80
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:t_should_relay_response: T_code=100, new_code=183
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:relay_reply: branch=0, save=0, relay=0
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:build_res_buf_from_sip_res: old size: 867, new size: 780
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:build_res_buf_from_sip_res: copied size: orig:117, new: 30, rest: 750 msg= SIP/2.0 183 Session Progress^M Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-b562ca09^M Record-Route: <sip:192.168.34.1;r2=on;lr=on>^M Record-Route: <sip:192.168.35.36;r2=on;lr=on>^M From: "0315080180" <sip:0315080180 at 192.168.35.36>;tag=40d3dff819e5d131o0^M To: <sip:0315080190 at 192.168.35.36>;tag=f9950f1e7f4263e3fdec46f4^M Call-ID: e4a790c4-f562f6d5 at 192.168.0.2^M CSeq: 101 INVITE^M User-Agent: Netstream VoIP Gateway^M Contact: <sip:gw01 at 192.168.128.61:5060>^M Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,REFER,SUBSCRIBE^M Content-Type: application/sdp^M Content-Length: 186^M ^M v=0^M o=- 227949608179227 1 IN IP4 192.168.128.61^M s=-^M c=IN IP4 192.168.128.61^M t=0 0^M m=audio 17124 RTP/AVP 0 101^M a=rtpmap:0 PCMU/8000^M a=rtpmap:101 telephone-event/8000^M a=fmtp:101 0-16^M
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:relay_reply: sent buf=0x71fda0: SIP/2.0 1..., shmem=0x7f852e6289b8: SIP/2.0 1
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:set_timer: relative timeout is 120
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:insert_timer_unsafe: [1]: 0x7f852e625820 (153)
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:destroy_avp_list: destroying list (nil)
Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:receive_msg: cleaning up
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_msg: SIP Reply (status):
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_msg: version: <SIP/2.0>
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_msg: status: <200>
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_msg: reason: <OK>
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: flags=2
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK93a6.ec962825.0>; state=6
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_via_param: found param type 234, <received> = <192.168.34.1>; state=16
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_via: end of header reached, state=5
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: via found, flags=2
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: this is the first via
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:receive_msg: After parse_msg...
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:forward_reply: found module nathelper, passing reply to it
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: flags=4
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=6
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-b562ca09>; state=16
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_via: end of header reached, state=5
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: via found, flags=4
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: parse_headers: this is the second via
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:forward_reply: found module tm, passing reply to it
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:t_check: start=0xffffffffffffffff
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: flags=22
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_to_param: tag=f9950f1e7f4263e3fdec46f4
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_to: end of header reached, state=29
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_to: display={}, ruri={sip:0315080190 at 192.168.35.36}
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:get_hdr_field: <To> [62]; uri=[sip:0315080190 at 192.168.35.36]
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:get_hdr_field: to body [<sip:0315080190 at 192.168.35.36>]
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:get_hdr_field: cseq <CSeq>: <101> <INVITE>
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: flags=8
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:t_reply_matching: hash 27193 label 1384278478 branch 0
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:t_reply_matching: reply matched (T=0x7f852e6255d0)!
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:t_check: end=0x7f852e6255d0
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:reply_received: org. status uas=183, uac[0]=183 local=0 is_invite=1)
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: ONREPLY_ROUTE
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: flags=80
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:t_should_relay_response: T_code=183, new_code=200
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:relay_reply: branch=0, save=0, relay=0
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:build_res_buf_from_sip_res: old size: 853, new size: 766
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:build_res_buf_from_sip_res: copied size: orig:103, new: 16, rest: 750 msg= SIP/2.0 200 OK^M Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-b562ca09^M Record-Route: <sip:192.168.34.1;r2=on;lr=on>^M Record-Route: <sip:192.168.35.36;r2=on;lr=on>^M From: "0315080180" <sip:0315080180 at 192.168.35.36>;tag=40d3dff819e5d131o0^M To: <sip:0315080190 at 192.168.35.36>;tag=f9950f1e7f4263e3fdec46f4^M Call-ID: e4a790c4-f562f6d5 at 192.168.0.2^M CSeq: 101 INVITE^M User-Agent: Netstream VoIP Gateway^M Contact: <sip:gw01 at 192.168.128.61:5060>^M Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,REFER,SUBSCRIBE^M Content-Type: application/sdp^M Content-Length: 186^M ^M v=0^M o=- 227949608179227 1 IN IP4 192.168.128.61^M s=-^M c=IN IP4 192.168.128.61^M t=0 0^M m=audio 17124 RTP/AVP 0 101^M a=rtpmap:0 PCMU/8000^M a=rtpmap:101 telephone-event/8000^M a=fmtp:101 0-16^M
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:insert_timer_unsafe: [2]: 0x7f852e625650 (42)
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:relay_reply: sent buf=0x71fda0: SIP/2.0 2..., shmem=0x7f852e6289b8: SIP/2.0 2
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:destroy_avp_list: destroying list (nil)
Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:receive_msg: cleaning up
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_msg: SIP Request:
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_msg: method: <ACK>
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_msg: uri: <sip:gw01 at 192.168.128.61:5060>
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_msg: version: <SIP/2.0>
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=2
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-15f908fd>; state=16
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_via: end of header reached, state=5
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: via found, flags=2
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: this is the first via
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:receive_msg: After parse_msg...
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:receive_msg: preparing to run routing scripts...
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:sl:sl_filter_ACK: to late to be a local ACK!
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=100
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_to_param: tag=f9950f1e7f4263e3fdec46f4
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_to: end of header reached, state=29
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_to: display={}, ruri={sip:0315080190 at 192.168.35.36}
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:get_hdr_field: <To> [62]; uri=[sip:0315080190 at 192.168.35.36]
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:get_hdr_field: to body [<sip:0315080190 at 192.168.35.36>]
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:get_hdr_field: cseq <CSeq>: <101> <ACK>
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:maxfwd:is_maxfwd_present: value = 70
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:check_via_address: params 195.176.213.123, 195.176.213.123, 0
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=80
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:uri:has_totag: totag found
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=200
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:rr:is_preloaded: is_preloaded: No
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:grep_sock_info: checking if host==us: 12==14 && [192.168.128.61] == [192.168.35.36]
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:grep_sock_info: checking if host==us: 12==14 && [192.168.128.61] == [192.168.34.1]
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:check_self: host != me
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:grep_sock_info: checking if host==us: 14==14 && [192.168.35.36] == [192.168.35.36]
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:rr:after_loose: Topmost route URI: 'sip:192.168.35.36;r2=on;lr=on' is me
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:grep_sock_info: checking if host==us: 14==14 && [192.168.34.1] == [192.168.35.36]
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:grep_sock_info: checking if host==us: 14==14 && [192.168.34.1] == [192.168.34.1]
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=200
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:get_hdr_field: content_length=0
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:get_hdr_field: found end of header
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:rr:find_next_route: No next Route HF found
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:rr:after_loose: no next URI found
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:rr:run_rr_callbacks: callback id 0 entered with <r2=on;lr=on>
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:dialog:dlg_onroute: Route param 'did' not found
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: ACCOUNTING START
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=78
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_to_param: tag=40d3dff819e5d131o0
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_to: end of header reached, state=29
Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_to: display={"0315080180"}, ruri={sip:0315080180 at 192.168.35.36}
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=78
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: ACC: request accounted: timestamp=1269246323;method=ACK;from_tag=40d3dff819e5d131o0;to_tag=f9950f1e7f4263e3fdec46f4;call_id=e4a790c4-f562f6d5 at 192.168.0.2;code=200;reason=ok
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: ROUTE 1
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:subst_run: running. r=1
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:subst_str: no match
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=ffffffffffffffff
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=78
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:tm:t_lookup_request: start searching: hash=27193, isACK=1
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=38
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:tm:t_lookup_request: REF_UNSAFE: after is 1
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:tm:t_lookup_request: e2e proxy ACK found
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:tm:t_newtran: building branch for end2end ACK
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:tm:t_relay_to: forwarding ACK
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:mk_proxy: doing DNS lookup...
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:check_via_address: params 195.176.213.123, 195.176.213.123, 0
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:forward_request: sending: ACK sip:gw01 at 192.168.128.61:5060 SIP/2.0^M Record-Route: <sip:192.168.34.1;r2=on;lr=on>^M Record-Route: <sip:192.168.35.36;r2=on;lr=on>^M Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK93a6.ec962825.2^M Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-15f908fd^M From: "0315080180" <sip:0315080180 at 192.168.35.36>;tag=40d3dff819e5d131o0^M To: <sip:0315080190 at 192.168.35.36>;tag=f9950f1e7f4263e3fdec46f4^M Call-ID: e4a790c4-f562f6d5 at 192.168.0.2^M CSeq: 101 ACK^M Max-Forwards: 69^M Contact: "0315080180" <sip:0315080180 at 195.176.213.123:5060>^M User-Agent: Sipura/SPA921-4.1.10(b)^M Content-Length: 0^M ^M .
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:forward_request: orig. len=518, new_len=613, proto=1
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:tm:t_unref_cell: UNREF_UNSAFE: after is 0
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:destroy_avp_list: destroying list 0x7f852e6282d0
Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:receive_msg: cleaning up
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_msg: SIP Request:
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_msg: method: <NOTIFY>
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_msg: uri: <sip:192.168.35.36>
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_msg: version: <SIP/2.0>
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=2
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-4cb4b718>; state=16
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_via: end of header reached, state=5
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: via found, flags=2
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: this is the first via
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:receive_msg: After parse_msg...
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:receive_msg: preparing to run routing scripts...
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=100
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_to: end of header reached, state=10
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_to: display={}, ruri={sip:192.168.35.36}
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: <To> [22]; uri=[sip:192.168.35.36]
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: to body [<sip:192.168.35.36>^M ]
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: cseq <CSeq>: <16736> <NOTIFY>
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:maxfwd:is_maxfwd_present: value = 70
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:check_via_address: params 195.176.213.123, 195.176.213.123, 0
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=80
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: content_length=0
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: found end of header
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:uri:has_totag: no totag
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=78
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:tm:t_lookup_request: start searching: hash=21918, isACK=0
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:tm:t_lookup_request: no transaction found
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=ffffffffffffffff
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:check_via_address: params 195.176.213.123, 195.176.213.123, 0
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:destroy_avp_list: destroying list (nil)
Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:receive_msg: cleaning up
Mar 22 09:25:27 openser /usr/sbin/openser[32380]: DBG:tm:timer_routine: timer routine:2,tl=0x7f852e625650 next=(nil), timeout=42
Mar 22 09:25:27 openser /usr/sbin/openser[32380]: DBG:tm:wait_handler: removing 0x7f852e6255d0 from table
Mar 22 09:25:27 openser /usr/sbin/openser[32380]: DBG:tm:delete_cell: delete transaction 0x7f852e6255d0
Mar 22 09:25:27 openser /usr/sbin/openser[32380]: DBG:tm:wait_handler: done
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_msg: SIP Request:
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_msg: method: <BYE>
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_msg: uri: <sip:0315080180 at 195.176.213.123:5060>
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_msg: version: <SIP/2.0>
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=2
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKf9950f1e6b2f5081fdec4739>; state=16
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_via: end of header reached, state=5
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: via found, flags=2
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: this is the first via
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:receive_msg: After parse_msg...
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:receive_msg: preparing to run routing scripts...
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=100
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:maxfwd:is_maxfwd_present: value = 70
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:check_via_address: params 192.168.128.61, 192.168.128.61, 0
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=80
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_to_param: tag=40d3dff819e5d131o0
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_to: end of header reached, state=29
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_to: display={"0315080180"}, ruri={sip:0315080180 at 192.168.35.36}
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:get_hdr_field: <To> [69]; uri=[sip:0315080180 at 192.168.35.36]
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:get_hdr_field: to body ["0315080180" <sip:0315080180 at 192.168.35.36>]
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:get_hdr_field: cseq <CSeq>: <1> <BYE>
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:get_hdr_field: found end of header
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:uri:has_totag: totag found
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=200
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:rr:is_preloaded: is_preloaded: No
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if host==us: 15==14 && [195.176.213.123] == [192.168.35.36]
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if host==us: 15==14 && [195.176.213.123] == [192.168.34.1]
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:check_self: host != me
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if host==us: 14==14 && [192.168.34.1] == [192.168.35.36]
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if host==us: 14==14 && [192.168.34.1] == [192.168.34.1]
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:rr:after_loose: Topmost route URI: 'sip:192.168.34.1;r2=on;lr=on' is me
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if host==us: 14==14 && [192.168.35.36] == [192.168.35.36]
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=200
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:get_hdr_field: found end of header
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:rr:find_next_route: No next Route HF found
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:rr:after_loose: no next URI found
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:rr:run_rr_callbacks: callback id 0 entered with <r2=on;lr=on>
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:dialog:dlg_onroute: Route param 'did' not found
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: ACCOUNTING STOP
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=78
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_to_param: tag=f9950f1e7f4263e3fdec46f4
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_to: end of header reached, state=29
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_to: display={}, ruri={sip:0315080190 at 192.168.35.36}
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=78
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: ACC: request accounted: timestamp=1269246328;method=BYE;from_tag=f9950f1e7f4263e3fdec46f4;to_tag=40d3dff819e5d131o0;call_id=e4a790c4-f562f6d5 at 192.168.0.2;code=200;reason=ok
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: ROUTE 1
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:subst_run: running. r=1
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:subst_str: no match
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=ffffffffffffffff
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=78
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:t_lookup_request: start searching: hash=19358, isACK=0
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:t_lookup_request: no transaction found
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:run_reqin_callbacks: trans=0x7f852e6255d0, callback type 1, id 1 entered
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:run_reqin_callbacks: trans=0x7f852e6255d0, callback type 1, id 0 entered
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:mk_proxy: doing DNS lookup...
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:check_via_address: params 192.168.128.61, 192.168.128.61, 0
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:set_timer: relative timeout is 500000
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:insert_timer_unsafe: [4]: 0x7f852e6257f0 (43200000)
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:set_timer: relative timeout is 30
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:insert_timer_unsafe: [0]: 0x7f852e625820 (72)
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:t_relay_to: new transaction fwd'ed
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:destroy_avp_list: destroying list (nil)
Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:receive_msg: cleaning up
Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_msg: SIP Reply (status):
Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_msg: version: <SIP/2.0>
Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_msg: status: <200>
Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_msg: reason: <OK>
Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=2
Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_to_param: tag=40d3dff819e5d131o0
Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_to: end of header reached, state=29
Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_to: display={"0315080180"}, ruri={sip:0315080180 at 192.168.35.36}
Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:get_hdr_field: <To> [69]; uri=[sip:0315080180 at 192.168.35.36]
Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:get_hdr_field: to body ["0315080180" <sip:0315080180 at 192.168.35.36>]
Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:get_hdr_field: cseq <CSeq>: <1> <BYE>
Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKe9b4.709d6d85.0>; state=16
Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_via: end of header reached, state=5
Héctor
-----Original Message-----
From: Vikram Ragukumar [mailto:vragukumar at signalogic.com]
Sent: Freitag, 19. März 2010 22:51
To: Ortiz Héctor, SCS-SIS-ICC-SPC-SBU
Cc: users at lists.kamailio.org
Subject: Re: [Kamailio-Users] Recording RTP session
Hector,
I could be wrong about what's happening here, but what you have provided
is a sip trace from an external utility (wireshark or tcpdump maybe .. ?).
Could you verify your kamailio log to see if it is actually handling SIP
messages?
I show below a portion of one of my logs for kamailio, that indicates
reception of a REGISTER message. (you might have to increase the
'debug=' value option in you kamailio.cfg)
localhost /usr/local/sbin/kamailio[3083]: DBG:core:io_watch_add:
io_watch_add(0x8156f00, 30, 1, (nil)), fd_no=0
localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_msg: SIP Request:
localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_msg: method:
<REGISTER>
localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_msg: uri:
<sip:61.24.320.543:5060>
localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_msg: version:
<SIP/2.0>
localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_headers: flags=2
localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_via_param:
found param type 235, <rport> = <n/a>; state=6
localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_via_param:
found param type 232, <branch> =
<z9hG4bKPj1AbnwayUehrY5eBxiVzMEG4UDoGoFAnj>; state=16
localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_via: end of
header reached, state=5
localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_headers: via
found, flags=2
localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_headers: this
is the first via
localhost /usr/local/sbin/kamailio[3075]: DBG:core:receive_msg: After
parse_msg...
Regards,
Vikram.
> Hi Vikram
>
> Yes, SIP messages are being proxied, otherwise the call wouldn't be possible.
>
> Here are the SIP messages that are being proxied in case this helps to debug my problem
>
> interface: eth1 (192.168.34.1/255.255.255.240)
> filter: (ip or ip6) and ( port 5060 )
>
> U 192.168.34.1:5060 -> 192.168.128.61:5060
> INVITE sip:0315080190 at 192.168.128.61 SIP/2.0.
> Record-Route: <sip:192.168.34.1;r2=on;lr=on>.
> Record-Route: <sip:192.168.35.36;r2=on;lr=on>.
> Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK2838.f3a91403.0.
> Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-a6818ce1.
> From: "0315080180" <sip:0315080180 at 192.168.35.36>;tag=58e4d381b7c3e699o0.
> To: <sip:0315080190 at 192.168.35.36>.
> Call-ID: b80ee3a1-19414f9 at 192.168.0.2.
> CSeq: 101 INVITE.
> Max-Forwards: 69.
> Contact: "0315080180" <sip:0315080180 at 195.176.213.123:5060>.
> Expires: 240.
> User-Agent: Sipura/SPA921-4.1.10(b).
> Content-Length: 403.
> Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER.
> Content-Type: application/sdp.
> .
> v=0.
> o=- 1956263 1956263 IN IP4 195.176.213.123.
> s=-.
> c=IN IP4 195.176.213.123.
> t=0 0.
> m=audio 16386 RTP/AVP 0 2 4 8 18 96 97 98 101.
> a=rtpmap:0 PCMU/8000.
> a=rtpmap:2 G726-32/8000.
> a=rtpmap:4 G723/8000.
> a=rtpmap:8 PCMA/8000.
> a=rtpmap:18 G729a/8000.
> a=rtpmap:96 G726-40/8000.
> a=rtpmap:97 G726-24/8000.
> a=rtpmap:98 G726-16/8000.
> a=rtpmap:101 telephone-event/8000.
> a=fmtp:101 0-15.
> a=ptime:30.
> a=sendrecv.
>
>
> U 192.168.128.61:5060 -> 192.168.34.1:5060
> SIP/2.0 100 Trying.
> Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK2838.f3a91403.0;received=192.168.34.1.
> Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-a6818ce1.
> Record-Route: <sip:192.168.34.1;r2=on;lr=on>.
> Record-Route: <sip:192.168.35.36;r2=on;lr=on>.
> From: "0315080180" <sip:0315080180 at 192.168.35.36>;tag=58e4d381b7c3e699o0.
> To: <sip:0315080190 at 192.168.35.36>;tag=f9950ba86292ab03fde8af7b.
> Call-ID: b80ee3a1-19414f9 at 192.168.0.2.
> CSeq: 101 INVITE.
> User-Agent: Netstream VoIP Gateway.
> Contact: <sip:gw01 at 192.168.128.61:5060>.
> .
>
>
> U 192.168.128.61:5060 -> 192.168.34.1:5060
> SIP/2.0 183 Session Progress.
> Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK2838.f3a91403.0;received=192.168.34.1.
> Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-a6818ce1.
> Record-Route: <sip:192.168.34.1;r2=on;lr=on>.
> Record-Route: <sip:192.168.35.36;r2=on;lr=on>.
> From: "0315080180" <sip:0315080180 at 192.168.35.36>;tag=58e4d381b7c3e699o0.
> To: <sip:0315080190 at 192.168.35.36>;tag=f9950ba86292ab03fde8af7b.
> Call-ID: b80ee3a1-19414f9 at 192.168.0.2.
> CSeq: 101 INVITE.
> User-Agent: Netstream VoIP Gateway.
> Contact: <sip:gw01 at 192.168.128.61:5060>.
> Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,REFER,SUBSCRIBE.
> Content-Type: application/sdp.
> Content-Length: 186.
> .
> v=0.
> o=- 227934408367722 1 IN IP4 192.168.128.61.
> s=-.
> c=IN IP4 192.168.128.61.
> t=0 0.
> m=audio 23984 RTP/AVP 0 101.
> a=rtpmap:0 PCMU/8000.
> a=rtpmap:101 telephone-event/8000.
> a=fmtp:101 0-16.
>
>
> U 192.168.128.61:5060 -> 192.168.34.1:5060
> SIP/2.0 200 OK.
> Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK2838.f3a91403.0;received=192.168.34.1.
> Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-a6818ce1.
> Record-Route: <sip:192.168.34.1;r2=on;lr=on>.
> Record-Route: <sip:192.168.35.36;r2=on;lr=on>.
> From: "0315080180" <sip:0315080180 at 192.168.35.36>;tag=58e4d381b7c3e699o0.
> To: <sip:0315080190 at 192.168.35.36>;tag=f9950ba86292ab03fde8af7b.
> Call-ID: b80ee3a1-19414f9 at 192.168.0.2.
> CSeq: 101 INVITE.
> User-Agent: Netstream VoIP Gateway.
> Contact: <sip:gw01 at 192.168.128.61:5060>.
> Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,REFER,SUBSCRIBE.
> Content-Type: application/sdp.
> Content-Length: 186.
> .
> v=0.
> o=- 227934408367722 1 IN IP4 192.168.128.61.
> s=-.
> c=IN IP4 192.168.128.61.
> t=0 0.
> m=audio 23984 RTP/AVP 0 101.
> a=rtpmap:0 PCMU/8000.
> a=rtpmap:101 telephone-event/8000.
> a=fmtp:101 0-16.
>
>
> U 192.168.34.1:5060 -> 192.168.128.61:5060
> ACK sip:gw01 at 192.168.128.61:5060 SIP/2.0.
> Record-Route: <sip:192.168.34.1;r2=on;lr=on>.
> Record-Route: <sip:192.168.35.36;r2=on;lr=on>.
> Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK2838.f3a91403.2.
> Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-c7ff7fbe.
> From: "0315080180" <sip:0315080180 at 192.168.35.36>;tag=58e4d381b7c3e699o0.
> To: <sip:0315080190 at 192.168.35.36>;tag=f9950ba86292ab03fde8af7b.
> Call-ID: b80ee3a1-19414f9 at 192.168.0.2.
> CSeq: 101 ACK.
> Max-Forwards: 69.
> Contact: "0315080180" <sip:0315080180 at 195.176.213.123:5060>.
> User-Agent: Sipura/SPA921-4.1.10(b).
> Content-Length: 0.
> .
>
>
> U 192.168.128.61:5060 -> 192.168.34.1:5060
> BYE sip:0315080180 at 195.176.213.123:5060 SIP/2.0.
> Route: <sip:192.168.34.1;r2=on;lr=on>.
> Route: <sip:192.168.35.36;r2=on;lr=on>.
> Via: SIP/2.0/UDP 192.168.128.61:5060;branch=z9hG4bKf9950ba86fb23261fde8afbb.
> Max-Forwards: 70.
> From: <sip:0315080190 at 192.168.35.36>;tag=f9950ba86292ab03fde8af7b.
> To: "0315080180" <sip:0315080180 at 192.168.35.36>;tag=58e4d381b7c3e699o0.
> Call-ID: b80ee3a1-19414f9 at 192.168.0.2.
> CSeq: 1 BYE.
> User-Agent: Netstream VoIP Gateway.
> .
>
>
> U 192.168.34.1:5060 -> 192.168.128.61:5060
> SIP/2.0 200 OK.
> To: "0315080180" <sip:0315080180 at 192.168.35.36>;tag=58e4d381b7c3e699o0.
> From: <sip:0315080190 at 192.168.35.36>;tag=f9950ba86292ab03fde8af7b.
> Call-ID: b80ee3a1-19414f9 at 192.168.0.2.
> CSeq: 1 BYE.
> Via: SIP/2.0/UDP 192.168.128.61:5060;rport=5060;branch=z9hG4bKf9950ba86fb23261fde8afbb.
> Record-Route: <sip:192.168.35.36;r2=on;lr=on>.
> Record-Route: <sip:192.168.34.1;r2=on;lr=on>.
> Server: Sipura/SPA921-4.1.10(b).
> Content-Length: 0.
> .
>
>
> Cheers
>
> Héctor
>
>
> -----Original Message-----
> From: Vikram Ragukumar [mailto:vragukumar at signalogic.com]
> Sent: Freitag, 19. März 2010 16:48
> To: Ortiz Héctor, SCS-SIS-ICC-SPC-SBU
> Cc: users at lists.kamailio.org
> Subject: Re: [Kamailio-Users] Recording RTP session
>
> Hector,
>> Hi everybody
>>
>>
>>
>> I've configured a SIP server (OpenSER 1.3.2) to work with rtpproxy and
>> so far everything is fine, but now I want to be able to record the audio
>> from a conversation. I've read that this is possible by using the
>> function start_recording from the module NATHelper but I'm not able to
>> get it working
>
> I'm no expert when it comes to rtpproxy or Kamailio , but i've
> encountered a similar problem in the past. I took a quick look at your
> logfile and i noticed that there aren't any SIP messages in the log (eg.
> REGISTER, INVITE...). Are you sure that SIP messages are being proxied ?
> if not recording would not be possible.
>
> Regards,
> Vikram.
>>
>>
>> RTPproxy 1.2.1 is running with the following options:
>>
>>
>>
>> root at openser:/opt/rtpproxy-1.2.1/bin# ps uax | grep rtpproxy
>>
>> rtpproxy 30827 0.0 0.0 26968 964 ? Ssl 14:49 0:00
>> /opt/rtpproxy-1.2.1/bin/rtpproxy -u rtpproxy rtpproxy -p
>> /var/run/rtpproxy/rtpproxy.pid -l 192.168.34.1 -s udp:127.0.0.1 7890 -r
>> /etc/openser/stored_conversations -S /tmp -a -d DBUG -P
>>
>> root 31547 0.0 0.0 7524 892 pts/1 R+ 15:59 0:00 grep
>> rtpproxy
>>
>>
>>
>> Output from netstat
>>
>>
>>
>> root at openser:/opt/rtpproxy-1.2.1/bin# netstat -tupna | grep rtpproxy
>>
>> udp 0 0 127.0.0.1:7890
>> 0.0.0.0:* 30827/rtpproxy
>>
>>
>>
>> Relevant parts of the configuration file
>>
>>
>>
>> ...
>>
>> # ------ nathelper params -----
>>
>> modparam("nathelper", "natping_interval", 30)
>>
>> modparam("nathelper", "ping_nated_only", 1)
>>
>> modparam("nathelper", "sipping_bflag", 7)
>>
>> modparam("nathelper", "sipping_from", "sip:pinger at openser.org")
>>
>>
>>
>> modparam("nathelper", "rtpproxy_sock", "udp:127.0.0.1:7890")
>>
>> modparam("nathelper", "force_socket", "udp:localhost:7890")
>>
>> ...
>>
>> route[6] {
>>
>> xlog("L_INFO", "ROUTE 6");
>>
>> # NAT handling
>>
>> # Set reply routing block, to which control is passed after a
>> transaction
>>
>> # completed with a negative result but before sending a final reply
>>
>> t_on_failure("1");
>>
>> # Check if we're NATed
>>
>> if (isflagset(5) || isbflagset(6)) {
>>
>> # Use rtpproxy
>>
>> force_rtp_proxy();
>>
>> if ( start_recording() ) {
>>
>> xlog("L_INFO", "RECORDING...");
>>
>> };
>>
>> }
>>
>> # Set reply routing block, to which control is passed each time
>> a reply
>>
>> # (provisional or final) for the transaction is received
>>
>> t_on_reply("1");
>>
>> }
>>
>> ...
>>
>> onreply_route[1] {
>>
>> xlog("L_INFO", "ONREPLY_ROUTE");
>>
>> if ((isflagset(5) || isbflagset(6)) &&
>> status=~"(180)|(183)|(2[0-9][0-9])") {
>>
>> xlog("L_INFO", "NAT'd TRANSACTION");
>>
>> fix_nated_contact();
>>
>> force_rtp_proxy();
>>
>> if ( start_recording() ) {
>>
>> xlog("L_INFO", "RECORDING...");
>>
>> };
>>
>> }
>>
>> else if (nat_uac_test("1")) {
>>
>> fix_nated_contact();
>>
>> }
>>
>> exit;
>>
>> }
>>
>>
>>
>> When I start OpenSER I see the following in syslog
>>
>>
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31630]: NOTICE:core:main:
>> version: openser 1.3.2-notls (x86_64/linux)
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:core:main: using
>> 256 Mb shared memory
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:core:main: using
>> 1 Mb private memory per process
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:sl:mod_init:
>> Initializing StateLess engine
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:tm:mod_init: TM -
>> initializing...
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:maxfwd:mod_init:
>> initializing...
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31630]:
>> INFO:usrloc:ul_init_locks: locks array size 512
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31630]:
>> INFO:registrar:mod_init: initializing...
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:textops:mod_init:
>> initializing...
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:xlog:mod_init:
>> initializing...
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31630]:
>> INFO:avpops:avpops_init: initializing...
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:acc:mod_init:
>> initializing...
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:dialog:mod_init:
>> Dialog module - initializing
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31630]:
>> INFO:core:probe_max_receive_buffer: using a UDP receive buffer of 255 kb
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31630]:
>> INFO:core:probe_max_receive_buffer: using a UDP receive buffer of 255 kb
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31632_0 V"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31632_0 20040107 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31632_1 VF 20050322"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31632_1 1 "
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31632]:
>> INFO:nathelper:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support
>> for it enabled
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31631_0 V"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31631_0 20040107 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31633_0 V"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31633_0 20040107 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31634_0 V"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31634_0 20040107 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31635_0 V"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31635_0 20040107 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31636_0 V"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31636_0 20040107 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31637_0 V"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31637_0 20040107 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31638_0 V"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31638_0 20040107 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31637_1 VF 20050322"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31637_1 1 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31631_1 VF 20050322"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31631_1 1 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31634_1 VF 20050322"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31634_1 1 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31636_1 VF 20050322"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31636_1 1 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31633_1 VF 20050322"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31633_1 1 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31635_1 VF 20050322"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31635_1 1 "
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31631]:
>> INFO:nathelper:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support
>> for it enabled
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31634]:
>> INFO:nathelper:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support
>> for it enabled
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31637]:
>> INFO:nathelper:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support
>> for it enabled
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31633]:
>> INFO:nathelper:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support
>> for it enabled
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31636]:
>> INFO:nathelper:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support
>> for it enabled
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31635]:
>> INFO:nathelper:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support
>> for it enabled
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31638]:
>> INFO:nathelper:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support
>> for it enabled
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31639_0 V"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31639_0 20040107 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31638_1 VF 20050322"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31638_1 1 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31640_0 V"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31640_0 20040107 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31642_0 V"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31642_0 20040107 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31643_0 V"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31643_0 20040107 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31644_0 V"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31644_0 20040107 "
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31642]:
>> INFO:nathelper:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support
>> for it enabled
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31643]:
>> INFO:nathelper:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support
>> for it enabled
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31645_0 V"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31645_0 20040107 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31639_1 VF 20050322"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31639_1 1 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31642_1 VF 20050322"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31642_1 1 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31644_1 VF 20050322"
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31644]:
>> INFO:nathelper:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support
>> for it enabled
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31644_1 1 "
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31640]:
>> INFO:nathelper:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support
>> for it enabled
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31639]:
>> INFO:nathelper:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support
>> for it enabled
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31640_1 VF 20050322"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31640_1 1 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31643_1 VF 20050322"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31643_1 1 "
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received
>> command "31645_1 VF 20050322"
>>
>> Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply
>> "31645_1 1 "
>>
>> Mar 19 16:08:45 openser /usr/sbin/openser[31645]:
>> INFO:nathelper:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support
>> for it enabled
>>
>>
>>
>> But when I place the call no debug info from rtpproxy is being generated
>> nor the RTP session is being saved to file.
>>
>>
>>
>> Any idea what the problem can be?
>>
>>
>>
>> Thanks in advance
>>
>>
>>
>> Héctor
>>
>>
>> ------------------------------------------------------------------------
>>
>> _______________________________________________
>> Kamailio (OpenSER) - Users mailing list
>> Users at lists.kamailio.org
>> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users
>> http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
>
>
> _______________________________________________
> Kamailio (OpenSER) - Users mailing list
> Users at lists.kamailio.org
> http://lists.kamailio.org/cgi-bin/mailman/listinfo/users
> http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
More information about the Users
mailing list