PJ_EINVAL when trying to connect player to sink

S.
SanveanRu .
Fri, Oct 28, 2016 1:01 AM

Hi list.

I am trying to create an app to stress test my SIP call recorder. This app
is written in python3 with pjsua2 and asyncio. It has variable number of
async workers. Each worker establishes a call to the destination URI, gets
call media, creates player, connects player port to call media, plays audio
file to it for some time, stops playback, disconnects player from call
media and then hangs up. After random delay it makes another call etc.

With small number of workers the app seems working fine, but when I create
50 or more workers (I have tried also 100 or 200 workers) things become
very strange. First  call for all workers completes fine, independent of
the number of workers. Each worker successfully connects its player port to
the media port. After hangup both conference ports are freed (I see this in
mediaEnumPorts() output), when new call with new media and new player is
made, it reuses previously freed ports on the bridge.  Sometime try to
connect player to media fails with following error:
media.cpp  pjsua_conf_connect(id, sink.id) error: Invalid value or argument
(PJ_EINVAL) (status=70004) [../src/pjsua2/media.cpp:198]

I print the list of allocated bridge ports just before startTransmit() call
and I see, that both ports are allocated:
Call 6a8442e6-a8d8-41fa-b9df-63401e104392: Media connected to port 30
CB ports: [53, 54, 59, 60, 65, 66, 44, 50, 12, 6, 5, 11, 42, 49, 35, 36,
13, 14, 17, 18, 19, 20, 29, 15, 31, 32, 47, 48, 3, 23, 24, 25, 26, 27, 28,
45, 46, 40, 43, 1, 2, 33, 34, 51, 52,
21, 22, 7, 8, 37, 38, 39, 41, 55, 56, 57, 58, 61, 10, 9, 62, 63, 64, 16,
4, 30]
02:44:06.688    pjsua_aud.c !Creating file player:
/home/sanvean/Music/smokey.wav..
02:44:06.688  wav_player.c  .File player '/home/sanvean/Music/smokey.wav'
created: samp.rate=44100, ch=2, bufsize=4KB, filesize=9441KB
02:44:06.688    resample.c  .resample created: high qualiy, large filter,
in/out rate=44100/8000
02:44:06.688    resample.c  .resample created: high qualiy, large filter,
in/out rate=8000/44100
02:44:06.688    pjsua_aud.c  .Player created, id=14, slot=3
CB ports: [53, 54, 59, 60, 65, 66, 44, 50, 12, 6, 5, 11, 42, 49, 35, 36,
13, 14, 17, 18, 19, 20, 29, 15, 31, 32, 47, 48, 23, 24, 25, 26, 27, 28, 45,
46, 40, 43, 1, 2, 33, 34, 51, 52, 2
1, 22, 7, 8, 37, 38, 39, 41, 55, 56, 57, 58, 61, 10, 9, 62, 63, 64, 16, 4,
30, 3]
Call 6a8442e6-a8d8-41fa-b9df-63401e104392: player created
Try to connect  3 --> 30
02:44:06.690    pjsua_aud.c !Conf connect: 3 --> 30
02:44:06.690      media.cpp  pjsua_conf_connect(id, sink.id) error: Invalid
value or argument (PJ_EINVAL) (status=70004) [../src/pjsua2/media.cpp:198]
Segmentation fault (core dumped)

I have noticed, that in most cases the problem arises, when bridge tries to
reuse ports, that were just freed. Here is small snippet of port
connection/disconnection history:
2016-10-28 02:43:54,707: MainThread Try to disconnect  2 -X> 1
2016-10-28 02:43:55,673: MainThread Try to connect      2 --> 1
2016-10-28 02:43:55,682: MainThread Try to disconnect  34 -X> 33
2016-10-28 02:43:56,671: MainThread Try to connect      34 --> 33
2016-10-28 02:43:56,688: MainThread Try to connect      52 --> 51
2016-10-28 02:43:57,676: MainThread Try to disconnect  41 -X> 39
2016-10-28 02:43:57,693: MainThread Try to disconnect  22 -X> 21
2016-10-28 02:43:57,749: MainThread Try to disconnect  38 -X> 37
2016-10-28 02:43:58,671: MainThread Try to connect      22 --> 21
2016-10-28 02:43:59,671: MainThread Try to disconnect  8 -X> 7
2016-10-28 02:44:00,690: MainThread Try to connect      8 --> 7
2016-10-28 02:44:01,731: MainThread Try to connect      38 --> 37
2016-10-28 02:44:01,749: MainThread Try to connect      41 --> 39
2016-10-28 02:44:02,671: MainThread Try to connect      56 --> 55
2016-10-28 02:44:02,689: MainThread Try to disconnect  62 -X> 61
2016-10-28 02:44:02,728: MainThread Try to connect      58 --> 57
2016-10-28 02:44:03,668: MainThread Try to disconnect  10 -X> 9
2016-10-28 02:44:03,674: MainThread Try to connect      10 --> 61
2016-10-28 02:44:05,670: MainThread Try to connect      62 --> 9
2016-10-28 02:44:05,689: MainThread Try to connect      64 --> 63
2016-10-28 02:44:05,707: MainThread Try to disconnect  30 -X> 16
2016-10-28 02:44:06,671: MainThread Try to disconnect  4 -X> 3
2016-10-28 02:44:06,675: MainThread Try to connect      4 --> 16
2016-10-28 02:44:06,690: MainThread Try to connect      3 --> 30

So, I stuck and ask for some clues.
Thanks in advance

