netmuxd-zeroconf unknown heartbeat error after a while

jkcoxson / netmuxd

An alternative to usbmuxd just for networking

128 stars 16 forks source link

netmuxd-zeroconf unknown heartbeat error after a while #10

Open Centterm opened 2 years ago

Centterm commented 2 years ago

Hello,

the old mdns discovery did not work at all for me so I extracted the netmuxd-zeroconf from the current docker container. This version works in the beginning quite well but after a while (hours) AltServer can not find the device anymore. The output of netmuxd is full of unknown heartbeat errors. It never recovers from there and after a restart everything works again.

Adding device 2edff                                                                                                                                                                                 
[2022-05-18T05:12:12Z ERROR netmuxd::heartbeat] Failed to create heartbeat client for udid 2edff: UnknownError                                                                                      
Removing 2edff                                                                                                                                                                                      
Adding device 2edff                                                                                                                                                                                 
[2022-05-18T05:12:27Z ERROR netmuxd::heartbeat] Failed to create heartbeat client for udid 2edff: UnknownError                                                                                      
Removing 2edff                                                                                                                                                                                      
Adding device 2edff                                                                                                                                                                                 
[2022-05-18T05:13:15Z ERROR netmuxd::heartbeat] Failed to create heartbeat client for udid 2edff: UnknownError                                                                                      
Removing 2edff                                                                                                                                                                                      
Adding device 2edff                                                                                                                                                                                 
[2022-05-18T05:16:02Z ERROR netmuxd::heartbeat] Failed to create heartbeat client for udid 2edff: UnknownError                                                                                      
Removing 2edff                                                                                                                                                                                      
Adding device 2edff                                                                                                                                                                                 
[2022-05-18T05:19:30Z ERROR netmuxd::heartbeat] Failed to create heartbeat client for udid 2edff: UnknownError                                                                                      
Removing 2edff

(UUID shorted for readability)

I do not know if that is the intended behavior but I do also get a lot of adding/removing the device when it works

Practicalbutterfly5 commented 2 years ago

I am also facing same issue. This is the error https://github.com/jkcoxson/netmuxd/blob/1275069eda9fe19160f1d06b1017b84c15f3a089/src/heartbeat.rs#L27

DrissiReda commented 2 years ago

I am also facing this issue.

I can see it in AltServer-Linux. It works fine with usbmuxd. But when I set the env var USBMUXD_SOCKET_ADDRESS to switch to netmuxd, I start getting the same error:

Adding device xxxxxxxx-xxxxxxxxx
[2022-07-03T17:26:21Z ERROR netmuxd::heartbeat] Failed to create heartbeat client for udid xxxxxxxx-xxxxxxxxx: UnknownError
Adding device xxxxxxxx-xxxxxxxxx
[2022-07-03T17:26:31Z ERROR netmuxd::heartbeat] Failed to create heartbeat client for udid xxxxxxxx-xxxxxxxxx: UnknownError
Adding device xxxxxxxx-xxxxxxxxx
[2022-07-03T17:26:41Z ERROR netmuxd::heartbeat] Failed to create heartbeat client for udid xxxxxxxx-xxxxxxxxx: UnknownError

Then it keeps repeating every 10 seconds.

jkcoxson commented 2 years ago

Can you run with the env var RUST_LOG=info

DrissiReda commented 2 years ago

