libimobiledevice / usbmuxd

A socket daemon to multiplex connections from and to iOS devices
https://libimobiledevice.org
GNU General Public License v2.0
1.44k stars 346 forks source link

1.1.1: usbmuxd is spamming that it cannot open plist file #154

Open kloczek opened 3 years ago

kloczek commented 3 years ago

Just aftre restart service:

Nov 25 03:33:18 domek usbmuxd[4631]: [03:33:18.132][3] Connecting to new device on location 0x20006 as ID 1
Nov 25 03:33:18 domek usbmuxd[4631]: [03:33:18.132][3] Connecting to new device on location 0x20007 as ID 2
Nov 25 03:33:18 domek usbmuxd[4631]: [03:33:18.133][3] Connected to v2.0 device 1 on location 0x20006 with serial number 5360b85f941843e8f5012e053fe9c28f447b7094
Nov 25 03:33:18 domek usbmuxd[4631]: [03:33:18.134][3] Connected to v2.0 device 2 on location 0x20007 with serial number 5a45df713aa451138ac0ec5d3b0e849a1f08f179
Nov 25 03:33:21 domek usbmuxd[4631]: [03:33:21.444][1] ERROR: Failed to read '/var/lib/lockdown/5360b85f941843e8f5012e053fe9c28f447b7094.plist': No such file or directory
Nov 25 03:33:26 domek usbmuxd[4631]: [03:33:26.446][1] ERROR: Failed to read '/var/lib/lockdown/5360b85f941843e8f5012e053fe9c28f447b7094.plist': No such file or directory
Nov 25 03:33:31 domek usbmuxd[4631]: [03:33:31.446][1] ERROR: Failed to read '/var/lib/lockdown/5360b85f941843e8f5012e053fe9c28f447b7094.plist': No such file or directory
Nov 25 03:33:36 domek usbmuxd[4631]: [03:33:36.443][1] ERROR: Failed to read '/var/lib/lockdown/5360b85f941843e8f5012e053fe9c28f447b7094.plist': No such file or directory
Nov 25 03:33:41 domek usbmuxd[4631]: [03:33:41.446][1] ERROR: Failed to read '/var/lib/lockdown/5360b85f941843e8f5012e053fe9c28f447b7094.plist': No such file or directory
Nov 25 03:33:46 domek usbmuxd[4631]: [03:33:46.445][1] ERROR: Failed to read '/var/lib/lockdown/5360b85f941843e8f5012e053fe9c28f447b7094.plist': No such file or directory
Nov 25 03:33:51 domek usbmuxd[4631]: [03:33:51.448][1] ERROR: Failed to read '/var/lib/lockdown/5360b85f941843e8f5012e053fe9c28f447b7094.plist': No such file or directory
Nov 25 03:33:56 domek usbmuxd[4631]: [03:33:56.443][1] ERROR: Failed to read '/var/lib/lockdown/5360b85f941843e8f5012e053fe9c28f447b7094.plist': No such file or directory
federicotorrielli commented 1 year ago

I have this exact problem @kloczek, did you manage to fix this?

kloczek commented 1 year ago

Nope ..

mexmer commented 1 year ago

does the directory exist? does usbmuxd have privileges to read and write files to that folder?

