Outbound calls

[pfox]

Hello, I am new in fusionPBX. I set up a voip trunk with telecomitalia, the inbound calls works but when I try to send a call I have a timeout error (Originate Failed. Cause: RECOVERY_ON_TIMER_EXPIRE),
here the logs:


2022-03-25 10:52:02.030401 [DEBUG] switch_ivr_originate.c:2242 Parsing global variables
2022-03-25 10:52:02.030401 [NOTICE] switch_channel.c:1118 New Channel sofia/external/3293608829 [a81b6b44-4e04-4689-a479-6dd29aea1be7]
2022-03-25 10:52:02.030401 [DEBUG] mod_sofia.c:5089 (sofia/external/3293608829) State Change CS_NEW -> CS_INIT
2022-03-25 10:52:02.030401 [DEBUG] switch_core_state_machine.c:585 (sofia/external/3293608829) Running State Change CS_INIT (Cur 2 Tot 80)
2022-03-25 10:52:02.030401 [DEBUG] switch_core_state_machine.c:628 (sofia/external/3293608829) State INIT
2022-03-25 10:52:02.030401 [DEBUG] mod_sofia.c:93 sofia/external/3293608829 SOFIA INIT
2022-03-25 10:52:02.030401 [DEBUG] sofia_glue.c:1618 sofia/external/3293608829 sending invite version: 1.10.3 -release 64bit
Local SDP:
v=0
o=FreeSWITCH 1648183872 1648183873 IN IP4 192.168.80.50
s=FreeSWITCH
c=IN IP4 192.168.80.50
t=0 0
m=audio 18050 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSuppff - - - -
a=ptime:20
a=sendrecv

