REFER with Replaces is ignored by Asterisk

fvv · November 13, 2019, 3:41pm

Hello,

I am experiencing an issue when calling from my Asterisk to an Alcatel OXE.

I call from an external number (PJSIP anonymous endpoint) and I dial 70018@oxe. The calls is answered and I do a blind transfer from 70018 to 60099 (another oxe user). Asterisk receives the following REFER message (see debug trace).

Asterisk accepts the REFER with a 202 and there is no INVITE generated from Asterisk to the new endpoint (60099). 70018 leaves the bridge and the anonymous endpoint is the only one left in the bridge.

I have added an external_replaces extension in my dialplan but it is not being used somehow…

Has anyone faced this issue before?

Thanks!

Debug trace:

REFER sip:asterisk@10.15.1.50:5060 SIP/2.0
Contact: sip:sip-n1.oxe1.mydomain.ch
Supported: timer,path,100rel
User-Agent: OmniPCX Enterprise R11.2.2 l2.300.33.a
Refer-To: <sip:60099@sip-n1.oxe1.mydomain.ch;user=phone?REPLACES=9fc12dc4-bbda-4ae3-b9ae-ee489ad017fe%3bto-tag%3df1adc0a8-dd76-45b7-b648-2409cfb1b63c%3bfrom-tag%3d6577bf301e3a81750da37d68e9190a60>
Referred-By: sip:70018@sip-n1.oxe1.mydomain.ch
To: sip:+34999999999@10.15.1.50;tag=f1adc0a8-dd76-45b7-b648-2409cfb1b63c
From: sip:70018@sip-n1.oxe1.mydomain.ch;tag=6577bf301e3a81750da37d68e9190a60
Call-ID: 9fc12dc4-bbda-4ae3-b9ae-ee489ad017fe
CSeq: 566070117 REFER
Via: SIP/2.0/UDP 137.138.34.239;branch=z9hG4bKcf205a6f33a0d52201e6673016b05b81
Max-Forwards: 70
Content-Length: 0

[Nov 13 15:57:14] DEBUG[32194] netsock2.c: Splitting 'myoxeip:5060' into...
[Nov 13 15:57:14] DEBUG[32194] netsock2.c: ...host 'myoxeip' and port '5060'.
[Nov 13 15:57:14] DEBUG[32194] netsock2.c: Splitting '10.15.1.50:5060' into...
[Nov 13 15:57:14] DEBUG[32194] netsock2.c: ...host '10.15.1.50' and port '5060'.
[Nov 13 15:57:14] DEBUG[32194] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f953c015ed8 for Request msg REFER/cseq=566070117 (rdata0x7f9524070fb8)
[Nov 13 15:57:14] DEBUG[32194] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/70018-00009f80 associated with dialog dlg0x7f953c015ed8
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_session.c: The state change pertains to the endpoint '70018(PJSIP/70018-0000035e)'
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_session.c: The UAS REFER transaction involved in this state change is 0x7f953c027968
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_session.c: The current transaction state is Trying
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_session.c: The transaction state change event is RX_MSG
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_session.c: The current inv state is CONFIRMED
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_session.c: Received request
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_session.c: Method is REFER
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_refer.c: Created progress monitor '0x7f94db0db660' for transfer occurring from channel 'PJSIP/70018-0000035e' and endpoint '70018'
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_refer.c: Accepting REFER request for progress monitor '0x7f944c033758'
[Nov 13 15:57:14] DEBUG[8162] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 10.15.1.50:5060 (this may be re-written again later)
[Nov 13 15:57:14] DEBUG[8162] netsock2.c: Splitting '10.15.1.50:5060' into...
[Nov 13 15:57:14] DEBUG[8162] netsock2.c: ...host '10.15.1.50' and port '5060'.
[Nov 13 15:57:14] DEBUG[8162] netsock2.c: Splitting '137.138.34.239:5060' into...
[Nov 13 15:57:14] DEBUG[8162] netsock2.c: ...host '137.138.34.239' and port '5060'.
[Nov 13 15:57:14] VERBOSE[8162] res_pjsip_logger.c: <--- Transmitting SIP response (625 bytes) to UDP:myoxeip:5060 --->
SIP/2.0 202 Accepted
Via: SIP/2.0/UDP 137.138.34.239;rport=5060;received=137.138.34.239;branch=z9hG4bKcf205a6f33a0d52201e6673016b05b81
Call-ID: 9fc12dc4-bbda-4ae3-b9ae-ee489ad017fe
From: <sip:70018@sip-n1.oxe1.mydomain.ch>;tag=6577bf301e3a81750da37d68e9190a60
To: <sip:+34999999999@10.15.1.50>;tag=f1adc0a8-dd76-45b7-b648-2409cfb1b63c
CSeq: 566070117 REFER
Expires: 600
Contact: <sip:asterisk@10.15.1.50:5060>
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Server: Asterisk PBX 13.27.1
Content-Length:  0