WARNING: Running in host mode will not work unless you are running a daemon in unix mode as well
[2022-07-03T17:31:32Z INFO  netmuxd::central_data] Getting UDID for MAC: "xx:xx:xx:xx:xx:xx"
[2022-07-03T17:31:32Z INFO  plist_plus] Parsing xml
[2022-07-03T17:31:32Z INFO  plist_plus] Creating plist from plist_t with id 2998967729
[2022-07-03T17:31:32Z INFO  plist_plus::types::dictionary] Getting dict item
[2022-07-03T17:31:32Z INFO  plist_plus] Creating plist from plist_t with id 1256711957
[2022-07-03T17:31:32Z INFO  plist_plus] Cloning plist
[2022-07-03T17:31:32Z INFO  plist_plus] Getting type of cloned plist
[2022-07-03T17:31:32Z INFO  plist_plus] Creating plist from plist_t with id 2938159892
[2022-07-03T17:31:32Z INFO  plist_plus] Dropping plist 1256711957
[2022-07-03T17:31:32Z INFO  plist_plus] Plist dropped
[2022-07-03T17:31:32Z INFO  plist_plus::types::string] Getting string value
[2022-07-03T17:31:32Z INFO  plist_plus::types::string] Converting cstring to string
[2022-07-03T17:31:32Z INFO  plist_plus] Dropping plist 2938159892
[2022-07-03T17:31:32Z INFO  plist_plus] Plist dropped
[2022-07-03T17:31:32Z INFO  plist_plus] Dropping plist 2998967729
[2022-07-03T17:31:32Z INFO  plist_plus] Plist dropped
[2022-07-03T17:31:32Z INFO  plist_plus] Parsing xml
[2022-07-03T17:31:32Z INFO  plist_plus] Creating plist from plist_t with id 1168404114
[2022-07-03T17:31:32Z INFO  plist_plus::types::dictionary] Getting dict item
[2022-07-03T17:31:32Z INFO  plist_plus] Creating plist from plist_t with id 2080556298
[2022-07-03T17:31:32Z INFO  plist_plus] Cloning plist
[2022-07-03T17:31:32Z INFO  plist_plus] Getting type of cloned plist
[2022-07-03T17:31:32Z INFO  plist_plus] Creating plist from plist_t with id 1402125424
[2022-07-03T17:31:32Z INFO  plist_plus] Dropping plist 2080556298
[2022-07-03T17:31:32Z WARN  plist_plus] Plist has already been freed
[2022-07-03T17:31:32Z INFO  plist_plus] Dropping plist 1402125424
[2022-07-03T17:31:32Z WARN  plist_plus] Plist has already been freed
[2022-07-03T17:31:32Z INFO  plist_plus] Dropping plist 1168404114
[2022-07-03T17:31:32Z INFO  plist_plus] Plist dropped
[2022-07-03T17:31:32Z INFO  plist_plus] Parsing xml
[2022-07-03T17:31:32Z INFO  plist_plus] Creating plist from plist_t with id 1492039906
[2022-07-03T17:31:32Z INFO  plist_plus::types::dictionary] Getting dict item
[2022-07-03T17:31:32Z INFO  plist_plus] Creating plist from plist_t with id 1748401340
[2022-07-03T17:31:32Z INFO  plist_plus] Cloning plist
[2022-07-03T17:31:32Z INFO  plist_plus] Getting type of cloned plist
[2022-07-03T17:31:32Z INFO  plist_plus] Creating plist from plist_t with id 3586890328
[2022-07-03T17:31:32Z INFO  plist_plus] Dropping plist 1748401340
[2022-07-03T17:31:32Z INFO  plist_plus] Plist dropped
[2022-07-03T17:31:32Z INFO  plist_plus::types::string] Getting string value
[2022-07-03T17:31:32Z INFO  plist_plus::types::string] Converting cstring to string
[2022-07-03T17:31:32Z INFO  plist_plus] Dropping plist 3586890328
[2022-07-03T17:31:32Z INFO  plist_plus] Plist dropped
[2022-07-03T17:31:32Z INFO  plist_plus] Dropping plist 1492039906
[2022-07-03T17:31:32Z INFO  plist_plus] Plist dropped
[2022-07-03T17:31:32Z INFO  netmuxd::central_data] Found UDID: "xxxxxxxx-xxxxxxxxx"
Adding device xxxxxxxx-xxxxxxxxx
[2022-07-03T17:31:32Z INFO  rusty_libimobiledevice::idevice] Converting udid to C string
[2022-07-03T17:31:32Z INFO  rusty_libimobiledevice::idevice] Creating udid ptr
[2022-07-03T17:31:32Z INFO  rusty_libimobiledevice::idevice] Converting ip address into bytes
[2022-07-03T17:31:32Z INFO  rusty_libimobiledevice::idevice] Encodings ipv4 address
[2022-07-03T17:31:32Z ERROR netmuxd::heartbeat] Failed to create heartbeat client for udid xxxxxxxx-xxxxxxxxx: UnknownError
[2022-07-03T17:31:32Z INFO  rusty_libimobiledevice::idevice] Dropping device xxxxxxxx-xxxxxxxxx
[2022-07-03T17:31:32Z INFO  netmuxd::heartbeat] Removing device xxxxxxxx-xxxxxxxxx from muxer
[2022-07-03T17:31:32Z INFO  netmuxd::central_data] Removing device: "xxxxxxxx-xxxxxxxxx"