2022-03-25 10:52:02.030401 [DEBUG] switch_core_state_machine.c:40 sofia/external/3293608829 Standard INIT
2022-03-25 10:52:02.030401 [DEBUG] switch_core_state_machine.c:48 (sofia/external/3293608829) State Change CS_INIT -> CS_ROUTING
2022-03-25 10:52:02.030401 [DEBUG] switch_core_state_machine.c:628 (sofia/external/3293608829) State INIT going to sleep
2022-03-25 10:52:02.050656 [DEBUG] switch_core_state_machine.c:585 (sofia/external/3293608829) Running State Change CS_ROUTING (Cur 2 Tot 80)
2022-03-25 10:52:02.050656 [DEBUG] sofia.c:7325 Channel sofia/external/3293608829 entering state [calling][0]
2022-03-25 10:52:02.050656 [DEBUG] switch_core_state_machine.c:644 (sofia/external/3293608829) State ROUTING
2022-03-25 10:52:02.050656 [DEBUG] mod_sofia.c:154 sofia/external/3293608829 SOFIA ROUTING
2022-03-25 10:52:02.050656 [DEBUG] switch_ivr_originate.c:67 (sofia/external/3293608829) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2022-03-25 10:52:02.050656 [DEBUG] switch_core_state_machine.c:644 (sofia/external/3293608829) State ROUTING going to sleep
2022-03-25 10:52:02.050656 [DEBUG] switch_core_state_machine.c:585 (sofia/external/3293608829) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 80)
2022-03-25 10:52:02.050656 [DEBUG] switch_core_state_machine.c:663 (sofia/external/3293608829) State CONSUME_MEDIA
2022-03-25 10:52:02.050656 [DEBUG] switch_core_state_machine.c:663 (sofia/external/3293608829) State CONSUME_MEDIA going to sleep
2022-03-25 10:52:02.090492 [DEBUG] sofia.c:7325 Channel sofia/external/3293608829 entering state [calling][0]
2022-03-25 10:52:05.190979 [DEBUG] sofia.c:7325 Channel sofia/external/3293608829 entering state [terminated][408]
2022-03-25 10:52:05.190979 [NOTICE] sofia.c:8558 Hangup sofia/external/3293608829 [CS_CONSUME_MEDIA] [RECOVERY_ON_TIMER_EXPIRE]
2022-03-25 10:52:05.190979 [DEBUG] switch_core_state_machine.c:585 (sofia/external/3293608829) Running State Change CS_HANGUP (Cur 2 Tot 80)
2022-03-25 10:52:05.190979 [DEBUG] switch_core_state_machine.c:848 (sofia/external/3293608829) Callstate Change DOWN -> HANGUP
2022-03-25 10:52:05.190979 [DEBUG] switch_core_state_machine.c:850 (sofia/external/3293608829) State HANGUP
2022-03-25 10:52:05.190979 [DEBUG] mod_sofia.c:453 Channel sofia/external/3293608829 hanging up, cause: RECOVERY_ON_TIMER_EXPIRE
2022-03-25 10:52:05.190979 [DEBUG] switch_core_state_machine.c:60 sofia/external/3293608829 Standard HANGUP, cause: RECOVERY_ON_TIMER_EXPIRE
2022-03-25 10:52:05.190979 [DEBUG] switch_core_state_machine.c:850 (sofia/external/3293608829) State HANGUP going to sleep
2022-03-25 10:52:05.190979 [DEBUG] switch_core_state_machine.c:620 (sofia/external/3293608829) State Change CS_HANGUP -> CS_REPORTING
2022-03-25 10:52:05.190979 [DEBUG] switch_core_state_machine.c:585 (sofia/external/3293608829) Running State Change CS_REPORTING (Cur 2 Tot 80)
2022-03-25 10:52:05.190979 [DEBUG] switch_core_state_machine.c:936 (sofia/external/3293608829) State REPORTING
2022-03-25 10:52:05.190979 [DEBUG] switch_core_state_machine.c:174 sofia/external/3293608829 Standard REPORTING, cause: RECOVERY_ON_TIMER_EXPIRE
2022-03-25 10:52:05.190979 [DEBUG] switch_core_state_machine.c:936 (sofia/external/3293608829) State REPORTING going to sleep
2022-03-25 10:52:05.190979 [DEBUG] switch_core_state_machine.c:611 (sofia/external/3293608829) State Change CS_REPORTING -> CS_DESTROY
2022-03-25 10:52:05.190979 [DEBUG] switch_core_session.c:1726 Session 80 (sofia/external/3293608829) Locked, Waiting on external entities
2022-03-25 10:52:05.211193 [DEBUG] switch_ivr_originate.c:3995 Originate Resulted in Error Cause: 102 [RECOVERY_ON_TIMER_EXPIRE]
2022-03-25 10:52:05.211193 [INFO] mod_dptools.c:3631 Originate Failed. Cause: RECOVERY_ON_TIMER_EXPIRE
2022-03-25 10:52:05.211193 [NOTICE] switch_channel.c:4941 Hangup sofia/internal/100@192.168.80.50 [CS_EXECUTE] [RECOVERY_ON_TIMER_EXPIRE]
2022-03-25 10:52:05.211193 [DEBUG] switch_core_session.c:2905 sofia/internal/100@192.168.80.50 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2022-03-25 10:52:05.211193 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/100@192.168.80.50) State EXECUTE going to sleep
2022-03-25 10:52:05.211193 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/100@192.168.80.50) Running State Change CS_HANGUP (Cur 2 Tot 80)
2022-03-25 10:52:05.211193 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/100@192.168.80.50) Callstate Change RINGING -> HANGUP
2022-03-25 10:52:05.211193 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/100@192.168.80.50) State HANGUP
2022-03-25 10:52:05.211193 [DEBUG] mod_sofia.c:447 sofia/internal/100@192.168.80.50 Overriding SIP cause 504 with 408 from the other leg
2022-03-25 10:52:05.211193 [DEBUG] mod_sofia.c:453 Channel sofia/internal/100@192.168.80.50 hanging up, cause: RECOVERY_ON_TIMER_EXPIRE
2022-03-25 10:52:05.211193 [DEBUG] mod_sofia.c:598 Responding to INVITE with: 408
2022-03-25 10:52:05.211193 [DEBUG] switch_core_state_machine.c:60 sofia/internal/100@192.168.80.50 Standard HANGUP, cause: RECOVERY_ON_TIMER_EXPIRE
2022-03-25 10:52:05.211193 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/100@192.168.80.50) State HANGUP going to sleep
2022-03-25 10:52:05.211193 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/100@192.168.80.50) State Change CS_HANGUP -> CS_REPORTING
2022-03-25 10:52:05.211193 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/100@192.168.80.50) Running State Change CS_REPORTING (Cur 2 Tot 80)
2022-03-25 10:52:05.211193 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/100@192.168.80.50) State REPORTING
2022-03-25 10:52:05.211193 [NOTICE] switch_core_session.c:1744 Session 80 (sofia/external/3293608829) Ended
2022-03-25 10:52:05.211193 [NOTICE] switch_core_session.c:1748 Close Channel sofia/external/3293608829 [CS_DESTROY]
2022-03-25 10:52:05.211193 [DEBUG] switch_core_state_machine.c:739 (sofia/external/3293608829) Running State Change CS_DESTROY (Cur 1 Tot 80)
2022-03-25 10:52:05.211193 [DEBUG] switch_core_state_machine.c:749 (sofia/external/3293608829) State DESTROY
2022-03-25 10:52:05.211193 [DEBUG] mod_sofia.c:364 sofia/external/3293608829 SOFIA DESTROY
2022-03-25 10:52:05.211193 [DEBUG] switch_core_state_machine.c:181 sofia/external/3293608829 Standard DESTROY
2022-03-25 10:52:05.211193 [DEBUG] switch_core_state_machine.c:749 (sofia/external/3293608829) State DESTROY going to sleep
2022-03-25 10:52:05.310409 [DEBUG] switch_core_state_machine.c:174 sofia/internal/100@192.168.80.50 Standard REPORTING, cause: RECOVERY_ON_TIMER_EXPIRE
2022-03-25 10:52:05.310409 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/100@192.168.80.50) State REPORTING going to sleep
2022-03-25 10:52:05.310409 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/100@192.168.80.50) State Change CS_REPORTING -> CS_DESTROY
2022-03-25 10:52:05.310409 [DEBUG] switch_core_session.c:1726 Session 79 (sofia/internal/100@192.168.80.50) Locked, Waiting on external entities
2022-03-25 10:52:05.310409 [NOTICE] switch_core_session.c:1744 Session 79 (sofia/internal/100@192.168.80.50) Ended
2022-03-25 10:52:05.310409 [NOTICE] switch_core_session.c:1748 Close Channel sofia/internal/100@192.168.80.50 [CS_DESTROY]
2022-03-25 10:52:05.310409 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/100@192.168.80.50) Running State Change CS_DESTROY (Cur 0 Tot 80)
2022-03-25 10:52:05.310409 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/100@192.168.80.50) State DESTROY
2022-03-25 10:52:05.310409 [DEBUG] mod_sofia.c:364 sofia/internal/100@192.168.80.50 SOFIA DESTROY
2022-03-25 10:52:05.310409 [DEBUG] switch_core_state_machine.c:181 sofia/internal/100@192.168.80.50 Standard DESTROY
2022-03-25 10:52:05.310409 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/100@192.168.80.50) State DESTROY going to sleep
2022-03-25 10:54:30.850429 [DEBUG] sofia_reg.c:2458 Changing expire time to 360 by request of proxy sip:85.38.255.72

