boredazfcuk / docker-icloudpd

An Alpine Linux container for the iCloud Photos Downloader command line utility
1.58k stars 149 forks source link

Telegram messaging not working #464

Closed DuncanTheFox closed 6 months ago

DuncanTheFox commented 6 months ago

2023-12-28 08:15:13 INFO Telegram notifications enabled 2023-12-28 08:15:13 INFO Telegram token: Numbers:LettersAndNumbers 2023-12-28 08:15:13 INFO Telegram chat id: Numbers 2023-12-28 08:15:13 INFO Telegram polling: true 2023-12-28 08:15:13 INFO Telegram notification URL: https://api.telegram.org/botXXXXX:AAEjWC3sVwWEEXXXXXXXXXX/sendMessage 2023-12-28 08:15:13 INFO Check Telegram bot initialised... 2023-12-28 08:15:34 INFO bot_check 2023-12-28 08:15:34 INFO - Bot has not been initialised or needs reinitialising. Please send a message to the bot from your iDevice and restart the container. Disabling remote wake 2023-12-28 08:15:44 INFO Latest update id: 0 2023-12-28 08:15:44 INFO Sending Telegram startup notification 2023-12-28 08:16:08 ERROR Telegram startup notification failed with status code: 000

Kinda strange when Telegram does not work the program quits.

notification_type Telegram telegram_token from Botfather added to config telegram_chat_id added to config Started convo in telegram

Manual test sending message to token and chat_id via curl works fine

If the exact command

https://api.telegram.org/botXXXXX:AAEjWC3sVwWEEXXXXXXXXXX/sendMessage

is used from the logging it is logical it does not work that will result in

{"ok":false,"error_code":400,"description":"Bad Request: message text is empty"}

Any tips?

Thanks in advance,

Duncan.

luc-ass commented 6 months ago

Same here. Also, this causes the telegram api to constantly max out the (admittedly slow) CPU.

This is what htop shows as the process:

curl
--silent -X POST https://api.telegram.org/botxxx:xxx/getUpdates

Edit: Version 1.0.685 seems to be working fine.

boredazfcuk commented 6 months ago

I don't see this behaviour and I use Telegram polling on all four of my containers.

There has to be something unusual with the configuration of the bot. Back when I first implemented Telegram notifications, there were oddities surrounding chat IDs which started with a '-' character. I believe this is because they were actually groups rather than bots.

Maybe the chat ID you are using is for a group which the bot is a member of and not a direct conversation with the bot itself?

luc-ass commented 6 months ago

That's true, my bot reports to a channel that contains all the messages for that location - but it still works fine with 1.0.685... really strange

DuncanTheFox commented 6 months ago

Thanks for the response @boredazfcuk,

Bot created, started the bot with /start. Started a direct conversation with the bot. I do not use a group and thus the bot uses my personal chat_id like my other bots. Like I stated when doing a curl it works fine.

Also removed the bot and recreated it. Works in curl. Not in icloudpd.

boredazfcuk commented 6 months ago

Sounds like it's setup same as mine then. Odd mine is working, but yours isn't. Does your chat Id start with a minus or not? I'll spin up a test container tonight, if I get time.

boredazfcuk commented 6 months ago

That's true, my bot reports to a channel that contains all the messages for that location - but it still works fine with 1.0.685... really strange

I do think there might be something which could have affected it actually, an iffy find/replace on an echo command for all scripts in my library. I thought I'd fixed all the issues, but maybe not. I'll compare code with 1.0.685 and see if there's and discrepancies.

DuncanTheFox commented 6 months ago

Sounds like it's setup same as mine then. Odd mine is working, but yours isn't. Does your chat Id start with a minus or not? I'll spin up a test container tonight, if I get time.

No it starts with a number. Thanks for the support!

