Lighthouse has a new layout. Prefer the old one? Return to the old layout, and switch back any time from the link at the top of each page.

Using multiple usbmuxd/libiphone clients fails

#50

As taken from bug #5 Integrate usbmuxd:

When attempting to use multiple clients that use usbmuxd I often receive libusb errors and things do not work.
The regular communication error I can see is "encountered USB read error: -104" on read and write.

Whenever that usb error happens, iphonesyslog shows me that the iPhone has trouble parsing the usbmux packets which probably is related:

Sun May 24 14:58:41 unknown com.apple.mobile.lockdown[21] <Notice>: Could not receive size of message
Sun May 24 14:58:41 unknown kernel[0] <Debug>: Error: void AppleUSBDeviceMux::handleMuxTCPInput(mbuf*) something is wrong, sending RST and closing 0xc6864f40
Sun May 24 14:58:41 unknown lockdownd[21] <Error>: (0x81fa00) handle_connection: Could not receive USB message #1 from unknown. Killing connection
Sun May 24 14:58:41 unknown kernel[0] <Debug>: void AppleUSBDeviceMux::handleMuxTCPInput(mbuf*) th.th_flags = 0x1, not TH_ACK(0x10)

Doing this I can reproduce the issue regularly:

  • Start usbmuxd -f -v -v -v -v -v
  • Start iproxy 5000 22
  • Connect with ssh to localhost:5000 and login to the device
  • Use ./dev/iphone_id to get the name which fails with ERROR: Can't connect to device
  • Quit the ssh session
  • Terminate iproxy
  • Terminate usbmuxd

I have uploaded a usbmuxd level 5 debug log for above session at http://gist.github.com/118058

From the log it looks like "peer sent connection reset. setting error: -104" and a rather repeating sequence of communication before that somehow reveal that we try to send some "bad stuff" multiple times to the device which then ends up in the error from the device syslog and resets the connection or similar.

What I also noticed is that in some occasions when trying multiple times at the iphone_id step from above it suddenly works once in like 15 attempts.

Reported by Martin S. · June 11th, 2009 @ 09:16 AM

State: resolved
Milestone: 1.0 Release
Assigned to: nobody

Activity

  1. Nikias Bassen
    Nikias Bassen

    I committed a little change to usbmuxd so that send operations are executed within a mutex. Try if that helps, if not perhaps we'll need another lock/unlock around the recv operations.

    June 15th, 2009 @ 03:14 AM

  2. Martin S.
    Martin S.
    • State changed from new to open

    Does it have to be caused by a concurrency issue? Even when doing nothing but calling one additional app (like having iFuse mount sitting there then calling ./iphone_id ) it already spits out the usb error -104 and fails to communicate at all. The mutex didn't help (tried it for the recv operations, too).

    It must be some sort of communication/protocol badness as the packets sent by usbmuxd seem definitely wrong according to what the iphone syslog says. I think dumping the communication and checking what's wrong exactly in the packets is the only way to solve this.

    Perhaps there had been some change in libiphone's recv functions which was not merged into the usbmuxd implementation?

    I am testing this with an iPod Touch 1G using OS 2.1.

    June 15th, 2009 @ 08:54 AM

  3. Nikias Bassen
    Nikias Bassen

    Hmmm, this is something I didn't think of. My device is iPhone 3G with iPhoneOS 2.2. I changed usbmuxd debugging output a bit so that with -v -v -v -v or more you'll get the packet contents dumped aswell. You can update your log, but perhaps it's inside SSL communications; just give it a try. If it is, enable extensive debugging output from libiphone to get the unencrypted data so we can see what's going on.

    June 15th, 2009 @ 11:09 AM

  4. Martin S.
    Martin S.

    Hmm, simply calling "iphone_id " already fails for me...
    See new log at: http://gist.github.com/130078
    Looks like I need to do an extensive output run aswell...

    June 15th, 2009 @ 12:45 PM

  5. Nikias Bassen
    Nikias Bassen

    As a reference: http://pims.selfip.net/usbmuxd_iphone_id.log is a log doing the same (running usbmuxd and then just calling iphone_id serial). What's strange is that it receives a connection reset when iphone_id is about to send a UniqueDeviceID GetValue request.

    What I noticed: the usbmuxd scan packet is sent over the first connection (fd=5) via the /var/run/usbmuxd socket. After receiving the list of devices, iphone_id calls usbmuxd_connect which will open another connection via usbmuxd's socket file (fd=6) which will then finally connect to the iphone. This seems to work, but about when the fd=5 connection is closed, the connection reset takes place for whatever reason, even if this connection is not between usbmuxd and the device, but between usbmuxd and iphone_id. Can you observe any delay about when the connection reset occurs?

    June 15th, 2009 @ 09:37 PM

  6. Martin S.
    Martin S.

    Yep, I notice a delay where it seems the read timeout completely runs out (I think at "recv_buf_timeout: fd=5 recv returned 0"). The packet before the delay appears to be the one that causes the entries in the iphone syslog and causes it to reset.

    June 15th, 2009 @ 09:51 PM

  7. Nikias Bassen
    Nikias Bassen
    • State changed from open to resolved

    Well, well. After a long debugging session (thanks Martin), this problem is history (at least I hope so).

    June 20th, 2009 @ 02:39 AM

  8. Martin S.
    Martin S.

    Apparently the issue was a race condition when an usbmux connection is setup.
    The problem even occurred on OS 3.0 but is fixed now.

    June 20th, 2009 @ 02:42 AM

Please Sign in or create a free account to add a new ticket.

With your very own profile, you can contribute to projects, track your activity, watch tickets, receive and update tickets through your email and much more.