Callforward configured in phone ends in from-sip-external

[comfine (Comfine GmbH)]

Hello!

today i noticed a weird problem, that i’ve never seen before. At an actual FreePBX somebody put a call forward to a external mobile number in a yealink phone. If we try now to call this extension from external, asterisk Playback the no service message.

I tried to use promiscredir=yes, trustrpid and send pai=no in the trunk and in the extension, but none helped. if i understand the attached log right, there is never even a try to do a outgoing call for this forward and the call ends up in from-sip-external, which i dont know why. because we have outgoing routes with restrictions, i created also a new outgoing route ontop of all existing ones without restrictions for testing - although normally freepbx would say “no route to destionation” if this would be the problem, but that didnt help aswell. i dont understand whats wrong here and why the call ends up in from-sip-external instead of a new call via trunk. can anybody help and may have an explanation whats happening here?

37546[2021-03-25 11:56:17] VERBOSE[7606][C-00000021] chan_sip.c: Got SIP response 302 “Moved Temporarily” back from 192.168.41.51:5060
37547[2021-03-25 11:56:17] VERBOSE[20029][C-00000021] app_dial.c: Now forwarding SIP/easybell-00000046 to ‘SIP/015XXXXXXXXX::::[email protected]:5060’ (thanks to SIP/52-00000047)
37548[2021-03-25 11:56:17] VERBOSE[20029][C-00000021] netsock2.c: Using SIP RTP TOS bits 184
37549[2021-03-25 11:56:17] VERBOSE[20029][C-00000021] netsock2.c: Using SIP RTP CoS mark 5
37550[2021-03-25 11:56:17] VERBOSE[20029][C-00000021] app_dial.c: Not accepting call completion offers from call-forward recipient SIP/192.168.139.6:5060-00000048
37551[2021-03-25 11:56:17] VERBOSE[6982] chan_sip.c: Extension Changed 52[ext-local] new state Idle for Notify User 15
37552[2021-03-25 11:56:17] VERBOSE[6982] chan_sip.c: Extension Changed 52[ext-local] new state Idle for Notify User 17
37553[2021-03-25 11:56:17] VERBOSE[6982] chan_sip.c: Extension Changed 52[ext-local] new state Idle for Notify User 13
37554[2021-03-25 11:56:17] VERBOSE[6982] chan_sip.c: Extension Changed 52[ext-local] new state Idle for Notify User 12
37555[2021-03-25 11:56:17] VERBOSE[6982] chan_sip.c: Extension Changed 52[ext-local] new state Idle for Notify User 53
37556[2021-03-25 11:56:17] VERBOSE[6982] chan_sip.c: Extension Changed 52[ext-local] new state Idle for Notify User 30
37557[2021-03-25 11:56:17] VERBOSE[7606][C-00000022] netsock2.c: Using SIP RTP TOS bits 184
37558[2021-03-25 11:56:17] VERBOSE[7606][C-00000022] netsock2.c: Using SIP RTP CoS mark 5
37559[2021-03-25 11:56:17] VERBOSE[20032][C-00000022] pbx.c: Executing [015XXXXXXXXX@from-sip-external:1] NoOp(“SIP/192.168.139.6-00000049”, “Received incoming SIP connection from unknown peer to 015XXXXXXXXX”) in new stack
37560[2021-03-25 11:56:17] VERBOSE[20032][C-00000022] pbx.c: Executing [015XXXXXXXXX@from-sip-external:2] Set(“SIP/192.168.139.6-00000049”, “DID=015XXXXXXXXX”) in new stack
37561[2021-03-25 11:56:17] VERBOSE[20032][C-00000022] pbx.c: Executing [015XXXXXXXXX@from-sip-external:3] Goto(“SIP/192.168.139.6-00000049”, “s,1”) in new stack
37562[2021-03-25 11:56:17] VERBOSE[20032][C-00000022] pbx_builtins.c: Goto (from-sip-external,s,1)
37563[2021-03-25 11:56:17] VERBOSE[20032][C-00000022] pbx.c: Executing [s@from-sip-external:1] GotoIf(“SIP/192.168.139.6-00000049”, “1?setlanguage:checkanon”) in new stack
37564[2021-03-25 11:56:17] VERBOSE[20032][C-00000022] pbx_builtins.c: Goto (from-sip-external,s,2)
37565[2021-03-25 11:56:17] VERBOSE[20032][C-00000022] pbx.c: Executing [s@from-sip-external:2] Set(“SIP/192.168.139.6-00000049”, “CHANNEL(language)=en”) in new stack
37566[2021-03-25 11:56:17] VERBOSE[20032][C-00000022] pbx.c: Executing [s@from-sip-external:3] GotoIf(“SIP/192.168.139.6-00000049”, “1?noanonymous”) in new stack
37567[2021-03-25 11:56:17] VERBOSE[20032][C-00000022] pbx_builtins.c: Goto (from-sip-external,s,5)
37568[2021-03-25 11:56:17] VERBOSE[20032][C-00000022] pbx.c: Executing [s@from-sip-external:5] Set(“SIP/192.168.139.6-00000049”, “TIMEOUT(absolute)=15”) in new stack
37569[2021-03-25 11:56:17] VERBOSE[20032][C-00000022] func_timeout.c: Channel will hangup at 2021-03-25 11:56:32.587 CET.
37570[2021-03-25 11:56:17] VERBOSE[20032][C-00000022] pbx.c: Executing [s@from-sip-external:6] Set(“SIP/192.168.139.6-00000049”, “receveip=recvip”) in new stack
37571[2021-03-25 11:56:17] VERBOSE[20032][C-00000022] pbx.c: Executing [s@from-sip-external:7] Log(“SIP/192.168.139.6-00000049”, "WARNING,“Rejecting unknown SIP connection from 192.168.139.6"”) in new stack
37572[2021-03-25 11:56:17] WARNING[20032][C-00000022] Ext. s: “Rejecting unknown SIP connection from 192.168.139.6”
37573[2021-03-25 11:56:17] VERBOSE[20032][C-00000022] pbx.c: Executing [s@from-sip-external:8] Answer(“SIP/192.168.139.6-00000049”, “”) in new stack
37574[2021-03-25 11:56:17] VERBOSE[20029][C-00000021] app_dial.c: SIP/192.168.139.6:5060-00000048 answered SIP/easybell-00000046
37575[2021-03-25 11:56:17] VERBOSE[20029][C-00000021] pbx.c: Executing [s@macro-auto-blkvm:1] Set(“SIP/192.168.139.6:5060-00000048”, “__MACRO_RESULT=”) in new stack
37576[2021-03-25 11:56:17] VERBOSE[20029][C-00000021] pbx.c: Executing [s@macro-auto-blkvm:2] Set(“SIP/192.168.139.6:5060-00000048”, “CFIGNORE=”) in new stack
37577[2021-03-25 11:56:17] VERBOSE[20029][C-00000021] pbx.c: Executing [s@macro-auto-blkvm:3] Set(“SIP/192.168.139.6:5060-00000048”, “MASTER_CHANNEL(CFIGNORE)=”) in new stack
37578[2021-03-25 11:56:17] VERBOSE[20029][C-00000021] pbx.c: Executing [s@macro-auto-blkvm:4] Set(“SIP/192.168.139.6:5060-00000048”, “FORWARD_CONTEXT=from-internal”) in new stack
37579[2021-03-25 11:56:17] VERBOSE[20029][C-00000021] pbx.c: Executing [s@macro-auto-blkvm:5] Set(“SIP/192.168.139.6:5060-00000048”, “MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal”) in new stack
37580[2021-03-25 11:56:17] VERBOSE[20029][C-00000021] pbx.c: Executing [s@macro-auto-blkvm:6] Macro(“SIP/192.168.139.6:5060-00000048”, “blkvm-clr,”) in new stack
37581[2021-03-25 11:56:17] VERBOSE[20029][C-00000021] pbx.c: Executing [s@macro-blkvm-clr:1] Set(“SIP/192.168.139.6:5060-00000048”, “SHARED(BLKVM,SIP/easybell-00000046)=”) in new stack
37582[2021-03-25 11:56:17] VERBOSE[20029][C-00000021] pbx.c: Executing [s@macro-blkvm-clr:2] Set(“SIP/192.168.139.6:5060-00000048”, “GOSUB_RETVAL=”) in new stack
37583[2021-03-25 11:56:17] VERBOSE[20029][C-00000021] pbx.c: Executing [s@macro-blkvm-clr:3] MacroExit(“SIP/192.168.139.6:5060-00000048”, “”) in new stack
37584[2021-03-25 11:56:17] VERBOSE[20029][C-00000021] pbx.c: Executing [s@macro-auto-blkvm:7] ExecIf(“SIP/192.168.139.6:5060-00000048”, “0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=)”) in new stack
37585[2021-03-25 11:56:17] VERBOSE[20029][C-00000021] pbx.c: Executing [s@macro-auto-blkvm:8] ExecIf(“SIP/192.168.139.6:5060-00000048”, “0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=)”) in new stack
37586[2021-03-25 11:56:17] VERBOSE[20033][C-00000021] bridge_channel.c: Channel SIP/192.168.139.6:5060-00000048 joined ‘simple_bridge’ basic-bridge
37587[2021-03-25 11:56:17] VERBOSE[20029][C-00000021] bridge_channel.c: Channel SIP/easybell-00000046 joined ‘simple_bridge’ basic-bridge
37588[2021-03-25 11:56:17] VERBOSE[20032][C-00000022] pbx.c: Executing [s@from-sip-external:9] Wait(“SIP/192.168.139.6-00000049”, “2”) in new stack
37589[2021-03-25 11:56:19] VERBOSE[20032][C-00000022] pbx.c: Executing [s@from-sip-external:10] Playback(“SIP/192.168.139.6-00000049”, “ss-noservice”) in new stack

