`pymobiledevice3.exceptions.ConnectionTerminatedError` on backup start

[tcrasset]

trafficstars

Test environment

• Host OS version. Ubuntu 24.04
• Target device model and iOS version.

❯ pymobiledevice3 usbmux list
[
    {
        "BuildVersion": "20G75",
        "ConnectionType": "USB",
        "DeviceClass": "iPhone",
        "DeviceName": "iPhone",
        "Identifier": "REDACTED",
        "ProductType": "iPhone12,8",
        "ProductVersion": "16.6",
        "UniqueDeviceID": "REDACTED"
    }
]

Describe the bug

I'm getting the following error (cfr logs) as soon as I start the backup process.

I first tried with libimobiledevice's idevicebackup2, and it was able to download a few files at the start, then errored out with error code (-4) indicating a SSL error.

Then, any further attempts crashed immediately with the same error code, it wouldn't backup any other files, whether with the same output directory for an incremental backup, or a brand new one for a fresh start.

Building libimobiledevice from source yielded the same error, and afterward yielded error code -256.

This is why I tried pymobiledevice3 which is more maintained (thanks BTW for that nice package).

I'm suspecting an issue with my openssl version, but not sure.

I know you probably won't be able to reproduce, but could you point me somewhere I could look to see debug?

To Reproduce

pymobiledevice3 backup2 backup --udid REDACTED --verbose ~/Documents/iphoneJadeBackup123

Logs:

  0%|                                                                        | 0/100 [00:05<?, ?it/s]
Traceback (most recent call last):
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/services/mobilebackup2.py", line 365, in device_link
    yield dl
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/services/mobilebackup2.py", line 91, in backup
    dl.dl_loop(progress_callback)
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/services/device_link.py", line 48, in dl_loop
    message = self.receive_message()
              ^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/services/device_link.py", line 188, in receive_message
    return self.service.recv_plist()
           ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/service_connection.py", line 177, in recv_plist
    return parse_plist(self.recv_prefixed(endianity=endianity))
                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/service_connection.py", line 147, in recv_prefixed
    size = self.recvall(4)
           ^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/service_connection.py", line 141, in recvall
    raise ConnectionAbortedError()
ConnectionAbortedError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/service_connection.py", line 124, in sendall
    self.socket.sendall(data)
  File "/home/tom/.asdf/installs/python/3.11.9/lib/python3.11/ssl.py", line 1273, in sendall
    v = self.send(byte_view[count:])
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/.asdf/installs/python/3.11.9/lib/python3.11/ssl.py", line 1242, in send
    return self._sslobj.write(data)
           ^^^^^^^^^^^^^^^^^^^^^^^^