May I have your help ? Thanks in advance

 

[DigitalDaz]

Try making the call and using sngrep to get a log

 

[hfoster]

>RECOVERY_ON_TIMER_EXPIRE

It usually means you aren't getting a response to your SIP INVITEs, so either networking issues or something at the carrier end. Your carrier may be able to shed some light as to whether they are receiving your SIP messages.

 

[pfox]

Thanks DigitalDaz and Infoster for your answers !
I gto log by sngrep, I think teh problem is in the Proxy Auth phase

I attached my trunk config and log, could you help me please ?

 

[hfoster]

I can't find your trunk provider's settings to assist much. From what I can tell the network part looks fine, but I would expect them to return a 401 Unauthorised instead of 408 Timeout. You checked the username and password, from, etc are all correct?

 

[Adrian Fretwell]

Your provider is returning a 100 Trying after you have sent credentials. As @hfoster says, if there is something wrong with your credentials, a 401 response would be more appropriate than a 408. This could be an internal fault with your provider. I would send the packet capture to them and ask for their comments.

 

[pfox]

Thanks for your reply, I checked the credentials and they are ok. I set up the trunk on Freepbx system usign PJSIP and SIP driver, and the trunk work with both driver. So I think that the problem is on my config.
I set "allow" in ACL rule for proxy IP, but this not fix the issue