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@sip.microcomaustralia.com.au bridge(user/1005@sip.microcomaustralia.com.au) 2022-08-01 20:06:45.066758 98.33% [DEBUG] switch_channel.c:1269 sofia/internal-ipv6/1004@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@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@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@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@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@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@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@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@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@59.167.180.193:50138;transport=TCP;rinstance=e58807bf09569293,1659349053,2001:44b8:4112:8a02:e88:d16b:f1f6:c2ed,34495,tcp,huey, 3 total. freeswitch@huey> sofia status profile internal-ipv6 reg Registrations: ================================================================================================= Call-ID: 5rG1JkQ51w4XzyjV7ET8ng.. User: 1004@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@sip.microcomaustralia.com.au Call-ID: kJaeILXv1Nta2tQEo8AV7A.. User: 1005@sip.microcomaustralia.com.au Contact: "" <sip:1005@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@sip.microcomaustralia.com.au Total items returned: 2 ================================================================================================= freeswitch@huey> sofia status profile internal reg Registrations: ================================================================================================= Call-ID: 3136333931393535353535353131-bybjp0g3gomy User: 1000@sip.microcomaustralia.com.au Contact: "Extension" <sip:1000@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@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@59.167.180.194 bridge(user/1005@sip.microcomaustralia.com.au) 2022-08-01 20:32:37.711523 98.03% [DEBUG] switch_channel.c:1269 sofia/internal/1004@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@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@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@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@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@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@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@59.167.180.193:50138) State INIT 2022-08-01 20:32:37.711523 98.03% [DEBUG] mod_sofia.c:97 sofia/internal/1005@59.167.180.193:50138 SOFIA INIT 2022-08-01 20:32:37.711523 98.03% [INFO] sofia_glue.c:1651 sofia/internal/1005@59.167.180.193:50138 sending invite call-id: (null) === cut === === cut === freeswitch@huey> sofia status profile internal reg Registrations: ================================================================================================= Call-ID: 3136333931393535353535353131-bybjp0g3gomy User: 1000@sip.microcomaustralia.com.au Contact: "Extension" <sip:1000@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@sip.microcomaustralia.com.au Call-ID: JStfFaD7O6YhbD5glF1O2w.. User: 1004@sip.microcomaustralia.com.au Contact: "" <sip:1004@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@sip.microcomaustralia.com.au Call-ID: pffe0efiQEXsqtVIjbxNoA.. User: 1005@sip.microcomaustralia.com.au Contact: "" <sip:1005@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@sip.microcomaustralia.com.au Call-ID: CkKLFKmXc User: 1001@sip.microcomaustralia.com.au Contact: "home" <sip:28256742@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@sip.microcomaustralia.com.au Total items returned: 4 ================================================================================================= freeswitch@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@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@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@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@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@linuxpenguins.xyz> https://linuxpenguins.xyz/brian/
OK, not sure I understand, but I think I resolved some issues: * The 1005 client had the STUN server settings enabled. But this is entirely within my network, without any NAT. So this setting not appropriate. Had I known better, I would have realised that the Contact field shown in the registrations was showing my external IP address, not the internal IP address which is required. The USER_NOT_REGISTERED message is a red hearing, I still get that when it is working. Weird. * Perhaps, just to make things more confusing the above only applies to IPv4, my IPv6 address was correct. Although my logs show that the 1005 was being registered to the IPv6 profile using its IPv4 address. Huh? Something to do with the client I guess (zoiper). This explains why calls worked one way, but not the other way. * For some reason setting zrtp_secure_media=false kills incoming connection handling. As in answering calls fails. Despite the fact all clients appear to have ZRTP disabled. Huh? I don't understand... * Now that I have worked out these unrelated issues, to investigate the 10 second audio problem again. Brian May <brian@linuxpenguins.xyz> writes:
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@linuxpenguins.xyz> https://linuxpenguins.xyz/brian/ -- Brian May <brian@linuxpenguins.xyz> https://linuxpenguins.xyz/brian/
I was wrong, calls still sometimes not getting through to local clients without any reason I can see. -- Brian May <brian@linuxpenguins.xyz> https://linuxpenguins.xyz/brian/
participants (1)
-
Brian May