Just attached the debug log.
Very Respectfully
Dimitry Nagorny
Trainee
robot5 GmbH
_____________________________________________________________
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.
./opensips[28089]: DBG:core:parse_msg: SIP Request:
./opensips[28089]: DBG:core:parse_msg:method:<INVITE>
./opensips[28089]: DBG:core:parse_msg:uri: <sip:[email protected]:5080>
./opensips[28089]: DBG:core:parse_msg:version: <SIP/2.0>
./opensips[28089]: DBG:core:parse_headers: flags=2
./opensips[28089]: DBG:core:parse_via_param: found param type 235, <rport> =
<n/a>; state=6
./opensips[28089]: DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bK1ytH5t8ZyF3aH>; state=16
./opensips[28089]: DBG:core:parse_via: end of header reached, state=5
./opensips[28089]: DBG:core:parse_headers: via found, flags=2
./opensips[28089]: DBG:core:parse_headers: this is the first via
./opensips[28089]: DBG:core:receive_msg: After parse_msg...
./opensips[28089]: DBG:core:receive_msg: preparing to run routing scripts...
./opensips[28089]: DBG:core:parse_headers: flags=100
./opensips[28089]: DBG:maxfwd:is_maxfwd_present: value = 69
./opensips[28089]: DBG:core:parse_headers: flags=8
./opensips[28089]: DBG:core:parse_to: end of header reached, state=10
./opensips[28089]: DBG:core:parse_to: display={},
ruri={sip:[email protected]:5080}
./opensips[28089]: DBG:core:get_hdr_field: <To> [30];
uri=[sip:[email protected]:5080]
./opensips[28089]: DBG:core:get_hdr_field: to body
[<sip:[email protected]:5080>#015#012]
./opensips[28089]: DBG:uri:has_totag: no totag
./opensips[28089]: DBG:core:parse_headers: flags=78
./opensips[28089]: DBG:core:get_hdr_field: cseq <CSeq>: <88641991> <INVITE>
./opensips[28089]: DBG:tm:t_lookup_request: start searching: hash=30020, isACK=0
./opensips[28089]: DBG:tm:matching_3261: RFC3261 transaction matching failed
./opensips[28089]: DBG:tm:t_lookup_request: no transaction found
./opensips[28089]: DBG:core:parse_headers: flags=200
./opensips[28089]: DBG:core:get_hdr_field: content_length=218
./opensips[28089]: DBG:core:get_hdr_field: found end of header
./opensips[28089]: DBG:rr:find_first_route: No Route headers found
./opensips[28089]: DBG:rr:loose_route: There is no Route HF
./opensips[28089]: DBG:core:parse_to_param: tag=m05SKryceZQ7F
./opensips[28089]: DBG:core:parse_to: end of header reached, state=29
./opensips[28089]: DBG:core:parse_to: display={"1001"},
ruri={sip:1001@[10.250.5.50:5090]}
./opensips[28089]: DBG:core:grep_sock_info: checking if host==us: 16==13
&&[10.250.5.50:5090] == [192.168.1.150]
./opensips[28089]: DBG:core:grep_sock_info: checking if port 5060 matches port
5060
./opensips[28089]: DBG:core:grep_sock_info: checking if host==us: 16==10
&&[10.250.5.50:5090] == [10.250.5.3]
./opensips[28089]: DBG:core:grep_sock_info: checking if port 5080 matches port
5060
./opensips[28089]: DBG:core:check_self: host != me
./opensips[28089]: DBG:core:grep_sock_info: checking if host==us: 10==13
&&[10.250.5.3] == [192.168.1.150]
./opensips[28089]: DBG:core:grep_sock_info: checking if port 5060 matches port
5080
./opensips[28089]: DBG:core:grep_sock_info: checking if host==us: 10==10
&&[10.250.5.3] == [10.250.5.3]
./opensips[28089]: DBG:core:grep_sock_info: checking if port 5080 matches port
5080
./opensips[28089]: DBG:core:buf_init: initializing...
./opensips[28089]: Into invite method.
./opensips[28089]: DBG:dialog:w_create_dialog2: bye on timeout activated
./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
./opensips[28089]: DBG:core:parse_headers: flags=ffffffffffffffff
./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
./opensips[28089]: DBG:dialog:dlg_add_leg_info: set leg 0 for 0x7fb36ea18a18:
tag=<m05SKryceZQ7F> rcseq=<0>
./opensips[28089]: DBG:dialog:link_dlg: ref dlg 0x7fb36ea18a18 with 4 -> 4 in
h_entry 0x7fb36e9f43d8 - 1723
./opensips[28089]: DBG:rr:add_rr_param: adding (;did=bb6.b255faa3)
./opensips[28089]: DBG:rr:add_rr_param: second RR lump found
./opensips[28089]: DBG:rr:add_rr_param: second RR lump found
./opensips[28089]: DBG:db_mysql:mysql_raise_event: MySQL status has not
changed: connected
./opensips[28089]: DBG:core:db_new_result: allocate 48 bytes for result set at
0x7fb3b2ef0970
./opensips[28089]: DBG:db_mysql:db_mysql_get_columns: 2 columns returned from
the query
./opensips[28089]: DBG:core:db_allocate_columns: allocate 56 bytes for result
columns at 0x7fb3b2ef09b8
./opensips[28089]: DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7fb3b2ef09c8)[0]=[username]
./opensips[28089]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
./opensips[28089]: DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7fb3b2ef09d8)[1]=[domain]
./opensips[28089]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
./opensips[28089]: DBG:db_mysql:db_mysql_convert_rows: no rows returned from
the query
./opensips[28089]: DBG:alias_db:alias_db_query: no alias found for R-URI
./opensips[28089]: DBG:core:db_free_columns: freeing result columns at
0x7fb3b2ef09b8
./opensips[28089]: DBG:core:db_free_rows: freeing 0 rows
./opensips[28089]: DBG:core:db_free_result: freeing result set at 0x7fb3b2ef0970
./opensips[28089]: [email protected]
./opensips[28089]: Jumped to Outbound.
./opensips[28089]: FS tries to call PBX! [email protected]:5080 via 10.250.5.50
./opensips[28089]: FS tries to call PBX! [email protected]:5060 via
10.250.5.50
./opensips[28089]: DBG:core:parse_headers: flags=ffffffffffffffff
./opensips[28089]: DBG:core:decode_mime_type: Decoding MIME type
for:[application/sdp]
./opensips[28089]: DBG:core:comp_scriptvar: str 20 : 10.250.5.50
./opensips[28089]: Offer rtpp Outbound.
./opensips[28089]: DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1
<rie> and param2 <none>
./opensips[28089]: DBG:core:parse_headers: flags=40
./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]
./opensips[28089]: DBG:rtpproxy:force_rtp_proxy_body: trying new rtpproxy node
localhost:5006
./opensips[28089]: DBG:rtpproxy:force_rtp_proxy_body: proxy reply: 35022
192.168.1.150
./opensips[28089]: DBG:tm:t_newtran: transaction on entrance=(nil)
./opensips[28089]: DBG:core:parse_headers: flags=ffffffffffffffff
./opensips[28089]: DBG:core:parse_headers: flags=78
./opensips[28089]: DBG:tm:t_lookup_request: start searching: hash=30020, isACK=0
./opensips[28089]: DBG:tm:matching_3261: RFC3261 transaction matching failed
./opensips[28089]: DBG:tm:t_lookup_request: no transaction found
./opensips[28089]: DBG:tm:run_reqin_callbacks: trans=0x7fb36ea19510, callback
type 1, id 1 entered
./opensips[28089]: DBG:dialog:dlg_onreq: t hash_index = 30020, t label =
223596535
./opensips[28089]: DBG:tm:run_reqin_callbacks: trans=0x7fb36ea19510, callback
type 1, id 0 entered
./opensips[28089]: DBG:core:parse_headers: flags=78
./opensips[28089]: DBG:core:parse_headers: flags=ffffffffffffffff
./opensips[28089]: DBG:core:_shm_resize: resize(0) called
./opensips[28089]: DBG:tm:_reply_light: reply sent out. buf=0x7fb3b2ef1238:
SIP/2.0 1..., shmem=0x7fb36ea1ce18: SIP/2.0 1
./opensips[28089]: DBG:tm:_reply_light: finished
./opensips[28089]: new branch at sip:[email protected]:5060
./opensips[28089]: DBG:core:mk_proxy: doing DNS lookup...
./opensips[28089]: DBG:core:parse_headers: flags=2000
./opensips[28089]: DBG:core:parse_headers: flags=ffffffffffffffff
./opensips[28089]: DBG:core:clen_builder: content-length: 238 (238)
./opensips[28089]: DBG:tm:set_timer: relative timeout is 500000
./opensips[28089]: DBG:tm:insert_timer_unsafe: [4]: 0x7fb36ea19730 (24100000)
./opensips[28089]: DBG:tm:insert_timer_unsafe: [0]: 0x7fb36ea19760 (28)
./opensips[28089]: DBG:tm:t_relay_to: new transaction fwd'ed
./opensips[28089]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fb36ea19510] after is 0
./opensips[28089]: DBG:dialog:unref_dlg: unref dlg 0x7fb36ea18a18 with 1 -> 3
in entry 0x7fb36e9f43d8
./opensips[28089]: DBG:core:destroy_avp_list: destroying list (nil)
./opensips[28089]: DBG:core:receive_msg: cleaning up
./opensips[28080]: DBG:core:parse_msg: SIP Reply(status):
./opensips[28080]: DBG:core:parse_msg:version: <SIP/2.0>
./opensips[28080]: DBG:core:parse_msg:status:<400>
./opensips[28080]: DBG:core:parse_msg:reason:<Bad Request>
./opensips[28080]: DBG:core:parse_headers: flags=2
./opensips[28080]: DBG:core:parse_to_param: tag=73249f74b80225097691065c86c67aec
./opensips[28080]: DBG:core:parse_to: end of header reached, state=29
./opensips[28080]: DBG:core:parse_to: display={},
ruri={sip:[email protected]:5080}
./opensips[28080]: DBG:core:get_hdr_field: <To> [67];
uri=[sip:[email protected]:5080]
./opensips[28080]: DBG:core:get_hdr_field: to body
[<sip:[email protected]:5080>]
./opensips[28080]: DBG:core:get_hdr_field: cseq <CSeq>: <88641991> <INVITE>
./opensips[28080]: DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bK4457.7ffc35d.0>; state=16
./opensips[28080]: DBG:core:parse_via: end of header reached, state=5
./opensips[28080]: DBG:core:parse_headers: via found, flags=2
./opensips[28080]: DBG:core:parse_headers: this is the first via
./opensips[28080]: DBG:core:receive_msg: After parse_msg...
./opensips[28080]: DBG:core:forward_reply: found module nathelper, passing
reply to it
./opensips[28080]: DBG:core:parse_headers: flags=4
./opensips[28080]: DBG:core:parse_via_param: found param type 234, <received> =
<10.250.5.50>; state=6
./opensips[28080]: DBG:core:parse_via_param: found param type 235, <rport> =
<5090>; state=6
./opensips[28080]: DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bK1ytH5t8ZyF3aH>; state=16
./opensips[28080]: DBG:core:parse_via: end of header reached, state=5
./opensips[28080]: DBG:core:parse_headers: via found, flags=4
./opensips[28080]: DBG:core:parse_headers: parse_headers: this is the second via
./opensips[28080]: DBG:core:forward_reply: found module tm, passing reply to it
./opensips[28080]: DBG:tm:t_check: start=0xffffffffffffffff
./opensips[28080]: DBG:core:parse_headers: flags=22
./opensips[28080]: DBG:core:parse_headers: flags=8
./opensips[28080]: DBG:tm:t_reply_matching: hash 30020 label 223596535 branch 0
./opensips[28080]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7fb36ea19510] after
is 1
./opensips[28080]: DBG:tm:t_reply_matching: reply matched (T=0x7fb36ea19510)!
./opensips[28080]: DBG:tm:run_trans_callbacks: trans=0x7fb36ea19510, callback
type 2, id 1 entered
./opensips[28080]: DBG:tm:t_check: end=0x7fb36ea19510
./opensips[28080]: DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0
is_invite=1)
./opensips[28080]: DBG:core:parse_headers: flags=18
./opensips[28080]: DBG:core:get_hdr_field: content_length=0
./opensips[28080]: DBG:core:get_hdr_field: found end of header
./opensips[28080]: ERROR:tm:send_ack: failed to generate a HBH ACK if key HFs
in reply missing
./opensips[28080]: ERROR:tm:reply_received: failed to send ACK (local=no)
./opensips[28080]: DBG:core:parse_headers: flags=20
./opensips[28080]: DBG:sipmsgops:has_body_f: content length is zero
./opensips[28080]: DBG:core:buf_init: initializing...
./opensips[28080]: incoming reply
./opensips[28080]: DBG:tm:t_should_relay_response: T_code=100, new_code=400
./opensips[28080]: DBG:tm:t_pick_branch: picked branch 0, code 400 (prio=600)
./opensips[28080]: DBG:tm:is_3263_failure: dns-failover test: branch=0,
last_recv=400, flags=2
./opensips[28080]: DBG:tm:relay_reply: branch=0, save=0, relay=0
./opensips[28080]: DBG:tm:run_trans_callbacks: trans=0x7fb36ea19510, callback
type 8, id 0 entered
./opensips[28080]: DBG:dialog:push_reply_in_dialog: 0x7fb36ea18a18 totag in rpl
is <73249f74b80225097691065c86c67aec> (32)
./opensips[28080]: DBG:dialog:push_reply_in_dialog: new branch with tag
<73249f74b80225097691065c86c67aec>
./opensips[28080]: DBG:dialog:init_leg_info: route_set , contact , cseq
88641991 and bind_addr udp:192.168.1.150:5060
./opensips[28080]: DBG:dialog:dlg_add_leg_info: set leg 1 for 0x7fb36ea18a18:
tag=<73249f74b80225097691065c86c67aec> rcseq=<88641991>
./opensips[28080]: DBG:core:build_res_buf_from_sip_res:old size: 403, new size:
337
./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
./opensips[28080]: DBG:tm:set_timer: relative timeout is 500000
./opensips[28080]: DBG:tm:insert_timer_unsafe: [4]: 0x7fb36ea19658 (24100000)
./opensips[28080]: DBG:tm:insert_timer_unsafe: [0]: 0x7fb36ea19688 (28)
./opensips[28080]: DBG:tm:run_trans_callbacks: trans=0x7fb36ea19510, callback
type 64, id 0 entered
./opensips[28080]: DBG:core:evi_param_set: adding string param
./opensips[28080]: DBG:core:evi_param_set: adding string param
./opensips[28080]: DBG:core:evi_param_set: adding int param
./opensips[28080]: DBG:core:evi_param_set: adding int param
./opensips[28080]: DBG:core:destroy_avp_list: destroying list (nil)
./opensips[28080]: DBG:dialog:next_state_dlg: dialog 0x7fb36ea18a18 changed
from state 1 to state 5, due event 4
./opensips[28080]: DBG:dialog:dlg_onreply: dialog 0x7fb36ea18a18 failed
(negative reply)
./opensips[28080]: DBG:dialog:unref_dlg: unref dlg 0x7fb36ea18a18 with 1 -> 2
in entry 0x7fb36e9f43d8
./opensips[28080]: DBG:tm:relay_reply: sent buf=0x7fb3b2eefc90: SIP/2.0 4...,
shmem=0x7fb36ea1ce18: SIP/2.0 4
./opensips[28080]: DBG:tm:run_trans_callbacks: trans=0x7fb36ea19510, callback
type 128, id 1 entered
./opensips[28080]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
./opensips[28080]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fb36ea19510] after is 0
./opensips[28080]: DBG:core:destroy_avp_list: destroying list (nil)
./opensips[28080]: DBG:core:receive_msg: cleaning up
./opensips[28090]: DBG:tm:utimer_routine: timer routine:4,tl=0x7fb36ea19730
next=0x7fb36ea19658, timeout=24100000
./opensips[28090]: DBG:tm:utimer_routine: timer routine:4,tl=0x7fb36ea19658
next=(nil), timeout=24100000
./opensips[28090]: DBG:tm:retransmission_handler: retransmission_handler :
reply resending (t=0x7fb36ea19510, SIP/2.0 4 ... )
./opensips[28090]: DBG:tm:t_retransmit_reply: buf=0x7fb3b2a9dfc0: SIP/2.0 4...,
shmem=0x7fb36ea1ce18: SIP/2.0 4
./opensips[28090]: DBG:tm:set_timer: relative timeout is 1000000
./opensips[28090]: DBG:tm:insert_timer_unsafe: [5]: 0x7fb36ea19658 (25100000)
./opensips[28090]: DBG:tm:retransmission_handler: retransmission_handler : done
./opensips[28090]: DBG:tm:utimer_routine: timer routine:5,tl=0x7fb36ea19658
next=(nil), timeout=25100000
./opensips[28090]: DBG:tm:retransmission_handler: retransmission_handler :
reply resending (t=0x7fb36ea19510, SIP/2.0 4 ... )
./opensips[28090]: DBG:tm:t_retransmit_reply: buf=0x7fb3b2a9dfc0: SIP/2.0 4...,
shmem=0x7fb36ea1ce18: SIP/2.0 4
./opensips[28090]: DBG:tm:set_timer: relative timeout is 2000000
./opensips[28090]: DBG:tm:insert_timer_unsafe: [6]: 0x7fb36ea19658 (27100000)
./opensips[28090]: DBG:tm:retransmission_handler: retransmission_handler : done
./opensips[28090]: DBG:core:parse_msg: SIP Request:
./opensips[28090]: DBG:core:parse_msg:method:<CANCEL>
./opensips[28090]: DBG:core:parse_msg:uri: <sip:[email protected]:5080>
./opensips[28090]: DBG:core:parse_msg:version: <SIP/2.0>
./opensips[28090]: DBG:core:parse_headers: flags=2
./opensips[28090]: DBG:core:parse_via_param: found param type 235, <rport> =
<n/a>; state=6
./opensips[28090]: DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bK1ytH5t8ZyF3aH>; state=16
./opensips[28090]: DBG:core:parse_via: end of header reached, state=5
./opensips[28090]: DBG:core:parse_headers: via found, flags=2
./opensips[28090]: DBG:core:parse_headers: this is the first via
./opensips[28090]: DBG:core:receive_msg: After parse_msg...
./opensips[28090]: DBG:core:receive_msg: preparing to run routing scripts...
./opensips[28090]: DBG:core:parse_headers: flags=100
./opensips[28090]: DBG:maxfwd:is_maxfwd_present: value = 69
./opensips[28090]: DBG:core:parse_headers: flags=8
./opensips[28090]: DBG:core:parse_to: end of header reached, state=10
./opensips[28090]: DBG:core:parse_to: display={},
ruri={sip:[email protected]:5080}
./opensips[28090]: DBG:core:get_hdr_field: <To> [30];
uri=[sip:[email protected]:5080]
./opensips[28090]: DBG:core:get_hdr_field: to body
[<sip:[email protected]:5080>#015#012]_______________________________________________
Users mailing list
[email protected]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