[comfine (Comfine GmbH)]

While i am still having this problem and try again to find a solution, i found my own post from some years ago:

Forward Call via Trunk

Hello, we just configured a call forward inside one of the yealink-phones. when you call the extension (from outside) within that phone, the phones sends “moved temporarily” with new destination back to asterisk. the forward-destination is getting called from asterisk inside a new call, but we want, that asterisk sends “moved temporarily” back to the provider (the trunk), so that the connection is done over there without asterisk beeing a stupid “bridge” between the two call-members. the provi…

…so what worked in those days (new call for the forwarding) is not working at this system now. i am still seeking for a solution and would be happy for a hint, as i really dont understand whats going wrong. seems to me almost like a bug in the actual freepbx-version.

could find out with this settings, that freepbx is signaling a new “incoming” call to the forwarded number, instead of doing an outgoing call (with that options it was routed to an extension, that ends with the same two digits like the foward-destination ends with, and the call could be completed normally, but of course, thats not what we want freepbx to do).

when i disallow “allow sip guests” the call is routed to the extensions mailbox.
so, to be more clear:
in the logfile i get this then:
Failed to authenticate on INVITE to ‘“061513600111” <sip:[email protected]>;tag=as1d32fb49’

so thats my number, which i am using for calling from extern.
the question is: why is FreePBX/Asterisk sending this forward:

