[core] Minor connection logging improvement.

[maxsharabayko]

It is not clear from SRT logs which SRT socket ID is associated with which local and remote IP. It is even more viable in group connections. Therefore a 'note'-level log message has been added one a connection is accepted by the listener.
Some logs were downgraded from 'note' to 'debug'.

Before

srt-xtransmit receive "srt://:4200?groupconnect=1" --enable-metrics -v --loglevel note
12:34:57.347682 [I] Log level set to note
12:34:57.359667 [I] SOCKET::SRT srt://:4200: bound to ':4200'.
12:34:58.939000/T18380.N:SRT.cn: PASSING request from: 127.0.0.1:5200 to agent:121901312
12:34:58.939000/T18380.N:SRT.cn: Listener managed the connection request from: 127.0.0.1:5200 result:waveahand
12:34:58.940000/T18380.N:SRT.cn: PASSING request from: 127.0.0.1:55596 to agent:121901312
12:34:58.940000/T18380.N:SRT.cn: Listener managed the connection request from: 127.0.0.1:55596 result:waveahand
12:34:58.940000/T18380.N:SRT.cn: PASSING request from: 127.0.0.1:5200 to agent:121901312
12:34:58.940000/T18380.N:SRT.cn: HSREQ/rcv: cmd=1(HSREQ) len=12 vers=0x10503 opts=0xbf delay=120
12:34:58.941000/T18380.N:SRT.gm: group/add: adding member @121901311 into group $1195643134
12:34:58.941000/T18380.N:SRT.cn: @121901312: listen ret: -1 - conclusion
12:34:58.942000/T18380.N:SRT.cn: Listener managed the connection request from: 127.0.0.1:5200 result:waveahand
12:34:58.942435/T18380.N:SRT.cn: PASSING request from: 127.0.0.1:55596 to agent:121901312
12:34:58.942000/T18380.N:SRT.cn: HSREQ/rcv: cmd=1(HSREQ) len=12 vers=0x10503 opts=0xbf delay=120
12:34:58.942769/T18380.N:SRT.gm: group/add: adding member @121901309 into group $1195643134
12:34:58.943183 [I] SOCKET::SRT @121901312 (srt://:4200) Accepted connection @1195643134. TSBPD Latency RCV 120ms, peer 0ms. KM state INVALID (RCV UNSECURED, SND UNSECURED). PB key length: -1. Cryptomode INVALID. Stream ID: not set.
12:34:58.943000/T18380.N:SRT.cn: @121901312: listen ret: -1 - conclusion
12:34:58.943000/T18380.N:SRT.cn: Listener managed the connection request from: 127.0.0.1:55596 result:waveahand

After

Listener

srt-xtransmit receive "srt://:4200?groupconnect=1" --enable-metrics -v --loglevel note
11:32:34.221383 [I] Log level set to note
11:32:34.236246 [I] SOCKET::SRT srt://:4200: bound to ':4200'.
11:32:45.411000/T30680.N:SRT.gm: group/add: adding member @748136174 into group $1821877997
11:32:45.413000/T30680.N:SRT.cn: @748136174 connection on listener @748136175 (127.0.0.1:4200) from peer @559345310 (127.0.0.1:5200)
11:32:45.414000/T30680.N:SRT.gm: group/add: adding member @748136172 into group $1821877997
11:32:45.416000/T30680.N:SRT.cn: @748136172 connection on listener @748136175 (127.0.0.1:4200) from peer @559345309 (127.0.0.1:58766)
11:32:45.417000 [I] SOCKET::SRT @748136175 (srt://:4200) Accepted connection @1821877997. TSBPD Latency RCV 120ms, peer 0ms. KM state INVALID (RCV UNSECURED, SND UNSECURED). PB key length: -1. Cryptomode INVALID. Stream ID: not set.
11:32:45.418948 [I] RECEIVE Latency, us: avg n/a, min n/a, max n/a. Jitter: 0us. Delay Factor: 1us. Pkts: rcvd 0, reordered 0 (dist 0), lost 0, MD5 err 0, bad len 0.
...
11:32:49.459000/T10276.N:SRT.gm: group/remove: removing member @748136172 from group $1821877997
11:32:49.460000/T10276.N:SRT.gm: group/remove: removing member @748136174 from group $1821877997
11:32:49.460000/T41776*E:SRT.gr: grp/recv: $1821877997: ABANDONING: opened=false connected=false
11:32:49.461063 [W] RECEIVE read::recv: Connection does not exist

Caller

srt-xtransmit generate "srt://127.0.0.1:4200?bind=:5200"
 "srt://127.0.0.1:4200" --enable-metrics -v --sendrate 10Mbps --duration 3s --loglevel note
11:32:45.394061 [I] Log level set to note
11:32:45.407000/T34896.N:SRT.gm: group/add: adding member @559345310 into group $1633087135
11:32:45.408000/T34896.N:SRT.gm: group/add: adding member @559345309 into group $1633087135
11:32:45.414000/T40032.N:SRT.cn: @559345310: Connection established from (unknown:0) to peer @748136174 (127.0.0.1:4200)
11:32:45.417000/T14588.N:SRT.cn: @559345309: Connection established from (unknown:0) to peer @748136172 (127.0.0.1:4200)
11:32:45.418150 [I] PACER sendrate 10000000 bps (inter send interval 1052 us)
11:32:46.420488 [I] GENERATE Sending at 9855 kbps
11:32:47.433989 [I] GENERATE Sending at 9997 kbps

To Consider

• Maybe @121901312: listen ret: -1 - conclusion should also be Debug-level log message.

[jeandube]

Do we see where the group is created in these logs or we need to catch the first add?
I think socket in hex would have help glue these sockets together (ex: adding @0x74410ff in $0x474410fe). The @ and $ are almost redundant.

[ethouris]

Do we see where the group is created in these logs or we need to catch the first add?

There's a log from CUDT::makeMePeerOf, which may create a new group, but this is on the listener side only. It could be a good idea to add one also to CUDT::createGroup.

I think socket in hex would have help glue these sockets together (ex: adding @0x74410ff in $0x474410fe). The @ and $ are almost redundant.

@ and $ are intended to mark the bare number as being the socket or group id respectively, so in that light rather the "member" and "group" words might be redundant. I'd leave the "member" word there though for clarity.

Not sure what this hex would be useful for. The decimal encoding for the socket and group ID is being used in these logs everywhere. For Wireshark we have also submitted a fix that should show them in decimal.

[maxsharabayko]

@jeandube

I think socket in hex would have help glue these sockets together (ex: adding @0x74410ff in $0x474410fe). The @ and $ are almost redundant.

Just like Mikolaj said, at some point we decided to make Socket IDs consistent in logs and switched to decimal format, including srt-xtransmit and Wireshark.

[maxsharabayko]

@jeandube

Do we see where the group is created in these logs or we need to catch the first add?

@ethouris

There's a log from CUDT::makeMePeerOf, which may create a new group, but this is on the listener side only. It could be a good idea to add one also to CUDT::createGroup.

Maybe this log should become a regular one with "note"-level.

HLOGC(cnlog.Debug,
        log << "newConnection(GROUP): Socket @" << ns->m_SocketID << " BELONGS TO $" << g->id() << " - will "
            << (should_submit_to_accept ? "" : "NOT ") << "report in accept");