Can you run with the env var RUST_LOG=info

@jkcoxson

jkcoxson commented 2 years ago

This looks like an error with an invalid pairing file. I would try regenerating it with usbmuxd.

Also, you seem to be running an outdated build, or it’s using outdated deps.

DrissiReda commented 2 years ago

This looks like an error with an invalid pairing file. I would try regenerating it with usbmuxd.

Also, you seem to be running an outdated build, or it’s using outdated deps.

I'm pulling them from debian, maybe that's why? I just generated the pairing file.

Tell me which dependencies might be causing an issue I'll try building them manually since debian has old versions.

DrissiReda commented 2 years ago

@jkcoxson

After unpairing/repairing I'm getting this:

WARNING: Running in host mode will not work unless you are running a daemon in unix mode as well
[2022-07-03T17:42:20Z INFO  netmuxd::central_data] Getting UDID for MAC: "xx:xx:xx:xx:xx"
[2022-07-03T17:42:20Z INFO  plist_plus] Parsing xml
[2022-07-03T17:42:20Z INFO  plist_plus] Creating plist from plist_t with id 2553729807
[2022-07-03T17:42:20Z INFO  plist_plus::types::dictionary] Getting dict item
[2022-07-03T17:42:20Z INFO  plist_plus] Creating plist from plist_t with id 3353063795
[2022-07-03T17:42:20Z INFO  plist_plus] Cloning plist
[2022-07-03T17:42:20Z INFO  plist_plus] Getting type of cloned plist
[2022-07-03T17:42:20Z INFO  plist_plus] Creating plist from plist_t with id 2708026803
[2022-07-03T17:42:20Z INFO  plist_plus] Dropping plist 3353063795
[2022-07-03T17:42:20Z INFO  plist_plus] Plist dropped
[2022-07-03T17:42:20Z INFO  plist_plus::types::string] Getting string value
[2022-07-03T17:42:20Z INFO  plist_plus::types::string] Converting cstring to string
[2022-07-03T17:42:20Z INFO  plist_plus] Dropping plist 2708026803
[2022-07-03T17:42:20Z INFO  plist_plus] Plist dropped
[2022-07-03T17:42:20Z INFO  plist_plus] Dropping plist 2553729807
[2022-07-03T17:42:20Z INFO  plist_plus] Plist dropped
[2022-07-03T17:42:20Z INFO  plist_plus] Parsing xml
[2022-07-03T17:42:20Z INFO  plist_plus] Creating plist from plist_t with id 3451195937
[2022-07-03T17:42:20Z INFO  plist_plus::types::dictionary] Getting dict item
[2022-07-03T17:42:20Z INFO  plist_plus] Creating plist from plist_t with id 2269541282
[2022-07-03T17:42:20Z INFO  plist_plus] Cloning plist
[2022-07-03T17:42:20Z INFO  plist_plus] Getting type of cloned plist
[2022-07-03T17:42:20Z INFO  plist_plus] Creating plist from plist_t with id 3065494590
[2022-07-03T17:42:20Z INFO  plist_plus] Dropping plist 2269541282
[2022-07-03T17:42:20Z WARN  plist_plus] Plist has already been freed
[2022-07-03T17:42:20Z INFO  plist_plus] Dropping plist 3065494590
[2022-07-03T17:42:20Z WARN  plist_plus] Plist has already been freed
[2022-07-03T17:42:20Z INFO  plist_plus] Dropping plist 3451195937
[2022-07-03T17:42:20Z INFO  plist_plus] Plist dropped
[2022-07-03T17:42:20Z INFO  plist_plus] Parsing xml
[2022-07-03T17:42:20Z INFO  plist_plus] Creating plist from plist_t with id 3988722464
[2022-07-03T17:42:20Z INFO  plist_plus::types::dictionary] Getting dict item
[2022-07-03T17:42:20Z INFO  plist_plus] Creating plist from plist_t with id 1099965478
[2022-07-03T17:42:20Z INFO  plist_plus] Cloning plist
[2022-07-03T17:42:20Z INFO  plist_plus] Getting type of cloned plist
[2022-07-03T17:42:20Z INFO  plist_plus] Creating plist from plist_t with id 359847415
[2022-07-03T17:42:20Z INFO  plist_plus] Dropping plist 1099965478
[2022-07-03T17:42:20Z INFO  plist_plus] Plist dropped
[2022-07-03T17:42:20Z INFO  plist_plus::types::string] Getting string value
[2022-07-03T17:42:20Z INFO  plist_plus::types::string] Converting cstring to string
[2022-07-03T17:42:20Z INFO  plist_plus] Dropping plist 359847415
[2022-07-03T17:42:20Z INFO  plist_plus] Plist dropped
[2022-07-03T17:42:20Z INFO  plist_plus] Dropping plist 3988722464
[2022-07-03T17:42:20Z INFO  plist_plus] Plist dropped
[2022-07-03T17:42:20Z INFO  netmuxd::central_data] Found UDID: "xxxxxxxx-xxxxxxxxx"
Adding device xxxxxxxx-xxxxxxxxx
[2022-07-03T17:42:20Z INFO  rusty_libimobiledevice::idevice] Converting udid to C string
[2022-07-03T17:42:20Z INFO  rusty_libimobiledevice::idevice] Creating udid ptr
[2022-07-03T17:42:20Z INFO  rusty_libimobiledevice::idevice] Converting ip address into bytes
[2022-07-03T17:42:20Z INFO  rusty_libimobiledevice::idevice] Encodings ipv4 address
[2022-07-03T17:42:20Z ERROR netmuxd::heartbeat] Failed to create heartbeat client for udid xxxxxxxx-xxxxxxxxx: UnknownError
[2022-07-03T17:42:20Z INFO  rusty_libimobiledevice::idevice] Dropping device xxxxxxxx-xxxxxxxxx
[2022-07-03T17:42:20Z INFO  netmuxd::heartbeat] Removing device xxxxxxxx-xxxxxxxxx from muxer
[2022-07-03T17:42:20Z INFO  netmuxd::central_data] Removing device: "xxxxxxxx-xxxxxxxxx"

