Good afternoon Ladies and Gentlemen,
I'm trying to use OpenSIPS as a Border Controller between a PSTN and a
FreeSWITCH. The PSTN is sending all SIP-messages through a SIP-trunk.
I got OpenSIPS working fine from PSTN through OpenSIPS to FreeSWITCH, but the
other way around (from FS over OpenSIPS to PSTN), I'm getting an error message
I can't solve.
As far as I can tell, when OpenSIPS opens up a new branch it is changing
internally the headers from the incoming SIP-message from FreeSWITCH into a
wrong format and after that it's throwing two errors:
- ERROR:tm:send_ack: failed to generate a HBH ACK if key HFs in reply
missing
ERROR:tm:reply_received: failed to send ACK (local=no)
o Here I looked at the relevant code but I can't tell what it is trying to do
in the transaction module
Additionally this piece of info:
- ... SIP/2.0 400 Bad Request..Warning: 399 192.168.1.30 "Malformed
headers : From " ...
o From this somehow I found out that it's missing the ":" after From
Please see the attached config, routing logic, oopensips-errorlog and the
sip-trace.
I would very much appreciate it if somebody could give me, at least, a hint how
I could fix the problem, because by now I googled these problems for three days
now w/o a solution.
Thanks in advance for any help I can get!
Very Respectfully
Dimitry Nagorny
Trainee
robot5 GmbH
Walter-Oehmichen-Straße 18
68519 Viernheim
Tel.: +49 6204 704 - 511
Fax: +49 6204 704 - 501
E-Mail: [email protected]<mailto:[email protected]>
Internet: www.robot5.de<http://www.robot5.de/>
_____________________________________________________________
Geschäftsführer:
Werner Oestreicher
Robert Schlabs
Stefan Wagner
Sitz der Gesellschaft: Viernheim
Amtsgericht: Darmstadt
Registerabteilung: Lampertheim HRB 92975
USt-IdNr.: DE293694382
Diese Email enthält vertrauliche und/oder rechtlich geschützte Informationen.
Wenn Sie nicht der richtige Adressat sind oder diese E-Mail irrtümlich erhalten
haben, informieren Sie bitte sofort den Absender und vernichten diese E-Mail.
Das unerlaubte Kopieren sowie die unbefugte Weitergabe dieser E-Mail ist
nicht gestattet.
This message is confidential and may contain privileged information.
If you are not the above named addressee or authorized to receive this
message on behalf of the addressee, please advise the sender immediately
and delete this message. Any unauthorized copying, disclosure or
distribution of the information in this e-mail is strictly forbidden.
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_msg: SIP
Request:
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_msg: method:
<INVITE>
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_msg: uri:
<sip:[email protected]:5080>
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_msg:
version: <SIP/2.0>
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_headers:
flags=2
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_via_param:
found param type 235, <rport> = <n/a>; state=6
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK1ytH5t8ZyF3aH>; state=16
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_via: end of
header reached, state=5
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_headers: via
found, flags=2
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_headers: this
is the first via
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:receive_msg: After
parse_msg...
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:receive_msg:
preparing to run routing scripts...
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_headers:
flags=100
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]:
DBG:maxfwd:is_maxfwd_present: value = 69
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_headers:
flags=8
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_to: end of
header reached, state=10
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_to:
display={}, ruri={sip:[email protected]:5080}
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:get_hdr_field: <To>
[30]; uri=[sip:[email protected]:5080]
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:get_hdr_field: to
body [<sip:[email protected]:5080>#015#012]
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:uri:has_totag: no totag
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_headers:
flags=78
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:get_hdr_field: cseq
<CSeq>: <88641991> <INVITE>
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:tm:t_lookup_request:
start searching: hash=30020, isACK=0
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:tm:matching_3261:
RFC3261 transaction matching failed
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:tm:t_lookup_request: no
transaction found
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_headers:
flags=200
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:get_hdr_field:
content_length=218
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:get_hdr_field:
found end of header
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:rr:find_first_route: No
Route headers found
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:rr:loose_route: There is
no Route HF
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_to_param:
tag=m05SKryceZQ7F
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_to: end of
header reached, state=29
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_to:
display={"1001"}, ruri={sip:1001@[10.250.5.50:5090]}
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:grep_sock_info:
checking if host==us: 16==13 && [10.250.5.50:5090] == [192.168.1.150]
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:grep_sock_info:
checking if port 5060 matches port 5060
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:grep_sock_info:
checking if host==us: 16==10 && [10.250.5.50:5090] == [10.250.5.3]
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:grep_sock_info:
checking if port 5080 matches port 5060
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:check_self: host !=
me
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:grep_sock_info:
checking if host==us: 10==13 && [10.250.5.3] == [192.168.1.150]
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:grep_sock_info:
checking if port 5060 matches port 5080
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:grep_sock_info:
checking if host==us: 10==10 && [10.250.5.3] == [10.250.5.3]
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:grep_sock_info:
checking if port 5080 matches port 5080
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:buf_init:
initializing...
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: Into invite method.
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:dialog:w_create_dialog2:
bye on timeout activated
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:dialog:build_new_dlg:
new dialog 0x7fb36ea18a18
(c=83c45345-647d-1234-e187-000c295a647b,f=sip:1001@[10.250.5.50:5090],t=sip:[email protected]:5080,ft=m05SKryceZQ7F)
on hash 1723
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_headers:
flags=ffffffffffffffff
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:dialog:init_leg_info:
route_set , contact sip:[email protected]:5090;transport=udp;gw=osips, cseq
88641991 and bind_addr udp:10.250.5.3:5080
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:dialog:dlg_add_leg_info:
set leg 0 for 0x7fb36ea18a18: tag=<m05SKryceZQ7F> rcseq=<0>
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:dialog:link_dlg: ref dlg
0x7fb36ea18a18 with 4 -> 4 in h_entry 0x7fb36e9f43d8 - 1723
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:rr:add_rr_param: adding
(;did=bb6.b255faa3)
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:rr:add_rr_param: second
RR lump found
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:rr:add_rr_param: second
RR lump found
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]:
DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:db_new_result:
allocate 48 bytes for result set at 0x7fb3b2ef0970
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]:
DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]:
DBG:core:db_allocate_columns: allocate 56 bytes for result columns at
0x7fb3b2ef09b8
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]:
DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7fb3b2ef09c8)[0]=[username]
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]:
DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]:
DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7fb3b2ef09d8)[1]=[domain]
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]:
DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]:
DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:alias_db:alias_db_query:
no alias found for R-URI
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:db_free_columns:
freeing result columns at 0x7fb3b2ef09b8
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:db_free_rows:
freeing 0 rows
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:db_free_result:
freeing result set at 0x7fb3b2ef0970
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: [email protected]
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: Jumped to Outbound.
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: FS tries to call PBX!
[email protected]:5080 via 10.250.5.50
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: FS tries to call PBX!
[email protected]:5060 via 10.250.5.50
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_headers:
flags=ffffffffffffffff
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:decode_mime_type:
Decoding MIME type for:[application/sdp]
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:comp_scriptvar: str
20 : 10.250.5.50
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: Offer rtpp Outbound.
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]:
DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1 <rie> and param2
<none>
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_headers:
flags=40
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]:
DBG:rtpproxy:force_rtp_proxy: Forcing body:#012[v=0#015#012o=FreeSWITCH
1457938126 1457938127 IN IP4 10.250.5.50#015#012s=FreeSWITCH#015#012c=IN IP4
10.250.5.50#015#012t=0 0#015#012m=audio 17984 RTP/AVP 8 101#015#012a=rtpmap:8
PCMA/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101
0-16#015#012a=ptime:20#015#012]
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]:
DBG:rtpproxy:force_rtp_proxy_body: trying new rtpproxy node localhost:5006
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]:
DBG:rtpproxy:force_rtp_proxy_body: proxy reply: 35022 192.168.1.150
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:tm:t_newtran:
transaction on entrance=(nil)
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_headers:
flags=ffffffffffffffff
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_headers:
flags=78
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:tm:t_lookup_request:
start searching: hash=30020, isACK=0
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:tm:matching_3261:
RFC3261 transaction matching failed
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:tm:t_lookup_request: no
transaction found
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:tm:run_reqin_callbacks:
trans=0x7fb36ea19510, callback type 1, id 1 entered
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:dialog:dlg_onreq: t
hash_index = 30020, t label = 223596535
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:tm:run_reqin_callbacks:
trans=0x7fb36ea19510, callback type 1, id 0 entered
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_headers:
flags=78
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_headers:
flags=ffffffffffffffff
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:_shm_resize:
resize(0) called
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:tm:_reply_light: reply
sent out. buf=0x7fb3b2ef1238: SIP/2.0 1..., shmem=0x7fb36ea1ce18: SIP/2.0 1
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:tm:_reply_light: finished
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: new branch at
sip:[email protected]:5060
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:mk_proxy: doing DNS
lookup...
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_headers:
flags=2000
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:parse_headers:
flags=ffffffffffffffff
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:clen_builder:
content-length: 238 (238)
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:tm:set_timer: relative
timeout is 500000
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:tm:insert_timer_unsafe:
[4]: 0x7fb36ea19730 (24100000)
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:tm:insert_timer_unsafe:
[0]: 0x7fb36ea19760 (28)
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:tm:t_relay_to: new
transaction fwd'ed
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:tm:t_unref:
UNREF_UNSAFE: [0x7fb36ea19510] after is 0
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:dialog:unref_dlg: unref
dlg 0x7fb36ea18a18 with 1 -> 3 in entry 0x7fb36e9f43d8
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:destroy_avp_list:
destroying list (nil)
Mar 14 12:48:29 r5dev-osipstest ./opensips[28089]: DBG:core:receive_msg:
cleaning up
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_msg: SIP
Reply (status):
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_msg:
version: <SIP/2.0>
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_msg: status:
<400>
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_msg: reason:
<Bad Request>
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_headers:
flags=2
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_to_param:
tag=73249f74b80225097691065c86c67aec
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_to: end of
header reached, state=29
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_to:
display={}, ruri={sip:[email protected]:5080}
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:get_hdr_field: <To>
[67]; uri=[sip:[email protected]:5080]
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:get_hdr_field: to
body [<sip:[email protected]:5080>]
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:get_hdr_field: cseq
<CSeq>: <88641991> <INVITE>
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK4457.7ffc35d.0>; state=16
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_via: end of
header reached, state=5
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_headers: via
found, flags=2
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_headers: this
is the first via
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:receive_msg: After
parse_msg...
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:forward_reply:
found module nathelper, passing reply to it
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_headers:
flags=4
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_via_param:
found param type 234, <received> = <10.250.5.50>; state=6
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_via_param:
found param type 235, <rport> = <5090>; state=6
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK1ytH5t8ZyF3aH>; state=16
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_via: end of
header reached, state=5
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_headers: via
found, flags=4
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_headers:
parse_headers: this is the second via
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:forward_reply:
found module tm, passing reply to it
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:t_check:
start=0xffffffffffffffff
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_headers:
flags=22
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_headers:
flags=8
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:t_reply_matching:
hash 30020 label 223596535 branch 0
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:t_reply_matching:
REF_UNSAFE:[0x7fb36ea19510] after is 1
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:t_reply_matching:
reply matched (T=0x7fb36ea19510)!
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:run_trans_callbacks:
trans=0x7fb36ea19510, callback type 2, id 1 entered
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:t_check:
end=0x7fb36ea19510
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:reply_received: org.
status uas=100, uac[0]=0 local=0 is_invite=1)
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_headers:
flags=18
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:get_hdr_field:
content_length=0
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:get_hdr_field:
found end of header
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: ERROR:tm:send_ack: failed to
generate a HBH ACK if key HFs in reply missing
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: ERROR:tm:reply_received:
failed to send ACK (local=no)
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:parse_headers:
flags=20
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:sipmsgops:has_body_f:
content length is zero
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:buf_init:
initializing...
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: incoming reply
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]:
DBG:tm:t_should_relay_response: T_code=100, new_code=400
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:t_pick_branch: picked
branch 0, code 400 (prio=600)
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:is_3263_failure:
dns-failover test: branch=0, last_recv=400, flags=2
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:relay_reply:
branch=0, save=0, relay=0
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:run_trans_callbacks:
trans=0x7fb36ea19510, callback type 8, id 0 entered
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]:
DBG:dialog:push_reply_in_dialog: 0x7fb36ea18a18 totag in rpl is
<73249f74b80225097691065c86c67aec> (32)
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]:
DBG:dialog:push_reply_in_dialog: new branch with tag
<73249f74b80225097691065c86c67aec>
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:dialog:init_leg_info:
route_set , contact , cseq 88641991 and bind_addr udp:192.168.1.150:5060
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:dialog:dlg_add_leg_info:
set leg 1 for 0x7fb36ea18a18: tag=<73249f74b80225097691065c86c67aec>
rcseq=<88641991>
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]:
DBG:core:build_res_buf_from_sip_res: old size: 403, new size: 337
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]:
DBG:core:build_res_buf_from_sip_res: copied size: orig:287, new: 221, rest: 116
msg=#012SIP/2.0 400 Bad Request#015#012Warning: 399 192.168.1.30 "Malformed
headers : From "#015#012To:
<sip:[email protected]:5080>;tag=73249f74b80225097691065c86c67aec#015#012Call-ID:
83c45345-647d-1234-e187-000c295a647b#015#012CSeq: 88641991 INVITE#015#012Via:
SIP/2.0/UDP
10.250.5.50:5090;received=10.250.5.50;rport=5090;branch=z9hG4bK1ytH5t8ZyF3aH#015#012Content-Length:
0
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:set_timer: relative
timeout is 500000
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:insert_timer_unsafe:
[4]: 0x7fb36ea19658 (24100000)
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:insert_timer_unsafe:
[0]: 0x7fb36ea19688 (28)
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:run_trans_callbacks:
trans=0x7fb36ea19510, callback type 64, id 0 entered
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:evi_param_set:
adding string param
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:evi_param_set:
adding string param
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:evi_param_set:
adding int param
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:evi_param_set:
adding int param
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:destroy_avp_list:
destroying list (nil)
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:dialog:next_state_dlg:
dialog 0x7fb36ea18a18 changed from state 1 to state 5, due event 4
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:dialog:dlg_onreply:
dialog 0x7fb36ea18a18 failed (negative reply)
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:dialog:unref_dlg: unref
dlg 0x7fb36ea18a18 with 1 -> 2 in entry 0x7fb36e9f43d8
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:relay_reply: sent
buf=0x7fb3b2eefc90: SIP/2.0 4..., shmem=0x7fb36ea1ce18: SIP/2.0 4
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:run_trans_callbacks:
trans=0x7fb36ea19510, callback type 128, id 1 entered
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:cleanup_uac_timers:
RETR/FR timers reset
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:tm:t_unref:
UNREF_UNSAFE: [0x7fb36ea19510] after is 0
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:destroy_avp_list:
destroying list (nil)
Mar 14 12:48:29 r5dev-osipstest ./opensips[28080]: DBG:core:receive_msg:
cleaning up
Mar 14 12:48:29 r5dev-osipstest ./opensips[28090]: DBG:tm:utimer_routine: timer
routine:4,tl=0x7fb36ea19730 next=0x7fb36ea19658, timeout=24100000
Mar 14 12:48:29 r5dev-osipstest ./opensips[28090]: DBG:tm:utimer_routine: timer
routine:4,tl=0x7fb36ea19658 next=(nil), timeout=24100000
Mar 14 12:48:29 r5dev-osipstest ./opensips[28090]:
DBG:tm:retransmission_handler: retransmission_handler : reply resending
(t=0x7fb36ea19510, SIP/2.0 4 ... )
Mar 14 12:48:29 r5dev-osipstest ./opensips[28090]: DBG:tm:t_retransmit_reply:
buf=0x7fb3b2a9dfc0: SIP/2.0 4..., shmem=0x7fb36ea1ce18: SIP/2.0 4
Mar 14 12:48:29 r5dev-osipstest ./opensips[28090]: DBG:tm:set_timer: relative
timeout is 1000000
Mar 14 12:48:29 r5dev-osipstest ./opensips[28090]: DBG:tm:insert_timer_unsafe:
[5]: 0x7fb36ea19658 (25100000)
Mar 14 12:48:29 r5dev-osipstest ./opensips[28090]:
DBG:tm:retransmission_handler: retransmission_handler : done
Mar 14 12:48:30 r5dev-osipstest ./opensips[28090]: DBG:tm:utimer_routine: timer
routine:5,tl=0x7fb36ea19658 next=(nil), timeout=25100000
Mar 14 12:48:30 r5dev-osipstest ./opensips[28090]:
DBG:tm:retransmission_handler: retransmission_handler : reply resending
(t=0x7fb36ea19510, SIP/2.0 4 ... )
Mar 14 12:48:30 r5dev-osipstest ./opensips[28090]: DBG:tm:t_retransmit_reply:
buf=0x7fb3b2a9dfc0: SIP/2.0 4..., shmem=0x7fb36ea1ce18: SIP/2.0 4
Mar 14 12:48:30 r5dev-osipstest ./opensips[28090]: DBG:tm:set_timer: relative
timeout is 2000000
Mar 14 12:48:30 r5dev-osipstest ./opensips[28090]: DBG:tm:insert_timer_unsafe:
[6]: 0x7fb36ea19658 (27100000)
Mar 14 12:48:30 r5dev-osipstest ./opensips[28090]:
DBG:tm:retransmission_handler: retransmission_handler : done
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_msg: SIP
Request:
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_msg: method:
<CANCEL>
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_msg: uri:
<sip:[email protected]:5080>
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_msg:
version: <SIP/2.0>
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_headers:
flags=2
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_via_param:
found param type 235, <rport> = <n/a>; state=6
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK1ytH5t8ZyF3aH>; state=16
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_via: end of
header reached, state=5
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_headers: via
found, flags=2
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_headers: this
is the first via
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:receive_msg: After
parse_msg...
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:receive_msg:
preparing to run routing scripts...
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_headers:
flags=100
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]:
DBG:maxfwd:is_maxfwd_present: value = 69
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_headers:
flags=8
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_to: end of
header reached, state=10
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_to:
display={}, ruri={sip:[email protected]:5080}
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:get_hdr_field: <To>
[30]; uri=[sip:[email protected]:5080]
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:get_hdr_field: to
body [<sip:[email protected]:5080>#015#012]
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:uri:has_totag: no totag
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:buf_init:
initializing...
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: Into cancel method line 265.
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_headers:
flags=78
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:get_hdr_field: cseq
<CSeq>: <88641991> <CANCEL>
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:t_lookupOriginalT:
searching on hash entry 30020
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:matching_3261:
RFC3261 transaction matched, tid=1ytH5t8ZyF3aH
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:t_lookupOriginalT:
canceled transaction found (0x7fb36ea19510)!
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:t_lookupOriginalT:
REF_UNSAFE:[0x7fb36ea19510] after is 1
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:run_trans_callbacks:
trans=0x7fb36ea19510, callback type 2048, id 0 entered
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:dialog:ref_dlg: ref dlg
0x7fb36ea18a18 with 1 -> 3
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:t_lookupOriginalT:
t_lookupOriginalT completed
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:t_newtran:
transaction on entrance=0xffffffffffffffff
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_headers:
flags=ffffffffffffffff
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:get_hdr_field:
content_length=0
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:get_hdr_field:
found end of header
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_headers:
flags=78
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:t_lookup_request:
start searching: hash=30020, isACK=0
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:matching_3261:
RFC3261 transaction matching failed
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:t_lookup_request: no
transaction found
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:run_reqin_callbacks:
trans=0x7fb36ea1d628, callback type 1, id 1 entered
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:dialog:ref_dlg: ref dlg
0x7fb36ea18a18 with 1 -> 4
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:run_reqin_callbacks:
trans=0x7fb36ea1d628, callback type 1, id 0 entered
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:parse_headers:
flags=ffffffffffffffff
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:_shm_resize:
resize(0) called
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:cleanup_uac_timers:
RETR/FR timers reset
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:insert_timer_unsafe:
[2]: 0x7fb36ea1d6a8 (31)
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:_reply_light: reply
sent out. buf=0x7fb3b2eefb48: SIP/2.0 2..., shmem=0x7fb36ea20038: SIP/2.0 2
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:_reply_light: finished
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:t_relay_to: new
transaction fwd'ed
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:t_unref_cell:
UNREF_UNSAFE: [0x7fb36ea19510] after is 0
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:tm:t_unref:
UNREF_UNSAFE: [0x7fb36ea1d628] after is 0
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:dialog:unref_dlg: unref
dlg 0x7fb36ea18a18 with 1 -> 3 in entry 0x7fb36e9f43d8
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:destroy_avp_list:
destroying list (nil)
Mar 14 12:48:31 r5dev-osipstest ./opensips[28090]: DBG:core:receive_msg:
cleaning up
Mar 14 12:48:32 r5dev-osipstest ./opensips[28090]: DBG:tm:utimer_routine: timer
routine:6,tl=0x7fb36ea19658 next=(nil), timeout=27100000
Mar 14 12:48:32 r5dev-osipstest ./opensips[28090]:
DBG:tm:retransmission_handler: retransmission_handler : reply resending
(t=0x7fb36ea19510, SIP/2.0 4 ... )
Mar 14 12:48:32 r5dev-osipstest ./opensips[28090]: DBG:tm:t_retransmit_reply:
buf=0x7fb3b2a9dfc0: SIP/2.0 4..., shmem=0x7fb36ea1ce18: SIP/2.0 4
Mar 14 12:48:32 r5dev-osipstest ./opensips[28090]: DBG:tm:set_timer: relative
timeout is 4000000
Mar 14 12:48:32 r5dev-osipstest ./opensips[28090]: DBG:tm:insert_timer_unsafe:
[7]: 0x7fb36ea19658 (31100000)
Mar 14 12:48:32 r5dev-osipstest ./opensips[28090]:
DBG:tm:retransmission_handler: retransmission_handler : done
Mar 14 11:53:32 r5dev-osipstest ./opensips[27999]: Into invite method.
Mar 14 11:53:32 r5dev-osipstest ./opensips[27999]: [email protected]
Mar 14 11:53:32 r5dev-osipstest ./opensips[27999]: Jumped to Outbound.
Mar 14 11:53:32 r5dev-osipstest ./opensips[27999]: FS tries to call PBX!
[email protected]:5080 via 10.250.5.50
Mar 14 11:53:32 r5dev-osipstest ./opensips[27999]: FS tries to call PBX!
[email protected]:5060 via 10.250.5.50
Mar 14 11:53:32 r5dev-osipstest ./opensips[27999]: Offer rtpp Outbound.
Mar 14 11:53:32 r5dev-osipstest ./opensips[27999]: new branch at
sip:[email protected]:5060
Mar 14 11:53:32 r5dev-osipstest ./opensips[27993]: ERROR:tm:send_ack: failed to
generate a HBH ACK if key HFs in reply missing
Mar 14 11:53:32 r5dev-osipstest ./opensips[27993]: ERROR:tm:reply_received:
failed to send ACK (local=no)
Mar 14 11:53:32 r5dev-osipstest ./opensips[27993]: incoming reply
Mar 14 11:53:33 r5dev-osipstest ./opensips[28004]: Into cancel method line 265.
debug=4
log_stderror=no
log_facility=LOG_LOCAL0
fork=yes
children=8
listen=udp:192.168.1.150:5060
listen=udp:10.250.5.3:5080
#set module path
mpath="/usr/local/opensips_21//lib64/opensips/modules/"
#### SIGNALING module
loadmodule "signaling.so"
#### StateLess module
loadmodule "sl.so"
#### Transaction Module
loadmodule "tm.so"
modparam("tm", "fr_timeout", 5)
modparam("tm", "fr_inv_timeout", 30)
modparam("tm", "restart_fr_on_each_reply", 0)
modparam("tm", "onreply_avp_mode", 1)
#### Record Route Module
loadmodule "rr.so"
/* do not append from tag to the RR (no need for this script) */
modparam("rr", "append_fromtag", 0)
#### MAX ForWarD module
loadmodule "maxfwd.so"
#### SIP MSG OPerationS module
loadmodule "sipmsgops.so"
#### FIFO Management Interface
loadmodule "mi_fifo.so"
modparam("mi_fifo", "fifo_name", "/tmp/opensips_fifo")
modparam("mi_fifo", "fifo_mode", 0666)
#### URI module
loadmodule "uri.so"
modparam("uri", "use_uri_table", 0)
#### MYSQL module
loadmodule "db_mysql.so"
#### USeR LOCation module
loadmodule "usrloc.so"
modparam("usrloc", "nat_bflag", "NAT")
modparam("usrloc", "db_mode", 0)
#### REGISTRAR module
loadmodule "registrar.so"
modparam("registrar", "tcp_persistent_flag", "TCP_PERSISTENT")
#### ACCounting module
loadmodule "acc.so"
/* what special events should be accounted ? */
modparam("acc", "early_media", 0)
modparam("acc", "report_cancels", 0)
/* by default we do not adjust the direct of the sequential requests.
if you enable this parameter, be sure the enable "append_fromtag"
in "rr" module */
modparam("acc", "detect_direction", 0)
modparam("acc", "failed_transaction_flag", "ACC_FAILED")
/* account triggers (flags) */
modparam("acc", "db_flag", "ACC_DO")
modparam("acc", "db_missed_flag", "ACC_MISSED")
modparam("acc", "db_url",
"mysql://root:<my password>@localhost/opensips")
#### ALIAS module
loadmodule "alias_db.so"
modparam("alias_db","db_url",
"mysql://root:<my password>@localhost/opensips")
#### DIALOG module
loadmodule "dialog.so"
modparam("dialog", "dlg_match_mode", 1)
modparam("dialog", "default_timeout", 21600) # 6 hours timeout
modparam("dialog", "db_mode", 2)
modparam("dialog", "db_url",
"mysql://root:<my password>@localhost/opensips")
#### NAT modules
loadmodule "nathelper.so"
modparam("nathelper", "natping_interval", 10)
modparam("nathelper", "ping_nated_only", 1)
modparam("nathelper","sipping_bflag", "SIP_PING_FLAG")
modparam("nathelper","sipping_from","sip:[email protected]")
modparam("nathelper", "received_avp", "$avp(received_nh)")
loadmodule "rtpproxy.so"
modparam("rtpproxy", "rtpproxy_sock", "udp:localhost:5006")
loadmodule "proto_udp.so"route {
force_rport();
if (!mf_process_maxfwd_header("2")) {
sl_send_reply("483","Too Many Hops");
exit;
}
if (has_totag()) {
xlog("Into Existing Session method!\n");
if (loose_route()) {
if ( $DLG_status!=NULL && !validate_dialog() ) {
xlog("In-Dialog $rm from $si (callid=$ci) is
not valid according to dialog\n");
}
if (is_method("BYE")) {
xlog("End Call!\n");
setflag(ACC_DO);
setflag(ACC_FAILED);
} else if (is_method("INVITE")) {
record_route();
}
route(relay);
} else {
if ( is_method("ACK") ) {
if ( t_check_trans() ) {
t_relay();
exit;
} else {
exit;
}
}
sl_send_reply("404","Not here");
}
exit;
}
if (is_method("CANCEL")) {
xlog("Into cancel method line 265.\n");
if ( t_check_trans() ) {
t_relay();
}
exit;
}
t_check_trans();
if (loose_route()) {
xlog("L_ERR", "Attempt to route with preloaded Route's
[$fu/$tu/$ru/$ci]");
if (!is_method("ACK"))
sl_send_reply("403","Preload Route denied");
exit;
}
if ( !(is_method("REGISTER") || (src_ip==192.168.1.30 &&
src_port==5060) ) ) {
if (from_uri==myself) {
} else {
if (!uri==myself) {
send_reply("403","Rely forbidden");
}
}
}
if (!is_method("REGISTER|MESSAGE"))
record_route();
if (is_method("INVITE")) {
xlog("Into invite method.\n");
if ( !create_dialog("B") ) {
send_reply("500","Internal Server Error");
exit;
}
setflag(ACC_DO);
}
if (is_method("PUBLISH|SUBSCRIBE")){
sl_send_reply("503","Service disabled");
}
if (is_method("REGISTER")) {
xlog("Into Register method line 304.\n");
if (!save("location")){
sl_reply_error();
}
exit;
}
if ($rU==NULL) {
sl_send_reply("484","Address Incomplete");
exit;
}
alias_db_lookup("dbaliases");
xlog("Recipient: $rU@$rd");
#FreeSWITCH
route(freeswitch);
#Outbound
route(outbound);
if (!lookup("location", "m")) {
t_newtran();
t_reply("404", "Not Found");
exit;
}
setflag(ACC_MISSED);
xlog("Reaching lowest Call Relay.\n");
route(relay);
}
route[outbound] {
xlog("Jumped to Outbound.\n");
if(!is_method("INVITE")){
return;
}
if ($rU=~"^[1-9][0-9]+$") {
xlog("FS tries to call PBX! $rU@$rd:$rp via $si");
$rd="192.168.1.30";
$rp="5060";
force_send_socket(udp:192.168.1.150:5060);
xlog("FS tries to call PBX! $rU@$rd:$rp via $si");
route(relay);
exit;
}
}
route[freeswitch] {
if(!is_method("INVITE")){
return;
}
if ( ($rU=~"^[5]$" || $rU=~"^[7]$") && src_ip==192.168.1.30 &&
src_port==5060) {
xlog("PBX tries to call FS! $rU@$rd:$rp via $si");
$rd="10.250.5.50";
$rp="5090";
force_send_socket(udp:10.250.5.3:5080);
route(relay);
exit;
}
}
route[relay] {
if (is_method("INVITE")) {
if (has_body("application/sdp") && $si=="192.168.1.30") {
xlog("Offer rtpp Inbound.\n");
rtpproxy_offer("rei");
}else{
xlog("Offer rtpp Outbound.\n");
rtpproxy_offer("rie");
}
t_on_branch("per_branch_ops");
t_on_reply("handle_nat");
t_on_failure("missed_call");
}
if (is_method("CANCEL|BYE")) {
rtpproxy_unforce();
}
if (!t_relay()) {
send_reply("500","Internal Error");
};
exit;
}
branch_route[per_branch_ops] {
xlog("new branch at $ru\n");
}
onreply_route[handle_nat] {
if( is_method("ACK") && has_body("application/sdp")){
xlog("Answer rtpp reply\n");
rtpproxy_answer("rie");
} else if(has_body("application/sdp")) {
xlog("Offer rtpp reply\n");
rtpproxy_offer("rei");
}
xlog("incoming reply\n");
}
failure_route[missed_call] {
if (t_was_cancelled()) {
xlog("Call cancelled.\n");
exit;
}
}
local_route {
if (is_method("BYE") && $DLG_dir=="UPSTREAM") {
acc_db_request("200 Dialog Timeout", "acc");
}
}
From FreeSWITCH UA to FreeSWITCH Server:
10.250.5.17:5090 -> 10.250.5.50:5090
INVITE sip:[email protected] SIP/2.0..Via: SIP/2.0/UDP 10.250.5.17:5090;b
ranch=z9hG4bK.I4KG97dOK;rport..From: <sip:[email protected]>;tag=MeYxCN9Lq..
To: sip:[email protected]: 20 INVITE..Call-ID: t2XYFvCyYU..Max-Forw
ards: 70..Route: <sip:10.250.5.50:5090;lr>..Supported: outbound..Allow: INV
ITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UP
DATE..Content-Type: application/sdp..Content-Length: 328..Contact: <sip:100
[email protected]:5090>;+sip.instance="<urn:uuid:2f0b19de-2db0-4bef-be7d-48bf48
3a8141>"..User-Agent: Linphone/3.9.1 (belle-sip/1.4.2)....v=0..o=1001 3679
1124 IN IP4 10.250.5.17..s=Talk..c=IN IP4 10.250.5.17..t=0 0..a=rtcp-xr:rcv
r-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics..m=audio 7078 R
TP/AVP 0 8 101..a=rtpmap:101 telephone-event/8000..m=video 9078 RTP/AVP 96
97..a=rtpmap:96 VP8/90000..a=rtpmap:97 H264/90000..a=fmtp:97 profile-level-
id=42801F..
10.250.5.50:5090 -> 10.250.5.17:5090
SIP/2.0 100 Trying..Via: SIP/2.0/UDP 10.250.5.17:5090;branch=z9hG4bK.I4KG97
dOK;rport=5090..From: <sip:[email protected]>;tag=MeYxCN9Lq..To: <sip:185511
@192.168.1.30>..Call-ID: t2XYFvCyYU..CSeq: 20 INVITE..User-Agent: FreeSWITC
H-mod_sofia/1.7.0+git~20151211T002348Z~cae255395f~64bit..Content-Length: 0.
...
From FreeSWITCH Server to OpenSIPS:
10.250.5.50:5090 -> 10.250.5.3:5080
INVITE sip:[email protected]:5080 SIP/2.0..Via: SIP/2.0/UDP 10.250.5.50:509
0;rport;branch=z9hG4bKQ4XSKc0vUp4FD..Max-Forwards: 69..From: "1001" <sip:10
01@[10.250.5.50:5090]>;tag=2XyUKHFD2y6pF..To: <sip:[email protected]:5080>.
.Call-ID: 65474177-6471-1234-e187-000c295a647b..CSeq: 88639388 INVITE..Cont
act: <sip:[email protected]:5090;transport=udp;gw=osips>..User-Agent: Fr
eeSWITCH-mod_sofia/1.7.0+git~20151211T002348Z~cae255395f~64bit..Allow: INVI
TE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTI
FY..Supported: timer, path, replaces..Allow-Events: talk, hold, conference,
refer..Content-Type: application/sdp..Content-Disposition: session..Conten
t-Length: 218..X-FS-Support: update_display,send_info..Remote-Party-ID: "10
01" <sip:[email protected]:5090>;party=calling;screen=yes;privacy=off....v=0
..o=FreeSWITCH 1457928161 1457928162 IN IP4 10.250.5.50..s=FreeSWITCH..c=IN
IP4 10.250.5.50..t=0 0..m=audio 22744 RTP/AVP 8 101..a=rtpmap:8 PCMA/8000.
.a=rtpmap:101 telephone-event/8000..a=fmtp:101 0-16..a=ptime:20..
U 10.250.5.3:5080 -> 10.250.5.50:5090
SIP/2.0 100 Giving a try..Via: SIP/2.0/UDP 10.250.5.50:5090;received=10.250
.5.50;rport=5090;branch=z9hG4bKQ4XSKc0vUp4FD..From: "1001" <sip:1001@[10.25
0.5.50:5090]>;tag=2XyUKHFD2y6pF..To: <sip:[email protected]:5080>..Call-ID:
65474177-6471-1234-e187-000c295a647b..CSeq: 88639388 INVITE..Server: OpenS
IPS (2.1.2 (x86_64/linux))..Content-Length: 0....
U 10.250.5.3:5080 -> 10.250.5.50:5090
SIP/2.0 400 Bad Request..Warning: 399 192.168.1.30 "Malformed headers : Fro
m "..To: <sip:[email protected]:5080>;tag=7ea5fd275b6bfe2bcdd1565b6841ecc6.
.Call-ID: 65474177-6471-1234-e187-000c295a647b..CSeq: 88639388 INVITE..Via:
SIP/2.0/UDP 10.250.5.50:5090;received=10.250.5.50;rport=5090;branch=z9hG4b
KQ4XSKc0vUp4FD..Content-Length: 0....
After that only timeout or cancels ends sending this error.
_______________________________________________
Users mailing list
[email protected]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
