Force a delay in ack getting sent?

[depsypher]

I'm using Flask-Socketio as the backend for an iOS app using Socket.IO-Client-Swift on the client side.

I'd like to test my message timeout logic on the client, so ideally I'd like to have a way of conditionally delaying the server from sending an acknowledgement. I tried putting a sleep in my socketio route but it seems that the ack gets sent before the route logic gets invoked.

Anyone have advice on how I can do this kind of testing?

[miguelgrinberg]

Acks are sent when the event function returns, so I think I'm either not understanding what you are doing fully, or you are not correctly timing out on the client. Can you share some code to clarify what you have tried?

[depsypher]

Thanks for the reply. Here's what I've tried. In a nutshell, sleeping for 3 seconds before returning on the 10th invocation of "write-audio". I set the client to timeout after 1 second but the logs don't show that happening:

Server side

t = 0
@socketio.on("write-audio")
def on_write_audio(data):
    """Write a chunk of audio from the client."""
    print(f"write {type(data)}")
    r.xadd(session['recording'], {"data": data}, maxlen=100)

    global t
    if t == 10:
        print("SLEEPING!!!!!")
        socketio.sleep(3) # also tried time.sleep(3)
    t += 1
    print(f"t={t}")

Server log (there's also a background thread running so the 'result' events are not related):

received event "write-audio" from k2U7Hp5WAjB_PuenAAAB [/]
47OHTxoXbquCy_bRAAAA: Sending packet MESSAGE data 310[]
write <class 'bytes'>
t=10
transcription={0: 'incidunt', 5: 'recusandae', 10: 'suscipit', 15: 'omnis', 20: 'id', 25: 'iste'}
127.0.0.1 - - [19/Feb/2024 09:59:29] "PUT /transcription HTTP/1.1" 200 -
47OHTxoXbquCy_bRAAAA: Received packet MESSAGE data 51-11["write-audio",{"_placeholder":true,"num":0}]
47OHTxoXbquCy_bRAAAA: Received packet MESSAGE data <binary>
received event "write-audio" from k2U7Hp5WAjB_PuenAAAB [/]
write <class 'bytes'>
SLEEPING!!!!!
emitting event "result" to k2U7Hp5WAjB_PuenAAAB [/]
47OHTxoXbquCy_bRAAAA: Sending packet MESSAGE data 2["result",{"transcription":"INCIDUNT RECUSANDAE SUSCIPIT OMNIS ID ISTE "}]
Sending results to websocket_sid=k2U7Hp5WAjB_PuenAAAB
transcription={0: 'incidunt', 5: 'recusandae', 10: 'suscipit', 15: 'omnis', 20: 'id', 25: 'iste', 30: 'accusantium'}
127.0.0.1 - - [19/Feb/2024 09:59:29] "PUT /transcription HTTP/1.1" 200 -
transcription={0: 'incidunt', 5: 'recusandae', 10: 'suscipit', 15: 'omnis', 20: 'id', 25: 'iste', 30: 'accusantium', 35: 'odit'}
127.0.0.1 - - [19/Feb/2024 09:59:30] "PUT /transcription HTTP/1.1" 200 -
Sending results to websocket_sid=k2U7Hp5WAjB_PuenAAAB
emitting event "result" to k2U7Hp5WAjB_PuenAAAB [/]
47OHTxoXbquCy_bRAAAA: Sending packet MESSAGE data 2["result",{"transcription":"INCIDUNT RECUSANDAE SUSCIPIT OMNIS ID ISTE ACCUSANTIUM ODIT "}]
transcription={0: 'incidunt', 5: 'recusandae', 10: 'suscipit', 15: 'omnis', 20: 'id', 25: 'iste', 30: 'accusantium', 35: 'odit', 40: 'consectetur'}
127.0.0.1 - - [19/Feb/2024 09:59:30] "PUT /transcription HTTP/1.1" 200 -
transcription={0: 'incidunt', 5: 'recusandae', 10: 'suscipit', 15: 'omnis', 20: 'id', 25: 'iste', 30: 'accusantium', 35: 'odit', 40: 'consectetur', 45: 'hic'}
127.0.0.1 - - [19/Feb/2024 09:59:31] "PUT /transcription HTTP/1.1" 200 -
Sending results to websocket_sid=k2U7Hp5WAjB_PuenAAAB
emitting event "result" to k2U7Hp5WAjB_PuenAAAB [/]
47OHTxoXbquCy_bRAAAA: Sending packet MESSAGE data 2["result",{"transcription":"INCIDUNT RECUSANDAE SUSCIPIT OMNIS ID ISTE ACCUSANTIUM ODIT CONSECTETUR HIC "}]
transcription={0: 'incidunt', 5: 'recusandae', 10: 'suscipit', 15: 'omnis', 20: 'id', 25: 'iste', 30: 'accusantium', 35: 'odit', 40: 'consectetur', 45: 'hic', 50: 'eum'}
127.0.0.1 - - [19/Feb/2024 09:59:31] "PUT /transcription HTTP/1.1" 200 -
transcription={0: 'incidunt', 5: 'recusandae', 10: 'suscipit', 15: 'omnis', 20: 'id', 25: 'iste', 30: 'accusantium', 35: 'odit', 40: 'consectetur', 45: 'hic', 50: 'eum', 55: 'adipisci'}
127.0.0.1 - - [19/Feb/2024 09:59:32] "PUT /transcription HTTP/1.1" 200 -
Sending results to websocket_sid=k2U7Hp5WAjB_PuenAAAB
emitting event "result" to k2U7Hp5WAjB_PuenAAAB [/]
47OHTxoXbquCy_bRAAAA: Sending packet MESSAGE data 2["result",{"transcription":"INCIDUNT RECUSANDAE SUSCIPIT OMNIS ID ISTE ACCUSANTIUM ODIT CONSECTETUR HIC EUM ADIPISCI "}]
transcription={0: 'incidunt', 5: 'recusandae', 10: 'suscipit', 15: 'omnis', 20: 'id', 25: 'iste', 30: 'accusantium', 35: 'odit', 40: 'consectetur', 45: 'hic', 50: 'eum', 55: 'adipisci', 60: 'nobis'}
127.0.0.1 - - [19/Feb/2024 09:59:32] "PUT /transcription HTTP/1.1" 200 -
Sending results to websocket_sid=k2U7Hp5WAjB_PuenAAAB
emitting event "result" to k2U7Hp5WAjB_PuenAAAB [/]
47OHTxoXbquCy_bRAAAA: Sending packet MESSAGE data 2["result",{"transcription":"INCIDUNT RECUSANDAE SUSCIPIT OMNIS ID ISTE ACCUSANTIUM ODIT CONSECTETUR HIC EUM ADIPISCI NOBIS "}]
t=11
47OHTxoXbquCy_bRAAAA: Sending packet MESSAGE data 311[]
47OHTxoXbquCy_bRAAAA: Received packet MESSAGE data 51-12["write-audio",{"num":0,"_placeholder":true}]
47OHTxoXbquCy_bRAAAA: Received packet MESSAGE data <binary>
received event "write-audio" from k2U7Hp5WAjB_PuenAAAB [/]

Client side:

        // send over websocket
        await self.networkService.emitWriteAudio(bytes) { timedOut in
            if timedOut {
                print("timedout!")
                buffer.reset()
            } else {
                print("ack received!")
            }
        }

    func emitWriteAudio(_ bytes: [UInt8], callback: @escaping ((Bool) -> ())) async {
        await withCheckedContinuation { continuation in
            let data = Data(bytes: bytes, count: bytes.count)
            socketManager.defaultSocket.emitWithAck("write-audio", data).timingOut(after: 1) { data in
                if data.first as? String ?? "passed" == SocketAckStatus.noAck {
                    print("ack timeout!")
                    callback(true)
                } else {
                    callback(false)
                }
                continuation.resume()
            }
        }
    }

Client log:

LOG SocketIOClient{/}: Handling ack: 9 with data: []
ack received!
process buffer completed
process buffer started
LOG SocketIOClient{/}: Emitting: 51-10["write-audio",{"_placeholder":true,"num":0}], Ack: false
LOG OnAckCallback: OnAckCallback for 10 being released
LOG SocketEngine: Writing ws: 51-10["write-audio",{"_placeholder":true,"num":0}] has data: true
LOG SocketEngineWebSocket: Sending ws: 51-10["write-audio",{"_placeholder":true,"num":0}] as type: 4
LOG SocketEngine: Got message: 4310[]
LOG SocketParser: Parsing 310[]
LOG SocketParser: Decoded packet as: SocketPacket {type: 3; data: []; id: 10; placeholders: -1; nsp: /}
LOG SocketIOClient{/}: Handling ack: 10 with data: []
ack received!
process buffer completed
didReceive challenge
put transcript 3 bytes
process buffer started
LOG SocketIOClient{/}: Emitting: 51-11["write-audio",{"_placeholder":true,"num":0}], Ack: false

[miguelgrinberg]

Okay. So this the client emit in the server logs:

47OHTxoXbquCy_bRAAAA: Received packet MESSAGE data 51-11["write-audio",{"_placeholder":true,"num":0}]

This is the ack, which occurs much later:

47OHTxoXbquCy_bRAAAA: Sending packet MESSAGE data 311[]

So I don't see any issues on the server, the acks are getting delayed as you want.

[depsypher]

Apologies, it does seem to be a problem with the client not recognizing the timeout. Seemingly a bug in SocketIO-Client-Swift, but I could very well be using it wrong. Anyway, thanks for helping diagnose.

[depsypher]

Yep, confirmed that switching to a fork that contained this fix the timeouts do get triggered for me:
socketio/socket.io-client-swift#1470
jonstaff/socket.io-client-swift@beffb5b

In any case the problem had nothing to with flask-socketio, just a problem with the client side; will close this.