curl -X POST "https://api.telegram.org/bot689XXXXXXX:AAEXXXXMUVlM7t5mQXXXXX1IQEP8ERXXXXX/sendMessage" -d "chat_id=2014XXXXX&text=Test 30 Dec" {"ok":true,"result":{"message_id":8,"from":{"id":689356XXXX,"is_bot":true,"first_name":"PDCloud","username":"XXXX_XXX_XXX"},"chat":{"id":2014XXXXX,"first_name":"Duncan","last_name":"TheFox","username":"TheXXXXXXX","type":"private"},"date":1703954018,"text":"Test 30 Dec"}}%

image

boredazfcuk commented 6 months ago

What do you get if you run:

curl -X POST "https://api.telegram.org/bot${telegram_token}/getUpdates"

?

boredazfcuk commented 6 months ago

I pushed a new container to Dockerhub and when I upgraded all four of my containers, noticed that two of them failed the bot initialisation check. I restarted these two failed containers and they both started working fine. I've pushed a new version of the container which just adds a random 0-15 second delay if polling is enabled. This is in case the requests are failing due to the API ignoring multiple requests per second.

I'm not sure how many containers you guys are running? Maybe it could be related to this?

DuncanTheFox commented 6 months ago

What do you get if you run:

curl -X POST "https://api.telegram.org/bot${telegram_token}/getUpdates"

?

{"ok":true,"result":[]}%

DuncanTheFox commented 6 months ago

I pushed a new container to Dockerhub and when I upgraded all four of my containers, noticed that two of them failed the bot initialisation check. I restarted these two failed containers and they both started working fine. I've pushed a new version of the container which just adds a random 0-15 second delay if polling is enabled. This is in case the requests are failing due to the API ignoring multiple requests per second.

I'm not sure how many containers you guys are running? Maybe it could be related to this?

Normally 2. But now always starting 1 to test. Updated to the new version. Still the same error.

2023-12-31 00:26:41 INFO      - Bot has not been initialised or needs reinitialising. Please send a message to the bot from your iDevice and restart the container. Disabling remote wake
2023-12-31 00:26:51 INFO     Latest update id: 0
2023-12-31 00:26:51 INFO     Sending Telegram startup notification
2023-12-31 00:27:15 ERROR    Telegram startup notification failed with status code: 000
2023-12-31 00:27:15 ERROR    ***** Please report problems here: https://github.com/boredazfcuk/docker-icloudpd/issues *****
boredazfcuk commented 6 months ago

Can you set:

debug_logging=true

in your icloudpd.conf file. Then update to the latest version and post another log snip, please?

boredazfcuk commented 6 months ago

Also, what do you get if you run:

curl --request POST --data "allowed_updates=message" --data "offset=0" "https://api.telegram.org/bot${telegram_token}/getUpdates"

?

Edit: Oh and one last thing... when you're running the curl commands, that's from within the container? Not from the host, a laptop or anything like that?

DuncanTheFox commented 6 months ago

Can you set:

debug_logging=true

in your icloudpd.conf file. Then update to the latest version and post another log snip, please?

2023-12-31 02:18:30 INFO Telegram notifications enabled 2023-12-31 02:18:30 DEBUG Cleaned notification title: boredazfcukiCloudPD 2023-12-31 02:18:30 DEBUG Telegram token: (hidden) 2023-12-31 02:18:30 DEBUG Telegram chat id: (hidden) 2023-12-31 02:18:30 DEBUG Telegram polling: true 2023-12-31 02:18:30 DEBUG Telegram notification URL: (hidden) 2023-12-31 02:18:30 INFO Check Telegram bot initialised... 2023-12-31 02:19:02 INFO - Bot has not been initialised or needs reinitialising. Please send a message to the bot from your iDevice and restart the container. Disabling remote wake 2023-12-31 02:19:02 DEBUG - bot_check = 2023-12-31 02:19:12 INFO Latest update id: 0 2023-12-31 02:19:12 DEBUG Telegram silent file notifications: false 2023-12-31 02:19:12 INFO Sending Telegram startup notification 2023-12-31 02:19:34 ERROR Telegram startup notification failed with status code: 000 2023-12-31 02:19:34 ERROR Please report problems here: https://github.com/boredazfcuk/docker-icloudpd/issues

