calling 1550 from 205 ivr/IVR-1550_82 is beeing played 15 seconds later while queue-youarenext is beeing played. I press '1' - music starts 15 seconds later the call is passed to '305' I hangup before pickup Mar 24 13:53:00 DEBUG[7700] acl.c: ##### Testing 87.48.236.18 with 192.168.0.0 Mar 24 13:53:00 DEBUG[7700] acl.c: ##### Testing 87.48.236.18 with 10.0.0.0 Mar 24 13:53:00 DEBUG[7700] acl.c: ##### Testing 87.48.236.18 with 172.16.0.0 Mar 24 13:53:00 DEBUG[7700] acl.c: ##### Testing 87.48.236.18 with 169.254.0.0 Mar 24 13:53:00 DEBUG[7700] chan_sip.c: Target address 87.48.236.18 is not local, substituting externip Mar 24 13:53:00 DEBUG[7700] chan_sip.c: Setting NAT on RTP to 524288 Mar 24 13:53:00 DEBUG[7700] chan_sip.c: Stopping retransmission on '3c26744668fb-4stx3x98nre6@snom360-0004132323A0' of Response 1: Match Found Mar 24 13:53:00 DEBUG[7700] chan_sip.c: Setting NAT on RTP to 524288 Mar 24 13:53:00 DEBUG[7700] chan_sip.c: Checking SIP call limits for device 205_82 Mar 24 13:53:00 DEBUG[7700] chan_sip.c: build_route: Contact hop: ;flow-id=1 Mar 24 13:53:00 DEBUG[7691] channel.c: Avoiding initial deadlock for 'SIP/205_82-a865' Mar 24 13:53:00 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "COMPANY=_82") in new stack Mar 24 13:53:00 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "COMPANYID=82") in new stack Mar 24 13:53:00 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "LANGUAGE()=da") in new stack Mar 24 13:53:00 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "CALLEEIDNUM=1550") in new stack Mar 24 13:53:00 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "CALLERNUM=205") in new stack Mar 24 13:53:00 DEBUG[26896] db.c: Unable to find key '1550_82' in family 'speednumber' Mar 24 13:53:00 DEBUG[26896] func_db.c: DB: speednumber/1550_82 not found in database. Mar 24 13:53:00 DEBUG[26896] pbx.c: Function result is '' Mar 24 13:53:00 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "SPEED=") in new stack Mar 24 13:53:00 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "TOUCH_MONITOR=1550_82-205_82") in new stack Mar 24 13:53:00 VERBOSE[26896] logger.c: -- Executing GotoIf("SIP/205_82-a865", "?found:notfound") in new stack Mar 24 13:53:00 VERBOSE[26896] logger.c: -- Goto (phones_82,1550,11) Mar 24 13:53:00 VERBOSE[26896] logger.c: -- Executing Goto("SIP/205_82-a865", "phone-in_82|1550|1") in new stack Mar 24 13:53:00 VERBOSE[26896] logger.c: -- Goto (phone-in_82,1550,1) Mar 24 13:53:00 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "CalledQueue=1550") in new stack Mar 24 13:53:00 VERBOSE[26896] logger.c: -- Executing Answer("SIP/205_82-a865", "") in new stack Mar 24 13:53:01 VERBOSE[26896] logger.c: -- Executing Wait("SIP/205_82-a865", "2") in new stack Mar 24 13:53:01 DEBUG[7700] chan_sip.c: Stopping retransmission on '3c26744668fb-4stx3x98nre6@snom360-0004132323A0' of Response 2: Match Found Mar 24 13:53:02 DEBUG[7699] chan_iax2.c: Peer lastms 6, historicms 6, maxms 2000 Mar 24 13:53:02 DEBUG[7699] chan_iax2.c: Peer lastms 7, historicms 7, maxms 2000 Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '727ded380d88d02d4fa8382373f2e67c@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '082f02bd5976ba300dde9fa70f0e8640@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '750f7091156f80085186a32c54803ee7@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '50271e30784dba936c98fd15071e703a@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '3f8a941f02a92e421e8022a07abf1a67@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '4564d922613f81875273a1b40e4a1e68@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '6f387e9f674a118b4e63be772fd753a6@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '6b84195a2fd86c417c8e5a3d56f4d4a2@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '7d16cf1714b124341a42cfc320d731a1@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '3f41acd27c2fd42f1f51903875a538db@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '6ec6475c52dfecef164850d658715f0f@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '10b25af65a2a48b022357acc0c06b269@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '30de2a3a4b9ed8f1271265141e6130de@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '1dbd2be523eb751f070d947214b4b029@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '66c08db50b71130141f9990a538f707b@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '7df7225d6cc91dea50036fdf35fce598@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '300c657f6a1ee8a578ec0c9461dc81de@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '74d736ae767d1d5c6d433d4b32a050ad@194.192.14.200' of Request 102: Match Found Mar 24 13:53:02 DEBUG[7700] chan_sip.c: Stopping retransmission on '14ee488f18f64a383b12dbb308cccd2d@194.192.14.200' of Request 102: Match Found Mar 24 13:53:03 DEBUG[7700] chan_sip.c: Stopping retransmission on '71cf3a464a66e91a649f04ea55e70dbf@194.192.14.200' of Request 102: Match Found Mar 24 13:53:03 DEBUG[7700] chan_sip.c: Stopping retransmission on '7269a6847dd1b6ee1e2f8649562c42d7@194.192.14.200' of Request 102: Match Found Mar 24 13:53:03 DEBUG[7700] chan_sip.c: Stopping retransmission on '0005a18056aa78bc008bd4e875f77097@194.192.14.200' of Request 102: Match Found Mar 24 13:53:03 VERBOSE[26896] logger.c: -- Executing Playback("SIP/205_82-a865", "ivr/IVR-1550_82") in new stack Mar 24 13:53:03 DEBUG[26896] channel.c: Scheduling timer at 160 sample intervals Mar 24 13:53:03 VERBOSE[26896] logger.c: -- Playing 'ivr/IVR-1550_82' (language 'da') Mar 24 13:53:04 DEBUG[7700] chan_sip.c: SIP message could not be handled, bad request: B755DA71-6937-4AF9-9384-7CE7F9E5FB20@192.168.1.100 Mar 24 13:53:05 DEBUG[7700] chan_sip.c: Auto destroying call '3c3b81428165-covvz8bbpv3u@snom190' Mar 24 13:53:06 DEBUG[26896] channel.c: Scheduling timer at 80 sample intervals Mar 24 13:53:06 DEBUG[26896] channel.c: Scheduling timer at 0 sample intervals Mar 24 13:53:06 DEBUG[26896] channel.c: Scheduling timer at 0 sample intervals Mar 24 13:53:06 VERBOSE[26896] logger.c: -- Executing Goto("SIP/205_82-a865", "phones_82|Queue-1550|1") in new stack Mar 24 13:53:06 VERBOSE[26896] logger.c: -- Goto (phones_82,Queue-1550,1) Mar 24 13:53:06 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "COMPANY=_82") in new stack Mar 24 13:53:06 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "COMPANYID=82") in new stack Mar 24 13:53:06 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "LANGUAGE()=da") in new stack Mar 24 13:53:06 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "CALLEEIDNUM=Queue-1550") in new stack Mar 24 13:53:06 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "CALLERNUM=205") in new stack Mar 24 13:53:06 DEBUG[26896] db.c: Unable to find key 'Queue-1550_82' in family 'speednumber' Mar 24 13:53:06 DEBUG[26896] func_db.c: DB: speednumber/Queue-1550_82 not found in database. Mar 24 13:53:06 DEBUG[26896] pbx.c: Function result is '' Mar 24 13:53:06 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "SPEED=") in new stack Mar 24 13:53:06 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "TOUCH_MONITOR=Queue-1550_82-205_82") in new stack Mar 24 13:53:06 VERBOSE[26896] logger.c: -- Executing GotoIf("SIP/205_82-a865", "?found:notfound") in new stack Mar 24 13:53:06 VERBOSE[26896] logger.c: -- Goto (phones_82,Queue-1550,11) Mar 24 13:53:06 VERBOSE[26896] logger.c: -- Executing Goto("SIP/205_82-a865", "phone-in_82|Queue-1550|1") in new stack Mar 24 13:53:06 VERBOSE[26896] logger.c: -- Goto (phone-in_82,Queue-1550,1) Mar 24 13:53:06 VERBOSE[26896] logger.c: -- Executing Queue("SIP/205_82-a865", "1550_82|tTwW|||30") in new stack Mar 24 13:53:06 VERBOSE[26896] logger.c: -- Started music on hold, class 'default', on SIP/205_82-a865 Mar 24 13:53:06 DEBUG[26896] channel.c: Scheduling timer at 160 sample intervals Mar 24 13:53:06 DEBUG[26896] chan_sip.c: Setting NAT on RTP to 524288 Mar 24 13:53:06 DEBUG[26896] chan_sip.c: Outgoing Call for Thorben Mar 24 13:53:06 VERBOSE[26896] logger.c: -- Called SIP/201_82 Mar 24 13:53:06 DEBUG[26896] channel.c: Generator got voice, switching to phase locked mode Mar 24 13:53:06 DEBUG[26896] channel.c: Scheduling timer at 0 sample intervals Mar 24 13:53:06 DEBUG[7700] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '242f529075fba95b0000086229868131@194.192.14.200' Request 102: Found Mar 24 13:53:06 DEBUG[7691] channel.c: Avoiding initial deadlock for 'SIP/201_82-d23f' Mar 24 13:53:06 VERBOSE[26896] logger.c: -- SIP/201_82-d23f is ringing Mar 24 13:53:07 DEBUG[7700] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '242f529075fba95b0000086229868131@194.192.14.200' Request 102: Found Mar 24 13:53:07 VERBOSE[26896] logger.c: -- SIP/201_82-d23f is ringing Mar 24 13:53:07 DEBUG[26882] manager.c: Manager received command 'Command' Mar 24 13:53:07 DEBUG[26882] manager.c: Manager received command 'Command' Mar 24 13:53:07 DEBUG[26882] manager.c: Manager received command 'Command' Mar 24 13:53:08 DEBUG[7700] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '242f529075fba95b0000086229868131@194.192.14.200' Request 102: Found Mar 24 13:53:08 VERBOSE[26896] logger.c: -- SIP/201_82-d23f is ringing Mar 24 13:53:10 DEBUG[7700] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '242f529075fba95b0000086229868131@194.192.14.200' Request 102: Found Mar 24 13:53:10 VERBOSE[26896] logger.c: -- SIP/201_82-d23f is ringing Mar 24 13:53:14 DEBUG[7700] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '242f529075fba95b0000086229868131@194.192.14.200' Request 102: Found Mar 24 13:53:14 VERBOSE[26896] logger.c: -- SIP/201_82-d23f is ringing Mar 24 13:53:19 DEBUG[7700] chan_sip.c: Auto destroying call '0f25ef223cc1f75b23c6aebe2691ac46@127.0.0.1' Mar 24 13:53:19 DEBUG[7700] chan_sip.c: Auto destroying call '2a97c45a047d370c1eda7e273a42fb23@127.0.0.1' Mar 24 13:53:20 DEBUG[7700] chan_sip.c: Auto destroying call '19762cb71fdd5d046af09c2f0c4601fb@127.0.0.1' Mar 24 13:53:20 DEBUG[7700] chan_sip.c: Auto destroying call '4cd6118b13c9cb7d75b2bf40600fbeb8@127.0.0.1' Mar 24 13:53:20 DEBUG[7700] chan_sip.c: Auto destroying call '291eacec6b58c800298fd81d79ae9c34@127.0.0.1' Mar 24 13:53:22 VERBOSE[26896] logger.c: -- Nobody picked up in 15000 ms Mar 24 13:53:22 DEBUG[26896] chan_sip.c: update_call_counter(Thorben) - decrement call limit counter Mar 24 13:53:22 DEBUG[26896] chan_sip.c: Acked pending invite 102 Mar 24 13:53:22 DEBUG[26896] chan_sip.c: Stopping retransmission on '242f529075fba95b0000086229868131@194.192.14.200' of Request 102: Match Found Mar 24 13:53:22 DEBUG[26896] chan_sip.c: Stopping retransmission on '242f529075fba95b0000086229868131@194.192.14.200' of Request 102: Match Found Mar 24 13:53:22 DEBUG[7700] chan_sip.c: Stopping retransmission on '242f529075fba95b0000086229868131@194.192.14.200' of Request 102: Match Not Found Mar 24 13:53:22 DEBUG[7700] chan_sip.c: Stopping retransmission on '242f529075fba95b0000086229868131@194.192.14.200' of Request 102: Match Not Found Mar 24 13:53:22 DEBUG[7700] chan_sip.c: Stopping retransmission on '04d4abaa713dfcb62daabda220146426@194.192.14.200' of Request 102: Match Found Mar 24 13:53:24 DEBUG[7700] chan_sip.c: SIP message could not be handled, bad request: B755DA71-6937-4AF9-9384-7CE7F9E5FB20@192.168.1.100 Mar 24 13:53:27 VERBOSE[26896] logger.c: -- Stopped music on hold on SIP/205_82-a865 Mar 24 13:53:27 DEBUG[26896] channel.c: Scheduling timer at 0 sample intervals Mar 24 13:53:27 DEBUG[26896] channel.c: Scheduling timer at 160 sample intervals Mar 24 13:53:27 VERBOSE[26896] logger.c: -- Playing 'queue-youarenext' (language 'da') Mar 24 13:53:29 DEBUG[26896] channel.c: Scheduling timer at 0 sample intervals Mar 24 13:53:29 VERBOSE[26896] logger.c: -- Started music on hold, class 'default', on SIP/205_82-a865 Mar 24 13:53:29 DEBUG[26896] channel.c: Scheduling timer at 160 sample intervals Mar 24 13:53:29 DEBUG[26896] chan_sip.c: Setting NAT on RTP to 524288 Mar 24 13:53:29 DEBUG[26896] chan_sip.c: Outgoing Call for Thorben Mar 24 13:53:29 VERBOSE[26896] logger.c: -- Called SIP/201_82 Mar 24 13:53:29 DEBUG[26896] channel.c: Generator got voice, switching to phase locked mode Mar 24 13:53:29 DEBUG[26896] channel.c: Scheduling timer at 0 sample intervals Mar 24 13:53:29 DEBUG[7700] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '554280b96906c9f400dd4e9a7d42379f@194.192.14.200' Request 102: Found Mar 24 13:53:29 DEBUG[7691] channel.c: Avoiding initial deadlock for 'SIP/201_82-cc5e' Mar 24 13:53:29 VERBOSE[26896] logger.c: -- SIP/201_82-cc5e is ringing Mar 24 13:53:29 DEBUG[7700] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '554280b96906c9f400dd4e9a7d42379f@194.192.14.200' Request 102: Found Mar 24 13:53:29 VERBOSE[26896] logger.c: -- SIP/201_82-cc5e is ringing Mar 24 13:53:29 DEBUG[7700] chan_sip.c: Auto destroying call '1703D526-89F6-40AE-872C-5C6FA2ED6916@192.168.1.100' Mar 24 13:53:30 DEBUG[7700] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '554280b96906c9f400dd4e9a7d42379f@194.192.14.200' Request 102: Found Mar 24 13:53:30 VERBOSE[26896] logger.c: -- SIP/201_82-cc5e is ringing Mar 24 13:53:32 DEBUG[7700] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '554280b96906c9f400dd4e9a7d42379f@194.192.14.200' Request 102: Found Mar 24 13:53:32 VERBOSE[26896] logger.c: -- SIP/201_82-cc5e is ringing Mar 24 13:53:35 DEBUG[7700] chan_sip.c: Auto destroying call '3c3b81428165-covvz8bbpv3u@snom190' Mar 24 13:53:36 DEBUG[7700] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '554280b96906c9f400dd4e9a7d42379f@194.192.14.200' Request 102: Found Mar 24 13:53:36 VERBOSE[26896] logger.c: -- SIP/201_82-cc5e is ringing Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Nobody picked up in 15000 ms Mar 24 13:53:44 DEBUG[26896] chan_sip.c: update_call_counter(Thorben) - decrement call limit counter Mar 24 13:53:44 DEBUG[26896] chan_sip.c: Acked pending invite 102 Mar 24 13:53:44 DEBUG[26896] chan_sip.c: Stopping retransmission on '554280b96906c9f400dd4e9a7d42379f@194.192.14.200' of Request 102: Match Found Mar 24 13:53:44 DEBUG[26896] chan_sip.c: Stopping retransmission on '554280b96906c9f400dd4e9a7d42379f@194.192.14.200' of Request 102: Match Found Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Stopped music on hold on SIP/205_82-a865 Mar 24 13:53:44 DEBUG[26896] channel.c: Scheduling timer at 0 sample intervals Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing Goto("SIP/205_82-a865", "IVR-1600_82|1|1") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Goto (IVR-1600_82,1,1) Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing Goto("SIP/205_82-a865", "phones_82|305|1") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Goto (phones_82,305,1) Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "COMPANY=_82") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "COMPANYID=82") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "LANGUAGE()=da") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "CALLEEIDNUM=305") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "CALLERNUM=205") in new stack Mar 24 13:53:44 DEBUG[26896] db.c: Unable to find key '305_82' in family 'speednumber' Mar 24 13:53:44 DEBUG[26896] func_db.c: DB: speednumber/305_82 not found in database. Mar 24 13:53:44 DEBUG[26896] pbx.c: Function result is '' Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "SPEED=") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "TOUCH_MONITOR=305_82-205_82") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing GotoIf("SIP/205_82-a865", "?found:notfound") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Goto (phones_82,305,11) Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing Goto("SIP/205_82-a865", "phone-in_82|305|1") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Goto (phone-in_82,305,1) Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing Macro("SIP/205_82-a865", "dial-sip|305|305||SIP/305_82|") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing NoOp("SIP/205_82-a865", "Macro-Dial-Sip") in new stack Mar 24 13:53:44 DEBUG[26896] db.c: Unable to find key 'SIP/305_82' in family 'CFWD' Mar 24 13:53:44 DEBUG[26896] func_db.c: DB: CFWD/SIP/305_82 not found in database. Mar 24 13:53:44 DEBUG[26896] pbx.c: Function result is '' Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "CFWD=") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing GotoIf("SIP/205_82-a865", "?forward:chkicr") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Goto (macro-dial-sip,s,5) Mar 24 13:53:44 DEBUG[26896] db.c: Unable to find key '305_82/205' in family 'ICR' Mar 24 13:53:44 DEBUG[26896] func_db.c: DB: ICR/305_82/205 not found in database. Mar 24 13:53:44 DEBUG[26896] pbx.c: Function result is '' Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "ICR=") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing GotoIf("SIP/205_82-a865", "?icr:chkdnd") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Goto (macro-dial-sip,s,8) Mar 24 13:53:44 DEBUG[26896] db.c: Unable to find key 'SIP/305_82' in family 'dnd' Mar 24 13:53:44 DEBUG[26896] func_db.c: DB: dnd/SIP/305_82 not found in database. Mar 24 13:53:44 DEBUG[26896] pbx.c: Function result is '' Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "tmp=") in new stack Mar 24 13:53:44 DEBUG[26896] pbx.c: Function result is '0' Mar 24 13:53:44 DEBUG[26896] pbx.c: Expression result is '0' Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing GotoIf("SIP/205_82-a865", "0?tmpfound:chkdual") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Goto (macro-dial-sip,s,14) Mar 24 13:53:44 DEBUG[26896] db.c: Unable to find key 'SIP/305_82' in family 'DUAL' Mar 24 13:53:44 DEBUG[26896] func_db.c: DB: DUAL/SIP/305_82 not found in database. Mar 24 13:53:44 DEBUG[26896] pbx.c: Function result is '' Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "DUAL=") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing GotoIf("SIP/205_82-a865", "?dualdial:stddial") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Goto (macro-dial-sip,s,16) Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing GotoIf("SIP/205_82-a865", "?vardial:fixdial") in new stack Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Goto (macro-dial-sip,s,17) Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Executing Dial("SIP/205_82-a865", "SIP/305_82|20|wWtT") in new stack Mar 24 13:53:44 DEBUG[26896] chan_sip.c: Setting NAT on RTP to 524288 Mar 24 13:53:44 DEBUG[26896] chan_sip.c: Outgoing Call for Jesper Mar 24 13:53:44 VERBOSE[26896] logger.c: -- Called 305_82 Mar 24 13:53:44 DEBUG[7700] chan_sip.c: Stopping retransmission on '554280b96906c9f400dd4e9a7d42379f@194.192.14.200' of Request 102: Match Not Found Mar 24 13:53:44 DEBUG[7700] chan_sip.c: Stopping retransmission on '554280b96906c9f400dd4e9a7d42379f@194.192.14.200' of Request 102: Match Not Found Mar 24 13:53:44 DEBUG[7700] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '55d14db57079698b7864c2ad32f06c7c@194.192.14.200' Request 102: Found Mar 24 13:53:44 VERBOSE[26896] logger.c: -- SIP/305_82-0d74 is ringing Mar 24 13:53:44 DEBUG[26896] channel.c: Driver for channel 'SIP/205_82-a865' does not support indication 3, emulating it Mar 24 13:53:44 DEBUG[26896] channel.c: Scheduling timer at 160 sample intervals Mar 24 13:53:44 DEBUG[26896] channel.c: Generator got voice, switching to phase locked mode Mar 24 13:53:44 DEBUG[26896] channel.c: Scheduling timer at 0 sample intervals Mar 24 13:53:44 DEBUG[7700] chan_sip.c: SIP message could not be handled, bad request: B755DA71-6937-4AF9-9384-7CE7F9E5FB20@192.168.1.100 Mar 24 13:53:45 DEBUG[7700] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '55d14db57079698b7864c2ad32f06c7c@194.192.14.200' Request 102: Found Mar 24 13:53:45 VERBOSE[26896] logger.c: -- SIP/305_82-0d74 is ringing Mar 24 13:53:46 DEBUG[7700] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '55d14db57079698b7864c2ad32f06c7c@194.192.14.200' Request 102: Found Mar 24 13:53:46 VERBOSE[26896] logger.c: -- SIP/305_82-0d74 is ringing Mar 24 13:53:47 DEBUG[26896] channel.c: Scheduling timer at 0 sample intervals Mar 24 13:53:47 DEBUG[26896] chan_sip.c: update_call_counter(Jesper) - decrement call limit counter Mar 24 13:53:47 DEBUG[26896] chan_sip.c: Acked pending invite 102 Mar 24 13:53:47 DEBUG[26896] chan_sip.c: Stopping retransmission on '55d14db57079698b7864c2ad32f06c7c@194.192.14.200' of Request 102: Match Found Mar 24 13:53:47 DEBUG[26896] chan_sip.c: Stopping retransmission on '55d14db57079698b7864c2ad32f06c7c@194.192.14.200' of Request 102: Match Found Mar 24 13:53:47 DEBUG[26896] app_dial.c: Exiting with DIALSTATUS=CANCEL. Mar 24 13:53:47 VERBOSE[26896] logger.c: == Spawn extension (macro-dial-sip, s, 17) exited non-zero on 'SIP/205_82-a865' in macro 'dial-sip' Mar 24 13:53:47 VERBOSE[26896] logger.c: == Spawn extension (phone-in_82, 305, 1) exited non-zero on 'SIP/205_82-a865' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is 'jrj@ipdanmark.dk' Mar 24 13:53:47 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "CALLER-EMAIL=jrj@ipdanmark.dk") in new stack Mar 24 13:53:47 DEBUG[26896] db.c: Unable to find key '305_82' in family 'email' Mar 24 13:53:47 DEBUG[26896] func_db.c: DB: email/305_82 not found in database. Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is '' Mar 24 13:53:47 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "CALLEE-EMAIL=") in new stack Mar 24 13:53:47 VERBOSE[26896] logger.c: -- Executing System("SIP/205_82-a865", "/etc/asterisk/sendcdr.sh 82 1143204827 0 @205 @305 @CANCEL &") in new stack Mar 24 13:53:47 VERBOSE[26896] logger.c: -- Executing System("SIP/205_82-a865", "/etc/asterisk/sendconversation.sh 205_82 305_82 jrj@ipdanmark.dk &") in new stack Mar 24 13:53:47 VERBOSE[26896] logger.c: -- Executing Set("SIP/205_82-a865", "CDR(accountcode)=305") in new stack Mar 24 13:53:47 VERBOSE[26896] logger.c: -- Executing Hangup("SIP/205_82-a865", "") in new stack Mar 24 13:53:47 VERBOSE[26896] logger.c: == Spawn extension (phone-in_82, h, 6) exited non-zero on 'SIP/205_82-a865' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is '"Jesper" <205>' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is '205' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is '305' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is 'phone-in_82' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is 'SIP/205_82-a865' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is 'SIP/305_82-0d74' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is 'Hangup' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is '(null)' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is '2006-03-24 13:53:00' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is '2006-03-24 13:53:01' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is '2006-03-24 13:53:47' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is '47' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is '46' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is 'ANSWERED' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is 'DOCUMENTATION' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is '305' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is '1143204780.486' Mar 24 13:53:47 DEBUG[26896] pbx.c: Function result is '(null)' Mar 24 13:53:47 DEBUG[26896] chan_sip.c: update_call_counter(205_82) - decrement call limit counter Mar 24 13:53:47 DEBUG[7700] chan_sip.c: Stopping retransmission on '55d14db57079698b7864c2ad32f06c7c@194.192.14.200' of Request 102: Match Not Found Mar 24 13:53:47 DEBUG[7700] chan_sip.c: Stopping retransmission on '55d14db57079698b7864c2ad32f06c7c@194.192.14.200' of Request 102: Match Not Found