[Dec 20 11:19:36] VERBOSE[2987797424]: [Dec 20 11:19:36] OpenPBX Ready. [Dec 20 11:19:36] == Primary D-Channel on span 1 up [Dec 20 11:19:36] DEBUG[2987531184]: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Dec 20 11:19:36] DEBUG[2987531184]: Stopping retransmission on '0d7c9afd5e38d36736011514762a6812@10.0.0.19' of Request 102: Match Found [Dec 20 11:19:36] DEBUG[2987531184]: Stopping retransmission on '402952fe6c6426385a1100ae0c620184@10.0.0.19' of Request 102: Match Found [Dec 20 11:19:36] DEBUG[2987531184]: Stopping retransmission on '025e628f53c3cb8c474b01c05b1047d9@10.0.0.19' of Request 102: Match Found [Dec 20 11:19:36] DEBUG[2988329904]: Device 'SIP/sipura02' changed to state '1' (Not in use) [Dec 20 11:19:36] DEBUG[2987531184]: Stopping retransmission on '3b2eb833316746c061531a861f96257e@10.0.0.19' of Request 102: Match Found [Dec 20 11:19:36] WARNING[3070643120]: Requested a timer with 1000000 nanosecond interval, but system timer reports a resolution of 4000250 nanosec. Timing may be unreliable! [Dec 20 11:19:36] DEBUG[2988329904]: Device 'SIP/3014' changed to state '1' (Not in use) [Dec 20 11:19:37] DEBUG[2988329904]: Device 'SIP/3017' changed to state '1' (Not in use) [Dec 20 11:19:37] DEBUG[2988329904]: Device 'SIP/2224' changed to state '1' (Not in use) [Dec 20 11:19:37] DEBUG[2988329904]: Device 'SIP/1313' changed to state '1' (Not in use) [Dec 20 11:19:37] DEBUG[2988329904]: Device 'SIP/2228' changed to state '1' (Not in use) [Dec 20 11:19:37] DEBUG[2988329904]: Device 'SIP/2225' changed to state '5' (Unavailable) [Dec 20 11:19:37] DEBUG[2988329904]: Device 'SIP/104' changed to state '5' (Unavailable) [Dec 20 11:19:39] NOTICE[3079035824]: Peer 'voipjet' is now UNREACHABLE! Time: 0 [Dec 20 11:19:39] DEBUG[2988329904]: Device 'IAX2/voipjet' changed to state '1' (Not in use) [Dec 20 11:19:41] DEBUG[2987531184]: Runt STUN packet (only 4, wanting at least 20) [Dec 20 11:19:44] DEBUG[2981866416]: Device 'Zap/23' changed to state '2' (In use) [Dec 20 11:19:44] VERBOSE[2987797424]: [Dec 20 11:19:44] -- Accepting call from '5152883667' to '4715009' on channel 0/23, span 1 [Dec 20 11:19:44] DEBUG[2987797424]: Enabled echo cancellation on channel 23 [Dec 20 11:19:44] DEBUG[2988329904]: Launching 'NoOp' [Dec 20 11:19:44] VERBOSE[2988329904]: [Dec 20 11:19:44] -- Executing NoOp("Zap/23-1", "Conference participant number") in new stack [Dec 20 11:19:44] DEBUG[2988329904]: Launching 'Wait' [Dec 20 11:19:44] VERBOSE[2988329904]: [Dec 20 11:19:44] -- Executing Wait("Zap/23-1", "1") in new stack [Dec 20 11:19:44] VERBOSE[2987797424]: [Dec 20 11:19:44] -- B-channel 0/1 successfully restarted on span 1 [Dec 20 11:19:44] VERBOSE[2987797424]: [Dec 20 11:19:44] -- B-channel 0/2 successfully restarted on span 1 [Dec 20 11:19:44] VERBOSE[2987797424]: [Dec 20 11:19:44] -- B-channel 0/3 successfully restarted on span 1 [Dec 20 11:19:44] VERBOSE[2987797424]: [Dec 20 11:19:44] -- B-channel 0/4 successfully restarted on span 1 [Dec 20 11:19:44] VERBOSE[2987797424]: [Dec 20 11:19:44] -- B-channel 0/5 successfully restarted on span 1 [Dec 20 11:19:44] VERBOSE[2987797424]: [Dec 20 11:19:44] -- B-channel 0/6 successfully restarted on span 1 [Dec 20 11:19:45] VERBOSE[2987797424]: [Dec 20 11:19:45] -- B-channel 0/7 successfully restarted on span 1 [Dec 20 11:19:45] VERBOSE[2987797424]: [Dec 20 11:19:45] -- B-channel 0/8 successfully restarted on span 1 [Dec 20 11:19:45] VERBOSE[2987797424]: [Dec 20 11:19:45] -- B-channel 0/9 successfully restarted on span 1 [Dec 20 11:19:45] VERBOSE[2987797424]: [Dec 20 11:19:45] -- B-channel 0/10 successfully restarted on span 1 [Dec 20 11:19:45] VERBOSE[2987797424]: [Dec 20 11:19:45] -- B-channel 0/11 successfully restarted on span 1 [Dec 20 11:19:45] VERBOSE[2987797424]: [Dec 20 11:19:45] -- B-channel 0/12 successfully restarted on span 1 [Dec 20 11:19:45] VERBOSE[2987797424]: [Dec 20 11:19:45] -- B-channel 0/13 successfully restarted on span 1 [Dec 20 11:19:45] VERBOSE[2987797424]: [Dec 20 11:19:45] -- B-channel 0/14 successfully restarted on span 1 [Dec 20 11:19:45] VERBOSE[2987797424]: [Dec 20 11:19:45] -- B-channel 0/15 successfully restarted on span 1 [Dec 20 11:19:45] VERBOSE[2987797424]: [Dec 20 11:19:45] -- B-channel 0/16 successfully restarted on span 1 [Dec 20 11:19:45] VERBOSE[2987797424]: [Dec 20 11:19:45] -- B-channel 0/17 successfully restarted on span 1 [Dec 20 11:19:45] VERBOSE[2987797424]: [Dec 20 11:19:45] -- B-channel 0/18 successfully restarted on span 1 [Dec 20 11:19:45] VERBOSE[2987797424]: [Dec 20 11:19:45] -- B-channel 0/19 successfully restarted on span 1 [Dec 20 11:19:45] VERBOSE[2987797424]: [Dec 20 11:19:45] -- B-channel 0/20 successfully restarted on span 1 [Dec 20 11:19:45] VERBOSE[2987797424]: [Dec 20 11:19:45] -- B-channel 0/21 successfully restarted on span 1 [Dec 20 11:19:45] VERBOSE[2987797424]: [Dec 20 11:19:45] -- B-channel 0/22 successfully restarted on span 1 [Dec 20 11:19:45] DEBUG[2988329904]: Launching 'Answer' [Dec 20 11:19:45] VERBOSE[2988329904]: [Dec 20 11:19:45] -- Executing Answer("Zap/23-1", "") in new stack [Dec 20 11:19:45] DEBUG[3079302064]: Avoiding initial deadlock for 'Zap/23-1' [Dec 20 11:19:45] DEBUG[2988329904]: Launching 'Wait' [Dec 20 11:19:45] VERBOSE[2988329904]: [Dec 20 11:19:45] -- Executing Wait("Zap/23-1", "1") in new stack [Dec 20 11:19:45] DEBUG[2981866416]: Device 'Zap/23' changed to state '2' (In use) [Dec 20 11:19:46] DEBUG[3070643120]: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Dec 20 11:19:46] DEBUG[3070643120]: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Dec 20 11:19:46] DEBUG[2987531184]: Stopping retransmission on '17669e5e00f0a510438ef154230ffa33@10.0.0.19' of Request 102: Match Found [Dec 20 11:19:46] DEBUG[2988329904]: Launching 'NoOp' [Dec 20 11:19:46] VERBOSE[2988329904]: [Dec 20 11:19:46] -- Executing NoOp("Zap/23-1", "Play greeting MVS Conference Services") in new stack [Dec 20 11:19:46] DEBUG[2988329904]: Launching 'Playback' [Dec 20 11:19:46] VERBOSE[2988329904]: [Dec 20 11:19:46] -- Executing Playback("Zap/23-1", "welcome-to-conf-fac|skip") in new stack [Dec 20 11:19:46] DEBUG[2988329904]: Trying to deactivate generator in Zap/23-1 [Dec 20 11:19:46] DEBUG[2988329904]: Generator on Zap/23-1 stopped after 0 iterations [Dec 20 11:19:46] VERBOSE[2988329904]: [Dec 20 11:19:46] -- Playing 'welcome-to-conf-fac' (language 'en') [Dec 20 11:19:47] DEBUG[2987531184]: Stopping retransmission on '1b3fcef53b5dbea44df739d5230b3e71@10.0.0.19' of Request 102: Match Found [Dec 20 11:19:51] DEBUG[2988329904]: Launching 'Wait' [Dec 20 11:19:51] VERBOSE[2988329904]: [Dec 20 11:19:51] -- Executing Wait("Zap/23-1", "1") in new stack [Dec 20 11:19:52] DEBUG[2988329904]: Launching 'NoOp' [Dec 20 11:19:52] VERBOSE[2988329904]: [Dec 20 11:19:52] -- Executing NoOp("Zap/23-1", "starting Conference 4715009") in new stack [Dec 20 11:19:56] DEBUG[3079035824]: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Dec 20 11:19:57] DEBUG[3079035824]: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Dec 20 11:19:57] DEBUG[2987531184]: Stopping retransmission on '0ef532d64a23eb0a7b8b31ca5cde4c51@10.0.0.19' of Request 102: Match Found [Dec 20 11:19:57] DEBUG[2987531184]: Stopping retransmission on '7a82bf2b70c3e5d13eaa4b9e4adf7a50@10.0.0.19' of Request 102: Match Found [Dec 20 11:20:01] DEBUG[2987531184]: Runt STUN packet (only 4, wanting at least 20) [Dec 20 11:20:02] VERBOSE[2988329904]: [Dec 20 11:20:02] -- Timeout on Zap/23-1 [Dec 20 11:20:02] VERBOSE[2988329904]: [Dec 20 11:20:02] == CDR updated on Zap/23-1 [Dec 20 11:20:02] DEBUG[2988329904]: Launching 'Goto' [Dec 20 11:20:02] VERBOSE[2988329904]: [Dec 20 11:20:02] -- Executing Goto("Zap/23-1", "#|1") in new stack [Dec 20 11:20:02] VERBOSE[2988329904]: [Dec 20 11:20:02] -- Goto (outbound,#,1) [Dec 20 11:20:02] DEBUG[2988329904]: Launching 'Playback' [Dec 20 11:20:02] VERBOSE[2988329904]: [Dec 20 11:20:02] -- Executing Playback("Zap/23-1", "demo-thanks") in new stack [Dec 20 11:20:02] DEBUG[2988329904]: Trying to deactivate generator in Zap/23-1 [Dec 20 11:20:02] DEBUG[2988329904]: Generator on Zap/23-1 stopped after 0 iterations [Dec 20 11:20:02] WARNING[2988329904]: Unexpected freqency 44100 [Dec 20 11:20:02] WARNING[2988329904]: Unable to open file on /opt/openpbx.org/var/data/sounds/en_US/MelanieTaylor/demo-thanks.wav [Dec 20 11:20:02] VERBOSE[2988329904]: [Dec 20 11:20:02] -- Playing 'demo-thanks' (language 'en') [Dec 20 11:20:05] VERBOSE[2987797424]: [Dec 20 11:20:05] -- Channel 0/23, span 1 got hangup request [Dec 20 11:20:05] WARNING[2988329904]: Failed to write frame [Dec 20 11:20:05] DEBUG[2988329904]: Spawn extension (outbound,#,1) exited non-zero on 'Zap/23-1' [Dec 20 11:20:05] VERBOSE[2988329904]: [Dec 20 11:20:05] == Spawn extension (outbound, #, 1) exited non-zero on 'Zap/23-1' [Dec 20 11:20:05] DEBUG[2988329904]: CDR SQLITE3 SQL [INSERT INTO cdr (clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata, start,answer,end,duration,billsec,disposition,amaflags, accountcode) VALUES ('5152883667', '5152883667', '#', 'outbound', 'Zap/23-1', '', 'Playback', 'demo-thanks', '2006-12-20 11:19:44', '2006-12-20 11:19:45', '2006-12-20 11:20:05', 21, 20, 4, 3, '')] [Dec 20 11:20:05] DEBUG[2988329904]: Inserting a CDR record. [Dec 20 11:20:05] DEBUG[2988329904]: SQL command executed: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2006-12-20 11:19:44','5152883667','5152883667','#','outbound', 'Zap/23-1','','Playback','demo-thanks',21,20,'ANSWERED',3,'','1166635184.0','') [Dec 20 11:20:05] DEBUG[2988329904]: Function result is '5152883667' [Dec 20 11:20:05] DEBUG[2988329904]: Function result is '5152883667' [Dec 20 11:20:05] DEBUG[2988329904]: Function result is '#' [Dec 20 11:20:05] DEBUG[2988329904]: Function result is 'outbound' [Dec 20 11:20:05] DEBUG[2988329904]: Function result is 'Zap/23-1' [Dec 20 11:20:05] DEBUG[2988329904]: Function result is '(null)' [Dec 20 11:20:05] DEBUG[2988329904]: Function result is 'Playback' [Dec 20 11:20:05] DEBUG[2988329904]: Function result is 'demo-thanks' [Dec 20 11:20:05] DEBUG[2988329904]: Function result is '2006-12-20 11:19:44' [Dec 20 11:20:05] DEBUG[2988329904]: Function result is '2006-12-20 11:19:45' [Dec 20 11:20:05] DEBUG[2988329904]: Function result is '2006-12-20 11:20:05' [Dec 20 11:20:05] DEBUG[2988329904]: Function result is '21' [Dec 20 11:20:05] DEBUG[2988329904]: Function result is '20' [Dec 20 11:20:05] DEBUG[2988329904]: Function result is 'ANSWERED' [Dec 20 11:20:05] DEBUG[2988329904]: Function result is 'DOCUMENTATION' [Dec 20 11:20:05] DEBUG[2988329904]: Function result is '(null)' [Dec 20 11:20:05] DEBUG[2988329904]: Function result is '1166635184.0' [Dec 20 11:20:05] DEBUG[2988329904]: Function result is '(null)' [Dec 20 11:20:05] DEBUG[2988329904]: Hanging up channel 'Zap/23-1' [Dec 20 11:20:05] DEBUG[2988329904]: zt_hangup(Zap/23-1) [Dec 20 11:20:05] DEBUG[2988329904]: Set option AUDIO MODE, value: ON(1) on Zap/23-1 [Dec 20 11:20:05] DEBUG[2988329904]: Hangup: channel: 23 index = 0, normal = 34, callwait = -1, thirdcall = -1 [Dec 20 11:20:05] DEBUG[2988329904]: Not yet hungup... Calling hangup once with icause, and clearing call [Dec 20 11:20:05] DEBUG[2988329904]: disabled echo cancellation on channel 23 [Dec 20 11:20:05] DEBUG[2988329904]: Set option TDD MODE, value: OFF(0) on Zap/23-1 [Dec 20 11:20:05] DEBUG[2988329904]: Updated conferencing on 23, with 0 conference users [Dec 20 11:20:05] DEBUG[2988329904]: Set option AUDIO MODE, value: OFF(0) on Zap/23-1 [Dec 20 11:20:05] DEBUG[2988329904]: disabled echo cancellation on channel 23 [Dec 20 11:20:05] VERBOSE[2988329904]: [Dec 20 11:20:05] -- Hungup 'Zap/23-1' [Dec 20 11:20:05] DEBUG[2988329904]: Generator : deactivate after channel unlock (hangup function) [Dec 20 11:20:05] DEBUG[2988329904]: Trying to deactivate generator in Zap/23-1 [Dec 20 11:20:05] DEBUG[2988329904]: Generator on Zap/23-1 stopped after 0 iterations [Dec 20 11:20:05] DEBUG[2981866416]: Device 'Zap/23' changed to state '0' (Unknown) [Dec 20 11:20:07] DEBUG[3070643120]: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Dec 20 11:20:07] DEBUG[3079035824]: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Dec 20 11:20:07] DEBUG[2987531184]: Stopping retransmission on '404fd7fe7650ed126c7b55244f09e36e@10.0.0.19' of Request 102: Match Found [Dec 20 11:20:07] NOTICE[2987531184]: Peer '2225' is now REACHABLE! (193ms / 200ms) [Dec 20 11:20:07] DEBUG[2988329904]: Device 'SIP/2225' changed to state '1' (Not in use) [Dec 20 11:20:07] DEBUG[2987531184]: Stopping retransmission on '04e45a4f01ddc7e24eaadcf1206ea000@10.0.0.19' of Request 102: Match Found