[Freeswitch-users] NOT_REGISTERED error
Brian May
brian at linuxpenguins.xyz
Mon Aug 1 10:47:19 UTC 2022
Hello,
I seem to be having random issues that come and go. So will deal with
them one at a time. First problem, the incoming call from one extension
to another randomly gets blocked. But other times it works.
Logs when calling 1005 from 1004:
=== cut ===
EXECUTE [depth=0] sofia/internal-ipv6/1004 at sip.microcomaustralia.com.au bridge(user/1005 at sip.microcomaustralia.com.au)
2022-08-01 20:06:45.066758 98.33% [DEBUG] switch_channel.c:1269 sofia/internal-ipv6/1004 at sip.microcomaustralia.com.au EXPORTING[export_vars] [RFC2822_DATE]=[Mon, 01 Aug 2022 20:06:45 +1000] to event
2022-08-01 20:06:45.066758 98.33% [DEBUG] switch_channel.c:1269 sofia/internal-ipv6/1004 at sip.microcomaustralia.com.au EXPORTING[export_vars] [dialed_extension]=[1005] to event
2022-08-01 20:06:45.066758 98.33% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables
2022-08-01 20:06:45.066758 98.33% [DEBUG] switch_channel.c:1269 sofia/internal-ipv6/1004 at sip.microcomaustralia.com.au EXPORTING[export_vars] [RFC2822_DATE]=[Mon, 01 Aug 2022 20:06:45 +1000] to event
2022-08-01 20:06:45.066758 98.33% [DEBUG] switch_channel.c:1269 sofia/internal-ipv6/1004 at sip.microcomaustralia.com.au EXPORTING[export_vars] [dialed_extension]=[1005] to event
2022-08-01 20:06:45.066758 98.33% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables
2022-08-01 20:06:45.066758 98.33% [NOTICE] switch_channel.c:1123 New Channel sofia/internal-ipv6/1005 at 59.167.180.193:50138 [43494707-9a11-45a6-956e-c6096b48f60b]
2022-08-01 20:06:45.066758 98.33% [DEBUG] mod_sofia.c:5121 (sofia/internal-ipv6/1005 at 59.167.180.193:50138) State Change CS_NEW -> CS_INIT
2022-08-01 20:06:45.066758 98.33% [DEBUG] switch_core_state_machine.c:581 (sofia/internal-ipv6/1005 at 59.167.180.193:50138) Running State Change CS_INIT (Cur 2 Tot 34)
2022-08-01 20:06:45.066758 98.33% [NOTICE] switch_ivr_originate.c:3039 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
=== cut ===
But the user is registered:
=== cut ===
freeswitch at huey> show registrations
reg_user,realm,token,url,expires,network_ip,network_port,network_proto,hostname,metadata
1000,sip.microcomaustralia.com.au,3136333931393535353535353131-bybjp0g3gomy,sofia/internal/sip:1000 at 192.168.2.97:45452;line=10p5s5g9,1659350487,192.168.2.97,45452,udp,huey,
1004,sip.microcomaustralia.com.au,5rG1JkQ51w4XzyjV7ET8ng..,sofia/internal-ipv6/sip:1004@[2001:44b8:4112:8a05:859:d448:94ef:d733]:35862;rinstance=e736892a33822d9d;transport=tcp,1659348746,2001:44b8:4112:8a05:859:d448:94ef:d733,36207,tcp,huey,
1005,sip.microcomaustralia.com.au,kJaeILXv1Nta2tQEo8AV7A..,sofia/internal-ipv6/sip:1005 at 59.167.180.193:50138;transport=TCP;rinstance=e58807bf09569293,1659349053,2001:44b8:4112:8a02:e88:d16b:f1f6:c2ed,34495,tcp,huey,
3 total.
freeswitch at huey> sofia status profile internal-ipv6 reg
Registrations:
=================================================================================================
Call-ID: 5rG1JkQ51w4XzyjV7ET8ng..
User: 1004 at sip.microcomaustralia.com.au
Contact: "" <sip:1004@[2001:44b8:4112:8a05:859:d448:94ef:d733]:35862;rinstance=e736892a33822d9d;transport=tcp>
Agent: Zoiper v2.10.17.3-mod
Status: Registered(TCP)(unknown) EXP(2022-08-01 20:12:26) EXPSECS(314)
Ping-Status: Reachable
Ping-Time: 0.00
Host: huey
IP: 2001:44b8:4112:8a05:859:d448:94ef:d733
Port: 36207
Auth-User: 1004
Auth-Realm: sip.microcomaustralia.com.au
MWI-Account: 1004 at sip.microcomaustralia.com.au
Call-ID: kJaeILXv1Nta2tQEo8AV7A..
User: 1005 at sip.microcomaustralia.com.au
Contact: "" <sip:1005 at 59.167.180.193:50138;transport=TCP;rinstance=e58807bf09569293>
Agent: Z 5.5.13 v2.10.18.3
Status: Registered(TCP)(unknown) EXP(2022-08-01 20:17:33) EXPSECS(621)
Ping-Status: Reachable
Ping-Time: 0.00
Host: huey
IP: 2001:44b8:4112:8a02:e88:d16b:f1f6:c2ed
Port: 34495
Auth-User: 1005
Auth-Realm: sip.microcomaustralia.com.au
MWI-Account: 1005 at sip.microcomaustralia.com.au
Total items returned: 2
=================================================================================================
freeswitch at huey> sofia status profile internal reg
Registrations:
=================================================================================================
Call-ID: 3136333931393535353535353131-bybjp0g3gomy
User: 1000 at sip.microcomaustralia.com.au
Contact: "Extension" <sip:1000 at 192.168.2.97:45452;line=10p5s5g9>
Agent: snomD785/10.1.84.15
Status: Registered(UDP)(unknown) EXP(2022-08-01 21:11:27) EXPSECS(3632)
Ping-Status: Reachable
Ping-Time: 0.00
Host: huey
IP: 192.168.2.97
Port: 45452
Auth-User: 1000
Auth-Realm: sip.microcomaustralia.com.au
MWI-Account: 1000 at sip.microcomaustralia.com.au
Total items returned: 1
=================================================================================================
=== cut ===
While there are some things I don't understand here, fact is I
believe sofia/internal-ipv6/1005 should be registered....
Curiously calls in the other direction - 1005 to 1004 work fine at the
moment.
I thought maybe the IPv6 profile was causing problems, so I deleted it,
but get similar problems:
=== cut ===
EXECUTE [depth=0] sofia/internal/1004 at 59.167.180.194 bridge(user/1005 at sip.microcomaustralia.com.au)
2022-08-01 20:32:37.711523 98.03% [DEBUG] switch_channel.c:1269 sofia/internal/1004 at 59.167.180.194 EXPORTING[export_vars] [RFC2822_DATE]=[Mon, 01 Aug 2022 20:32:37 +1000] to event
2022-08-01 20:32:37.711523 98.03% [DEBUG] switch_channel.c:1269 sofia/internal/1004 at 59.167.180.194 EXPORTING[export_vars] [dialed_extension]=[1005] to event
2022-08-01 20:32:37.711523 98.03% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables
2022-08-01 20:32:37.711523 98.03% [DEBUG] switch_channel.c:1269 sofia/internal/1004 at 59.167.180.194 EXPORTING[export_vars] [RFC2822_DATE]=[Mon, 01 Aug 2022 20:32:37 +1000] to event
2022-08-01 20:32:37.711523 98.03% [DEBUG] switch_channel.c:1269 sofia/internal/1004 at 59.167.180.194 EXPORTING[export_vars] [dialed_extension]=[1005] to event
2022-08-01 20:32:37.711523 98.03% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables
2022-08-01 20:32:37.711523 98.03% [NOTICE] switch_channel.c:1123 New Channel sofia/internal/1005 at 59.167.180.193:50138 [e2d0ccc0-26eb-4b99-9aff-162a182435dd]
2022-08-01 20:32:37.711523 98.03% [DEBUG] mod_sofia.c:5121 (sofia/internal/1005 at 59.167.180.193:50138) State Change CS_NEW -> CS_INIT
2022-08-01 20:32:37.711523 98.03% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1005 at 59.167.180.193:50138) Running State Change CS_INIT (Cur 2 Tot 6)
2022-08-01 20:32:37.711523 98.03% [NOTICE] switch_ivr_originate.c:3039 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
2022-08-01 20:32:37.711523 98.03% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/1005 at 59.167.180.193:50138) State INIT
2022-08-01 20:32:37.711523 98.03% [DEBUG] mod_sofia.c:97 sofia/internal/1005 at 59.167.180.193:50138 SOFIA INIT
2022-08-01 20:32:37.711523 98.03% [INFO] sofia_glue.c:1651
sofia/internal/1005 at 59.167.180.193:50138 sending invite call-id: (null)
=== cut ===
=== cut ===
freeswitch at huey> sofia status profile internal reg
Registrations:
=================================================================================================
Call-ID: 3136333931393535353535353131-bybjp0g3gomy
User: 1000 at sip.microcomaustralia.com.au
Contact: "Extension" <sip:1000 at 192.168.2.97:45452;line=10p5s5g9>
Agent: snomD785/10.1.84.15
Status: Registered(UDP)(unknown) EXP(2022-08-01 21:11:27) EXPSECS(2322)
Ping-Status: Reachable
Ping-Time: 0.00
Host: huey
IP: 192.168.2.97
Port: 45452
Auth-User: 1000
Auth-Realm: sip.microcomaustralia.com.au
MWI-Account: 1000 at sip.microcomaustralia.com.au
Call-ID: JStfFaD7O6YhbD5glF1O2w..
User: 1004 at sip.microcomaustralia.com.au
Contact: "" <sip:1004 at 192.168.5.69:35862;rinstance=424e027f47c09f90;transport=tcp>
Agent: Zoiper v2.10.17.3-mod
Status: Registered(TCP)(unknown) EXP(2022-08-01 20:42:37) EXPSECS(592)
Ping-Status: Reachable
Ping-Time: 0.00
Host: huey
IP: 192.168.5.69
Port: 55579
Auth-User: 1004
Auth-Realm: 59.167.180.194
MWI-Account: 1004 at sip.microcomaustralia.com.au
Call-ID: pffe0efiQEXsqtVIjbxNoA..
User: 1005 at sip.microcomaustralia.com.au
Contact: "" <sip:1005 at 59.167.180.193:50138;transport=TCP;rinstance=dafd96f89850cb02>
Agent: Z 5.5.13 v2.10.18.3
Status: Registered(TCP)(unknown) EXP(2022-08-01 20:43:24) EXPSECS(639)
Ping-Status: Reachable
Ping-Time: 0.00
Host: huey
IP: 192.168.2.216
Port: 51245
Auth-User: 1005
Auth-Realm: sip.microcomaustralia.com.au
MWI-Account: 1005 at sip.microcomaustralia.com.au
Call-ID: CkKLFKmXc
User: 1001 at sip.microcomaustralia.com.au
Contact: "home" <sip:28256742 at 192.168.5.213:53628;transport=tcp;ob>
Agent: unknown
Status: Registered(TCP)(unknown) EXP(2022-08-01 20:48:31) EXPSECS(946)
Ping-Status: Reachable
Ping-Time: 0.00
Host: huey
IP: 192.168.5.213
Port: 53628
Auth-User: 1001
Auth-Realm: sip.microcomaustralia.com.au
MWI-Account: 1001 at sip.microcomaustralia.com.au
Total items returned: 4
=================================================================================================
freeswitch at huey> show registrations
reg_user,realm,token,url,expires,network_ip,network_port,network_proto,hostname,metadata
1000,sip.microcomaustralia.com.au,3136333931393535353535353131-bybjp0g3gomy,sofia/internal/sip:1000 at 192.168.2.97:45452;line=10p5s5g9,1659352287,192.168.2.97,45452,udp,huey,
1004,sip.microcomaustralia.com.au,JStfFaD7O6YhbD5glF1O2w..,sofia/internal/sip:1004 at 192.168.5.69:35862;rinstance=424e027f47c09f90;transport=tcp,1659350557,192.168.5.69,55579,tcp,huey,
1005,sip.microcomaustralia.com.au,pffe0efiQEXsqtVIjbxNoA..,sofia/internal/sip:1005 at 59.167.180.193:50138;transport=TCP;rinstance=dafd96f89850cb02,1659350604,192.168.2.216,51245,tcp,huey,
1001,sip.microcomaustralia.com.au,CkKLFKmXc,sofia/internal/sip:28256742 at 192.168.5.213:53628;transport=tcp;ob,1659350911,192.168.5.213,53628,tcp,huey,
4 total.
=== cut ===
As a result I put IPv6 back again.
1001 is an experimental client which I don't entirely trust, but don't
think that is causing any issues for calls where it is not involved.
Just quick summary of the some of the other issues:
* Occasionally the calls just freeze. Nothing shown in freeswitch logs.
No sign of any packets being dropped. Just client (zoiper) freezes and
does nothing. I suspect this might be a client issue, maybe nothing to
do with freeswitch.
* (the real problem I am trying to investigate) outgoing PSTN calls work
fine. But incoming calls from our VOIP provider - there is a 10+
second delay on all incoming audio, and I can't see any reason for
this. i.e. I mean I say something on remote end, wait 10 seconds, then
it is received at local end.
* Turning on echo cancellation on a Linux based host running zoiper
seemed to cut out audio after about 1 second. So I disabled that
option, seems to have fixed that problem.
Any ideas?
--
Brian May <brian at linuxpenguins.xyz>
https://linuxpenguins.xyz/brian/
More information about the FreeSWITCH-users
mailing list