[Nov 13 15:57:14] DEBUG[8162] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_session.c: The state change pertains to the endpoint '70018(PJSIP/70018-0000035e)'
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_session.c: The UAS REFER transaction involved in this state change is 0x7f953c027968
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_session.c: The current transaction state is Completed
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_session.c: The transaction state change event is TX_MSG
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_session.c: The current inv state is CONFIRMED
[Nov 13 15:57:14] DEBUG[8162] res_pjsip_refer.c: Attended transfer from 'PJSIP/70018-0000035e' pushed to second channel serializer
**[Nov 13 15:57:14] DEBUG[8162] res_pjsip_refer.c: Performing a REFER attended transfer - Transferer #1: PJSIP/70018-0000035e Transferer #2: PJSIP/70018-0000035e**
[Nov 13 15:57:14] DEBUG[19973][C-000001ae] bridge_native_rtp.c: Bridge '510233fa-e5e0-42e2-95cd-67d45b633d9c'.  Tech starting 'PJSIP/anonymous-0000035d' and 'PJSIP/70018-0000035e' with target 'PJSIP/anonymous-0000035d'
[Nov 13 15:57:14] DEBUG[32155] devicestate.c: No provider found, checking channel drivers for PJSIP - anonymous
[Nov 13 15:57:14] VERBOSE[19973][C-000001ae] res_musiconhold.c: Stopped music on hold on PJSIP/anonymous-0000035d
[Nov 13 15:57:14] DEBUG[32155] res_odbc.c: Reusing ODBC handle 0x14ff508 from class 'asterisk'
[Nov 13 15:57:14] DEBUG[32155] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM ps_endpoints WHERE id = ?
[Nov 13 15:57:14] DEBUG[19973][C-000001ae] channel.c: Channel PJSIP/anonymous-0000035d setting write format path: alaw -> alaw
[Nov 13 15:57:14] DEBUG[19973][C-000001ae] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Nov 13 15:57:14] DEBUG[32155] res_config_odbc.c: Parameter 1 ('id') = 'anonymous'
[Nov 13 15:57:14] DEBUG[8162] bridge.c: Moving 0x7f9474006608(PJSIP/anonymous-0000035d) into bridge 510233fa-e5e0-42e2-95cd-67d45b633d9c swapping with PJSIP/70018-0000035e
[Nov 13 15:57:14] DEBUG[8162] bridge_channel.c: Bridge 510233fa-e5e0-42e2-95cd-67d45b633d9c: pulling 0x7f9474006608(PJSIP/anonymous-0000035d)
[Nov 13 15:57:14] DEBUG[32155] res_odbc.c: Releasing ODBC handle 0x14ff508 into pool
[Nov 13 15:57:14] VERBOSE[8162] bridge_channel.c: Channel PJSIP/anonymous-0000035d left 'native_rtp' basic-bridge <510233fa-e5e0-42e2-95cd-67d45b633d9c>
[Nov 13 15:57:14] DEBUG[8162] bridge_channel.c: Bridge 510233fa-e5e0-42e2-95cd-67d45b633d9c: 0x7f9474006608(PJSIP/anonymous-0000035d) is leaving native_rtp technology
[Nov 13 15:57:14] DEBUG[32155] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval
[Nov 13 15:57:14] DEBUG[8162] bridge_native_rtp.c: Bridge '510233fa-e5e0-42e2-95cd-67d45b633d9c'.  Channel 'PJSIP/anonymous-0000035d' is leaving bridge tech
[Nov 13 15:57:14] DEBUG[32155] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Nov 13 15:57:14] DEBUG[8162] bridge_native_rtp.c: Bridge '510233fa-e5e0-42e2-95cd-67d45b633d9c'.  Detaching hook data 0x7f9474006540 from 'PJSIP/anonymous-0000035d'
[Nov 13 15:57:14] DEBUG[32155] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0)
[Nov 13 15:57:14] DEBUG[8162] bridge_native_rtp.c: Bridge '510233fa-e5e0-42e2-95cd-67d45b633d9c'.  Tech stopping 'PJSIP/anonymous-0000035d' and 'PJSIP/70018-0000035e' with target 'none'
[Nov 13 15:57:14] DEBUG[32155] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Nov 13 15:57:14] DEBUG[8162] bridge_native_rtp.c: Discontinued RTP bridging of 'PJSIP/anonymous-0000035d' and 'PJSIP/70018-0000035e' - media will flow through Asterisk core
[Nov 13 15:57:14] DEBUG[8162] bridge_native_rtp.c: Destroying channel tech_pvt data 0x7f9474004c90
[Nov 13 15:57:14] DEBUG[32155] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Nov 13 15:57:14] DEBUG[32155] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Nov 13 15:57:14] DEBUG[32157] cdr.c: Finalized CDR for PJSIP/anonymous-0000035d - start 1573657028.152844 answer 1573657029.781731 end 1573657034.784586 dispo ANSWERED
[Nov 13 15:57:14] DEBUG[32155] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Nov 13 15:57:14] DEBUG[8162] bridge_channel.c: Bridge 510233fa-e5e0-42e2-95cd-67d45b633d9c: pushing 0x7f9474006608(PJSIP/anonymous-0000035d) by swapping with 0x7f9474006408(PJSIP/70018-0000035e)
[Nov 13 15:57:14] DEBUG[32155] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Nov 13 15:57:14] DEBUG[8162] bridge_channel.c: Setting 0x7f9474006408(PJSIP/70018-0000035e) state from:0 to:2
[Nov 13 15:57:14] DEBUG[8162] bridge_channel.c: Bridge 510233fa-e5e0-42e2-95cd-67d45b633d9c: pulling 0x7f9474006408(PJSIP/70018-0000035e)
[Nov 13 15:57:14] VERBOSE[8162] bridge_channel.c: Channel PJSIP/70018-0000035e left 'native_rtp' basic-bridge <510233fa-e5e0-42e2-95cd-67d45b633d9c>
[Nov 13 15:57:14] DEBUG[8162] bridge_channel.c: Bridge 510233fa-e5e0-42e2-95cd-67d45b633d9c: 0x7f9474006408(PJSIP/70018-0000035e) is leaving native_rtp technology
[Nov 13 15:57:14] DEBUG[8162] bridge_native_rtp.c: Bridge '510233fa-e5e0-42e2-95cd-67d45b633d9c'.  Channel 'PJSIP/70018-0000035e' is leaving bridge tech
[Nov 13 15:57:14] DEBUG[32155] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Nov 13 15:57:14] DEBUG[8162] bridge_native_rtp.c: Bridge '510233fa-e5e0-42e2-95cd-67d45b633d9c'.  Detaching hook data 0x7f9474004d20 from 'PJSIP/70018-0000035e'
[Nov 13 15:57:14] DEBUG[8162] bridge_native_rtp.c: Destroying channel tech_pvt data 0x7f94740106b0
[Nov 13 15:57:14] DEBUG[8162] bridge_channel.c: Channel PJSIP/70018-0000035e will survive this bridge; clearing outgoing (dialed) flag

