Fix timelapse shooting on PTP cameras

[gswirski]

Steps to reproduce:

Take photos in a loop (either using code and Rocc, or Camrote)

Actual behavior:

The app hangs after a while, waiting for a callback that never arrives

Expected behavior:

The routine continues until the battery is drained :)

System configuration

Rocc version:

f3763b8 / Camrote 1.6.5

iOS/macOS version:

iOS 14.2

Camera manufacturer and model:

RX100 VII

Other questions

Does the issue still occur after updating your Camera's Firmware?:

Yes

Have you tried any other versions of NVDA?

What's NVDA? :)

---

I think I've seen this hanging in every possible completion callback in https://github.com/simonmitchell/rocc/blob/master/Sources/Manufacturer%20Implementations/Sony/PTP%20IP%20Camera/SonyPTPIPCamera+TakePicture.swift#L22 Moreover, my app waits for photo download before starting a new capture, and sometimes it hangs there, too (i.e. no JPEG is recognized even though objectAdded and objectRemoved events were received as usual).

My current hypothesis is that when we execute a command that is immediately followed by getAllDevicePropDesc (because some event was received) the camera assumes that responses to previous queries were included in "all device props" and doesn't bother dealing with old commands. This is supported by the fact that transactionId of responses seems to always monotonic (warning: this is not scientific, that's just what I saw with my sample sequences).

Unfortunately, so far I wasn't able to reliably serialize commands (so that getAllDevicePropDesc is called only after all previous commands finished) without any side effects. I also tried timing out all completion callbacks that were awaiting transactionIds older than the last received one. Again, that didn't seem to fully resolve the issue and caused problems with exposure settings.

Another idea is that there might be some field in getAllDevicePropDesc that instructs how to handle outstanding requests.

I'm a bit reluctant to attach my Wireshark sessions here because: 1) they might contain private data and I haven't had the time to clean them up 2) they contain random experimentations and I have no confidence they represent the normal Rocc behavior 3) if anyone is interested and has time to investigate the issue, I'll be more than happy to prepare them a custom-tailored Wireshark session from my RX100 VII. :)

In terms of next steps, I'm working on a custom Wireshark dissector that will more reliably detect Sony PTPIP packets based on this work: https://github.com/sboisson/wireshark-ptpip (GPL alert, don't base your apps on that, use only as an external validation tool). My hope is that it'll be easier to spot differences between Sony's app behavior and Rocc.

[simonmitchell]

Thanks for the write up @gswirski and hope you have a lovely Christmas! I’m going to take a look at this hopefully too between Christmas and New Years ☺️

[gswirski]

Merry Christmas! I should be able to work on this full-time for a few days starting Tuesday.

I noticed that when I take photos with Rocc, there are 4 getAllDevicePropDesc calls vs just one in Imaging Edge Mobile. This might be why the camera is overwhelmed. Also, Imaging Edge Mobile calculates transactionIds differently. Almost always getAllDevicePropDesc has transactionId = 2 but is sometimes incremented if photo transfer is in progress. Not sure if this changes anything or is just implementation quirk in the Sony app.

I'll attach Wireshark sessions from Rocc and Imaging Edge Mobile on Monday. No progress on the custom dissector, I think it loses packets and thus it wasn't any more useful than the builtin dissector.

[simonmitchell]

getAllDevicePropDesc could definitely do with some improvements too... for example I know for a fact that currently we get ALL device prop desc for every request we make (talking eventing here mostly) but you can request only the changes that occurred since last call. This will require some changes to fetching events using CameraEventNotifier so as to achieve the same behaviour where a complete event is received in Camrote each time the camera advertises one but I think that may also do a lot to improve the situation!

[simonmitchell]

transactionId may be based on number of in-progress requests in imaging edge possibly then? In ROCC we just increment... according to the spec it shouldn't matter, but who knows when Sony are involved ;)

[simonmitchell]

Have tried a basic implementation of that here @gswirski :) https://github.com/simonmitchell/rocc/tree/feature/partial_events Won't have time to test it until later today probably, it needs doing anyways as it massively reduces the amount of data being sent between the camera and the phone.

What it doesn't do, is reduce the number of calls to getAllDevicePropDesc caused by this line in takePicture:

self.getDevicePropDescriptionFor(propCode: .objectInMemory, callback: { (result) in

I wonder if it's worth simply commenting out that for now and seeing if we can rely entirely on handlePTPIPEvent in SonyPTPIPCamera.swift?

Also need to look at the implementation of getDevicePropDescriptionFor() and see if we can change the order of the if statements so it also performs less intensive calls to the camera!

[simonmitchell]

Okay commenting that out getDevicePropDescriptionFor didn't resolve a anything, so I'm taking a deeper dive!

Edit, it's something to do with awaiting bytes, added some logging to log the actual hex data received on the control loop:

2020-12-27 15:19:38.811192+0000 Camrote[21939:6413879] [InputOutputPacketStream] Sending control packet to device: {
    length: 22
    code: cmdRequest
    transactionId: 966
    command: setControlDeviceB
    data: c2 d2 00 00 
}
2020-12-27 15:19:38.811293+0000 Camrote[21939:6413879] [InputOutputPacketStream] Sending control packet to device: {
    length: 20
    code: startDataPacket
    transactionId: 966
    dataLength:  2
    data: 14 00 00 00 09 00 00 00 c6 03 00 00 02 00 00 00 00 00 00 00 
}
2020-12-27 15:19:38.811339+0000 Camrote[21939:6413879] [InputOutputPacketStream] Sending control packet to device: {
    length: 14
    code: endDataPacket
    data: 0e 00 00 00 0c 00 00 00 c6 03 00 00 01 00 
}
2020-12-27 15:19:38.811364+0000 Camrote[21939:6413879] [InputOutputPacketStream] Stream has space available
2020-12-27 15:19:38.838096+0000 Camrote[21939:6413879] [InputOutputPacketStream] Stream has bytes available
2020-12-27 15:19:38.838114+0000 Camrote[21939:6413879] [InputOutputPacketStream] Start reading available bytes
2020-12-27 15:19:38.838177+0000 Camrote[21939:6413879] [InputOutputPacketStream] Read control available bytes (8)
2020-12-27 15:19:38.838196+0000 Camrote[21939:6413879] [InputOutputPacketStream] Control available bytes (0e 00 00 00 07 00 00 00 )
2020-12-27 15:19:38.838247+0000 Camrote[21939:6413879] [InputOutputPacketStream] Stream has bytes available
2020-12-27 15:19:38.838260+0000 Camrote[21939:6413879] [InputOutputPacketStream] Start reading available bytes
2020-12-27 15:19:38.838284+0000 Camrote[21939:6413879] [InputOutputPacketStream] Read event available bytes (8)
2020-12-27 15:19:38.841591+0000 Camrote[21939:6413879] [InputOutputPacketStream] Stream has bytes available
2020-12-27 15:19:38.841612+0000 Camrote[21939:6413879] [InputOutputPacketStream] Start reading available bytes
2020-12-27 15:19:38.841642+0000 Camrote[21939:6413879] [InputOutputPacketStream] Read event available bytes (36)
2020-12-27 15:19:38.841755+0000 Camrote[21939:6413879] [PTPIPClient] Received packet from device: {
    length: 18
    code: event
    event: propertyChanged
    data: ff ff ff ff 00 00 00 00 
}
2020-12-27 15:19:38.841774+0000 Camrote[21939:6413879] [CameraEventNotifier] Camera indicated event available
2020-12-27 15:19:38.841791+0000 Camrote[21939:6413879] [CameraEventNotifier] Fetching next event
2020-12-27 15:19:38.841878+0000 Camrote[21939:6413879] [InputOutputPacketStream] Sending control packet to device: {
    length: 22
    code: cmdRequest
    transactionId: 967
    command: getAllDevicePropData
    data: 00 00 00 00 
}
2020-12-27 15:19:38.841941+0000 Camrote[21939:6413879] [PTPIPClient] Received packet from device: {
    length: 18
    code: event
    event: objectAdded
    data: ff ff ff ff 01 c0 ff ff 
}
2020-12-27 15:19:38.841970+0000 Camrote[21939:6413879] [SonyPTPIPCamera] Handling "Object Added" event, initiating transfer. Awaiting object: true
2020-12-27 15:19:38.841981+0000 Camrote[21939:6413879] [SonyPTPIPCamera] Got object ID
2020-12-27 15:19:38.842059+0000 Camrote[21939:6413879] [InputOutputPacketStream] Sending control packet to device: {
    length: 22
    code: cmdRequest
    transactionId: 968
    command: getObjectInfo
    data: 01 c0 ff ff 
}
2020-12-27 15:19:38.842100+0000 Camrote[21939:6413879] [InputOutputPacketStream] Stream has space available
2020-12-27 15:19:38.851173+0000 Camrote[21939:6413879] [InputOutputPacketStream] Stream has bytes available
2020-12-27 15:19:38.851191+0000 Camrote[21939:6413879] [InputOutputPacketStream] Start reading available bytes
2020-12-27 15:19:38.851236+0000 Camrote[21939:6413879] [InputOutputPacketStream] Read control available bytes (6)
2020-12-27 15:19:38.851252+0000 Camrote[21939:6413879] [InputOutputPacketStream] Control available bytes (01 20 c6 03 00 00 )

You can see here that the last line corresponds to the transactionId 966 which is still awaiting response, however this never gets sent to the delegate for some reason. So the issue definitely lies ROCC-side and not from the camera. Possibly a race condition? I'm going to add a simple test to make sure it passes if it receives that data one after the other first off.

[simonmitchell]

I know what the problem is, and I have a pretty simple fix! So sony sometimes seems to send command response packets in two parts... As can be seen above: 0e 00 00 00 07 00 00 00 | 01 20 c6 03 00 00. This is why in InputOutputPacketStream we have awaitingFurtherDataPacket... The problem stems from here:

https://github.com/simonmitchell/rocc/blob/9ae0c6c26a43fe3ad23fc5cd87c5e1649b8c428e/Sources/Helpers/PTP/InputOutputPacketStream.swift#L199

We set awaitingFurtherDataPacket based on the data received from the loop, when data is received on both the control loop and the event loop. This means that if:

Control Loop -> 0e 00 00 00 07 00 00 00 Event Loop -> {EVENT PACKET HEX HERE} (awaitingFurtherDataPacket set to nil) Control Loop -> 01 20 c6 03 00 00

Then we never receive the command response! Easy solution: Move the awaitingFurtherDataPacket = ... to only execute when the stream is the control stream! :D

[simonmitchell]

Have tested with a 100 shot Timelapse and it's worked flawlessly! Closing out... will create a release of ROCC now for you @gswirski :)

[gswirski]

It works great, thank you!

I tested it with a 150 shot time-lapse, 20x 20s BULB exposures, and exposure bracketing. No hiccups. 🎉