[3.8.1beta1] Existing connection gets allocated to a new channel

[dtinth]

Describe the bug

It seems like in some circumstances, when a new connection arrives, existing connections get assigned into the same channel. When this happens, the symptom is:

• On the client, the affected users gets these symptoms:

  • The sound begins stuttering.
  • The user receives a welcome message again.
  • The users appears multiple times in the client list.

  It basically disrupted the whole session.

• On the server, we get weird logs that said that several people connected on the same second, but the number of connected people does not increase.

  2021-09-25 00:03:36, 112.**.112.120, connected (15)
  2021-09-25 00:03:36, 171.**.89.130, connected (15)
  2021-09-25 00:03:36, 171.**.24.59, connected (15)
  2021-09-25 00:03:36, 182.**.53.34, connected (16)
  

To Reproduce
Run a server with -u 25 for max 25 users, and get several people to join. It will take a while. See this comment for a repro.

Expected behavior
Server should go smoothly.

Screenshots

Operating system
Linux, built from source

Version of Jamulus
3.8.1beta

Additional context
I suspect that there could be a bug with this PR:

• Faster channel lookup #1979

So, I reverted the PR (git revert 15ee6093df26efdb0cbf264e5f8dd34c6785dea6 -m 1), recompiled, and deployed it to my server. As of writing, I did not encounter the problem since.

[softins]

Ok, thanks for the report. PR #1979 is mine, so I will look at this to see why it’s happening.

[softins]

@dtinth - were you running the server with -T for multi-threading? If so, how many cores?

[dtinth]

@softins I just realized I forgot to add the -T flag, so no, multi threading is not enabled.

[softins]

Interesting, I think the problem is more subtle than just the channel creation. The creation and deletion in CServer::FindChannel() and CServer::FreeChannel() are protected by the mutex MutexChanOrder, so should be consistent. This is borne out by my testing.

A channel is created by the reception of an audio packet from an IP:port that is not already connected. So to test this, I have a client system with 7 different IP addresses (to make the logging more visible), and a perl script that creates 7 new channels with no delay between them:

#!/usr/bin/perl

use IO::Socket::INET;

$| = 1;

my %socket;

# my various local IPs
my @ips = qw(
        192.168.20.2
        192.168.20.3
        192.168.20.4
        192.168.20.5
        192.168.20.6
        192.168.20.7
        192.168.20.22
);

foreach $ip (@ips) {
        $socket{$ip} = new IO::Socket::INET(
                PeerAddr => 'hp3:22124',
                LocalAddr => $ip,
                LocalPort => 22133,
                Proto => 'udp'
        ) or die "Can't create UDP socket: $!\n";
}

sleep(2);

my $audio = pack("CCCa23", 0, 255, 254, '');

foreach $ip (@ips) {
        $socket{$ip}->send($audio);
        #sleep(1);
}

sleep(5);

foreach $ip (@ips) {
        $socket{$ip}->close();
}

hp3 is the host on which I am running the server (this is just on my LAN). I just send one audio packet from each IP, and allow the channel to time out within Jamulus after 30 seconds.

If I first run the above script with the sleep(1) uncommented, to space out the channel creation, the logging on the server looks like this:

[tony@hp3 jamulus]$ ./Jamulus -s -n
- server mode chosen
- no GUI mode chosen
Using "192.168.20.24" as external IP.
Recording state not initialised
 *** Jamulus, Version 3.8.1beta1dev-3886689
 *** Internet Jam Session Software
 *** Released under the GNU General Public License (GPL)
2021-09-27 14:53:35, 192.168.20.2, connected (1)
2021-09-27 14:53:36, 192.168.20.3, connected (2)
2021-09-27 14:53:37, 192.168.20.4, connected (3)
2021-09-27 14:53:38, 192.168.20.5, connected (4)
2021-09-27 14:53:39, 192.168.20.6, connected (5)
2021-09-27 14:53:40, 192.168.20.7, connected (6)
2021-09-27 14:53:41, 192.168.20.22, connected (7)
2021-09-27 14:54:11,, server idling -------------------------------------

If I then remove the sleep(1) to create all the channels almost at once, the logging looks like this:

2021-09-27 14:56:21, 192.168.20.2, connected (2)
2021-09-27 14:56:21, 192.168.20.3, connected (7)
2021-09-27 14:56:21, 192.168.20.4, connected (7)
2021-09-27 14:56:21, 192.168.20.5, connected (7)
2021-09-27 14:56:21, 192.168.20.6, connected (7)
2021-09-27 14:56:21, 192.168.20.7, connected (7)
2021-09-27 14:56:21, 192.168.20.22, connected (7)