david551 · November 13, 2019, 4:11pm

Assuming it works the same as chan_sip, I wouldn’t expect an INVITE at this point; I’d expect it at the time the enquiry call was made, unless the original enquiry completely bypassed Asterisk.

fvv · November 14, 2019, 10:17am

The original enquiry call bypasses Asterisk as this is a call within the Alcatel OXE.

In a similar call, when the destination is another extension in the Alcatel (not local to the switch), I am receiving a REFER withouth the Replaces part in the Refer-To. That triggers a dialplan query and a new Invite from Asterisk, following the latest modification to res_pjsip_refer I could find (ASTERISK-24376: res_pjsip_refer: REFER request for remote session attempts to direct channel to external_replaces extension instead of context, without providing for the Referred-To SIP URI):

Use the TRANSFER_CONTEXT if available

Use the endpoint context next

See if we have an extension matching the user portion of the Referred-To header.

If so, go there.

So 1 does not happen for me as I am not setting a transfer_context, so it analyses the endpoint context for the Refer-to user part and it finds a valid extension.

The weird thing is that this whole process is not being triggered with the Refer-To with a Replaces header that I added in my debug trace:

Refer-To: <sip:60099@sip-n1.oxe1.mydomain.ch;user=phone?REPLACES=9fc12dc4-bbda-4ae3-b9ae-ee489ad017fe%3bto-tag%3df1adc0a8-dd76-45b7-b648-2409cfb1b63c%3bfrom-tag%3d6577bf301e3a81750da37d68e9190a60>