DuncanTheFox commented 6 months ago

Also, what do you get if you run:

curl --request POST --data "allowed_updates=message" --data "offset=0" "https://api.telegram.org/bot${telegram_token}/getUpdates"

?

Edit: Oh and one last thing... when you're running the curl commands, that's from within the container? Not from the host, a laptop or anything like that?

No because the docker stops if Telegram is not configured correctly. I removed all the Telegram settings from the conf. Weird error... cannot resolve api.telegram.org but can resolve it for a ping...

/ # curl --request POST --data "allowed_updates=message" --data "offset=0" "https://api.telegram.org/bot68 93XXXXXX:AAENoHjMUVXXXXXmQXXXXI1IQEP8XXXXX/getUpdates" curl: (6) Could not resolve host: api.telegram.org / # ping api.telegram.org PING api.telegram.org (149.154.167.220): 56 data bytes 64 bytes from 149.154.167.220: seq=0 ttl=53 time=5.382 ms 64 bytes from 149.154.167.220: seq=1 ttl=53 time=4.840 ms

--- api.telegram.org ping statistics --- 2 packets transmitted, 2 packets received, 0% packet loss round-trip min/avg/max = 4.840/5.111/5.382 ms

boredazfcuk commented 6 months ago

Looks like something odd is happening with the networking on that host. Make sure the container isn't connected to the default network. I've seen weird things happen on that one as it doesn't operate quite the same as a named network.

If you already have a named network, try re-resting it.

DuncanTheFox commented 6 months ago

Thanks for the suggestions @boredazfcuk,

Hardlinked the hosts file to a hosts file on Unraid with

149.154.167.220 api.telegram.org

added to the hosts file.

And now it is working fine. Tested on another docker with the same bridged network with the curl command there it works fine without a hosts file change.

Seems to be something fishy with the DNS on the icloudpd container as ping knows where api.telegram.org is but curl does not.

boredazfcuk commented 6 months ago

Can you try

curl -6 -X POST "https://api.telegram.org/bot${telegram_token}/getUpdates"

and

curl -4 -X POST "https://api.telegram.org/bot${telegram_token}/getUpdates"

I'm wondering if curl is failing because it's defaulting to IPv6.

luc-ass commented 6 months ago

Version 1.0.685:

# curl -6 -X POST "https://api.telegram.org/bot${telegram_token}/getUpdates"
curl: (7) Failed to connect to api.telegram.org port 443 after 27 ms: Couldn't connect to server

# curl -4 -X POST "https://api.telegram.org/bot${telegram_token}/getUpdates"
{"ok":true,"result":[]}/ # 

# curl -X POST "https://api.telegram.org/bot${telegram_token}/getUpdates"
{"ok":true,"result":[]}/ #

latest version stops here:

2023-12-31 15:03:38 INFO     Telegram notification URL: https://api.telegram.org/botxxx:xxx/sendMessage
2023-12-31 15:03:38 INFO     Check Telegram bot initialised...
DuncanTheFox commented 6 months ago

Can you try

curl -6 -X POST "https://api.telegram.org/bot${telegram_token}/getUpdates"

and

curl -4 -X POST "https://api.telegram.org/bot${telegram_token}/getUpdates"

I'm wondering if curl is failing because it's defaulting to IPv6.

/ # curl -6 -X POST "https://api.telegram.org/botXX/getUpdates" curl: (6) Could not resolve host: api.telegram.org

/ # curl -4 -X POST "https://api.telegram.org/botXX/getUpdates" curl: (6) Could not resolve host: api.telegram.org

boredazfcuk commented 6 months ago

I've created a few new containers today with different networking configurations and cannot replicate this issue at all.

Out of curiosity... What do you get if you run this inside the container:

nslookup www.google.com
Server:         127.0.0.11
Address:        127.0.0.11:53