ssl.SSLEOFError: EOF occurred in violation of protocol (_ssl.c:2427)

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/tom/Downloads/test-pymobiledevice/env/bin/pymobiledevice3", line 8, in <module>
    sys.exit(main())
             ^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/__main__.py", line 110, in main
    cli()
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/click/core.py", line 1157, in __call__
    return self.main(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/click/core.py", line 1078, in main
    rv = self.invoke(ctx)
         ^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/click/core.py", line 1688, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/click/core.py", line 1688, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/click/core.py", line 1434, in invoke
    return ctx.invoke(self.callback, **ctx.params)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/click/core.py", line 783, in invoke
    return __callback(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/cli/cli_common.py", line 150, in wrap_callback_calling
    callback(service_provider=service_provider, **kwargs)
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/cli/backup.py", line 46, in backup
    backup_client.backup(full=full, backup_directory=backup_directory, progress_callback=update_bar)
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/services/mobilebackup2.py", line 60, in backup
    with self.device_link(backup_directory) as dl, \
  File "/home/tom/.asdf/installs/python/3.11.9/lib/python3.11/contextlib.py", line 158, in __exit__
    self.gen.throw(typ, value, traceback)
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/services/mobilebackup2.py", line 367, in device_link
    dl.disconnect()
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/services/device_link.py", line 191, in disconnect
    self.service.send_plist(['DLMessageDisconnect', '___EmptyParameterString___'])
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/service_connection.py", line 183, in send_plist
    return self.sendall(build_plist(d, endianity, fmt))
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tom/Downloads/test-pymobiledevice/env/lib/python3.11/site-packages/pymobiledevice3/service_connection.py", line 126, in sendall
    raise ConnectionTerminatedError from e
pymobiledevice3.exceptions.ConnectionTerminatedError

[doronz88]

That probably won't be too easy to figure out. Maybe you can try to perform the backup on one terminal, while the other performs the following:

pymobiledevice3 syslog live -mi backup

This could provide useful hints arround what happened when the error occurred.

[exculibar]

That probably won't be too easy to figure out. Maybe you can try to perform the backup on one terminal, while the other performs the following:

pymobiledevice3 syslog live -mi backup

This could provide useful hints arround what happened when the error occurred.

I had a similar problem when I executed the backup2 command using a wifi connection. (The syslog can not found any error)

First, watching the syslog

Then, execute backup

But, when I filter the error log in syslog, these following lines be print

2024-08-27 13:53:58.954690 remoted{Network}[51] <ERROR>: nw_path_necp_check_for_updates Failed to copy updated result (22)
2024-08-27 13:53:59.058468 lockdownd{CoreTelephony}[80] <ERROR>: Updating selectors after delegate removal failed with: Error Domain=NSCocoaErrorDomain Code=4099 UserInfo={NSDebugDescription=<private>}
2024-08-27 13:53:59.073090 CommCenter{CommCenter}[94] <ERROR>: Unknown device type.
2024-08-27 13:53:59.073771 CommCenter{CommCenter}[94] <ERROR>: Unknown device type.
2024-08-27 13:53:59.074550 lockdownd{CoreTelephony}[80] <ERROR>: Updating selectors after delegate removal failed with: Error Domain=NSCocoaErrorDomain Code=4099 UserInfo={NSDebugDescription=<private>}
2024-08-27 13:53:59.083503 lockdownd{CoreTelephony}[80] <ERROR>: Updating selectors after delegate removal failed with: Error Domain=NSCocoaErrorDomain Code=4099 UserInfo={NSDebugDescription=<private>}
2024-08-27 13:53:59.395532 remotepairingdeviced{remotepairingdeviced}[404] <ERROR>: Pairing deletion failed with error: <private>
2024-08-27 13:53:59.500675 remoted{Network}[51] <ERROR>: [C125 IPv6#76ee64fe.58510 tcp, interface: utun4, local: fdf8:2bb3:131c::1.56286, definite, attribution: developer, server, prohibit joining] is already cancelled, ignoring cancel
2024-08-27 13:53:59.500976 remoted{Network}[51] <ERROR>: [C125 IPv6#76ee64fe.58510 tcp, interface: utun4, local: fdf8:2bb3:131c::1.56286, definite, attribution: developer, server, prohibit joining] is already cancelled, ignoring cancel
2024-08-27 13:53:59.502799 remoted{Network}[51] <ERROR>: [C126 IPv6#76ee64fe.58510 tcp, interface: utun4, local: fdf8:2bb3:131c::1.56286, definite, attribution: developer, server, prohibit joining] is already cancelled, ignoring cancel
2024-08-27 13:53:59.503076 remoted{Network}[51] <ERROR>: [C126 IPv6#76ee64fe.58510 tcp, interface: utun4, local: fdf8:2bb3:131c::1.56286, definite, attribution: developer, server, prohibit joining] is already cancelled, ignoring cancel
2024-08-27 13:53:59.503489 remoted{Network}[51] <ERROR>: [C126 IPv6#76ee64fe.58510 tcp, interface: utun4, local: fdf8:2bb3:131c::1.56286, definite, attribution: developer, server, prohibit joining] is already cancelled, ignoring cancel
2024-08-27 13:53:59.505273 remoted{RemoteXPC}[51] <NOTICE>: [0x3a00fcf00] Cancel complete, delivering XPC_ERROR_CONNECTION_INVALID
2024-08-27 13:53:59.505894 remoted{Network}[51] <ERROR>: nw_socket_handle_socket_event <private> Socket SO_ERROR [54: Connection reset by peer]

Other command on wifi is well

[doronz88]

Technically the remoted and lockdownd are two completely different protocol stacks so lets keep the focus on the lockdown connection. The attached syslog are non relevant for lockdownd

[Lakr233]

I'm facing the same issue, and I've found the bug.

2024-09-26 20:25:45.858398 kernel{kernel}[0] <NOTICE>: 381.114 memorystatus: killing_highwater_process pid 348 [BackupAgent2] (highwater 60) 1110402KB - memorystatus_available_pages: 133844 compressor_size:15894

I dont know if there gonna be a fix for this kind of bug on our side.

[Lakr233]

Further investigation indicates that the problem persists when sending large files:

Downloading 1 files of size 1.04 GB

Does pymobiledevice3 split large files into smaller parts or send them all at once?

[doronz88]

From my understanding, its the device that tries to send this data, not the client fault. If you understand otherwise, can you maybe find the line where it's performed?

[Lakr233]

Downloading 1 files of size 1.04 GB

This is the log on device with syslog, and I am performing restore operation. With that said, it's device downloading the file. If we, the client, are sending large data more then device memory, it could fail.

I'm not able to find the line that make this happen because it's on device. And I'm looking for way to debug these line of code.

                # send file metadata
                self.service.sendall(struct.pack(SIZE_FORMAT, len(data) + struct.calcsize(CODE_FORMAT)))
                self.service.sendall(struct.pack(CODE_FORMAT, CODE_FILE_DATA))

                # split into chunks, otherwise we may crash BackupAgent2 by OOM
                # https://github.com/doronz88/pymobiledevice3/issues/1165#issuecomment-2376815692
                chunk_size = 32768
                while len(data) > 0:
                    chunk_data = data[:chunk_size]
                    data = data[chunk_size:]
                    self.service.sendall(chunk_data)

                buffer = struct.pack(SIZE_FORMAT, struct.calcsize(CODE_FORMAT)) + struct.pack(CODE_FORMAT, CODE_SUCCESS)
                self.service.sendall(buffer)

[Lakr233]

Update:

The bug persists when sending large files. I've tried 5 times, and each attempt crashed at the same 1.04 GB file. Immediately after the device logs the download, the kernel kills the process due to an out-of-memory issue.

The code above for splitting large data does not help. Finder can restore this backup without any issues.

Further investigation is needed.

[doronz88]

From my understanding this issue should now be fixed. Feel free to reopen if it isn't

[sunny-bwp]

i am facing same error while working with nuggets

[doronz88]

Does it occur with latest pymobiledevice3? If so, can your provide steps to reproduce?