iOS/TVOS 16 HKSV issue?

[n0rt0nthec4t]

Current Situation

There seems to be a change with a project I developed using HKSV since the release of TVOS16 yesterday (wasn't an issue before this update even running iOS16 betas and RC)

Seems that all HKSV recordings now end with a status of "TIMEOUT" and from what I can see, takes around 7-10seconds after the code notifies the last segment in code for HomeKit to issue the acknowledge stream function call

Have any other HKSV developers seen this issue occur since public release of TVOS/HomePod OS 16 etc?

Cheers

Logs

...

Configuration

..

Environment

Hap-NodeJS 0.10.3-beta5 Hap-NodeJS 0.10.3 release

Process Supervisor

not applicable

Additional Context

No response

[bauer-andreas]

Does the same HKSV implementation still work with iOS 15 based devices, in case you still have some laying around? Might be helpful to link to the code you are referring to.

You only have Apple TVs and no HomePods?

[n0rt0nthec4t]

Have both AppleTVs and HomePod minis for the hubs, nothing left on OS15 and was working fine before the AppleTvs and HomePods were updated yesterday

Code: https://github.com/n0rt0nthec4t/Nest_accfactory/blob/main/Nest_accfactory.js

starting from line 1008

This is an example of the lag and error.. Weird thing it still seems they record

2022-09-14 13:44:04 [NEST] Motion ended on 'xx:xx:xx:xx:xx:xx' 2022-09-14 13:44:16 [NEXUS] Stopped recording stream from 'trapworker104-us1.dropcam.com' 2022-09-14 13:44:16 [HKSV] Recording completed with error on 'xx:xx:xx:xx:xx:xx'. Reason was 'TIMEOUT'

[n0rt0nthec4t]

Some debugging

  HAP-NodeJS:EventedHTTPServer:Connection [::ffff:10.0.1.74] HTTP Response is finished +17ms
2022-09-19 10:24:31 [NEST] Motion ended on '55:55:55:55:55:01'
  HAP-NodeJS:EventedHTTPServer:Connection [::ffff:10.0.1.74] Sending HAP event notifications [ { aid: 1, iid: 10, value: 0 } ] +3s
  HAP-NodeJS:EventedHTTPServer:Connection [::ffff:10.0.1.76] Sending HAP event notifications [ { aid: 1, iid: 10, value: 0 } ] +0ms
  HAP-NodeJS:Camera:RecordingManagement [HDS ::ffff:10.0.1.76] Sending DATA_SEND DATA for stream 1 with metadata: { dataType: 'mediaFragment', dataSequenceNumber: 34, dataChunkSequenceNumber: 1, isLastDataChunk: false, dataTotalSize: 369172 } and length 262144; EoS: undefined +4s
  HAP-NodeJS:Camera:RecordingManagement [HDS ::ffff:10.0.1.76] Sending DATA_SEND DATA for stream 1 with metadata: { **dataType: 'mediaFragment', dataSequenceNumber: 34, dataChunkSequenceNumber: 2, isLastDataChunk: true, dataTotalSize: undefined } and length 107028; EoS: true +2ms
  HAP-NodeJS:Camera:RecordingManagement [HDS ::ffff:10.0.1.76] Finished DATA_SEND transmission for stream 1! +1ms
  HAP-NodeJS:Camera:RecordingManagement [HDS ::ffff:10.0.1.76] Received DATA_SEND CLOSE for streamId 1 with reason TIMEOUT +9s**
2022-09-19 10:24:40 [NEXUS] Stopped recording stream from 'trapworker280-us1.dropcam.com'
2022-09-19 10:24:40 [HKSV] Recording completed with error on '55:55:55:55:55:01'. Reason was 'TIMEOUT'

[bauer-andreas]

HAP-NodeJS:Camera:RecordingManagement [HDS ::ffff:10.0.1.76] Sending DATA_SEND DATA for stream 1 with metadata: { **dataType: 'mediaFragment', dataSequenceNumber: 34, dataChunkSequenceNumber: 2, isLastDataChunk: true, dataTotalSize: undefined } and length 107028; EoS: true +2ms

Looking at this line, the server-side (HAP-NodeJS) seems to be closing the stream properly 🤔 So not sure, why the client-side still keeps waiting for data to arrive.

Since I saw that the code was inspired by the unifi implementation, @hjdhjd did you experience similar issues with iOS 16?

[n0rt0nthec4t]

Assuming you mean the client side as in the “hubs”? Yes, weird, and weird that even with a timeout error, still records the event. So seems to have only occurred with tvOS and HomePod OS 16 releases as had the betas on iOS 16 running without the issue.. see if a software update changes things

[bauer-andreas]

Yeah HAP clients, so the hubs 😅

Yes, weird, and weird that even with a timeout error, still records the event.

So the recordings are still saved? Maybe, we messed something up in the protocol and the Hub expects some sort of close message idk. But this is what the EoS flag actually does 🤔 Lets see, if either anyone figures out, we get more reports on this or if the behaviour changes/fixes itself in a future update.

[n0rt0nthec4t]

Yep, recordings still appear saved.

[hjdhjd]

@Supereg No issues at all in iOS 16 / HomePod 16 / tvOS 16 with respect to HKSV. I've seen pretty smooth behavior and so has the Protect user community, by and large.

[github-actions[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[github-actions[bot]]

This issue has been closed as no further activity has occurred.

[adriancable]

@n0rt0nthec4t / @Supereg - I know this issue got closed due to being stale, but I have a little bit more info on this that I thought might be helpful to share.

Historically (prior to tvOS 16), once a recording stream had started, there were two ways it could stop: either motion detection -> false, or the generator yields isLast: true. In either case, HomeKit would close the stream (with code NORMAL) and acknowledgeStream on the delegate would get called.

In tvOS 16 onwards (whether deliberately or due to a bug), this changes in two ways. First, acknowledgeStream on the delegate is never called any more - no matter how the stream stops. Second, isLast: true now seems to be mishandled by the HK hub side. So, if you are doing the common pattern of sending fragments while motion is ongoing, and then at some point sending a packet with isLast: true when things are finishing up, what happens is that (in tvOS 16 onwards) HomeKit does not send a close stream request. Instead, it seems to be continuing to wait for packets (which of course never show up, because the generator function doesn't get resumed after sending a fragment with isLast: true). So after 8 seconds, HomeKit closes the stream with TIMEOUT - same as would happen if it didn't receive a fragment for 8 seconds ordinarily.

So whether you hit this or not depends on your implementation. If motion -> false always precedes you yielding a fragment with isLast: true, then things will work as before and your streams will terminate with NORMAL. If however your implementation actually has a chance of sending a fragment with isLast: true, then this will 'stick up' the HSV side and rather than closing the stream immediately (or even if motion -> false happens afterwards), it'll instead wait for the 8 seconds to elapse and then terminate the stream with TIMEOUT. If in your implementation either can happen, you essentially have a race condition and things can end in one way or the other.

So the way things work in tvOS 16 is as if the 'meaning/interpretation' of the isLast flag on the HSV side in tvOS 16 onwards is actually: keep the stream open (and await further fragments) even if motion -> false. Again, I don't know if this is a deliberate change or due to a bug. I don't have access to any 'official' HK documentation to check.

If a stream ends with TIMEOUT instead of NORMAL, it still gets recorded to the HSV timeline which is why some people may not have noticed this change. But ending with TIMEOUT is not entirely harmless, because it means that after motion ends, during the 8 seconds prior to the timeout, another recording event cannot start (since only one recording stream can be active at a time). So, during this period, if another motion event occurs it'll get missed. The 'fix' is to always pass isLast: false, and allow the stream to be ended by the HK hub when motion -> false. When this happens, the HK hub generally waits for 1 more fragment to arrive before closing the stream with code NORMAL.

Hope this info helps make sense of the behaviour you're seeing.

[n0rt0nthec4t]

@adriancable

Thank you for taking the time to explain this in details it really was" just dismissed" by most people. It makes sense, and as suggested always setting isLast to false and removing the "acknowledgeStream" function override, things operate without the TIMEOUT error

@Supereg

The question with using this fix will be, In RecordingManagement.ts, there is a specific check for isLast. Will be get this warning error at some points or do we need to removed the check?

  if (!lastFragmentWasMarkedLast && !this.closed) {
        // Delegate violates the contract. Exited normally on a non-closed stream without properly setting `isLast`.
        console.warn(`[HDS ${this.connection.remoteAddress}] Delegate finished streaming for ${this.streamId} without setting RecordingPacket.isLast. \
        Can't notify Controller about endOfStream!`);
      }

[adriancable]

@n0rt0nthec4t - presume there's a typo there and you mean 'as suggested always setting isLast to false'.

if I remember correctly (I haven't looked at the code recently) - that check makes sure that the generator doesn't return while the stream is still open. That check still makes sense. As long as motion is true (and hence the data stream is open), the generator should be continually yielding fragments. It should never just return (which will trigger this warning, if isLast is not set). If anything, the check should be 'broadened' to remove the !lastFragmentWasMarkedLast part from the condition, since isLast doesn't seem to work any more, and the warning message should be changed to say 'delegate finished streaming while the stream is still open' or something similar.

It makes sense that HSV expects a continuous stream of fragments to be sent while motion is true. My guess is that in 16.0, the spec has been amended to make this a requirement (or maybe it's been there all along, it's just enforced now), i.e. the accessory cannot unilaterally decide to stop sending fragments while motion is occurring. This does more or less make sense to me - it seems like a reasonable requirement - if there's motion for X seconds, the generator should return at least prebuffer + X seconds of fragments.