Hello everyone!
I'm trying to understand the internal mechanisms of opensips. I assume that by
default opensips works like a statefull proxy. In my installation, opensips
serves as a sip proxy. Balances incoming traffic between multiple freeswitch.
And so I get INVITE from the external system. The first. I look at the log
debug and I do not see that any transaction is being created about this.
Does this mean that incoming Invite starts being processed as stateless?
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:parse_msg: SIP
Request:
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:parse_msg: method:
<INVITE>
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:parse_msg: uri:
<sip:999999999@My-server;user=phone>
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:parse_msg:
version: <SIP/2.0>
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:parse_headers:
flags=2
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK-23003-1-0>; state=16
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:parse_via: end of
header reached, state=5
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:parse_headers: via
found, flags=2
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:parse_headers:
this is the first via
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:receive_msg: After
parse_msg...
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:receive_msg:
preparing to run routing scripts...
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:parse_headers:
flags=100
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:_parse_to: end of
header reached, state=10
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:_parse_to:
display={}, ruri={sip:[email protected];user=phone}
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:get_hdr_field:
<To> [49]; uri=[sip:[email protected];user=phone]
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:get_hdr_field: to
body [<sip:[email protected];user=phone>#015#012]
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:get_hdr_field:
cseq <CSeq>: <1> <INVITE>
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:get_hdr_field:
content_length=478
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:get_hdr_field:
found end of header
The second.
At a certain stage of processing Invites, I need to send request to AS via
http(using async_rest) and remove the ISUP body from this INVITE. As soon as
the script does it, Opensips tries to find a transaction for this INVITE.
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: MIME part from INVITE was
delete
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:tm:t_newtran:
transaction on entrance=(nil)
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:parse_headers:
flags=ffffffffffffffff
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:parse_headers:
flags=78
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:tm:t_lookup_request:
start searching: hash=25168, isACK=0
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:tm:matching_3261:
RFC3261 transaction matching failed
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:tm:t_lookup_request: no
transaction found
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:tm:run_reqin_callbacks:
trans=0x7fd9e490a6a0, callback type 1, id 0 entered
As I understand, opensips says that still there is no transaction for this
INVITE... And here comes a new function "run_reqin_callbacks".
Could you explain in more detail the essence of this function. After calling
this functions opensips looks like to start to work as statefull proxy. Or I am
wrong?
Third. I get a response from AS via http and send 403. It's just my
busines-logic for some INVITEs. For sending 403 I use "send_reply" functions.
From documentation I have read that "send_reply" works as statefull if original
request was statefull and stateless if original request was stateless. From
debug log I don't understand how this message was sent in fact.
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]:
DBG:rest_client:resume_async_http_req: HTTP response code: 200
Jun 23 07:05:55 xx-xxxx-1 /usr/sbin/opensips[18398]: DBG:tm:io_watch_del:
[UDP_worker] io_watch_del op on index -1 7 (0x8024c0, 7, -1, 0x10,0x1) fd_no=5
called
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:comp_scriptvar:
int 26 : 1 / 0
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:comp_scriptvar:
int 29 : 200 / 200
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]:
rest_post(http://127.0.0.1:28080/vms/v1/call_action) success, resp={ "action":
"reject", "isup_code": 21, "reason": "noservice", "sip_code": "403" }
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:comp_scriptvar:
str 20 : reject
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:comp_scriptvar:
str 20 : reject
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:parse_headers:
flags=ffffffffffffffff
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:tm:run_trans_callbacks:
trans=0x7fd9e490a6a0, callback type 64, id 0 entered
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:evi_param_set:
adding string param
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:evi_param_set:
adding string param
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:evi_param_set:
adding string param
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:evi_param_set:
adding string param
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:evi_param_set:
adding string param
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:evi_param_set:
adding int param
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:evi_param_set:
adding int param
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:destroy_avp_list:
destroying list (nil)
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:dialog:next_state_dlg:
dialog 0x7fd9e4909910 changed from state 1 to state 5, due event 4
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:dialog:dlg_onreply:
dialog 0x7fd9e4909910 failed (negative reply)
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:dialog:unref_dlg: unref
dlg 0x7fd9e4909910 with 1 -> 2 in entry 0x7fd9e48cfa60
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:tm:clean_msg_clone:
removing hdr->parsed 7
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:tm:cleanup_uac_timers:
RETR/FR timers reset
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:tm:insert_timer_unsafe:
[0]: 0x7fd9e490a818 (35659)
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:tm:_reply_light: reply
sent out. buf=0x7fd9e8740a50: SIP/2.0 4..., shmem=0x7fd9e490ea50: SIP/2.0 4
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:tm:run_trans_callbacks:
trans=0x7fd9e490a6a0, callback type 32768, id 3 entered
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:siptrace:trace_tm_out:
TM out triggered req=(nil), rpl=0xffffffffffffffff
Jun 23 07:05:55 xx-spx-1 /usr/sbin/opensips[18396]: DBG:core:parse_msg: SIP
Request:
Jun 23 07:05:55 xx-spx-1 /usr/sbin/opensips[18396]: DBG:core:parse_msg: method:
<ACK>
Jun 23 07:05:55 xx-spx-1 /usr/sbin/opensips[18396]: DBG:core:parse_msg: uri:
<sip:[email protected];user=phone>
Jun 23 07:05:55 xx-spx-1 /usr/sbin/opensips[18398]:
DBG:siptrace:trace_onreply_out: trace onreply out
Jun 23 07:05:55 xx-spx-1 /usr/sbin/opensips[18398]: DBG:core:parse_headers:
flags=40
Jun 23 07:05:55 xx-spx-1 /usr/sbin/opensips[18398]: DBG:siptrace:pipport2su:
proto 132, host 192.168.50.11 , port 5060
Jun 23 07:05:55 xx-spx-1 /usr/sbin/opensips[18398]: DBG:siptrace:pipport2su:
proto 132, host 192.168.50.61 , port 5060
Jun 23 07:05:55 xx-spx-1 /usr/sbin/opensips[18398]:
DBG:proto_hep:add_hep_chunk: Chunk with (id=17; vendor=0) not found! Creating!
Jun 23 07:05:55 xx-spx-1 /usr/sbin/opensips[18398]:
DBG:proto_hep:add_hep_chunk: Hep chunk with (id=17; vendor=0) successfully
built!
Jun 23 07:05:55 xx-spx-1 /usr/sbin/opensips[18398]: DBG:core:mk_proxy: doing
DNS lookup...
Jun 23 07:05:55 xx-spx-1 /usr/sbin/opensips[18398]: DBG:tm:_reply_light:
finished
Jun 23 07:05:55 xx-spx-1 /usr/sbin/opensips[18398]: The call was rejected with
403 and noservice
Jun 23 07:05:55 xx-spx-1 /usr/sbin/opensips[18398]: DBG:tm:t_unref:
UNREF_UNSAFE: [0x7fd9e490a6a0] after is 0
Jun 23 07:05:56 xx-spx-1 /usr/sbin/opensips[18398]: DBG:dialog:unref_dlg: unref
dlg 0x7fd9e4909910 with 1 -> 1 in entry 0
ACK comes to 403 immediately, which is already processed as it seems to me as a
statefull
Jun 23 07:05:56 xx-xxx-1 /usr/sbin/opensips[18396]: DBG:core:parse_headers:
flags=78
Jun 23 07:05:56 xx-xxx-1 /usr/sbin/opensips[18396]: DBG:tm:t_lookup_request:
start searching: hash=25168, isACK=1
Jun 23 07:05:56 xx-xxx-1 /usr/sbin/opensips[18396]: DBG:tm:matching_3261:
RFC3261 transaction matched, tid=-23003-1-0
Jun 23 07:05:56 xx-xxx-1 /usr/sbin/opensips[18396]: DBG:tm:t_lookup_request:
REF_UNSAFE:[0x7fd9e490a6a0] after is 1
Jun 23 07:05:56 xx-xxx-1 /usr/sbin/opensips[18396]: DBG:tm:t_lookup_request:
transaction found (T=0x7fd9e490a6a0)
Jun 23 07:05:56 xx-xxx-1 /usr/sbin/opensips[18396]: DBG:tm:run_trans_callbacks:
trans=0x7fd9e490a6a0, callback type 16384, id 2 entered
Jun 23 07:05:56 xx-xxx-1 /usr/sbin/opensips[18396]: DBG:siptrace:trace_tm_in:
TM in triggered req=0x7fd9e871a7f8, rpl=(nil)
Jun 23 07:05:56 xx-xxx-1 /usr/sbin/opensips[18396]: DBG:core:parse_headers:
flags=40
Results
How to make opensips when accepting INVITE immediately start working as a
statefull proxy? What is the function for "run_reqin_callbacks".?
I want to achieve the following behavior from my system:
I get an invite. I process it. Maybe I will complete some 403 calls right at
opensips. If this happens. Then I want to re-send 403 until I get an ACK on 403
from the remote side.
--
Oleg Podguyko_______________________________________________
Users mailing list
[email protected]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