These lines are output by the ServerLogging module. We need to understand the meaning of the number in brackets. It is actually the total number of connected channels at the time the message is composed in the line:

Logging.AddNewConnection ( RecHostAddr.InetAddr, GetNumberOfConnectedClients() );

within the event handler CServer::OnNewConnection(). I think this handler is called in a different thread from the audio packet reception.

So when the channels are all created at the same moment, the total number of connected clients has already gone up to 2 when the first connection is logged, and up to 7 by the time the second connection is logged.

It's possible to get more detailed logging of the channel list by uncommenting the line DumpChannels ( __FUNCTION__ ); at the end of CServer::FindChannel() and CServer::FreeChannel().

If I do that, and repeat the second test above, I get:

[tony@hp3 jamulus]$ ./Jamulus -s -n
- server mode chosen
- no GUI mode chosen
Using "192.168.20.24" as external IP.
Recording state not initialised
 *** Jamulus, Version 3.8.1beta1dev-3886689-dirty
 *** Internet Jam Session Software
 *** Released under the GNU General Public License (GPL)
FindChannel
  0: [0] 192.168.20.2:22133
----------
  1: [1] 0.0.0.0:0
  2: [2] 0.0.0.0:0
  3: [3] 0.0.0.0:0
  4: [4] 0.0.0.0:0
  5: [5] 0.0.0.0:0
  6: [6] 0.0.0.0:0
  7: [7] 0.0.0.0:0
  8: [8] 0.0.0.0:0
  9: [9] 0.0.0.0:0
FindChannel
  0: [1] 192.168.20.3:22133
  1: [0] 192.168.20.2:22133
----------
  2: [2] 0.0.0.0:0
  3: [3] 0.0.0.0:0
  4: [4] 0.0.0.0:0
  5: [5] 0.0.0.0:0
  6: [6] 0.0.0.0:0
  7: [7] 0.0.0.0:0
  8: [8] 0.0.0.0:0
  9: [9] 0.0.0.0:0
2021-09-27 15:16:23, 192.168.20.2, connected (2)
FindChannel
  0: [2] 192.168.20.4:22133
  1: [1] 192.168.20.3:22133
  2: [0] 192.168.20.2:22133
----------
  3: [3] 0.0.0.0:0
  4: [4] 0.0.0.0:0
  5: [5] 0.0.0.0:0
  6: [6] 0.0.0.0:0
  7: [7] 0.0.0.0:0
  8: [8] 0.0.0.0:0
  9: [9] 0.0.0.0:0
2021-09-27 15:16:23, 192.168.20.3, connected (3)
FindChannel
  0: [3] 192.168.20.5:22133
  1: [2] 192.168.20.4:22133
  2: [1] 192.168.20.3:22133
  3: [0] 192.168.20.2:22133
----------
  4: [4] 0.0.0.0:0
  5: [5] 0.0.0.0:0
  6: [6] 0.0.0.0:0
  7: [7] 0.0.0.0:0
  8: [8] 0.0.0.0:0
  9: [9] 0.0.0.0:0
FindChannel
  0: [4] 192.168.20.6:22133
  1: [3] 192.168.20.5:22133
  2: [2] 192.168.20.4:22133
  3: [1] 192.168.20.3:22133
  4: [0] 192.168.20.2:22133
----------
  5: [5] 0.0.0.0:0
  6: [6] 0.0.0.0:0
  7: [7] 0.0.0.0:0
  8: [8] 0.0.0.0:0
  9: [9] 0.0.0.0:0
FindChannel
  0: [5] 192.168.20.7:22133
  1: [4] 192.168.20.6:22133
  2: [3] 192.168.20.5:22133
  3: [2] 192.168.20.4:22133
  4: [1] 192.168.20.3:22133
  5: [0] 192.168.20.2:22133
----------
  6: [6] 0.0.0.0:0
  7: [7] 0.0.0.0:0
  8: [8] 0.0.0.0:0
  9: [9] 0.0.0.0:0
FindChannel
  0: [6] 192.168.20.22:22133
  1: [5] 192.168.20.7:22133
  2: [4] 192.168.20.6:22133
  3: [3] 192.168.20.5:22133
  4: [2] 192.168.20.4:22133
  5: [1] 192.168.20.3:22133
  6: [0] 192.168.20.2:22133
----------
  7: [7] 0.0.0.0:0
  8: [8] 0.0.0.0:0
  9: [9] 0.0.0.0:0