Non-authoritative answer:
Name:   www.google.com
Address: 2a00:1450:4009:815::2004

Non-authoritative answer:
Name:   www.google.com
Address: 142.250.178.4
thew1se commented 6 months ago

Probably related, so just thought I'd mention that people are having similar issues with Pushover notifications. Issue 458 seems exactly the same and issue 459 is hanging on startup.

boredazfcuk commented 6 months ago

Yeah, I'd guess they're probably all related too, but I'm unable to replicate this issue.

It must be something related to the configuration/version of the container platform running on the host systems.

This (10 years old) solution suggests that curl uses TCP to perform DNS lookups (in addition to UDP): https://serverfault.com/a/645004

It may be that the version of curl packaged in Alpine Linux 3.19 now defaults to TCP only DNS lookups, where ping still uses UDP.

If the icloudpd network does not have a firewall rule to allow TCP DNS requests, but does have a rule for UDP DNS requests, and ping uses UDP to lookup the host names, it would explain why curl is failing and ping is working.

boredazfcuk commented 6 months ago

curl -4 -X POST "https://api.telegram.org/bot${telegram_token}/getUpdates"

Just in case you're using an external DNS server, can you try telling curl to use Docker's internal DNS server?:

curl --dns-servers 127.0.0.11 -4 -X POST "https://api.telegram.org/botXX/getUpdates"

I think this should work, but haven't tested it yet.

DuncanTheFox commented 6 months ago

curl -4 -X POST "https://api.telegram.org/bot${telegram_token}/getUpdates"

Just in case you're using an external DNS server, can you try telling curl to use Docker's internal DNS server?:

curl --dns-servers 127.0.0.11 -4 -X POST "https://api.telegram.org/botXX/getUpdates"

I think this should work, but haven't tested it yet.

Found it... I use PiHole.... and when using this als my DNS the api call fails... when I use my internal router or 8.8.8.8 it does not. I am so sorry for taking up your time.

Happy new year (at least here it is).

Best wishes for 2024,

Duncan.

boredazfcuk commented 6 months ago

No worries, just for completeness though, did nslookup work from within the container? I still find it odd that ping was resolving names successfully.

The only root cause I can put this down to is the whole TCP Vs UDP DNS requests thing. Plus multiple people are reporting the same problem so maybe curl has changed after all.

DuncanTheFox commented 6 months ago

nslookup www.google.com

/ # nslookup www.google.com
Server:         192.168.1.1
Address:        192.168.1.1:53

Non-authoritative answer:
Name:   www.google.com
Address: 142.250.179.196

Non-authoritative answer:
Name:   www.google.com
Address: 2a00:1450:400e:801::2004

/ # nslookup api.telegram.org
Server:         192.168.1.1
Address:        192.168.1.1:53

Non-authoritative answer:
Name:   api.telegram.org
Address: 149.154.167.220

Non-authoritative answer:
Name:   api.telegram.org
Address: 2001:67c:4e8:f004::9

2024-01-01 11:05:08 INFO     Telegram notifications enabled
2024-01-01 11:05:08 DEBUG    Cleaned notification title: boredazfcukiCloudPD
2024-01-01 11:05:08 DEBUG    Telegram token: (hidden)
2024-01-01 11:05:08 DEBUG    Telegram chat id: (hidden)
2024-01-01 11:05:08 DEBUG    Telegram polling: false
2024-01-01 11:05:08 DEBUG    Telegram notification URL: (hidden)
2024-01-01 11:05:08 DEBUG    Telegram silent file notifications: false
2024-01-01 11:05:08 INFO     Sending Telegram startup notification
2024-01-01 11:05:32 ERROR    Telegram startup notification failed with http status code: 000 and curl exit code: 6
2024-01-01 11:05:32 ERROR    ***** Please report problems here: https://github.com/boredazfcuk/docker-icloudpd/issues *****
boredazfcuk commented 6 months ago

So this looks like it is due to TCP vs UDP requests... to confirm, from inside the container, can you try:

