search

pjsip / pjproject

PJSIP project
http://www.pjsip.org
GNU General Public License v2.0
2.06k stars 781 forks source link

Unable to make an outgoing call #3652

Closed SAndreyV1683 closed 1 year ago

SAndreyV1683 commented 1 year ago

Describe the bug

An error occurs when trying to make an outgoing call. "Unable to register socket with ioqueue because socket fd is too large."

Steps to reproduce

make an outgoing call

PJSIP version

2.13

Context

Log, call stack, etc

08-03 16:09:08.476 11423 11423 D PjSipManager: Current_thread_name main
08-03 16:09:08.476 11423 11423 D MyLogWriter: 16:09:08.476           pjsua_call.c !Making call with acc #0 to sip:1317@sbc2.teleswyz.ru
08-03 16:09:08.476 11423 11423 D MyLogWriter: 16:09:08.476            pjsua_aud.c  .Set sound device: capture=-1, playback=-2, mode=0, use_default_settings=0
08-03 16:09:08.476 11423 11423 D MyLogWriter: 16:09:08.476            pjsua_aud.c  ..Opening sound device (speaker + mic) PCM@16000/1/20ms
08-03 16:09:08.477 11423 11423 D MyLogWriter: 16:09:08.476      android_jni_dev.c  ...Creating Android JNI stream
08-03 16:09:08.478 11423 11423 D MyLogWriter: 16:09:08.478      android_jni_dev.c  ...Using audio input source : 7
08-03 16:09:08.502 11423 11423 D MyLogWriter: 16:09:08.502      android_jni_dev.c  ...Audio record initialized successfully.
08-03 16:09:08.503 11423 15771 D MyLogWriter: 16:09:08.503      android_jni_dev.c !Recorder thread started
08-03 16:09:08.503 11423 15771 D MyLogWriter: 16:09:08.503         os_core_unix.c  Setting thread priority to -19 successful
08-03 16:09:08.512 11423 11423 W AudioTrack: Use of stream types is deprecated for operations other than volume control
08-03 16:09:08.512 11423 11423 W AudioTrack: See the documentation of AudioTrack() for what to use instead with android.media.AudioAttributes to qualify your playback use case
08-03 16:09:08.513 11423 11423 D MyLogWriter: 16:09:08.513      android_jni_dev.c !...Audio track initialized successfully.
08-03 16:09:08.513 11423 11423 D MyLogWriter: 16:09:08.513   ec0xb400007540816100  ...Creating Echo suppressor
08-03 16:09:08.513 11423 11423 D MyLogWriter: 16:09:08.513   ec0xb400007540816100  ...Using delay buffer with WSOLA.
08-03 16:09:08.513 11423 11423 D MyLogWriter: 16:09:08.513   ec0xb400007540816100  ...Echo suppressor created, clock_rate=16000, channel=1, samples per frame=320, tail length=200 ms, latency=100 ms
08-03 16:09:08.513 11423 11423 D MyLogWriter: 16:09:08.513      android_jni_dev.c  ...Android JNI stream started
08-03 16:09:08.513 11423 11423 D MyLogWriter: 16:09:08.513  dlg0xb400007473af08a8  .UAC dialog created
08-03 16:09:08.513 11423 11423 D MyLogWriter: 16:09:08.513  dlg0xb400007473af08a8  ..Session count inc to 2 by mod-pjsua
08-03 16:09:08.513 11423 11423 D MyLogWriter: 16:09:08.513          pjsua_media.c  .Call 1: initializing media..
08-03 16:09:08.514 11423 15776 D MyLogWriter: 16:09:08.514      android_jni_dev.c !Playback thread started
08-03 16:09:08.514 11423 15776 D MyLogWriter: 16:09:08.514         os_core_unix.c  Setting thread priority to -19 successful
08-03 16:09:08.516 11423 11423 D MyLogWriter: 16:09:08.516          pjsua_media.c !..RTP socket reachable at 10.77.5.14:16010
08-03 16:09:08.516 11423 11423 D MyLogWriter: 16:09:08.516          pjsua_media.c  ..RTCP socket reachable at 10.77.5.14:16011
08-03 16:09:08.516 11423 11423 D MyLogWriter: 16:09:08.516                  pjlib  ..Failed to register socket to ioqueue because socket fd is too big (fd=1337/FD_SETSIZE=1024)
08-03 16:09:08.516 11423 11423 D MyLogWriter: 16:09:08.516  udp0xb40000754080cc00  ..UDP media transport destroyed
08-03 16:09:08.516 11423 11423 D MyLogWriter: 16:09:08.516          pjsua_media.c  ..Unable to create media transport: Size is too big (PJ_ETOOBIG) [status=70017]
08-03 16:09:08.516 11423 11423 D MyLogWriter: 16:09:08.516          pjsua_media.c  ..Error creating media transport: Size is too big (PJ_ETOOBIG) [status=70017]
08-03 16:09:08.516 11423 11423 D MyLogWriter: 16:09:08.516          pjsua_media.c  ..Call 1: cleaning up provisional media, prov_med_cnt=2, med_cnt=0
08-03 16:09:08.516 11423 11423 D MyLogWriter: 16:09:08.516           pjsua_call.c  .Error initializing media channel: Size is too big (PJ_ETOOBIG) [status=70017]
08-03 16:09:08.516 11423 11423 D MyLogWriter: 16:09:08.516  dlg0xb400007473af08a8  ..Session count dec to 1 by mod-pjsua
08-03 16:09:08.517 11423 11423 D MyLogWriter: 16:09:08.517  dlg0xb400007473af08a8  .Dialog destroyed!
08-03 16:09:08.517 11423 11423 D MyLogWriter: 16:09:08.517          pjsua_media.c  .Call 1: deinitializing media..
08-03 16:09:08.517 11423 11423 D MyLogWriter: 16:09:08.517               call.cpp  pjsua_call_make_call(acc.getId(), &pj_dst_uri, param.p_opt, this, param.p_msg_data, &id) error: Size is too big (PJ_ETOOBIG) (status=70017) [../src/pjsua2/call.cpp:701]
08-03 16:09:08.517 11423 11423 D MyAccount: Title:       pjsua_call_make_call(acc.getId(), &pj_dst_uri, param.p_opt, this, param.p_msg_data, &id)
08-03 16:09:08.517 11423 11423 D MyAccount: Code:        70017
08-03 16:09:08.517 11423 11423 D MyAccount: Description: Size is too big (PJ_ETOOBIG)
08-03 16:09:08.517 11423 11423 D MyAccount: Location:    ../src/pjsua2/call.cpp:701
08-03 16:09:08.517 11423 11423 D PjSipManager: Current_thread_name main
08-03 16:09:08.603 11423 15776 D MyLogWriter: 16:09:08.602   ec0xb400007540816100 !Latency bufferring complete
08-03 16:09:08.689 11423 15776 D MyLogWriter: 16:09:08.689   ec0xb400007540816100  479 samples reduced, buf_cnt=1761
08-03 16:09:08.689 11423 15776 D MyLogWriter: 16:09:08.689   ec0xb400007540816100  Buffer size adjusted from 2240 to 1761 (eff_cnt=1440)
08-03 16:09:08.729 11423 15776 D MyLogWriter: 16:09:08.729   ec0xb400007540816100  479 samples reduced, buf_cnt=1282
08-03 16:09:08.729 11423 15776 D MyLogWriter: 16:09:08.729   ec0xb400007540816100  Buffer size adjusted from 1761 to 1282 (eff_cnt=1440)
08-03 16:09:09.518 11423 12584 D MyLogWriter: 16:09:09.517            pjsua_aud.c !Closing sound device after idle for 1 second(s)
08-03 16:09:09.519 11423 12584 D MyLogWriter: 16:09:09.519            pjsua_aud.c  .Closing Android JNI sound playback device and Android JNI sound capture device
08-03 16:09:09.519 11423 12584 D MyLogWriter: 16:09:09.519      android_jni_dev.c  .Android JNI stream stopped
08-03 16:09:09.520 11423 12584 D MyLogWriter: 16:09:09.520      android_jni_dev.c  .Destroying Android JNI stream...
08-03 16:09:09.525 11423 15771 D MyLogWriter: 16:09:09.525      android_jni_dev.c !Recorder thread stopped
08-03 16:09:09.529 11423 15776 D MyLogWriter: 16:09:09.529      android_jni_dev.c !Player thread stopped
08-03 16:09:09.583 11423 12584 D MyLogWriter: 16:09:09.583      android_jni_dev.c !.Audio record released
08-03 16:09:09.583 11423 12584 D AudioTrack: stop(3504): called with 17600 frames delivered
08-03 16:09:09.588 11423 12584 D MyLogWriter: 16:09:09.587      android_jni_dev.c  .Audio track released
08-03 16:09:09.588 11423 12584 D MyLogWriter: 16:09:09.588      android_jni_dev.c  .Android JNI stream destroyed
sauwming commented 1 year ago

It's likely because the app is leaking socket descriptors (i.e. opening them without closing, Google around for more details).

Let us know if this happens in our sample app, as well as how to reproduce it, since I don't think this will happen during the very first few calls.

SAndreyV1683 commented 1 year ago

Playback steps: App closed, once per minute the app receives a notification from a Fire Base Messaging service that starts a background service on the device. The background service starts the "end point" and registers on the sip server, the background service ends. After 5 hours of work in this mode, the user launches the application, tries to make a call. The error described above occurs.

sauwming commented 1 year ago

Okay, so it seems to pretty much confirm the socket leak issue.

The leak could be caused by the app or the library. To investigate further, you can add some logs in sock_bsd.c, in pj_sock_socket(), and pj_sock_close(), to print the sockets being opened and closed. Then you need to reproduce the issue.

The good news is that it's likely you won't need hours to identify the problem. If after a few calls or some period, you notices in the logs that there are some sockets being opened but not closed, then you have found out the root cause. But if the logs show no leak, then the issue is most likely within the app. Perhaps you forget to delete or dereference certain objects?