Increase Timeout in app_rpt of HTTP-based Registrations (1s ->6+s)

JayCue702 commented 4 months ago

rpi3b+ w/ latest ASL 3 build image

Have two nodes. Both have issues using http_registrations. I disabled it and turned back on iax2 registrations at the moment to get working. One node has issues doing stat post. The other does not. Both are new clean ASL3 build image for raspberry pi 3b+.

JayCue702 commented 4 months ago

now i dont have issue of statpost after changing this node to iax2 registration :/ instead of http_registrations.

So if someone can help with making http_registrations work then let me know what info you need on my part.

jxmx commented 4 months ago

Can you please switch back to HTTP registrations and look for any errors in the log as well as display rpt show registrations here?

JayCue702 commented 4 months ago

ASL61952*CLI> rpt show registrations Host Username Perceived Refresh State 34.105.111.212:443 61952 0 Not Registered 1 HTTP registration.

[2024-07-06 18:00:17.776] Asterisk 20.8.1+asl3-3.0.0-1.deb12 built by builder @ allstarlink.org on a aarch64 running Linux on 2024-06-13 23:09:36 UTC [2024-07-06 18:00:17.856] NOTICE[152644] loader.c: 69 modules will be loaded. [2024-07-06 18:00:17.963] NOTICE[152644] cdr.c: CDR simple logging enabled. [2024-07-06 18:00:17.969] NOTICE[152644] dnsmgr.c: Managed DNS entries will be refreshed every 300 seconds. [2024-07-06 18:00:18.020] NOTICE[152644] indications.c: Default country for indication tones: us [2024-07-06 18:00:18.020] NOTICE[152644] indications.c: Setting default indication country to 'us' [2024-07-06 18:00:18.188] NOTICE[152644] res_smdi.c: No SMDI interfaces are available to listen on, not starting SMDI listener. [2024-07-06 18:00:18.205] WARNING[152644] chan_dahdi.c: Only FXO signalled channels may belong to a call group [2024-07-06 18:00:18.205] WARNING[152644] chan_dahdi.c: Only FXO signalled channels may belong to a pickup group [2024-07-06 18:00:18.205] NOTICE[152644] chan_dahdi.c: Ignoring any changes to 'userbase' (on reload) at line 23. [2024-07-06 18:00:18.205] NOTICE[152644] chan_dahdi.c: Ignoring any changes to 'vmsecret' (on reload) at line 31. [2024-07-06 18:00:18.205] NOTICE[152644] chan_dahdi.c: Ignoring any changes to 'hassip' (on reload) at line 35. [2024-07-06 18:00:18.205] NOTICE[152644] chan_dahdi.c: Ignoring any changes to 'hasiax' (on reload) at line 39. [2024-07-06 18:00:18.205] NOTICE[152644] chan_dahdi.c: Ignoring any changes to 'hasmanager' (on reload) at line 47. [2024-07-06 18:00:18.205] WARNING[152644] chan_dahdi.c: Only FXO signalled channels may belong to a call group [2024-07-06 18:00:18.205] WARNING[152644] chan_dahdi.c: Only FXO signalled channels may belong to a pickup group [2024-07-06 18:00:23.708] WARNING[152644] loader.c: Module 'res_adsi' has been loaded but may be removed in a future release. [2024-07-06 18:00:24.030] NOTICE[152687] app_rpt.c: Normal Repeater Init 61952
[2024-07-06 18:00:28.634] WARNING[152688] res_rpt_http_registrations.c: Resolving timed out after 1000 milliseconds [2024-07-06 18:00:28.635] WARNING[152688] res_rpt_http_registrations.c: Failed to curl URL 'https://register.allstarlink.org/' [2024-07-06 18:03:29.030] WARNING[152688] res_rpt_http_registrations.c: Resolving timed out after 1000 milliseconds [2024-07-06 18:03:29.030] WARNING[152688] res_rpt_http_registrations.c: Failed to curl URL 'https://register.allstarlink.org/' [2024-07-06 18:05:23.099] NOTICE[152668] dnsmgr.c: dnssrv: host 'register.allstarlink.org' changed from 34.105.111.212:443 to 162.248.92.131:443

Allan-N commented 4 months ago

I see that we are passing a connect timeout of 1000ms (1s). This may be a bit too short. Should we extend the timeout(s)?

Allan-N commented 4 months ago

@JayCue702 What type of network connection does this node have? Do you have generally good connectivity? DSL, Cable, Fiber, Satellite? What are the ping times from your node to "register.allstarlink.org" ?

