Receiving SIP call cause "quiddity 0 not found" warning
Summary
When receiving a SIP call, Switcher prints following warning :
2022-10-12 11:39:33.510|test|36137748-5c0b-4c96-a456-2ac5c06d10b3|1071774|1071821|warning: quiddity 0 not found|container.hpp:168
Version used to reproduce issue
- switcher: develop@0dc63250 (Oct 12, 2022 11:42am GMT-0400)
How to reproduce ?
- Register callee
import pyquid, json
sip_server = "dev.sip.scenic.sat.qc.ca"
callee_user = "qasip1"
callee_password = "<redacted>"
callee_sip_config = pyquid.InfoTree(json.dumps({
"port": "5060",
"user": f"{callee_user}@{sip_server}", "pass": f"{callee_password}",
"stun": f"{sip_server}", "turn": f"{sip_server}",
"turn_user": f"{callee_user}", "turn_pass": f"{callee_password}"
}))
callee_sw = pyquid.Switcher("callee", debug=True)
callee_sip = callee_sw.create("sip", "sip_callee", callee_sip_config)
callee_sip.set("mode", "everybody")
- Call callee from caller
import pyquid, json, time
sip_server = "dev.sip.scenic.sat.qc.ca"
callee_user = "qasip1"
caller_user = "qasip2"
caller_password = "<redacted>"
caller_sip_config = pyquid.InfoTree(json.dumps({
"port": "5061",
"user": f"{caller_user}@{sip_server}", "pass": f"{caller_password}",
"stun": f"{sip_server}", "turn": f"{sip_server}",
"turn_user": f"{caller_user}", "turn_pass": f"{caller_password}"
}))
caller_sw = pyquid.Switcher("caller", debug=True)
caller_aud = caller_sw.create("audiotestsrc", "aud1")
caller_aud.set("wave", "0")
caller_aud.set("started", "true")
caller_sip = caller_sw.create("sip", "sip_caller", caller_sip_config)
caller_sip.invoke("add_buddy", [f"{callee_user}@{sip_server}"])
caller_aud_shmpath = list(caller_aud.get_info("shmdata.writer"))[0]
caller_sip.invoke("attach_shmdata_to_contact", [caller_aud_shmpath, f"{callee_user}@{sip_server}", "true"])
caller_sip.invoke("send", [f"{callee_user}@{sip_server}"])
time.sleep(1)
caller_sip.invoke("hang-up", [f"{callee_user}@{sip_server}"])
Callee process shows warning:
2022-10-12 13:03:36.973|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079252|warning: quiddity 0 not found|container.hpp:168
Caller hangs-up automatically after 1 second, callee completes inbound call normally and exits cleanly without crashing.
Here is complete callee session log:
ogauthier@ws2:~/git/gitlab/sat-mtl/tools/switcher$ python3
Python 3.9.2 (default, Feb 28 2021, 17:03:44)
[GCC 10.2.1 20210110] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import pyquid, json
>>> sip_server = "dev.sip.scenic.sat.qc.ca"
>>> callee_user = "qasip1"
>>> callee_password = "<redacted>"
>>> callee_sip_config = pyquid.InfoTree(json.dumps({
... "port": "5060",
... "user": f"{callee_user}@{sip_server}", "pass": f"{callee_password}",
... "stun": f"{sip_server}", "turn": f"{sip_server}",
... "turn_user": f"{callee_user}", "turn_pass": f"{callee_password}"
... }))
>>> callee_sw = pyquid.Switcher("callee", debug=True)
[...]
>>> callee_sip = callee_sw.create("sip", "sip_callee", callee_sip_config)
2022-10-12 13:03:25.910|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079209|debug: SIP is trying to set port from configuration|pj-sip-plugin.cpp:230
13:03:25.911 os_core_unix.c !pjlib 2.10 for POSIX initialized
2022-10-12 13:03:25.918|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079213|debug: Successfully started SIP transport on port 5060|pj-sip-plugin.cpp:305
2022-10-12 13:03:25.921|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079213|debug: local IP found for interface docker0: 172.17.0.1|pj-call.cpp:66
2022-10-12 13:03:25.921|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079213|debug: local IP found for interface ens18: 10.100.100.110|pj-call.cpp:66
2022-10-12 13:03:25.921|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079213|debug: local IP found for interface lo: 127.0.0.1|pj-call.cpp:66
2022-10-12 13:03:25.921|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079213|debug: local IP found for interface tun0: 10.10.40.4|pj-call.cpp:66
2022-10-12 13:03:25.921|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079213|warning: install codecs failed|pj-call.cpp:96
2022-10-12 13:03:25.927|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079209|debug: SIP is trying to set STUN/TURN from configuration|pj-sip-plugin.cpp:259
2022-10-12 13:03:26.448|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079218|debug: ICE state Candidate Gathering Complete|pj-ice-stream-trans.cpp:92
2022-10-12 13:03:26.450|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079218|debug: ICE initialization successful|pj-ice-stream-trans.cpp:104
2022-10-12 13:03:26.451|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079209|debug: sip has set STUN/TURN from configuration|pj-sip-plugin.cpp:261
2022-10-12 13:03:26.451|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079209|debug: SIP is trying to register from configuration|pj-sip-plugin.cpp:269
2022-10-12 13:03:26.511|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079216|debug: registration SIP status code 200|pj-presence.cpp:477
2022-10-12 13:03:26.512|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079209|debug: sip registered using configuration file|pj-sip-plugin.cpp:273
>>> callee_sip.set("mode", "everybody")
True
>>> 2022-10-12 13:03:35.016|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079219|debug: incoming call from sip:qasip1@<redacted>:5060;ob|pj-call.cpp:501
2022-10-12 13:03:35.017|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079219|debug: buddy added|pj-presence.cpp:343
2022-10-12 13:03:35.500|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079218|debug: ICE state Candidate Gathering Complete|pj-ice-stream-trans.cpp:92
2022-10-12 13:03:35.500|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079218|debug: ICE initialization successful|pj-ice-stream-trans.cpp:104
2022-10-12 13:03:36.503|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079219|debug: writer initialized|switcher-logger.hpp:39
2022-10-12 13:03:36.510|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079219|debug: SDP :
[...]
2022-10-12 13:03:36.510|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079219|debug: ICE ufrag received: 79e11687|pj-call.cpp:1330
2022-10-12 13:03:36.510|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079219|debug: ICE pwd received: 75f2bf0273a2db3d5790da71|pj-call.cpp:1336
2022-10-12 13:03:36.510|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079219|debug: ICE candidate received: Sa64646e 1 UDP 1694498815 <redacted> 35813 typ srflx|pj-call.cpp:1352
2022-10-12 13:03:36.510|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079219|debug: ICE candidate received: Ha64646e 1 UDP 2130706431 10.100.100.110 35813 typ host|pj-call.cpp:1352
2022-10-12 13:03:36.510|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079219|debug: ICE candidate received: Hac110001 1 UDP 2130706431 172.17.0.1 35813 typ host|pj-call.cpp:1352
2022-10-12 13:03:36.510|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079219|debug: ICE candidate received: Ha0a2804 1 UDP 2130706431 10.10.40.4 35813 typ host|pj-call.cpp:1352
2022-10-12 13:03:36.511|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079219|debug: ICE candidate received: R343ca7fc 1 UDP 16777215 52.60.167.252 60490 typ relay|pj-call.cpp:1352
2022-10-12 13:03:36.511|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079219|debug: PJSIP_INV_STATE_CONNECTING|pj-call.cpp:413
2022-10-12 13:03:36.533|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079216|debug: PJSIP_INV_STATE_CONFIRMED|pj-call.cpp:405
2022-10-12 13:03:36.533|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079216|debug: call connected|pj-call.cpp:303
2022-10-12 13:03:36.940|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079218|debug: ICE state Negotiation Success|pj-ice-stream-trans.cpp:92
2022-10-12 13:03:36.940|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079218|debug: ICE negotiation successful|pj-ice-stream-trans.cpp:104
2022-10-12 13:03:36.948|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079218|debug: resizing shmdata (/run/user/1001/switcher_callee_1_3-0) from 1 bytes to 1044 bytes|switcher-logger.hpp:39
2022-10-12 13:03:36.973|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079252|warning: quiddity 0 not found|container.hpp:168
>>> 2022-10-12 13:04:14.560|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079216|debug: PJSIP_INV_STATE_DISCONNECTED|pj-call.cpp:401
2022-10-12 13:04:14.560|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079216|debug: call disconnected. Reason=200 (Normal call clearing)|pj-call.cpp:223
2022-10-12 13:04:14.563|callee|61657a3e-c2ec-4431-9429-562a02d392c8|1079209|1079246|debug: client removed, remaining 0|switcher-logger.hpp:39
Expected behavior
Container creation should succeed without going thru construct_error_return
.
What is the frequency of occurrence of this behavior ?
Every time Switcher receives a call.
Other comment
This have something to do with the nickname breaking change of Switcher 3.x.
If I comment out line 341 in plugins/pjsip/pj-sip-plugin.cpp, it goes thru without the warning.
2022-10-12 13:21:01.778|callee|8897ad79-7aa1-47b5-991f-8d160489d0ab|1081234|1081253|debug: call connected|pj-call.cpp:303
2022-10-12 13:21:02.194|callee|8897ad79-7aa1-47b5-991f-8d160489d0ab|1081234|1081255|debug: ICE state Negotiation Success|pj-ice-stream-trans.cpp:92
2022-10-12 13:21:02.194|callee|8897ad79-7aa1-47b5-991f-8d160489d0ab|1081234|1081255|debug: ICE negotiation successful|pj-ice-stream-trans.cpp:104
2022-10-12 13:21:02.204|callee|8897ad79-7aa1-47b5-991f-8d160489d0ab|1081234|1081255|debug: resizing shmdata (/run/user/1001/switcher_callee_1_3-0) from 1 bytes to 1044 bytes|switcher-logger.hpp:39
2022-10-12 13:21:02.255|callee|8897ad79-7aa1-47b5-991f-8d160489d0ab|1081234|1081290|debug: received server info, shm_size 1, type audio/x-raw, format=(string)S16LE, layout=(string)interleaved, rate=(int)44100, channels=(int)1, switcher-name=(string)callee, quiddity-id=(int)1|switcher-logger.hpp:39
2022-10-12 13:21:02.255|callee|8897ad79-7aa1-47b5-991f-8d160489d0ab|1081234|1081290|debug: client connected|switcher-logger.hpp:39
I believe that we used to use extshmsrc nickname to store media-label received from inbound SIP call. It was okay because Switcher used quiddity ids internally. Now that Switcher uses quiddity nicknames to refer to quiddities, we cannot override extshmsrc nickname after creation.
I'm not sure of the media-label lifecycle callee side. I believe that it's already stored somewhere else like in a label description.