[BUG] SRT return SRT_REJ_UNSECURED on BADSECRET

[jeandube]

SRT has a reject reason for BADSECRET (SRT_REJ_BADSECRET) but srt_getrejecreason() returns SRT_REJ_UNSECURE in that case.
caller, srt_getrejectreason() called from connect callback.

10:29:36.683214 mxphubN2.ravo: <App:Cx>[1]srt: Open succeeded
10:29:36.749172 SRTLIB: processSrtMsg_KMRSP(crypto.cpp:424): /SRT:RcvQ:w1!W:SRT.cn: processSrtMsg_KMRSP: received failure report. STATE: BADSECRET
10:29:36.749290 SRTLIB: interpretSrtHandshake(core.cpp:2663): /SRT:RcvQ:w1*E:SRT.cn: @263439354: KMRSP failed - rejecting connection as per enforced encryption.
10:29:36.749367 SRTLIB: processAsyncConnectRequest(core.cpp:3877): /SRT:RcvQ:w1!W:SRT.cn: @263439354: processAsyncConnectRequest: REJECT reported from HS processing: Password required or unexpected - not processing further
[Switching to LWP 30390]

Thread 6 "SRT:RcvQ:w1" hit Breakpoint 1, SrtConn_ConnectCB (opaq=0x5e5e10, ns=263439354, errorcode=1002, psaPeer=0x7fec005fa8, token=-1)
    at ../../libraries/ravo/mxpmod_lib/srtc_mod.c:2535
2535            iRejReason = srt_getrejectreason(ns);
(gdb) clear
Deleted breakpoint 1 
(gdb) c
Continuing.
10:29:43.067281 mxphubN2.ravo: <UEpoll>[1]srt: (lr:1) rx event: state=connecting->disconnected(sst:6)
10:29:43.067428 mxphubN2.ravo: <UEpoll>[1]srt: sock[@263439354] connecting->disconnected
10:29:43.067506 mxphubN2.ravo: <UEpoll>[1]srt: ReconnectEx(0x5e5e10[@263439354], 0, !mutexHeld)
10:29:43.067543 mxphubN2.ravo: <UEpoll>[1]srt: close(0x5e5e10[@263439354])
10:29:43.067572 mxphubN2.ravo: <UEpoll>[1]srt: sock[@263439354] disconnected->closing
10:29:43.067599 mxphubN2.ravo: <UEpoll>[1]srt: srt_close(@263439354)
10:29:43.067704 mxphubN2.ravo: <UEpoll>[1]srt: sock[@263439354->INV] closing->closed
10:29:43.067738 mxphubN2.ravo: <UEpoll>[1]srt: reconnecting
10:29:43.067767 mxphubN2.ravo: <UEpoll>[1]srt: c-open(0x5e5e10[INV],((nil),0)[10.65.10.234:9953],0x1) clnt srt://10.65.10.234:9953
10:29:43.067902 mxphubN2.ravo: <UEpoll>[1]srt: sock[INV->@263439353] closed->opened
10:29:43.067937 mxphubN2.ravo: <UEpoll>[1]srt: syncmode(0x5e5e10[@263439353],async)
10:29:43.067985 mxphubN2.ravo: <UEpoll>[1]srt: sock[@263439353] set(SNDSYN, 0)
10:29:43.068014 mxphubN2.ravo: <UEpoll>[1]srt: sock[@263439353] set(RCVSYN, 0)
10:29:43.068045 mxphubN2.ravo: <UEpoll>[1]srt: cfg(MSS,1376)
10:29:43.068073 mxphubN2.ravo: <UEpoll>[1]srt: cfg(RCVBUF,10240000)
10:29:43.068109 mxphubN2.ravo: 
Thread 6 "SRT:RcvQ:w1" hit Breakpoint 2, SrtConn_ConnectCB (opaq=0x5e5e10, ns=263439354, errorcode=1002, psaPeer=0x7fec005fa8, token=-1)
    at ../../libraries/ravo/mxpmod_lib/srtc_mod.c:2536
