Logs filled with errors re: checkip server
telnetdoogie opened this issue · 31 comments
My logs seem to be filled with these errors... reaching api.ipify.org from the host and even connecting to the container and pinging api.ipify.org works fine... Anyone have any ideas? I'm not sure how to run in debug mode (inadyn -l debug) from a compose config
04/26/2023 1:16:41 AM
inadyn[1]: In-a-dyn version 2.11.0-rc1 -- Dynamic DNS update client.
04/26/2023 1:16:51 AM
inadyn[1]: Failed resolving hostname api.ipify.org: Try again
04/26/2023 1:16:51 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/26/2023 1:16:51 AM
inadyn[1]: Failed to get IP address for default@tunnelbroker.net, giving up!
04/26/2023 4:04:29 AM
inadyn[1]: SSL handshake with api.ipify.org failed: Error in the pull function.
04/26/2023 4:04:29 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/26/2023 4:04:29 AM
inadyn[1]: Failed to get IP address for default@domains.google.com, giving up!
04/26/2023 5:13:07 AM
inadyn[1]: SSL handshake with api.ipify.org failed: Error in the pull function.
04/26/2023 5:13:07 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/26/2023 5:13:07 AM
inadyn[1]: Failed to get IP address for default@domains.google.com, giving up!
04/26/2023 7:31:07 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/26/2023 7:31:07 AM
inadyn[1]: Failed to get IP address for default@domains.google.com, giving up!
04/26/2023 8:43:15 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/26/2023 8:43:15 AM
inadyn[1]: Failed to get IP address for default@domains.google.com, giving up!
04/26/2023 9:03:47 AM
inadyn[1]: SSL handshake with api.ipify.org failed: Error in the pull function.
04/26/2023 9:03:47 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/26/2023 9:03:47 AM
inadyn[1]: Failed to get IP address for default@tunnelbroker.net, giving up!
04/26/2023 9:04:17 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/26/2023 9:04:17 AM
inadyn[1]: Failed to get IP address for default@domains.google.com, giving up!
04/26/2023 9:06:45 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/26/2023 9:06:45 AM
inadyn[1]: Failed to get IP address for default@domains.google.com, giving up!
04/26/2023 10:12:13 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/26/2023 10:12:13 AM
inadyn[1]: Failed to get IP address for default@tunnelbroker.net, giving up!
04/26/2023 10:14:56 AM
inadyn[1]: SSL handshake with api.ipify.org failed: Error in the pull function.
04/26/2023 10:14:56 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/26/2023 10:14:56 AM
inadyn[1]: Failed to get IP address for default@domains.google.com, giving up!
04/26/2023 11:23:23 AM
inadyn[1]: Failed receiving HTTPS response: Decryption has failed.
04/26/2023 11:23:23 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/26/2023 11:23:23 AM
inadyn[1]: Failed to get IP address for default@tunnelbroker.net, giving up!
04/26/2023 8:35:51 PM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/26/2023 8:35:51 PM
inadyn[1]: Failed to get IP address for default@domains.google.com, giving up!
04/26/2023 10:08:11 PM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/26/2023 10:08:11 PM
inadyn[1]: Failed to get IP address for default@domains.google.com, giving up!
...ok I did figure out how to run it with a different debug mode... will keep an eye on things for a while. (It usually works at first and then starts failing over and over after running for a while)
FYI in case anyone else is running with docker compose, add a custom entrypoint:
services:
inadyn:
entrypoint: /usr/sbin/inadyn --foreground --loglevel=debug
container_name: blah blah
in your docker-compose.yml file
This looks like DNS resolution errors inside the container, or possibly outside (docker connection to host).
...no errors at all since running in debug mode for the past 23 hours. I'm wondering if just running in debug mode just works better? I'll keep watching it.
@troglobit when I was getting these previously (yesterday at 10pm for example, when the last log entry showed), I checked resolution to api.ipify.org by attaching to /bin/ash in the container, and resolving and pinging worked fine... same with resolving and pinging from the host... I almost wondered if api.ipify.org was throttling me or something, but their documentation says there's no throttle...
I'm going to close this for now, if this issue comes up again I can always re-open... Even forcing updates every 10 seconds I can't observe any errors... based on the SSL stuff in those logs I have to wonder if there was some weird docker network thing happening... This is certainly not the first time I've seen my logs filled with those errors, and usually I have to restart the container to resolve.
It's almost like I can't see the issue when debug mode is enabled...
04/27/2023 9:37:28 PM
inadyn[1]: In-a-dyn version 2.11.0-rc1 -- Dynamic DNS update client.
04/28/2023 2:14:11 AM
inadyn[1]: Failed receiving HTTPS response: Decryption has failed.
04/28/2023 2:14:11 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/28/2023 2:14:11 AM
inadyn[1]: Failed to get IP address for default@domains.google.com, giving up!
04/28/2023 3:01:43 AM
inadyn[1]: Failed connecting to api.ipify.org: Operation in progress
04/28/2023 3:01:43 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/28/2023 3:01:43 AM
inadyn[1]: Failed to get IP address for default@tunnelbroker.net, giving up!
04/28/2023 3:02:42 AM
inadyn[1]: Failed receiving HTTPS response: Decryption has failed.
04/28/2023 3:02:42 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/28/2023 3:02:42 AM
inadyn[1]: Failed to get IP address for default@domains.google.com, giving up!
04/28/2023 4:02:36 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/28/2023 4:02:36 AM
inadyn[1]: Failed to get IP address for default@domains.google.com, giving up!
04/28/2023 5:13:16 AM
inadyn[1]: Failed receiving HTTPS response: Decryption has failed.
04/28/2023 5:13:16 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/28/2023 5:13:16 AM
inadyn[1]: Failed to get IP address for default@domains.google.com, giving up!
04/28/2023 5:54:50 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/28/2023 5:54:50 AM
inadyn[1]: Failed to get IP address for default@domains.google.com, giving up!
04/28/2023 7:28:24 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/28/2023 7:28:24 AM
inadyn[1]: Failed to get IP address for default@domains.google.com, giving up!
It's obviously not happening every time since my period is 120s so it's just sporadic.
attaching to the container:
# wget -q -O - https://api.ipify.org
47.188.219.230/ #Switching back to debug mode.
...nix that. I'm going to try running the 2.10.0 tag for a while (pulling from :latest right now)
I checked back in my pihole logs, and have found the lookups for those times this morning where issues occurred. No issue with retreiving an IP for api.ipify.org. In fact, no DNS errors at all resolving api.ipify.org - So I'm wondering if those SSL errors that occur are significant. Perhaps this is a sporadic issue with ipify. I want to say I saw the exact same issue when not specifying checkip-server = default as well, however. I don't have logs from then.
I did notice that these entries in the log and subsequent failures seem to always be preceded by a inadyn[1]: Failed receiving HTTPS response: Decryption has failed. entry. And then the errors begin, for some of the lookups
You can try setting checkip-server = checkip.dyndns.com and see if that is more stable. If ipify turns out to be unstable we should drop it as the default/builtin.
I think there's something going on with my ISP or on my network:
wget -O - https://checkip.dyndns.org && echo
--2023-04-28 09:21:54-- https://checkip.dyndns.org/
Resolving checkip.dyndns.org (checkip.dyndns.org)... 132.226.247.73, 193.122.130.0, 132.226.8.169, ...
Connecting to checkip.dyndns.org (checkip.dyndns.org)|132.226.247.73|:443... connected.
GnuTLS: Error in the pull function.
Unable to establish SSL connection.api.ipify.org is working, for now... but attempting to use checkip.dyndns.org or .com doesn't work for me, it looks like it's blocked somehow. I switched my WAN to my secondary and same problem, so I'm wondering if something's happening on the router
** note: looks like I'm dumb and checkip.dyndns.org doesn't support SSL. Works fine with http **
this is the first 'oddity' I've seen so far in the logs with debug enabled:
inadyn[1]: Get address for default@domains.google.com
04/28/2023 9:38:03 AM
inadyn[1]: Checking for IP# change, initiating HTTPS ...
04/28/2023 9:38:03 AM
inadyn[1]: Checking for IP# change, connecting to api.ipify.org([173.231.16.77]:443)
04/28/2023 9:38:08 AM
inadyn[1]: Waiting (5 sec) for three-way handshake to complete ...
04/28/2023 9:38:13 AM
inadyn[1]: Failed connecting to that server: No such file or directory
04/28/2023 9:38:13 AM
inadyn[1]: Checking for IP# change, reconnecting to api.ipify.org([104.237.62.211]:443)
04/28/2023 9:38:14 AM
inadyn[1]: Certificate OK
04/28/2023 9:38:14 AM
inadyn[1]: SSL server cert subject: CN=*.ipify.org
04/28/2023 9:38:14 AM
inadyn[1]: SSL server cert issuer: C=GB,ST=Greater Manchester,L=Salford,O=Sectigo Limited,CN=Sectigo RSA Domain Validation Secure Server CA
04/28/2023 9:38:14 AM
inadyn[1]: Querying DDNS checkip server for my public IP#: GET / HTTP/1.0
04/28/2023 9:38:14 AM
Host: api.ipify.org
04/28/2023 9:38:22 AM
inadyn[1]: Successfully received HTTPS response (130/8191 bytes)!
Ok, I got my first hit that matches the output from previous. This is with v2.10.0 as well so it doesn't look like it differs from latest:
04/28/2023 10:13:01 AM
inadyn[1]: Checking IPv4 address [redacted] ...
04/28/2023 10:13:01 AM
inadyn[1]: IPv4 address [redacted] is valid.
04/28/2023 10:13:01 AM
inadyn[1]: No IP# change detected for default@domains.google.com, still at [redacted]
04/28/2023 10:13:01 AM
inadyn[1]: Get address for default@domains.google.com
04/28/2023 10:13:01 AM
inadyn[1]: Checking for IP# change, initiating HTTPS ...
04/28/2023 10:13:01 AM
inadyn[1]: Checking for IP# change, connecting to api.ipify.org([104.237.62.211]:443)
04/28/2023 10:13:06 AM
inadyn[1]: Waiting (5 sec) for three-way handshake to complete ...
04/28/2023 10:13:11 AM
inadyn[1]: Failed connecting to that server: No such file or directory
04/28/2023 10:13:11 AM
inadyn[1]: Checking for IP# change, reconnecting to api.ipify.org([64.185.227.155]:443)
04/28/2023 10:13:16 AM
inadyn[1]: Waiting (5 sec) for three-way handshake to complete ...
04/28/2023 10:13:21 AM
inadyn[1]: Failed connecting to that server: No such file or directory
04/28/2023 10:13:21 AM
inadyn[1]: Checking for IP# change, reconnecting to api.ipify.org([173.231.16.77]:443)
04/28/2023 10:13:26 AM
inadyn[1]: Waiting (5 sec) for three-way handshake to complete ...
04/28/2023 10:13:31 AM
inadyn[1]: Failed connecting to api.ipify.org: No such file or directory
04/28/2023 10:13:31 AM
inadyn[1]: Communication with checkip server api.ipify.org failed, run again with 'inadyn -l debug' if problem persists
04/28/2023 10:13:31 AM
inadyn[1]: Failed to get IP address for default@domains.google.com, giving up!
Does this provide any clues @troglobit ?
In case it helps, I have 3 entries in my conf file, so it's possible they all attempt connections at the same time or very close together? Here's the entirety of my config with details redacted ( I know it makes it not super useful, but otherwise everything's working) - just wondering if concurrency / multiple configs with the same checkip might be a factor, or with multiple 'versions' with the same google domains call (different hostnames, different username and password for both)
period = 120
provider default@domains.google.com:1 {
checkip-server = default
username = [redacted]
password = [redacted]
hostname = [redacted]
}
provider default@domains.google.com:2 {
checkip-server = default
username = [redacted]
password = [redacted]
hostname = [redacted]
}
provider default@tunnelbroker.net {
checkip-server = default
username = [redacted]
password = [redacted]
hostname = [redacted]
}
Looks like the normal behavior is to roll to the next IP in the set when a failure occurs, so the Failed to get IP address for default@domains.google.com, giving up! error only shows when the same error happens on all of the endpoints. In the below example, the error happens only on the first host:
04/28/2023 11:14:47 AM
inadyn[1]: Checking for IP# change, connecting to api.ipify.org([173.231.16.77]:443)
04/28/2023 11:14:52 AM
inadyn[1]: Waiting (5 sec) for three-way handshake to complete ...
04/28/2023 11:14:57 AM
inadyn[1]: Failed connecting to that server: No such file or directory
04/28/2023 11:14:57 AM
inadyn[1]: Checking for IP# change, reconnecting to api.ipify.org([64.185.227.155]:443)
04/28/2023 11:15:00 AM
inadyn[1]: Certificate OK
04/28/2023 11:15:00 AM
inadyn[1]: SSL server cert subject: CN=*.ipify.org
04/28/2023 11:15:00 AM
inadyn[1]: SSL server cert issuer: C=GB,ST=Greater Manchester,L=Salford,O=Sectigo Limited,CN=Sectigo RSA Domain Validation Secure Server CA
04/28/2023 11:15:00 AM
inadyn[1]: Querying DDNS checkip server for my public IP#: GET / HTTP/1.0
04/28/2023 11:15:00 AM
inadyn[1]: Successfully sent HTTPS request!
04/28/2023 11:15:34 AM
inadyn[1]: Successfully received HTTPS response (130/8191 bytes)!
04/28/2023 11:15:34 AM
inadyn[1]: Server response: HTTP/1.0 200 OK
I think this was the original reason I shifted to ipify
04/28/2023 1:51:43 PM
inadyn[1]: Please note, checkip.dyndns.com seems unstable, consider overriding it in your configuration with 'checkip-server = default'
04/28/2023 1:52:13 PM
inadyn[1]: Failed connecting to checkip.dyndns.com: Connection refused
04/28/2023 1:52:13 PM
inadyn[1]: Communication with checkip server checkip.dyndns.com failed, run again with 'inadyn -l debug' if problem persists
04/28/2023 1:52:13 PM
inadyn[1]: Retrying with built-in 'default', api.ipify.org ...
04/28/2023 1:52:14 PM
inadyn[1]: Please note, checkip.dyndns.com seems unstable, consider overriding it in your configuration with 'checkip-server = default'
04/28/2023 1:54:44 PM
inadyn[1]: Failed connecting to checkip.dyndns.com: Connection refused
04/28/2023 1:54:44 PM
inadyn[1]: Communication with checkip server checkip.dyndns.com failed, run again with 'inadyn -l debug' if problem persists
04/28/2023 1:54:44 PM
inadyn[1]: Retrying with built-in 'default', api.ipify.org ...
04/28/2023 1:54:44 PM
inadyn[1]: Please note, checkip.dyndns.com seems unstable, consider overriding it in your configuration with 'checkip-server = default'
04/28/2023 1:55:14 PM
inadyn[1]: Failed connecting to checkip.dyndns.com: Connection refused
04/28/2023 1:55:14 PM
inadyn[1]: Communication with checkip server checkip.dyndns.com failed, run again with 'inadyn -l debug' if problem persists
04/28/2023 1:55:14 PM
inadyn[1]: Retrying with built-in 'default', api.ipify.org ...
...throttled, perhaps
Ah right, forgot about how unstable checkip.dyndns.com is. Definitely throttled.
I've been testing the reliability myself of https://api.ipify.org, but I cannot see the same issue as you. So it's almost as if there's something else blocking your request to the outside world from the docker container.
As a final last-ditch-effort, could you try https://ifconfig.me/ip as the checkip server? If that too proves to be spotty I'd venture to say it's not Inadyn but your network/docker setup that's causing the headaches.
@troglobit I'm happy to give that a try... how do I specify that?
I still think it might be related to concurrent calls to api.ipify.org (perhaps a thread / concurrency issue with the underlying library (not yours), since connectivity looks fine and the errors are related to SSL handshake versus connectivity.
But I'll absolutely try this alternative.
OK I've got that running now.... Looks like I set it up correctly, I'll leave it for a couple of days and see how the logs look.
provider default@domains.google.com {
checkip-server = ifconfig.me
checkip-path = /ip
...
...
OK I've got that running now.... Looks like I set it up correctly, I'll leave it for a couple of days and see how the logs look.
Awesome, thanks! Very appreciated, and sorry for the late reply.
Running for >60 hours now... not a single error in the logs yet.
Looking good
...touch wood
91 hours in... not a single error.
This is great news! I'll prepare a change of default checkip server to ifconfig.me ... let's wait another day or so though.
@troglobit apologies for the noise... I did notice in the release notes for 2.10.0 it mentions:
Use HTTP-only for api.ipify.org, default (fallback) checkip service
and in ddns.h I see:
/*
* 2020-02-18: ipify.org support HTTPS and should be default for new
* providers, unless the provider has its own checkip infrastructure.
*/
#define DDNS_MY_IP_SERVER "api.ipify.org"
#define DDNS_MY_CHECKIP_URL "/"
#define DDNS_MY_IP_SSL DDNS_CHECKIP_SSL_UNSUPPORTEDyet the errors I was seeing related to api.ipify.org were SSL / TLS handshake related. Maybe (very likely) I don't understand where it's getting set, but if I'm using checkip-server = default does that not imply api.ipify.org and if so, why is SSL being used given the above defaults?
Ah, right. That could actually be the root cause of the issues we've seen, apologies. I'll have to investigate that a bit more for the general case of ipify in existing plugins.
However, for your setup the checkip-ssl = <true | false> should be done. Sorry about that.
No worries at all. I'll continue to report over the next few days as I check logs and I'll leave it to you to close this issue whenever you choose. Thanks so much for everything you're doing here and for the community. Super appreciated! Let me know if there's any way I can help out!
Thank you! I'll probably push the changes at the end of the weekend to get the pending release out the door 😄
6 days / 155 hours of ifconfig.me usage, with 3 domain specs and updates every 120 seconds...
Zero errors. 👍
Great stuff, I'll get right on updating to that server!
There, fixed! I'll start the release prep and testing of v2.11.0 now. Thank you so much for helping isolate this and testing out the replacement! <3
Working great now without the need for the override! Many thanks!
Makes me very happy to hear! Thank you for reporting back