also (althought i don't think, it will be the case), check if there are no connect/disconnect device message in the log with same frequency as those error

federicotorrielli commented 1 year ago

The directory does exist but the file is not created or nonexistent @mexmer

mexmer commented 1 year ago

that's why i'm asking about permission, there is no problem, if file doesn't exits, usbmuxd will create new one, but only if it can create it.

also i tried to reproduce behavior you have observed, but only way i could do that was calling repeatedly ideviceinfo on unpaired device, can you check, there is no other sofware running, that could try to access device after plugin? might be desktop app or something.

this error shows in log, when ReadPairingRecord command is sent to usbmuxd, and that command is invoked when you want to communicate with connected device. so it looks like some process on your computer is trying to obtain device info from unpaired device.

federicotorrielli commented 1 year ago

This is part of my journalctl for usbmuxd:

Dec 04 19:31:37 evilscript-pc systemd[1]: Started Socket daemon for the usbmux protocol used by Apple devices.
Dec 04 19:31:37 evilscript-pc usbmuxd[47367]: [19:31:37.001][3] usbmuxd v1.1.1-35-gbccae83 starting up
Dec 04 19:31:37 evilscript-pc usbmuxd[47367]: [19:31:37.001][3] Successfully dropped privileges to 'usbmux'
Dec 04 19:31:37 evilscript-pc usbmuxd[47367]: [19:31:37.001][3] Using libusb 1.0.25
Dec 04 19:31:37 evilscript-pc usbmuxd[47367]: libusb: warning [op_get_configuration] device unconfigured
Dec 04 19:31:37 evilscript-pc usbmuxd[47367]: [19:31:37.048][3] Initialization complete
Dec 04 19:31:37 evilscript-pc usbmuxd[47367]: [19:31:37.048][3] Enabled exit on SIGUSR1 if no devices are attached. Start a new i>
Dec 04 19:31:37 evilscript-pc usbmuxd[47367]: [19:31:37.057][3] Connecting to new device on location 0x1002e as ID 1
Dec 04 19:31:37 evilscript-pc usbmuxd[47367]: [19:31:37.057][3] Connected to v2.0 device 1 on location 0x1002e with serial number>
Dec 04 19:31:37 evilscript-pc usbmuxd[47367]: [19:31:37.368][1] ERROR: Failed to read '/var/lib/lockdown/00008110-001C20223E29401>
Dec 04 19:31:37 evilscript-pc usbmuxd[47367]: [19:31:37.678][3] Removed device 1 on location 0x1002e
Dec 04 19:31:37 evilscript-pc usbmuxd[47367]: [19:31:37.681][3] usbmuxd shutting down
Dec 04 19:31:37 evilscript-pc usbmuxd[47367]: [19:31:37.782][3] Shutdown complete
Dec 04 19:31:37 evilscript-pc systemd[1]: usbmuxd.service: Deactivated successfully.
Dec 04 19:31:43 evilscript-pc systemd[1]: Started Socket daemon for the usbmux protocol used by Apple devices.
Dec 04 19:31:43 evilscript-pc usbmuxd[47404]: [19:31:43.624][3] usbmuxd v1.1.1-35-gbccae83 starting up
Dec 04 19:31:43 evilscript-pc usbmuxd[47404]: [19:31:43.625][3] Successfully dropped privileges to 'usbmux'
Dec 04 19:31:43 evilscript-pc usbmuxd[47404]: [19:31:43.625][3] Using libusb 1.0.25
Dec 04 19:31:43 evilscript-pc usbmuxd[47404]: [19:31:43.627][3] Initialization complete
Dec 04 19:31:43 evilscript-pc usbmuxd[47404]: [19:31:43.627][3] Enabled exit on SIGUSR1 if no devices are attached. Start a new i>
Dec 04 23:32:45 evilscript-pc systemd[1]: Stopping Socket daemon for the usbmux protocol used by Apple devices...
Dec 04 23:32:45 evilscript-pc usbmuxd[47404]: [23:32:45.568][3] Caught signal 15, exiting
Dec 04 23:32:45 evilscript-pc usbmuxd[47404]: [23:32:45.568][3] usbmuxd shutting down
Dec 04 23:32:45 evilscript-pc usbmuxd[47404]: [23:32:45.669][3] Shutdown complete
Dec 04 23:32:45 evilscript-pc systemd[1]: usbmuxd.service: Deactivated successfully.

I'm running on the latest PoP_OS! My laptop works correctly, my pc is the culprit of the log above. They have the same set of applications.

Here's a video of what happens + journalctl -f when connecting the iPhone 14:

https://user-images.githubusercontent.com/31370059/205731718-4b3b87a6-c432-4051-9e55-b416e3197c3b.mp4

(alternative download link: https://oshi.at/pGkR (open it in VLC))

@mexmer

mexmer commented 1 year ago

looks to me, there is issue either with your usb or might be also wrong cable, but as you can see from log, phone is connected, then connection is powered down (look at mfi_charge messages), disconnects, then connects again.

might be also issue with upowerd, try connecting phone again, after you disable it.

while i can't rule out problem with usbmuxd, disconnection of device from usb are not caused by usbmuxd, for some reason connection between phone and your computer is powering up and down, which causes cycling of usbmuxd (i suppose you running usbmuxd in systemd mode)

still first thing i would try to rule out hardware failure, so check if iphone connector is clean, try different cable, try different computer usb port.

smartmic commented 1 month ago

I had the same problem, in my case the culprit was upowerd, as @mexmer suggested. After killing that service and reconnecting the phone, everything worked fine.

pwaller commented 1 month ago

@smartmic :tada: :tada: I've been trying to get this to work for years. I had some difficulty because I think there is also a physical hardware issue with the phone's connection. But with some care to hold the cable right so that it would charge, and care to kill upowerd first, (and make sure it didn't auto-restart, which it was also doing), I can also confirm stopping upowerd did the trick!