2536            srtcLog(srtc, LOG_DEBUG, "connectCB(%p[%s],%s,%d[%s:%d],%s,%d)\n",
(gdb) p iRejReason
$3 = 11
(gdb)```

[ethouris]

Weird. I don't have any similar log messages even if I use non-blocking mode. I am also using the callback registerred by srt_connect_callback() and here is what is displayed:

Opening SRT target caller(non-blocking, backlog=1) on skal4:5000
EPOLL: creating eid=1 and adding @446719530 in target+error mode
Connecting to skal4:5000 ... [ASYNC] [Connection error reported on @446719530 errcode=1002 reason=10]

The code:

static void TransmitConnectCallback(void*, SRTSOCKET socket, int errorcode, const sockaddr* /*peer*/, int /*token*/)
{
    int reason = srt_getrejectreason(socket);
    transmit_error_storage[socket] = TransmitErrorReason { errorcode, reason };
    Verb() << "[Connection error reported on @" << socket << " errcode=" << errorcode << " reason=" << reason << "]";
}

I modified it now to display the other data, this is not the official version, but this was also displayed there.

What exactly are you trying to do?

[jeandube]

I only have the following log FA enabled: 0x846

[jeandube]

And the listening peer has SRTO_ENFORCEDENCRYPTION=false

[ethouris]

With ENFORCEDENCRYPTION=false it also doesn't report any error - it allows for connection without problems. This is also the intended version, AFAIK. Just in case of BADSECRET it won't be able to send anything in any direction.

I can see this thing in my logs in this case:

17:18:09.786701/SRT:RcvQ:w1!W:SRT.cn: processSrtMsg_KMRSP: received failure report. STATE: BADSECRET
17:18:09.786705/SRT:RcvQ:w1.N:SRT.cn: processSrtMsg_KMRSP: cmd=4(KMRSP) len=16 KmState: SND=BADSECRET RCV=BADSECRET
17:18:09.786709/SRT:RcvQ:w1 D:SRT.cn: @952270796: updateAfterSrtHandshake: HS version 5
17:18:09.786713/SRT:RcvQ:w1 D:SRT.cn: @952270796: updateAfterSrtHandshake: version=5 side=INITIATOR
17:18:09.786716/SRT:RcvQ:w1 D:SRT.cn: AFTER HS: Set Rcv TsbPd mode: delay=0.120s RCV START: 9D 01:44:16.450417 [STDY]
17:18:09.786720/SRT:RcvQ:w1 D:SRT.cn: AFTER HS: Set Snd TsbPd mode with TLPktDrop: delay=0.120s START TIME: 9D 01:44:16.377353 [STDY]
17:18:09.786728/SRT:RcvQ:w1 D:SRT.cc: Creating LiveCC: bw=125000000 avgplsize=1316
17:18:09.786731/SRT:RcvQ:w1 D:SRT.cc: LiveCC: sending period updated: 10.88 by avg pktsize=1316, bw=125000000
17:18:09.786744/SRT:RcvQ:w1 D:SRT.rs: @952270796: setupCC: setting parameters: mss=1500 maxCWNDSize/FlowWindowSize=8192 rcvrate=16p/s (23296B/S) rtt=100000 bw=1
17:18:09.786748/SRT:RcvQ:w1 D:SRT.rs: @952270796: updateCC: EVENT:init
17:18:09.786752/SRT:RcvQ:w1 D:SRT.cc: LiveCC: sending period updated: 10.88 by avg pktsize=1316, bw=125000000
17:18:09.786756/SRT:RcvQ:w1 D:SRT.rs: @952270796: updateCC/TEV_INIT: updating BW=-1 (UNCHANGED)
17:18:09.786759/SRT:RcvQ:w1 D:SRT.rs: @952270796: updateCC: emitting signal for EVENT:init
17:18:09.786762/SRT:RcvQ:w1 D:SRT.rs: @952270796: updateCC: updated values from congctl: interval=10 us (tk (10.88us) cgwindow=8.19e+03
17:18:09.786772/SRT:RcvQ:w1 D:SRT.rs: @952270796: udpateCC: finished handling for EVENT:init
17:18:09.786778/SRT:RcvQ:w1 D:SRT.cn: @952270796:setting socket PENDING FOR CONNECTION
17:18:09.786783/SRT:RcvQ:w1 D:SRT.cn: removeConnector: removing @952270796
17:18:09.786793/SRT:RcvQ:w1 D:SRT.in: pton: Handshake address: 10.129.10.66:56090 provided in SRT IPv4 format
17:18:09.786804/SRT:RcvQ:w1 D:SRT.ei: epoll/update: @952270796 +[W]: E1 TRACKING: @952270796:[W][E] 
17:18:09.786823/SRT:RcvQ:w1.N:SRT.cn: @952270796: Connection established to: 10.0.129.4:5000
17:18:09.786831/SRT:RcvQ:w1 D:SRT.cn: @952270796: processAsyncConnectResponse: response processing result: ACCEPTED; REQ-TIME LOW to enforce immediate response
17:18:09.786836/SRT:RcvQ:w1 D:SRT.qr: worker: result for the unit: ACCEPTED

[jeandube]

It allows for connection? do you have a bad passphrase with ENFORCEDENCRYPTION in local caller?

[ethouris]

As long as you set this flag on BOTH endpoints, yes. This is also consistent with the old behavior from before this option was introduced.

If I have enforcedencryption=no on the listener, but yes on the caller, I have a rejection this time:

17:39:06.951819/SRT:RcvQ:w1!W:SRT.cn: processSrtMsg_KMRSP: received failure report. STATE: BADSECRET
17:39:06.951823/SRT:RcvQ:w1.N:SRT.cn: processSrtMsg_KMRSP: cmd=4(KMRSP) len=16 KmState: SND=BADSECRET RCV=BADSECRET
17:39:06.951826/SRT:RcvQ:w1*E:SRT.cn: @77526969: KMRSP failed - rejecting connection as per enforced encryption.
17:39:06.951830/SRT:RcvQ:w1 D:SRT.cn: @77526969: processAsyncConnectResponse: response processing result: REJECTED; REQ-TIME LOW to enforce immediate response
17:39:06.951834/SRT:RcvQ:w1 D:SRT.qr: worker: result for the unit: REJECTED
17:39:06.951838/SRT:RcvQ:w1 D:SRT.qr: worker: RECEIVED PACKET --> updateConnStatus. cst=REJECTED id=77526969 pkt-payload-size=72
17:39:06.951841/SRT:RcvQ:w1 D:SRT.cn: updateConnStatus: updating after getting pkt with DST socket ID @77526969 status: REJECTED
17:39:06.951845/SRT:RcvQ:w1 D:SRT.cn: RID: socket @77526969 still active (remaining 2.925779s of TTL)...
17:39:06.951853/SRT:RcvQ:w1 D:SRT.cn: RID:@77526969 cst=REJECTED -- repeating connection request.
17:39:06.951857/SRT:RcvQ:w1 D:SRT.cn: updateConnStatus: collected 1 for processing, 0 to close
17:39:06.951861/SRT:RcvQ:w1 D:SRT.cn: updateConnStatus: cst=REJECTED for @77526969
17:39:06.951863/SRT:RcvQ:w1 D:SRT.cn: updateConnStatus: processing async conn for @77526969 FROM 10.0.129.4:5000
17:39:06.951868/SRT:RcvQ:w1 D:SRT.cn: @77526969: processAsyncConnectRequest: REQ-TIME: HIGH. Should prevent too quick responses.
17:39:06.951872/SRT:RcvQ:w1!W:SRT.cn: @77526969: processAsyncConnectRequest: REJECT reported from HS processing: Password required or unexpected - not processing further

And in such a case I have indeed the same that you:

Connecting to skal4:5000 ... [ASYNC] [Connection error reported on @77526969 errcode=1002 reason=11]
[CALLBACK(error): {@77526969 error=1002 reason=11} ]
FAILURE
srt_connect(async/cb): [1002] Connection rejected: [11]: Password required or unexpected
Open FAILED - closing SRT sockets

But it's also an intended behavior. This time you have a listener that allows in the unsecure client and actually ACCEPTS the connection. But the caller realizes that it doesn't want unsecure connection and closes the connection itself.

BADSECRET is a rejection caused on the listener socket and passed this to the caller, so the caller reports the rejection as received from the listener. UNSECURE is a local error that the caller has caused itself, at least in this case. This error may be also reported from the listener in case when the listener has no password set and it has enforcedencryption=yes. Currently in the code these situation can't be really distinguished.

I'm not sure whether this situation with unsecure listener=enforced-encryption and caller=relaxed-encryption the call should be rejected in case when the caller has set a password, maybe this behavior should be actually changed.