JayCue702 commented 4 months ago

here is ping results from the two servers linked to register.allstarlink.org

PING register.allstarlink.org (162.248.92.131) 56(84) bytes of data. 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=1 ttl=51 time=58.9 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=2 ttl=51 time=67.2 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=3 ttl=51 time=58.8 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=4 ttl=51 time=66.0 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=5 ttl=51 time=65.9 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=6 ttl=51 time=64.4 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=7 ttl=51 time=66.7 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=8 ttl=51 time=63.9 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=9 ttl=51 time=65.6 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=10 ttl=51 time=67.1 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=11 ttl=51 time=64.9 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=12 ttl=51 time=65.8 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=13 ttl=51 time=67.0 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=14 ttl=51 time=67.4 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=15 ttl=51 time=66.6 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=16 ttl=51 time=71.4 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=17 ttl=51 time=65.6 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=18 ttl=51 time=73.0 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=19 ttl=51 time=75.2 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=20 ttl=51 time=65.3 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=21 ttl=51 time=66.6 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=22 ttl=51 time=67.1 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=23 ttl=51 time=67.1 ms 64 bytes from v-162-248-92-131.unman-vds.premium-chicago.nfoservers.com (162.248.92.131): icmp_seq=24 ttl=51 time=63.8 ms ^C --- register.allstarlink.org ping statistics --- 24 packets transmitted, 24 received, 0% packet loss, time 23033ms rtt min/avg/max/mdev = 58.752/66.306/75.201/3.455 ms

PING register.allstarlink.org (34.105.111.212) 56(84) bytes of data. 64 bytes from register-west1-b.allstarlink.org (34.105.111.212): icmp_seq=1 ttl=53 time=50.4 ms 64 bytes from register-west1-b.allstarlink.org (34.105.111.212): icmp_seq=2 ttl=53 time=61.7 ms 64 bytes from register-west1-b.allstarlink.org (34.105.111.212): icmp_seq=3 ttl=53 time=81.5 ms 64 bytes from register-west1-b.allstarlink.org (34.105.111.212): icmp_seq=4 ttl=53 time=56.2 ms 64 bytes from register-west1-b.allstarlink.org (34.105.111.212): icmp_seq=5 ttl=53 time=52.3 ms 64 bytes from register-west1-b.allstarlink.org (34.105.111.212): icmp_seq=6 ttl=53 time=51.4 ms 64 bytes from register-west1-b.allstarlink.org (34.105.111.212): icmp_seq=7 ttl=53 time=52.6 ms 64 bytes from register-west1-b.allstarlink.org (34.105.111.212): icmp_seq=8 ttl=53 time=51.4 ms 64 bytes from register-west1-b.allstarlink.org (34.105.111.212): icmp_seq=9 ttl=53 time=52.6 ms 64 bytes from register-west1-b.allstarlink.org (34.105.111.212): icmp_seq=10 ttl=53 time=57.1 ms 64 bytes from register-west1-b.allstarlink.org (34.105.111.212): icmp_seq=11 ttl=53 time=56.7 ms 64 bytes from register-west1-b.allstarlink.org (34.105.111.212): icmp_seq=12 ttl=53 time=71.1 ms 64 bytes from register-west1-b.allstarlink.org (34.105.111.212): icmp_seq=13 ttl=53 time=53.1 ms 64 bytes from register-west1-b.allstarlink.org (34.105.111.212): icmp_seq=14 ttl=53 time=54.9 ms ^C --- register.allstarlink.org ping statistics --- 14 packets transmitted, 14 received, 0% packet loss, time 13018ms rtt min/avg/max/mdev = 50.358/57.365/81.537/8.484 ms

JayCue702 commented 4 months ago

speedtest.net results 602 Mbps download, 545.05 Mbps upload

JayCue702 commented 4 months ago

changed my dns to see if it helped, still same error

Allan-N commented 4 months ago

Well, it looks like you've got excellent network connectivity. We'll keep thinking.

JayCue702 commented 4 months ago

so one thing to think about. im behind double nat. i can register with the older iax2 way but cannot register this way. If i use openvpn to get me to connect to vpn server then im able to do http_registrations.

Allan-N commented 4 months ago

Interesting and most certainly something we need to investigate.

jxmx commented 4 months ago

Does something in your upstream ISP do some sort of proxying or content inspection? That could be slowing down the HTTP POST request. Can you post the results of running this from your node:

time curl --header "Content-Type: application/json" \
        --request POST \
        --data "{}" \
        https://repo.allstarlink.org/usage/usage

JayCue702 commented 4 months ago

real 0m5.615s user 0m0.324s sys 0m0.028s

jxmx commented 4 months ago

Yeah that isn't right AT ALL. Your "real" time should be within a few millis of user. Something is terribly killing your upload network connectivity.

JayCue702 commented 4 months ago

probably this double nat :/ is there way to give it more time before timeout for my setup?

jxmx commented 4 months ago

Definitely something we should look at. 1s is probably too aggressive.

jxmx commented 4 months ago

But to be honest, this is not going to be a priority at the moment. We won’t lose track of it, but I would suggest rolling back to IAX registrations for now.

JayCue702 commented 4 months ago

sounds good! thanks for keeping me in the loop

Allan-N commented 4 months ago

Is it really a simple double-NAT? or have you got something else that's trying to do content filtering?

JayCue702 commented 4 months ago

Allan yeah unfortunately my isp is known for this issue. WELINK. I can not do any port forwarding. The only way i could get around it was by putting my node through openvpn to vpn that supports port forwarding.

Allan-N commented 4 months ago

And, while I don't expect the following command to tell us much more than we already know, you might want to try the curl again with the "--verbose" option.

time curl --verbose --header "Content-Type: application/json" \
        --request POST \
        --data "{}" \
        https://repo.allstarlink.org/usage/usage

JayCue702 commented 4 months ago

Trying 104.21.40.206:443...
Connected to repo.allstarlink.org (104.21.40.206) port 443 (#0)
ALPN: offers h2,http/1.1
TLSv1.3 (OUT), TLS handshake, Client hello (1):
CAfile: /etc/ssl/certs/ca-certificates.crt
CApath: /etc/ssl/certs
TLSv1.3 (IN), TLS handshake, Server hello (2):
TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
TLSv1.3 (IN), TLS handshake, Certificate (11):
TLSv1.3 (IN), TLS handshake, CERT verify (15):
TLSv1.3 (IN), TLS handshake, Finished (20):
TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
TLSv1.3 (OUT), TLS handshake, Finished (20):
SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
ALPN: server accepted h2
Server certificate:
subject: CN=allstarlink.org
start date: May 21 04:35:08 2024 GMT
expire date: Aug 19 04:35:07 2024 GMT
subjectAltName: host "repo.allstarlink.org" matched cert's "*.allstarlink.org"
issuer: C=US; O=Let's Encrypt; CN=E1
SSL certificate verify ok.
using HTTP/2
h2h3 [:method: POST]
h2h3 [:path: /usage/usage]
h2h3 [:scheme: https]
h2h3 [:authority: repo.allstarlink.org]
h2h3 [user-agent: curl/7.88.1]
h2h3 [accept: /]
h2h3 [content-type: application/json]
h2h3 [content-length: 2]
Using Stream ID: 1 (easy handle 0x557cf077c0)

POST /usage/usage HTTP/2 Host: repo.allstarlink.org user-agent: curl/7.88.1 accept: / content-type: application/json content-length: 2
We are completely uploaded and fine
TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
old SSL session ID is stale, removing < HTTP/2 500 < date: Sun, 07 Jul 2024 22:55:09 GMT < content-type: application/octet-stream < content-length: 0 < x-frame-options: same-origin < x-content-type-options: nosniff < cache-control: no-cache < cf-cache-status: DYNAMIC < report-to: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v4?s=DikY0haxoZ0Lol8MjI2rp6OoJrIlVW8JL%2F1JsfXvAD9n0V2SgiikWn%2F0XDmqM%2FJ%2FcZWvUb0CUfj6l8%2Fu9PFF12rb%2Bv6zA%2BeKG2ZfN71A8fnUruxW5N43d9lsdipXK75jLPkc%2Bn4u9A%3D%3D"}],"group":"cf-nel","max_age":604800} < nel: {"success_fraction":0,"report_to":"cf-nel","max_age":604800} < server: cloudflare < cf-ray: 89fb6ba3a9cd2f67-LAX < alt-svc: h3=":443"; ma=86400 <
Connection #0 to host repo.allstarlink.org left intact

real 0m5.664s user 0m0.364s sys 0m0.034s

Allan-N commented 3 months ago

The fix for this issue has been incorporated into ASL3-Asterisk 20.9.1+asl3-3.0.4-1

AllStarLink / app_rpt

Increase Timeout in app_rpt of HTTP-based Registrations (1s ->6+s) #352