PS By the way, SIP recorder, that is written using same paradigm and uses
mediaRecorder does not crash under this load.

--
Denis

Hi list. I am trying to create an app to stress test my SIP call recorder. This app is written in python3 with pjsua2 and asyncio. It has variable number of async workers. Each worker establishes a call to the destination URI, gets call media, creates player, connects player port to call media, plays audio file to it for some time, stops playback, disconnects player from call media and then hangs up. After random delay it makes another call etc. With small number of workers the app seems working fine, but when I create 50 or more workers (I have tried also 100 or 200 workers) things become very strange. First call for all workers completes fine, independent of the number of workers. Each worker successfully connects its player port to the media port. After hangup both conference ports are freed (I see this in mediaEnumPorts() output), when new call with new media and new player is made, it reuses previously freed ports on the bridge. Sometime try to connect player to media fails with following error: media.cpp pjsua_conf_connect(id, sink.id) error: Invalid value or argument (PJ_EINVAL) (status=70004) [../src/pjsua2/media.cpp:198] I print the list of allocated bridge ports just before startTransmit() call and I see, that both ports are allocated: Call 6a8442e6-a8d8-41fa-b9df-63401e104392: Media connected to port 30 CB ports: [53, 54, 59, 60, 65, 66, 44, 50, 12, 6, 5, 11, 42, 49, 35, 36, 13, 14, 17, 18, 19, 20, 29, 15, 31, 32, 47, 48, 3, 23, 24, 25, 26, 27, 28, 45, 46, 40, 43, 1, 2, 33, 34, 51, 52, 21, 22, 7, 8, 37, 38, 39, 41, 55, 56, 57, 58, 61, 10, 9, 62, 63, 64, 16, 4, 30] 02:44:06.688 pjsua_aud.c !Creating file player: /home/sanvean/Music/smokey.wav.. 02:44:06.688 wav_player.c .File player '/home/sanvean/Music/smokey.wav' created: samp.rate=44100, ch=2, bufsize=4KB, filesize=9441KB 02:44:06.688 resample.c .resample created: high qualiy, large filter, in/out rate=44100/8000 02:44:06.688 resample.c .resample created: high qualiy, large filter, in/out rate=8000/44100 02:44:06.688 pjsua_aud.c .Player created, id=14, slot=3 CB ports: [53, 54, 59, 60, 65, 66, 44, 50, 12, 6, 5, 11, 42, 49, 35, 36, 13, 14, 17, 18, 19, 20, 29, 15, 31, 32, 47, 48, 23, 24, 25, 26, 27, 28, 45, 46, 40, 43, 1, 2, 33, 34, 51, 52, 2 1, 22, 7, 8, 37, 38, 39, 41, 55, 56, 57, 58, 61, 10, 9, 62, 63, 64, 16, 4, 30, 3] Call 6a8442e6-a8d8-41fa-b9df-63401e104392: player created Try to connect 3 --> 30 02:44:06.690 pjsua_aud.c !Conf connect: 3 --> 30 02:44:06.690 media.cpp pjsua_conf_connect(id, sink.id) error: Invalid value or argument (PJ_EINVAL) (status=70004) [../src/pjsua2/media.cpp:198] Segmentation fault (core dumped) I have noticed, that in most cases the problem arises, when bridge tries to reuse ports, that were just freed. Here is small snippet of port connection/disconnection history: 2016-10-28 02:43:54,707: MainThread Try to disconnect 2 -X> 1 2016-10-28 02:43:55,673: MainThread Try to connect 2 --> 1 2016-10-28 02:43:55,682: MainThread Try to disconnect 34 -X> 33 2016-10-28 02:43:56,671: MainThread Try to connect 34 --> 33 2016-10-28 02:43:56,688: MainThread Try to connect 52 --> 51 2016-10-28 02:43:57,676: MainThread Try to disconnect 41 -X> 39 2016-10-28 02:43:57,693: MainThread Try to disconnect 22 -X> 21 2016-10-28 02:43:57,749: MainThread Try to disconnect 38 -X> 37 2016-10-28 02:43:58,671: MainThread Try to connect 22 --> 21 2016-10-28 02:43:59,671: MainThread Try to disconnect 8 -X> 7 2016-10-28 02:44:00,690: MainThread Try to connect 8 --> 7 2016-10-28 02:44:01,731: MainThread Try to connect 38 --> 37 2016-10-28 02:44:01,749: MainThread Try to connect 41 --> 39 2016-10-28 02:44:02,671: MainThread Try to connect 56 --> 55 2016-10-28 02:44:02,689: MainThread Try to disconnect 62 -X> 61 2016-10-28 02:44:02,728: MainThread Try to connect 58 --> 57 2016-10-28 02:44:03,668: MainThread Try to disconnect 10 -X> 9 2016-10-28 02:44:03,674: MainThread Try to connect 10 --> 61 2016-10-28 02:44:05,670: MainThread Try to connect 62 --> 9 2016-10-28 02:44:05,689: MainThread Try to connect 64 --> 63 2016-10-28 02:44:05,707: MainThread Try to disconnect 30 -X> 16 2016-10-28 02:44:06,671: MainThread Try to disconnect 4 -X> 3 2016-10-28 02:44:06,675: MainThread Try to connect 4 --> 16 2016-10-28 02:44:06,690: MainThread Try to connect 3 --> 30 So, I stuck and ask for some clues. Thanks in advance PS By the way, SIP recorder, that is written using same paradigm and uses mediaRecorder does not crash under this load. -- Denis