jcolp · November 14, 2019, 10:31am

Replaces indicates that it is an attended transfer, not a blind transfer, so the logic you stated would not be executed. A full SIP trace including all calls would be needed to match up potentially what is going on, but few on here likely have any knowledge of what exactly things mean on the side of the Alcatel (since it is the source of the REFER) and what it expects to happen.

fvv · November 14, 2019, 11:00am

Thanks for your answer.

Based on this part of the documentation, even if it is an attended transfer, it should do a dialplan query to find the external_replaces extension in the endpoint context (which exists):

https://wiki.asterisk.org/wiki/display/AST/res_pjsip+Remote+Attended+Transfers

If that does not work, I should be getting an error like this one, but I’m not:

ast_log(LOG_ERROR, “Received REFER for remote session on channel ‘%s’ from endpoint ‘%s’ but ‘external_replaces’ extension not found in context %s\n”,

github.com

asterisk/asterisk/blob/master/res/res_pjsip_refer.c#L822


      
          
          static struct refer_data *refer_data_create(const struct ast_refer *refer)
          {
          	char *uri_params;
          	const char *destination;
          	struct refer_data *rdata = ao2_alloc_options(sizeof(*rdata), refer_data_destroy, AO2_ALLOC_OPT_LOCK_NOLOCK);
          
          	if (!rdata) {
          		return NULL;
          	}
          
          	/* typecast to suppress const warning */
          	rdata->refer = ast_refer_ref((struct ast_refer *) refer);
          	destination = ast_refer_get_to(refer);
          
          	/* To starts with 'pjsip:' which needs to be removed. */
          	if (!(destination = strchr(destination, ':'))) {
          		goto failure;
          	}
          	++destination;/* Now skip the ':' */

jcolp · November 14, 2019, 11:02am

Right, so you’d have to dig into why. You are in off-nominal territory. Even getting past that, it’s an attended transfer and not a blind transfer like you stated - so what exactly is the Alcatel expecting to happen in practice? Just ignore the fact that it is an attended transfer? Send the call back with the Replaces information?

fvv · November 14, 2019, 2:21pm

I think I found out why. The doc says:

If the dialog is found in the Asterisk system, then Asterisk simply performs a local attended transfer. This involves internal operations such as moving a channel from one bridge to another, or creating a local channel to link two bridges together.

The problem here is that the Alcatel is replacing the existing call-id and tags with the same ones, so Asterisk gets to this if:

github.com

asterisk/asterisk/blob/master/res/res_pjsip_refer.c#L776


      
          
          		pjsip_uri_print(PJSIP_URI_IN_REQ_URI, refer->refer_to, refer_to, sizeof(refer_to));
          		pbx_builtin_setvar_helper(chan, "SIPREFERTOHDR", S_OR(refer_to, NULL));
          	} else {
          		pbx_builtin_setvar_helper(chan, "SIPREFERTOHDR", NULL);
          	}
          }
          
          /*!
           * \internal
           * \brief Set the passed in context variable to the determined transfer context.
           * \since 13.3.0
           *
           * \param context Set to the determined transfer context.
           * \param session INVITE dialog SIP session.
           */
          #define DETERMINE_TRANSFER_CONTEXT(context, session)									\
          	do {																				\
          		ast_channel_lock((session)->channel);											\
          		context = pbx_builtin_getvar_helper((session)->channel, "TRANSFER_CONTEXT");	\
          		if (ast_strlen_zero(context)) {													\

And it is probably right, and is the Alcatel here who is not doing things in the right way…

For testing purposes, I would like to skip that if adding a condition on the user agent. As you authored that file, do you know if there is a way of doing something like this?

if ((dlg = pjsip_ua_find_dialog(&replaces->call_id, &replaces->to_tag, &replaces->from_tag, PJ_TRUE)) && user_agent != “OmniPCX Enterprise”)

I am not sure if the user-agent info is accesible from here…

Thanks for the help!

jcolp · November 14, 2019, 2:27pm

Uhhhh. The rdata is the incoming SIP request. There is code in res/res_pjsip_registrar.c which retrieves the User-Agent from such a request. That could be used as a base to get the User-Agent in this case.

jcolp · November 14, 2019, 2:28pm

You could also instead add a check that if it is replacing itself… to treat it as a blind transfer.

system · December 14, 2019, 2:28pm

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.