We are seeing odd behavior with the conferencing module. Based on our testing, this behavior is only occurring within the conferencing module. Any suggestions are greatly appreciated!
Issue Overview
3CX conferencing module consistently drops external VOIP calls after 15 minutes.
Using the same VOIP line routed directly to phones works with no issues. This issue seems to be centered around the conference module itself.
Setup and Configuration
- SonicWall NSA 2400 Firewall. SIP and RTP ports are forwarded and functional
- Version V10.0.22686.2297 SP.5
- SIP Provider Configuration
- Support Re-invite = False
- Supports Replace = False
- PBX Delivers Audio = True
Testing Completed
Test#1
VOIP Line routed to active conference bridge with one internal VOIP phone active (Polycom)
Status: External call routed to conference bridge dropped after just over 15 minutes with “ACK is not received”
Test#2
VOIP Line routed to active conference bridge with one internal VOIP phone active (Cisco)
Status: External call routed to conference bridge dropped after just over 15 minutes with “ACK is not received”
Test#3
VOIP Line routed directly to internal Cisco phone (no conference module)
Status: Call succeeded to over 20 minutes before test considered a pass
Logging from Test #2 (FAIL CONDITION)
12:24:33.702 [CM503008]: Call(1): Call is terminated
12:24:23.472 [CM503008]: Call(2): Call is terminated
12:24:23.466 [CM503021]: Call(2): ACK is not received
12:24:21.698 Currently active calls - 2: [1,2]
12:23:51.388 [MS210003] C:2.1:Answer provided. Connection(transcoding mode[unsecure]):71.39.116.253:9000(9001)
12:23:51.386 [MS210001] C:2.3:Answer received. RTP connection[unsecure]: 127.0.0.1:40316(40317)
12:23:51.384 Remote SDP is set for legC:2.3
12:23:51.178 [MS210002] C:2.3:Offer provided. Connection(transcoding mode): 127.0.0.1:7008(7009)
12:23:51.177 [MS210000] C:2.1:Offer received. RTP connection: 66.62.60.229:21736(21737)
12:23:51.176 Remote SDP is set for legC:2.1
12:23:49.582 Currently active calls - 2: [1,2]
12:23:19.426 Currently active calls - 2: [1,2]
12:22:47.245 Currently active calls - 2: [1,2]
12:22:15.062 Currently active calls - 2: [1,2]
12:21:44.868 Currently active calls - 2: [1,2]
12:21:12.685 Currently active calls - 2: [1,2]
12:20:42.491 Currently active calls - 2: [1,2]
12:20:10.308 Currently active calls - 2: [1,2]
12:19:38.121 Currently active calls - 2: [1,2]
12:19:05.938 Currently active calls - 2: [1,2]
12:18:33.722 Currently active calls - 2: [1,2]
12:18:01.361 Currently active calls - 2: [1,2]
12:17:39.273 [CM504001]: Ext.130: new contact is registered. Contact(s): [sip:[email protected]:5060/130]
12:17:38.589 [CM504001]: Ext.100: new contact is registered. Contact(s): [sip:[email protected]:5060/100]
12:17:37.843 [CM504001]: Ext.120: new contact is registered. Contact(s): [sip:[email protected]:5060/120]
12:17:28.997 Currently active calls - 2: [1,2]
12:16:56.634 Currently active calls - 2: [1,2]
12:16:24.273 Currently active calls - 2: [1,2]
12:15:51.911 Currently active calls - 2: [1,2]
12:15:19.549 Currently active calls - 2: [1,2]
12:14:47.188 Currently active calls - 2: [1,2]
12:14:14.826 Currently active calls - 2: [1,2]
12:13:42.464 Currently active calls - 2: [1,2]
12:13:10.316 Currently active calls - 2: [1,2]
12:12:38.220 Currently active calls - 2: [1,2]
12:12:06.123 Currently active calls - 2: [1,2]
12:11:34.019 Currently active calls - 2: [1,2]
12:11:01.897 Currently active calls - 2: [1,2]
12:10:29.774 Currently active calls - 2: [1,2]
12:09:57.651 Currently active calls - 2: [1,2]
12:09:25.527 Currently active calls - 2: [1,2]
12:08:59.578 [CM503007]: Call(2): Device joined: sip:[email protected]:40300;rinstance=a52782f1946d36f6
12:08:59.574 [MS210003] C:2.3:Answer provided. Connection(transcoding mode[unsecure]):127.0.0.1:7008(7009)
12:08:59.573 [MS210002] C:2.1:Offer provided. Connection(transcoding mode): 71.39.116.253:9000(9001)
12:08:59.571 [MS210000] C:2.3:Offer received. RTP connection: 127.0.0.1:40316(40317)
12:08:59.570 Remote SDP is set for legC:2.3
12:08:59.569 [CM505001]: Ext.701: Device info: Device Identified: [Man: 3CX Ltd.;Mod: Conference place;Rev: General] Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [3CX Conference Place] PBX contact: [sip:[email protected]:5060]
12:08:59.569 [CM503002]: Call(2): Alerting sip:[email protected]:40300;rinstance=a52782f1946d36f6
12:08:59.410 [CM503025]: Call(2): Calling Ext:Ext.701@[Dev:sip:[email protected]:40300;rinstance=a52782f1946d36f6]
12:08:59.353 [CM503004]: Call(2): Route 1: Ext:Ext.701@[Dev:sip:[email protected]:40300;rinstance=a52782f1946d36f6]
12:08:59.352 [CM503010]: Making route(s) to <sip:[email protected]:5060>
12:08:59.351 [CM505003]: Provider:[DID For Sale] Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [] PBX contact: [sip:xxx.xxx%[email protected]:5060]
12:08:59.351 Refer: from=<sip:[email protected]:5060>;tag=d6182348; to="12082729833:"<sip:[email protected]:5060;nf=e>;tag=53747276; RefTo=<sip:[email protected]:5060>
12:08:57.227 [MS211000] C:2.1: 66.62.60.229:21736 is delivering DTMF using RTP payload (RFC2833). In-Band DTMF tone detection is disabled for this call segment.
12:08:53.405 Currently active calls - 2: [1,2]
12:08:53.154 Session 151 of leg C:2.1 is confirmed
12:08:52.894 [CM503007]: Call(2): Device joined: sip:[email protected]:40300;rinstance=b5858397a8b72940
12:08:52.892 [CM503007]: Call(2): Device joined: sip:xxxxx%[email protected]:5060
12:08:52.890 [MS210003] C:2.1:Answer provided. Connection(transcoding mode[unsecure]):71.39.116.253:9000(9001)
12:08:52.888 [MS210001] C:2.2:Answer received. RTP connection[unsecure]: 127.0.0.1:40314(40315)
12:08:52.887 Remote SDP is set for legC:2.2
12:08:52.884 [CM505001]: Ext.700: Device info: Device Identified: [Man: 3CX Ltd.;Mod: Conference gateway;Rev: General] Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [3CX Conference Room] PBX contact: [sip:[email protected]:5060]
12:08:52.884 [CM503002]: Call(2): Alerting sip:[email protected]:40300;rinstance=b5858397a8b72940
12:08:52.725 [CM503025]: Call(2): Calling Ext:Ext.700@[Dev:sip:[email protected]:40300;rinstance=b5858397a8b72940]
12:08:52.723 [MS210002] C:2.2:Offer provided. Connection(transcoding mode): 127.0.0.1:7006(7007)
12:08:52.694 [CM503004]: Call(2): Route 1: Ext:Ext.700@[Dev:sip:[email protected]:40300;rinstance=b5858397a8b72940]
12:08:52.694 [CM503010]: Making route(s) to <sip:[email protected]:5060>
12:08:52.694 [MS210000] C:2.1:Offer received. RTP connection: 66.62.60.229:21736(21737)
Logging from test #3 (SUCCESS CONDITION)
12:45:12.980 Currently active calls - 1: [3]
12:44:40.861 Currently active calls - 1: [3]
12:44:08.744 Currently active calls - 1: [3]
12:43:58.194 [MS210003] C:3.1:Answer provided. Connection(transcoding mode[unsecure]):71.39.116.253:9002(9003)
12:43:58.193 [MS210001] C:3.2:Answer received. RTP connection[unsecure]: 172.16.32.28:16464(16465)
12:43:58.192 Remote SDP is set for legC:3.2
12:43:58.145 [MS210002] C:3.2:Offer provided. Connection(transcoding mode): 172.16.32.13:7010(7011)
12:43:58.144 [MS210000] C:3.1:Offer received. RTP connection: 66.62.60.229:17226(17227)
12:43:58.142 Remote SDP is set for legC:3.1
12:43:36.627 Currently active calls - 1: [3]
12:43:04.511 Currently active calls - 1: [3]
12:42:32.395 Currently active calls - 1: [3]
12:42:00.278 Currently active calls - 1: [3]
12:41:28.161 Currently active calls - 1: [3]
12:40:58.050 Currently active calls - 1: [3]
12:40:25.884 Currently active calls - 1: [3]
12:39:53.706 Currently active calls - 1: [3]
12:39:21.527 Currently active calls - 1: [3]
12:38:49.349 Currently active calls - 1: [3]
12:38:17.169 Currently active calls - 1: [3]
12:37:44.989 Currently active calls - 1: [3]
12:37:12.811 Currently active calls - 1: [3]
12:36:40.633 Currently active calls - 1: [3]
12:36:08.451 Currently active calls - 1: [3]
12:35:36.196 Currently active calls - 1: [3]
12:35:03.840 Currently active calls - 1: [3]
12:34:31.483 Currently active calls - 1: [3]
12:33:59.128 Currently active calls - 1: [3]
12:33:26.773 Currently active calls - 1: [3]
12:32:54.418 Currently active calls - 1: [3]
12:32:22.062 Currently active calls - 1: [3]
12:32:14.478 [CM504001]: Ext.300: new contact is registered. Contact(s): [sip:[email protected]:5060/300]
12:31:49.706 Currently active calls - 1: [3]
12:31:17.351 Currently active calls - 1: [3]
12:30:45.011 Currently active calls - 1: [3]
12:30:12.917 Currently active calls - 1: [3]
12:29:42.824 Currently active calls - 1: [3]
12:29:10.730 Currently active calls - 1: [3]
12:28:59.585 Session 489 of leg C:3.1 is confirmed
12:28:59.329 [CM503007]: Call(3): Device joined: sip:[email protected]:5060
12:28:59.324 [CM503007]: Call(3): Device joined: sip:xxx.xxx%[email protected]:5060
12:28:59.322 [MS210003] C:3.1:Answer provided. Connection(transcoding mode[unsecure]):71.39.116.253:9002(9003)
12:28:59.320 [MS210001] C:3.2:Answer received. RTP connection[unsecure]: 172.16.32.28:16464(16465)
12:28:59.319 Remote SDP is set for legC:3.2
12:28:57.481 [CM505001]: Ext.110: Device info: Device Identified: [Man: Cisco;Mod: SPA Series;Rev: General] Capabilities:[reinvite, replaces, unable-no-sdp, no-recvonly] UserAgent: [Cisco/SPA525G2-7.4.9a] PBX contact: [sip:[email protected]:5060]
12:28:57.480 [CM503002]: Call(3): Alerting sip:[email protected]:5060
12:28:57.388 [CM503025]: Call(3): Calling Ext:Ext.110@[Dev:sip:[email protected]:5060]
12:28:57.388 [MS210002] C:3.2:Offer provided. Connection(transcoding mode): 172.16.32.13:7010(7011)
12:28:57.358 [CM503004]: Call(3): Route 1: Ext:Ext.110@[Dev:sip:[email protected]:5060]
12:28:57.354 [CM503010]: Making route(s) to <sip:[email protected]:5060>
12:28:57.354 [MS210000] C:3.1:Offer received. RTP connection: 66.62.60.229:17226(17227)
12:28:57.353 Remote SDP is set for legC:3.1
Issue Overview
3CX conferencing module consistently drops external VOIP calls after 15 minutes.
Using the same VOIP line routed directly to phones works with no issues. This issue seems to be centered around the conference module itself.
Setup and Configuration
- SonicWall NSA 2400 Firewall. SIP and RTP ports are forwarded and functional
- Version V10.0.22686.2297 SP.5
- SIP Provider Configuration
- Support Re-invite = False
- Supports Replace = False
- PBX Delivers Audio = True
Testing Completed
Test#1
VOIP Line routed to active conference bridge with one internal VOIP phone active (Polycom)
Status: External call routed to conference bridge dropped after just over 15 minutes with “ACK is not received”
Test#2
VOIP Line routed to active conference bridge with one internal VOIP phone active (Cisco)
Status: External call routed to conference bridge dropped after just over 15 minutes with “ACK is not received”
Test#3
VOIP Line routed directly to internal Cisco phone (no conference module)
Status: Call succeeded to over 20 minutes before test considered a pass
Logging from Test #2 (FAIL CONDITION)
12:24:33.702 [CM503008]: Call(1): Call is terminated
12:24:23.472 [CM503008]: Call(2): Call is terminated
12:24:23.466 [CM503021]: Call(2): ACK is not received
12:24:21.698 Currently active calls - 2: [1,2]
12:23:51.388 [MS210003] C:2.1:Answer provided. Connection(transcoding mode[unsecure]):71.39.116.253:9000(9001)
12:23:51.386 [MS210001] C:2.3:Answer received. RTP connection[unsecure]: 127.0.0.1:40316(40317)
12:23:51.384 Remote SDP is set for legC:2.3
12:23:51.178 [MS210002] C:2.3:Offer provided. Connection(transcoding mode): 127.0.0.1:7008(7009)
12:23:51.177 [MS210000] C:2.1:Offer received. RTP connection: 66.62.60.229:21736(21737)
12:23:51.176 Remote SDP is set for legC:2.1
12:23:49.582 Currently active calls - 2: [1,2]
12:23:19.426 Currently active calls - 2: [1,2]
12:22:47.245 Currently active calls - 2: [1,2]
12:22:15.062 Currently active calls - 2: [1,2]
12:21:44.868 Currently active calls - 2: [1,2]
12:21:12.685 Currently active calls - 2: [1,2]
12:20:42.491 Currently active calls - 2: [1,2]
12:20:10.308 Currently active calls - 2: [1,2]
12:19:38.121 Currently active calls - 2: [1,2]
12:19:05.938 Currently active calls - 2: [1,2]
12:18:33.722 Currently active calls - 2: [1,2]
12:18:01.361 Currently active calls - 2: [1,2]
12:17:39.273 [CM504001]: Ext.130: new contact is registered. Contact(s): [sip:[email protected]:5060/130]
12:17:38.589 [CM504001]: Ext.100: new contact is registered. Contact(s): [sip:[email protected]:5060/100]
12:17:37.843 [CM504001]: Ext.120: new contact is registered. Contact(s): [sip:[email protected]:5060/120]
12:17:28.997 Currently active calls - 2: [1,2]
12:16:56.634 Currently active calls - 2: [1,2]
12:16:24.273 Currently active calls - 2: [1,2]
12:15:51.911 Currently active calls - 2: [1,2]
12:15:19.549 Currently active calls - 2: [1,2]
12:14:47.188 Currently active calls - 2: [1,2]
12:14:14.826 Currently active calls - 2: [1,2]
12:13:42.464 Currently active calls - 2: [1,2]
12:13:10.316 Currently active calls - 2: [1,2]
12:12:38.220 Currently active calls - 2: [1,2]
12:12:06.123 Currently active calls - 2: [1,2]
12:11:34.019 Currently active calls - 2: [1,2]
12:11:01.897 Currently active calls - 2: [1,2]
12:10:29.774 Currently active calls - 2: [1,2]
12:09:57.651 Currently active calls - 2: [1,2]
12:09:25.527 Currently active calls - 2: [1,2]
12:08:59.578 [CM503007]: Call(2): Device joined: sip:[email protected]:40300;rinstance=a52782f1946d36f6
12:08:59.574 [MS210003] C:2.3:Answer provided. Connection(transcoding mode[unsecure]):127.0.0.1:7008(7009)
12:08:59.573 [MS210002] C:2.1:Offer provided. Connection(transcoding mode): 71.39.116.253:9000(9001)
12:08:59.571 [MS210000] C:2.3:Offer received. RTP connection: 127.0.0.1:40316(40317)
12:08:59.570 Remote SDP is set for legC:2.3
12:08:59.569 [CM505001]: Ext.701: Device info: Device Identified: [Man: 3CX Ltd.;Mod: Conference place;Rev: General] Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [3CX Conference Place] PBX contact: [sip:[email protected]:5060]
12:08:59.569 [CM503002]: Call(2): Alerting sip:[email protected]:40300;rinstance=a52782f1946d36f6
12:08:59.410 [CM503025]: Call(2): Calling Ext:Ext.701@[Dev:sip:[email protected]:40300;rinstance=a52782f1946d36f6]
12:08:59.353 [CM503004]: Call(2): Route 1: Ext:Ext.701@[Dev:sip:[email protected]:40300;rinstance=a52782f1946d36f6]
12:08:59.352 [CM503010]: Making route(s) to <sip:[email protected]:5060>
12:08:59.351 [CM505003]: Provider:[DID For Sale] Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [] PBX contact: [sip:xxx.xxx%[email protected]:5060]
12:08:59.351 Refer: from=<sip:[email protected]:5060>;tag=d6182348; to="12082729833:"<sip:[email protected]:5060;nf=e>;tag=53747276; RefTo=<sip:[email protected]:5060>
12:08:57.227 [MS211000] C:2.1: 66.62.60.229:21736 is delivering DTMF using RTP payload (RFC2833). In-Band DTMF tone detection is disabled for this call segment.
12:08:53.405 Currently active calls - 2: [1,2]
12:08:53.154 Session 151 of leg C:2.1 is confirmed
12:08:52.894 [CM503007]: Call(2): Device joined: sip:[email protected]:40300;rinstance=b5858397a8b72940
12:08:52.892 [CM503007]: Call(2): Device joined: sip:xxxxx%[email protected]:5060
12:08:52.890 [MS210003] C:2.1:Answer provided. Connection(transcoding mode[unsecure]):71.39.116.253:9000(9001)
12:08:52.888 [MS210001] C:2.2:Answer received. RTP connection[unsecure]: 127.0.0.1:40314(40315)
12:08:52.887 Remote SDP is set for legC:2.2
12:08:52.884 [CM505001]: Ext.700: Device info: Device Identified: [Man: 3CX Ltd.;Mod: Conference gateway;Rev: General] Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [3CX Conference Room] PBX contact: [sip:[email protected]:5060]
12:08:52.884 [CM503002]: Call(2): Alerting sip:[email protected]:40300;rinstance=b5858397a8b72940
12:08:52.725 [CM503025]: Call(2): Calling Ext:Ext.700@[Dev:sip:[email protected]:40300;rinstance=b5858397a8b72940]
12:08:52.723 [MS210002] C:2.2:Offer provided. Connection(transcoding mode): 127.0.0.1:7006(7007)
12:08:52.694 [CM503004]: Call(2): Route 1: Ext:Ext.700@[Dev:sip:[email protected]:40300;rinstance=b5858397a8b72940]
12:08:52.694 [CM503010]: Making route(s) to <sip:[email protected]:5060>
12:08:52.694 [MS210000] C:2.1:Offer received. RTP connection: 66.62.60.229:21736(21737)
Logging from test #3 (SUCCESS CONDITION)
12:45:12.980 Currently active calls - 1: [3]
12:44:40.861 Currently active calls - 1: [3]
12:44:08.744 Currently active calls - 1: [3]
12:43:58.194 [MS210003] C:3.1:Answer provided. Connection(transcoding mode[unsecure]):71.39.116.253:9002(9003)
12:43:58.193 [MS210001] C:3.2:Answer received. RTP connection[unsecure]: 172.16.32.28:16464(16465)
12:43:58.192 Remote SDP is set for legC:3.2
12:43:58.145 [MS210002] C:3.2:Offer provided. Connection(transcoding mode): 172.16.32.13:7010(7011)
12:43:58.144 [MS210000] C:3.1:Offer received. RTP connection: 66.62.60.229:17226(17227)
12:43:58.142 Remote SDP is set for legC:3.1
12:43:36.627 Currently active calls - 1: [3]
12:43:04.511 Currently active calls - 1: [3]
12:42:32.395 Currently active calls - 1: [3]
12:42:00.278 Currently active calls - 1: [3]
12:41:28.161 Currently active calls - 1: [3]
12:40:58.050 Currently active calls - 1: [3]
12:40:25.884 Currently active calls - 1: [3]
12:39:53.706 Currently active calls - 1: [3]
12:39:21.527 Currently active calls - 1: [3]
12:38:49.349 Currently active calls - 1: [3]
12:38:17.169 Currently active calls - 1: [3]
12:37:44.989 Currently active calls - 1: [3]
12:37:12.811 Currently active calls - 1: [3]
12:36:40.633 Currently active calls - 1: [3]
12:36:08.451 Currently active calls - 1: [3]
12:35:36.196 Currently active calls - 1: [3]
12:35:03.840 Currently active calls - 1: [3]
12:34:31.483 Currently active calls - 1: [3]
12:33:59.128 Currently active calls - 1: [3]
12:33:26.773 Currently active calls - 1: [3]
12:32:54.418 Currently active calls - 1: [3]
12:32:22.062 Currently active calls - 1: [3]
12:32:14.478 [CM504001]: Ext.300: new contact is registered. Contact(s): [sip:[email protected]:5060/300]
12:31:49.706 Currently active calls - 1: [3]
12:31:17.351 Currently active calls - 1: [3]
12:30:45.011 Currently active calls - 1: [3]
12:30:12.917 Currently active calls - 1: [3]
12:29:42.824 Currently active calls - 1: [3]
12:29:10.730 Currently active calls - 1: [3]
12:28:59.585 Session 489 of leg C:3.1 is confirmed
12:28:59.329 [CM503007]: Call(3): Device joined: sip:[email protected]:5060
12:28:59.324 [CM503007]: Call(3): Device joined: sip:xxx.xxx%[email protected]:5060
12:28:59.322 [MS210003] C:3.1:Answer provided. Connection(transcoding mode[unsecure]):71.39.116.253:9002(9003)
12:28:59.320 [MS210001] C:3.2:Answer received. RTP connection[unsecure]: 172.16.32.28:16464(16465)
12:28:59.319 Remote SDP is set for legC:3.2
12:28:57.481 [CM505001]: Ext.110: Device info: Device Identified: [Man: Cisco;Mod: SPA Series;Rev: General] Capabilities:[reinvite, replaces, unable-no-sdp, no-recvonly] UserAgent: [Cisco/SPA525G2-7.4.9a] PBX contact: [sip:[email protected]:5060]
12:28:57.480 [CM503002]: Call(3): Alerting sip:[email protected]:5060
12:28:57.388 [CM503025]: Call(3): Calling Ext:Ext.110@[Dev:sip:[email protected]:5060]
12:28:57.388 [MS210002] C:3.2:Offer provided. Connection(transcoding mode): 172.16.32.13:7010(7011)
12:28:57.358 [CM503004]: Call(3): Route 1: Ext:Ext.110@[Dev:sip:[email protected]:5060]
12:28:57.354 [CM503010]: Making route(s) to <sip:[email protected]:5060>
12:28:57.354 [MS210000] C:3.1:Offer received. RTP connection: 66.62.60.229:17226(17227)
12:28:57.353 Remote SDP is set for legC:3.1
Phone System 