nslookup -vc google.com <pihole-ip>

If it doesn't recognise the vc parameter, then:

apk add bind-tools
dig google.com @<pihole-ip> +tcp
dig google.com @<pihole-ip>

I should be able to add a container startup check to make sure DNS can be resolved over TCP. If it can't, I can kick out a meaningful error message, rather than have the container just hang, or give a 000 error.

DuncanTheFox commented 6 months ago
nslookup google.com 192.168.1.200

QUERY_TYPE: soa,ns,a,aaaa,cname,mx,txt,ptr,srv,any
/ # nslookup  google.com 192.168.1.200
;; connection timed out; no servers could be reached

/ # apk add dig
fetch https://dl-cdn.alpinelinux.org/alpine/v3.19/main/x86_64/APKINDEX.tar.gz
fetch https://dl-cdn.alpinelinux.org/alpine/v3.19/community/x86_64/APKINDEX.tar.gz
ERROR: unable to select packages:
  dig (no such package):
    required by: world[dig]
boredazfcuk commented 6 months ago

The nslookup command is missing the -vc parameter... or was that just the result?

I did actually ninja edit my comment to refer the bind-tools package instead of dig, but looks like you were too quick to for me lol

DuncanTheFox commented 6 months ago

The nslookup command is missing the -vc parameter... or was that just the result?

I did actually ninja edit my comment to refer the bind-tools package instead of dig, but looks like you were too quick to for me lol

The -vc gave an error. Here is the test again:

# nslookup -vc google.com 192.168.1.200
BusyBox v1.36.1 (2023-11-07 18:53:09 UTC) multi-call binary.

Usage: nslookup [-type=QUERY_TYPE] [-debug] HOST [DNS_SERVER]

Query DNS about HOST

QUERY_TYPE: soa,ns,a,aaaa,cname,mx,txt,ptr,srv,any

/ # dig google.com 192.168.1.200 +tcp
;; communications error to 192.168.1.200#53: timed out
;; communications error to 192.168.1.200#53: timed out
;; communications error to 192.168.1.200#53: timed out

; <<>> DiG 9.18.19 <<>> google.com 192.168.1.200 +tcp
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 30053
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;google.com.                    IN      A

;; ANSWER SECTION:
google.com.             68      IN      A       142.251.36.14

;; Query time: 2 msec
;; SERVER: 192.168.1.1#53(192.168.1.1) (UDP)
;; WHEN: Mon Jan 01 16:00:50 CET 2024
;; MSG SIZE  rcvd: 55

;; Connection to 192.168.1.200#53(192.168.1.200) for 192.168.1.200 failed: host unreachable.
;; Connection to 192.168.1.200#53(192.168.1.200) for 192.168.1.200 failed: timed out.
;; Connection to 192.168.1.200#53(192.168.1.200) for 192.168.1.200 failed: host unreachable.
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 5635
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;192.168.1.200.                 IN      A

;; AUTHORITY SECTION:
.                       86400   IN      SOA     a.root-servers.net. nstld.verisign-grs.com. 2024010100 1800 900 604800 86400

;; Query time: 15 msec
;; SERVER: 192.168.1.1#53(192.168.1.1) (TCP)
;; WHEN: Mon Jan 01 16:01:03 CET 2024
;; MSG SIZE  rcvd: 117

/ # dig google.com 192.168.1.200
boredazfcuk commented 6 months ago

Ah right. nslookup is failing because the one included with BusyBox is a bit lame. I'll defo need to rebuild the container with additional packages then.

Might have to see if I can replicate this behaviour by blocking DNS requests from my Docker network for a little while.

boredazfcuk commented 6 months ago

I've pushed a new version to Dockerhub which should now force the DNS check it performs during the container startup process to perform it's nslookup using TCP. This should now give people an explanation to their problem.

boredazfcuk commented 6 months ago

I'll mark this as closed now. Presumably this is all working fine for you... remote wake working as expected?