jkcoxson commented 2 years ago

Please try the latest build that was just pushed. Post logs with RUST_LOG=info.

Demuos commented 2 years ago

I compiled from source. Still got a Hearthbeat failure after a while.

full log: https://gist.github.com/Demuos/a04d0c5a3878697064d5fb387448d366

Staubgeborener commented 2 years ago

I have the same problem @jkcoxson, here is my netmuxd logfile: https://gist.github.com/Staubgeborener/fdcb8d88060c59daea25e2666c048592

There seems to be also a difference by running netmuxd as root or not:

[user@nuc ~]$ sudo netmuxd disable-unix host 127.0.0.1
Starting netmuxd
Starting mDNS discovery
Listening on /var/run/usbmuxd
Adding device UUID-OF-MY-IPHONE

[user@nuc ~]$ netmuxd disable-unix host 127.0.0.1
Starting netmuxd
Starting mDNS discovery
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Os { code: 98, kind: AddrInUse, message: "Address already in use" }', src/main.rs:151:75
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

The Adding device UUID-OF-MY-IPHONE appears when i enter export USBMUXD_SOCKET_ADDRESS=127.0.0.1:27015 in a different tab. idevice_id can list my iPhone over USB-Cable, but without USB-Cable (only wifi), i'll get ERROR: Unable to retrieve device list! - but netmuxd seems to recognize my iPhone as i get the Adding device UUID-OF-MY-IPHONE after setting the env variable USBMUXD_SOCKET_ADDRESS. More informations can be found here. What is the correct way to pair the device with usbmuxd? I only did idevicepair pair so far which creates a /var/lib/lockdown/UUID-OF-MY-IPHONE.plist file.

I also tried the netmuxd-zeroconf file from the latest docker build like

docker pull ghcr.io/jkcoxson/netmuxd:latest
docker run ghcr.io/jkcoxson/netmuxd
docker cp 21b258146c14:/usr/local/bin/netmuxd-zeroconf /usr/local/bin/netmuxd-zeroconf

which runs into

[user@nuc ~]$ sudo ./netmuxd-zeroconf 
Starting netmuxd
Listening on /var/run/usbmuxd
iDevice plugged in!
iDevice plugged in!
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Busy', src/usb.rs:47:18
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
Serial number: serialnumberstring
Starting mDNS discovery for _apple-mobdev2._tcp.local with zeroconf
Adding device UUID-OF-IPHONE

# Starting AltServer and Press "Refresh All" in Altstore on iPhone
Failed to handle request:There was an error connecting to the device.

