I met a strange question in FreeSWITCH. FreeSWITCH version: 1.10.7, OS: CentOS 7.9
Registered two users A and B, A is hotspot or wifi, B is 4G, B make call A, it is successful, voice and video is ok between A and B, But I call user B by FreeSWITCH command, It's not reachable, or once in a while is ok!
Command:
bgapi originate user/B &echo
call log:
freeswitch@ecs-44d8-0514058> bgapi originate user/1000000701100012 &echo
+OK Job-UUID: 293cf906-86c5-11ed-9d16-3b47fece8f98
2022-12-28 23:34:47.676493 99.70% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables
2022-12-28 23:34:47.696498 99.70% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables
2022-12-28 23:34:47.696498 99.70% [NOTICE] switch_channel.c:1123 New Channel sofia/internal/1000000701100012@192.168.43.174:56858 [293ec5d8-86c5-11ed-9d1a-3b47fece8f98]
2022-12-28 23:34:47.696498 99.70% [DEBUG] mod_sofia.c:5121 (sofia/internal/1000000701100012@192.168.43.174:56858) State Change CS_NEW -> CS_INIT
2022-12-28 23:34:47.696498 99.70% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1000000701100012@192.168.43.174:56858) Running State Change CS_INIT (Cur 1 Tot 844)
2022-12-28 23:34:47.696498 99.70% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/1000000701100012@192.168.43.174:56858) State INIT
2022-12-28 23:34:47.696498 99.70% [DEBUG] mod_sofia.c:97 sofia/internal/1000000701100012@192.168.43.174:56858 SOFIA INIT
2022-12-28 23:34:47.696498 99.70% [DEBUG] sofia_glue.c:1620 sip:1000000701100012@123.116.254.94:4392;transport=udp Setting proxy route to sofia/internal/1000000701100012@192.168.43.174:56858
2022-12-28 23:34:47.696498 99.70% [INFO] sofia_glue.c:1651 sofia/internal/1000000701100012@192.168.43.174:56858 sending invite call-id: (null)
2022-12-28 23:34:47.696498 99.70% [DEBUG] sofia_glue.c:1654 sofia/internal/1000000701100012@192.168.43.174:56858 sending invite version: 1.10.7 -release 64bit
Local SDP:
v=0
o=FreeSWITCH 1672214247 1672214248 IN IP4 125.124.216.102
s=FreeSWITCH
c=IN IP4 125.124.216.102
t=0 0
m=audio 27440 RTP/AVP 102 0 8
a=rtpmap:102 opus/48000/2
a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=ptime:20
a=sendrecv
m=video 25820 RTP/AVP 103
b=AS:4096
a=rtpmap:103 H264/90000
a=rtpmap:104 VP8/90000
a=sendrecv
2022-12-28 23:34:47.696498 99.70% [DEBUG] switch_core_state_machine.c:40 sofia/internal/1000000701100012@192.168.43.174:56858 Standard INIT
2022-12-28 23:34:47.696498 99.70% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1000000701100012@192.168.43.174:56858) State Change CS_INIT -> CS_ROUTING
2022-12-28 23:34:47.696498 99.70% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/1000000701100012@192.168.43.174:56858) State INIT going to sleep
2022-12-28 23:34:47.696498 99.70% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1000000701100012@192.168.43.174:56858) Running State Change CS_ROUTING (Cur 1 Tot 844)
2022-12-28 23:34:47.696498 99.70% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1000000701100012@192.168.43.174:56858) State ROUTING
2022-12-28 23:34:47.696498 99.70% [DEBUG] mod_sofia.c:158 sofia/internal/1000000701100012@192.168.43.174:56858 SOFIA ROUTING
2022-12-28 23:34:47.696498 99.70% [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1000000701100012@192.168.43.174:56858) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2022-12-28 23:34:47.696498 99.70% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1000000701100012@192.168.43.174:56858) State ROUTING going to sleep
2022-12-28 23:34:47.696498 99.70% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1000000701100012@192.168.43.174:56858) Running State Change CS_CONSUME_MEDIA (Cur 1 Tot 844)
2022-12-28 23:34:47.696498 99.70% [DEBUG] switch_core_state_machine.c:659 (sofia/internal/1000000701100012@192.168.43.174:56858) State CONSUME_MEDIA
2022-12-28 23:34:47.696498 99.70% [DEBUG] switch_core_state_machine.c:659 (sofia/internal/1000000701100012@192.168.43.174:56858) State CONSUME_MEDIA going to sleep
2022-12-28 23:34:47.696498 99.70% [DEBUG] sofia.c:7499 Channel sofia/internal/1000000701100012@192.168.43.174:56858 entering state [calling][0]
2022-12-28 23:34:51.876495 99.70% [NOTICE] switch_cpp.cpp:1465 lua take the users...
2022-12-28 23:34:51.876495 99.70% [NOTICE] switch_cpp.cpp:1465 start connect DB...
2022-12-28 23:34:51.876495 99.70% [NOTICE] switch_cpp.cpp:1465 123456
2022-12-28 23:35:16.876494 99.63% [DEBUG] sofia.c:6575 Ping to sip user '1000000701100012@125.124.216.102' succeeded with code 200 - count 1, state Reachable
2022-12-28 23:35:19.696492 99.67% [DEBUG] sofia.c:7499 Channel sofia/internal/1000000701100012@192.168.43.174:56858 entering state [terminated][408]
2022-12-28 23:35:19.696492 99.67% [NOTICE] sofia.c:8738 Hangup sofia/internal/1000000701100012@192.168.43.174:56858 [CS_CONSUME_MEDIA] [RECOVERY_ON_TIMER_EXPIRE]
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1000000701100012@192.168.43.174:56858) Running State Change CS_HANGUP (Cur 1 Tot 844)
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/1000000701100012@192.168.43.174:56858) Callstate Change DOWN -> HANGUP
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/1000000701100012@192.168.43.174:56858) State HANGUP
2022-12-28 23:35:19.696492 99.67% [DEBUG] mod_sofia.c:468 Channel sofia/internal/1000000701100012@192.168.43.174:56858 hanging up, cause: RECOVERY_ON_TIMER_EXPIRE
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_core_state_machine.c:59 sofia/internal/1000000701100012@192.168.43.174:56858 Standard HANGUP, cause: RECOVERY_ON_TIMER_EXPIRE
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/1000000701100012@192.168.43.174:56858) State HANGUP going to sleep
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/1000000701100012@192.168.43.174:56858) State Change CS_HANGUP -> CS_REPORTING
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1000000701100012@192.168.43.174:56858) Running State Change CS_REPORTING (Cur 1 Tot 844)
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/1000000701100012@192.168.43.174:56858) State REPORTING
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_core_state_machine.c:168 sofia/internal/1000000701100012@192.168.43.174:56858 Standard REPORTING, cause: RECOVERY_ON_TIMER_EXPIRE
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/1000000701100012@192.168.43.174:56858) State REPORTING going to sleep
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/1000000701100012@192.168.43.174:56858) State Change CS_REPORTING -> CS_DESTROY
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_core_session.c:1753 Session 844 (sofia/internal/1000000701100012@192.168.43.174:56858) Locked, Waiting on external entities
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_ivr_originate.c:4035 Originate Resulted in Error Cause: 102 [RECOVERY_ON_TIMER_EXPIRE]
2022-12-28 23:35:19.696492 99.67% [NOTICE] switch_ivr_originate.c:3039 Cannot create outgoing channel of type [user] cause: [RECOVERY_ON_TIMER_EXPIRE]
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_ivr_originate.c:4035 Originate Resulted in Error Cause: 102 [RECOVERY_ON_TIMER_EXPIRE]
2022-12-28 23:35:19.696492 99.67% [NOTICE] switch_core_session.c:1771 Session 844 (sofia/internal/1000000701100012@192.168.43.174:56858) Ended
2022-12-28 23:35:19.696492 99.67% [NOTICE] switch_core_session.c:1775 Close Channel sofia/internal/1000000701100012@192.168.43.174:56858 [CS_DESTROY]
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/1000000701100012@192.168.43.174:56858) Running State Change CS_DESTROY (Cur 0 Tot 844)
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/1000000701100012@192.168.43.174:56858) State DESTROY
2022-12-28 23:35:19.696492 99.67% [DEBUG] mod_sofia.c:379 sofia/internal/1000000701100012@192.168.43.174:56858 SOFIA DESTROY
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_core_state_machine.c:175 sofia/internal/1000000701100012@192.168.43.174:56858 Standard DESTROY
2022-12-28 23:35:19.696492 99.67% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/1000000701100012@192.168.43.174:56858) State DESTROY going to sleep
NAT config:
#internal.xml
<param name="apply-nat-acl" value="rfc1918.auto"/> // or nat.auto
user B(wifi or hotspot network) show registrations info:
reg_user,realm,token,url,expires,network_ip,network_port,network_proto,hostname,metadata
1000000701100012,125.124.216.102,463403000446,sofia/internal/sip:1000000701100012@192.168.43.174:56858;transport=udp;fs_nat=yes;fs_path=sip%3A1000000701100012%40123.116.254.94%3A4392%3Btransport%3Dudp,1672241946,123.116.254.94,4392,udp,ecs-44d8-0514058,
freeswitch@ecs-44d8-0514058> sofia status profile internal
Name internal
Domain Name N/A
Auto-NAT true
DBName sofia_reg_internal
Pres Hosts 125.124.216.102,172.16.0.101
Dialplan XML
Context default
Challenge Realm auto_from
RTP-IP 172.16.0.101
Ext-RTP-IP 125.124.216.102
SIP-IP 172.16.0.101
Ext-SIP-IP 125.124.216.102
By wireshark , FreeSWITCH send more INVITE, but user not recv any one. But is B make call A , It can be connected immediately. enter image description here
I guess is NAT problem, But I cannot Analysis and verification
By Comparative test, Why B call A is ok. but freeSWITCH call B by command. It is not reachable.
I config internal.xml
// modify value to nat.auto, it is not usefulI've been debugging for several days. I really don't know where the problem is?Who can help me, thanks for everyone!