[OpenSIPS-Users] Understanding statefuli proxy mode opensips.

Sun Jun 23 05:13:56 EDT 2019

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 at 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:+999999999 at My-server.ru;user=phone}
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:get_hdr_field: <To> [49]; uri=[sip:+5555555555 at My-server.ru;user=phone]
Jun 23 07:05:55 xx-xxx-1 /usr/sbin/opensips[18398]: DBG:core:get_hdr_field: to body [<sip:+999999999 at My-server.ru;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:+999999999 at Mu-server.ru.ru;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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20190623/8811d74b/attachment-0001.html>