2021-09-27 15:16:23, 192.168.20.4, connected (7)
2021-09-27 15:16:23, 192.168.20.5, connected (7)
2021-09-27 15:16:23, 192.168.20.6, connected (7)
2021-09-27 15:16:23, 192.168.20.7, connected (7)
2021-09-27 15:16:23, 192.168.20.22, connected (7)

That clearly shows the correct channel allocation and the delay in logging with the current number of channels.

So I'm not denying there is an issue you have experienced, but I don't think it is as simple as wrongly reusing a channel, and I'd like to get to the bottom of it, so any insight you can provide would be very welcome!

[dtinth]

@softins From looking at the code, two specific parts of the code stand out as suspicious to me. I haven’t tested it, so I may be totally wrong here.

• The first is the binary search code in CServer::FindChannel. It is mainly because I cannot trust myself to write binary search — I never get it right the first time. I don’t think it’s your code. It’s me — binary search is currently beyond my comprehension, therefore all hand-written binary search looks suspicious to me. 😂

  Usually I would reach for higher-level functions like bsearch instead. IIRC, C++ has a lower_bound and upper_bound functions that can be used with vectors (I am not sure which one to use though). I am curious if there is a specific reason for writing binary search manually instead of using aforementioned library functions.

• The second is CHostAddress::Compare, the last line, which is return (int) thisAddr - (int) otherAddr;. Since it has been converted from quint32, IP addresses where first (or last?) byte at or above 128 can becomes a negative number. I am not sure if and how it will affect the binary search behavior… but without some kind of automated fuzz testing, this code looks very scary to me.

  Personally I would rewrite it as return thisAddr < otherAddr ? -1 : thisAddr > otherAddr ? 1 : 0; instead, or convert the CHostAddress to string and use well-established string comparison functions instead. Not sure if it would solve the problem, though.

  But if this is the culprit, in order to test it, you would need connections from multiple IP blocks. As seen from my logs, I have both people with IP above 128 and below 128 in my server.

What I would normally do is refactor the code into a unit that can be tested on its own, and then do some sort of automated fuzz testing against that code. But that would take quite some considerable effort to do, so for now I am just posting what I think. Let me know if you would like some help.

[softins]

Thank for the feedback:

From looking at the code, two specific parts of the code stand out as suspicious to me. I haven’t tested it, so I may be totally wrong here.

• The first is the binary search code in CServer::FindChannel. It is mainly because I cannot trust myself to write binary search — I never get it right the first time. I don’t think it’s your code. It’s me — binary search is currently beyond my comprehension, therefore all hand-written binary search looks suspicious to me. joy

I am pretty confident in the algorithm and that code. I prototyped it in perl before implementing it in Jamulus, and tested it thoroughly. In the definition of a search window, l is the first element, and r is after the last element, so r-l is the size of the window. I find this more intuitive than r pointing to the last actual element of the window.

Usually I would reach for higher-level functions like bsearch instead. IIRC, C++ has a lower_bound and upper_bound functions that can be used with vectors (I am not sure which one to use though). I am curious if there is a specific reason for writing binary search manually instead of using aforementioned library functions.