[user@nuc ~]$ sudo ./netmuxd-zeroconf --disable-unix --host 127.0.0.1
Starting netmuxd
Listening on 127.0.0.1:27015
WARNING: Running in host mode will not work unless you are running a daemon in unix mode as well
Starting mDNS discovery for _apple-mobdev2._tcp.local with zeroconf
Adding device UUID-OF-IPHONE
[2022-07-31T09:03:14Z ERROR netmuxd::heartbeat] Failed to create heartbeat client for udid UUID-OF-IPHONE: UnknownError
Removing UUID-OF-IPHONE

# Starting AltServer and Press "Refresh All" in Altstore on iPhone
Failed to handle request:AltServer could not find the device.

Btw i already re-paired the iPhone several times like

sudo rm /var/lib/lockdown/UUID-OF-IPHONE.plist
idevicepair pair
SUCCESS: Paired with device UUID-OF-IPHONE

Practicalbutterfly5 commented 2 years ago

@Staubgeborener I was in the same boat as you, was getting the heartbeat issue. For now, I am able to solve it. Here are all steps I did. You can try step 0 first and see if that solves the issue, if not try all the steps.

EDIT: Step 0: Restart wifi on ios

sudo systemctl restart avahi-daemon
sudo killall -s SIGKILL altserver usbmuxd netmuxd
Start usbmuxd(sudo usbmuxd) altserver(sudo altserver) and connect device via usb
Refresh one app, it should go successfully.
sudo kill -9 $(pidof usbmuxd)
Make sure usbmuxd is not running (ps -A | grep usbmuxd)
Start netmuxd(sudo netmuxd). Note that --disable-unix flag and host parameter was not included.
Start altserver without the environment variable(sudo altserver)

Staubgeborener commented 2 years ago

@Practicalbutterfly5 I can confirm, that this is working. The most important step is sudo kill -9 $(pidof usbmuxd). Only using sudo systemctl stop usbmuxd is not enough. In my case, the steps to get rid of this issue:

Start usbmuxd(sudo usbmuxd) and connect device via usb
idevicepair pair
check deviceinfo with ideviceinfo
sudo kill -9 $(pidof usbmuxd) (check the pid with ps -a | grep usbmuxd)
sudo ./netmuxd (in my case i dont need the -host 127.0.0.1:27015 argument)
open a new tab in terminal and start ./AltServer

Demuos commented 2 years ago

I´m not using AltServer with netmuxd, but with the libmobiledevice Library the Heartbeat error after a while ist still present. The described Solution indeed helped, when netmuxd doesn`t want to start at all. @staubgeborener Are there no more Heartbeat failures in your netmuxd log?

[2022-08-04T08:37:57Z INFO  netmuxd::devices] Getting UDID for MAC: "xxx"
[2022-08-04T08:37:57Z INFO  netmuxd::devices] Found UDID: "00008030-xxx"
[2022-08-04T08:37:57Z INFO  netmuxd::mdns] Device has already been added to muxer, skipping
[2022-08-04T08:37:59Z INFO  netmuxd::heartbeat] Heartbeat failed for 00008030-xxx
[2022-08-04T08:37:59Z INFO  rusty_libimobiledevice::services::heartbeat] Dropping heartbeat client
Removing 00008030-xxx
[2022-08-04T08:37:59Z INFO  rusty_libimobiledevice::idevice] Dropping device 00008030-xxx
[2022-08-04T08:37:59Z INFO  netmuxd::devices] Removing device: "00008030-xxx"

Netmuxd keeps Adding and Removing the Device all the time. Which makes automatic headless iphone backup to my Ubuntu NAS not possible.

Adding device 00008030-xxx
Removing 00008030-xxx
Adding device 00008030-xxx
Removing 00008030-xxx
Adding device 00008030-xxx
Removing 00008030-xxx

I already tried a cron Script that waits for the Adding Device output and then start backup, but even then I often get No Device found and it only works in 10% of the cases.

Staubgeborener commented 2 years ago

@Demuos No, i don't have any errors. Netmuxd runs the last 3 days without issues. I'll get the adding device message when i unlock my iPhone and the removing message when my device is locked. So i don't really care about it as i use this only for AltServer. And in this case, my iPhone is always unlocked. I can't tell you where the problem really is on your side, but like i said, killing the usbmuxd process sudo kill -9 $(pidof usbmuxd) was my solution.

Demuos commented 2 years ago

I found a problem with my startscript, which tried to start netmuxd more than once. Netmuxd and automated backups are working fine for 2 days now.