Now forwarding PJSIP/easybell_PJSIP-0000000f to ‘SIP/01XXXXXXX::::[email protected]:5060’ (thanks to SIP/52-00000307)

not to the trunk but generating an incoming call?

i think this is a bug, and not a support/configuration-problem, so i filed a bug now after i updated and switched from asterisk 16 to 18.1.1:
https://issues.freepbx.org/browse/FREEPBX-22419?filter=-2

[jcolp (Joshua Colp)]

This occurs in chan_sip if “promiscredir” is set to “yes”. If set to “no” then a Local channel is used instead of dialing a SIP channel.

[comfine (Comfine GmbH)]

thanks jcolp for your reply.

first, the trunk is setup with PJSIP now, and second: promiscredir was not set to yes before i started looking into this problem and the default value is no if i remember correct, i just enabled it for testing. anyway, i set it to no in the chan_sip settings via “other sip settings” and the problem still persists.

[jcolp (Joshua Colp)]

I would suggest providing output for configuration that does not have “promiscredir” to “yes”.

[comfine (Comfine GmbH)]

jcolp,

thanks again, your hint was golden! after i removed the promiscredir option in the sip-driver again, it behaved differently. outgoing call was still not possible, but at least the dialplan looked right after the moved temporary - and it turned out, now i have another problem with the pjsip-trunk with easybell on call-forwards, also if they are configured via follow me for example - but using a sip-trunk instead of pjsip it is working now, which did not before update from asterisk 16 to 18, changing couple of settings, etc. - not sure what did solve the problem, but something did, and enabling promiscredir just made more problems instead of solving one.

anyway, i will try to get pjsip as trunk to work aswell now, because sip is dead… and will report back my final working configuration in a short sum-up.

[jcolp (Joshua Colp)]

I don’t know of easybell specifics, but you may find your issue to be callerid related or something in that area.

[comfine (Comfine GmbH)]

dont know why, but while normal outgoing calls are possible, if a follow me is configured,
the provider replies with trying on the invite, and after that it sends “authentication required”, while the invite was already sent out with authentication. makes no sense to me. i am asking the provider why is that. but with sip instead of pjsip everything works, so not sure if asterisk/freepbx or easybell is doing something wrong.

[jcolp (Joshua Colp)]

It’s unlikely it’s easybell, it’s more likely configuration related. For example the “From username” not being set to the account username can cause that to happen.