I'm not familiar with bsearch(), and I wrote it manually because I could be certain of what the code was doing, and could integrate the search with the allocation of a new channel when required. I didn't use a vector (I'm a C programmer at heart!), but just an array of channel indices to hold the order of active channels.

• The second is CHostAddress::Compare, the last line, which is return (int) thisAddr - (int) otherAddr;. Since it has been converted from quint32, IP addresses where first (or last?) byte at or above 128 can becomes a negative number. I am not sure if and how it will affect the binary search behavior… but without some kind of automated fuzz testing, this code looks very scary to me.
  Personally I would rewrite it as return thisAddr < otherAddr ? -1 : thisAddr > otherAddr ? 1 : 0; instead, or convert the CHostAddress to string and use well-established string comparison functions instead. Not sure if it would solve the problem, though.

I don't think it would make any difference. So long as the result of (int) a - (int) b is consistent, the search should be repeatable. But I'm happy to test the other approach. What would be very useful would be the output of your Jamulus log from idle to the point where it failed, including complete IP addresses (you can send it privately), so I could test the search with those actual values.

But if this is the culprit, in order to test it, you would need connections from multiple IP blocks. As seen from my logs, I have both people with IP above 128 and below 128 in my server.

What I would normally do is refactor the code into a unit that can be tested on its own, and then do some sort of automated fuzz testing against that code. But that would take quite some considerable effort to do, so for now I am just posting what I think. Let me know if you would like some help.

Maybe I need to do that, but the prototyping seemed ok.

I can think of two possible areas to examine more thoroughly:

1. Double check what happens when the array is full and a new channel comes in. Your issue did seem to be when the server was full?
2. Try your return thisAddr < otherAddr ? -1 : thisAddr > otherAddr ? 1 : 0; approach. Maybe with the current approach, it is possible for a < b and b < c but a > c due to sign overflow? I would need to run some tests to see if that is actually a possibility and if so, what effect it has on the array search. This is why your log of exact IPs would be useful. You can find my email address from any of my commits in git log.

[dtinth]

@softins Thanks for the response, so I believe that it is not with the binary search.

What would be very useful would be the output of your Jamulus log from idle to the point where it failed, including complete IP addresses (you can send it privately), so I could test the search with those actual values.

I wish I could send you the logs, but it turns out my systemd installation does not retain logs across reboots 😭.

Your issue did seem to be when the server was full?

I just checked my server config again. My server holds 25 people; the problem starts happening at around 15 people. When the server is a bit more than half-full. I am sorry for the confusion.

I just extracted the relevant code from Server.cpp into a simple fuzz test written in C.

https://gist.github.com/dtinth/c88221fd422b8e7a4be1880a2985c014

Basically, it:

1. Generate a list of 16 random IP addresses, stored as unsigned int.
2. Loop through the list, calls FindChannel, and records the allocated channel ID.
3. Dumps the channel list.
4. Loop through the list again, calls FindChannel, and verifies that returned channel ID is the same.

Here is the output:

Assigned channel 0 to address 4027842786
Assigned channel 1 to address 2012654168
Assigned channel 2 to address 1193667013
Assigned channel 3 to address 4122052051
Assigned channel 4 to address 4263011998
Assigned channel 5 to address 4108484205
Assigned channel 6 to address 4166756072
Assigned channel 7 to address 365088398
Assigned channel 8 to address 4240532790
Assigned channel 9 to address 1946523757
Assigned channel 10 to address 1210978930
Assigned channel 11 to address 4166500835
Assigned channel 12 to address 2184978
Assigned channel 13 to address 372076193
Assigned channel 14 to address 4183190416
Assigned channel 15 to address 10790629
0: 10 => 1210978930
1: 3 => 4122052051
2: 5 => 4108484205
3: 0 => 4027842786
4: 1 => 2012654168
5: 9 => 1946523757
6: 2 => 1193667013
7: 13 => 372076193
8: 7 => 365088398
9: 15 => 10790629
10: 12 => 2184978
11: 4 => 4263011998
12: 8 => 4240532790
13: 14 => 4183190416
14: 6 => 4166756072
15: 11 => 4166500835
Address 4027842786 got channel ID 16, which is different from previous channel ID 0
Address 4122052051 got channel ID 17, which is different from previous channel ID 3
Address 4108484205 got channel ID 18, which is different from previous channel ID 5
Address 1210978930 got channel ID 19, which is different from previous channel ID 10
seed=78, 4 violations

You can see that the channel list is no longer sorted when IP address with value ≥ 2³¹, is present. This causes an existing user to get allocated a new channel ID. This kinda explains why when this happens, some people get the welcome message again, and some users is displayed multiple times.

• Without the presence of IP whose value ≥ 2³¹, if this line is commented out, then the problem is resolved:

  -    iRand |= 0xF0000000;

• Using manual comparison instead of subtraction also resolves this issue:

  +    return InetAddr1 < InetAddr2 ? -1 : InetAddr1 > InetAddr2 ? 1 : 0;
  -    return (int)InetAddr1 - (int)InetAddr2;

Now how rare is this problem? Given 16 people, with uniformly random IP address, I tested the same code with srand(1) to srand(10000).

Number of violations	Seeds found
0	9100
1	767
2	91
3	18
4	13
5	8
6	1
7	2

The issue only happens 9% of the time, which kinda makes this bug kinda hard to pin down.

---

(Unrelated) For the general approach of caching the mapping from IP address to channel ID, personally I would use a HashMap (e.g. std::map or a QMap) instead of a sorted list, as it provides near-constant time for lookup, insertion and deletion.

[softins]

@dtinth - thank you very much for doing the tests! I think if you repeated them with the improved comparison of IPv4 addresses, you might find no violations (EDIT: ah yes, I see you did that already!). Please see my PR #2048. If you are able to try it and let me know if it is better, that would be great.

[dtinth]

@softins Thank you! Our next scheduled jam session is on Wednesday, so I will let you know after the session.