[Dec 3 09:54:41] Asterisk 13.5.0 built by root @ tuc-emg03.voip.tuc.local on a x86_64 running Linux on 2015-11-26 10:11:35 UTC [Dec 3 09:54:44] VERBOSE[23597][C-000005ce] pbx.c: Spawn extension (DefaultPlan, 6730, 3) exited non-zero on 'SIP/emg03emg01-0000112d' [Dec 3 09:54:44] VERBOSE[23597][C-000005ce] pbx_realtime.c: Executing [h@DefaultPlan:1] Macro("SIP/emg03emg01-0000112d", "cdr-end") [Dec 3 09:54:44] VERBOSE[23597][C-000005ce] pbx_realtime.c: Executing [s@macro-cdr-end:1] Set("SIP/emg03emg01-0000112d", "ODBC_STATCDREND()=1449129273.4397,1449129273.4397") [Dec 3 09:54:44] VERBOSE[23597][C-000005ce] pbx_realtime.c: Executing [s@macro-cdr-end:2] MacroExit("SIP/emg03emg01-0000112d", "") [Dec 3 09:55:05] DEBUG[2532] chan_sip.c: Allocating new SIP dialog for 2f8f648f2d1329fd61a9d5fa74bcb9f0@147.27.13.13:5060 - OPTIONS (No RTP) [Dec 3 09:55:05] DEBUG[2532] acl.c: For destination '147.27.13.10', our source address is '147.27.13.13'. [Dec 3 09:55:05] DEBUG[2532] chan_sip.c: Setting AST_TRANSPORT_UDP with address 147.27.13.13:5060 [Dec 3 09:55:05] DEBUG[2532] chan_sip.c: SIP call-id changed from '2f8f648f2d1329fd61a9d5fa74bcb9f0@147.27.13.13:5060' to '5a0af6112706c4c76688f4975fab957f@147.27.13.13:5060' [Dec 3 09:55:05] DEBUG[2532] chan_sip.c: Initializing initreq for method OPTIONS - callid 5a0af6112706c4c76688f4975fab957f@147.27.13.13:5060 [Dec 3 09:55:05] DEBUG[2532] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 147.27.13.10:5060 [Dec 3 09:55:05] DEBUG[2532] chan_sip.c: = Looking for Call ID: 5a0af6112706c4c76688f4975fab957f@147.27.13.13:5060 (Checking To) --From tag as6072a28b --To-tag 3b4a13887635eabbad1b5c1a866f32fa.bea8 [Dec 3 09:55:05] DEBUG[2532] chan_sip.c: Stopping retransmission on '5a0af6112706c4c76688f4975fab957f@147.27.13.13:5060' of Request 102: Match Found [Dec 3 09:55:05] DEBUG[2532] chan_sip.c: Destroying SIP dialog 5a0af6112706c4c76688f4975fab957f@147.27.13.13:5060 [Dec 3 09:55:05] DEBUG[22560][C-000005b2] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 3 09:55:05] DEBUG[22560][C-000005b2] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Dec 3 09:55:05] DEBUG[22560][C-000005b2] netsock2.c: Splitting 'tuc-emg03.voip.tuc.local' into... [Dec 3 09:55:05] DEBUG[22560][C-000005b2] netsock2.c: ...host 'tuc-emg03.voip.tuc.local' and port ''. [Dec 3 09:55:05] DEBUG[22560][C-000005b2] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Dec 3 09:55:05] DEBUG[22560][C-000005b2] acl.c: Attached to given IP address [Dec 3 09:55:05] DEBUG[2561] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Channel: SIP/emg03emg01-000010da ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2821087130 CallerIDName: 2821087130 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: DefaultPlan Exten: 7456 Priority: 2 Uniqueid: 1449128350.4314 Linkedid: 1449128350.4314 To: 147.27.13.13:0 From: 147.27.13.11:19503 RTT: 0.0000 SSRC: 0x19b0e661 PT: 200(SR) ReportCount: 1 SentNTP: 1449129305.17538797162496 SentRTP: 7600160 SentPackets: 47501 SentOctets: 7600160 Report0SourceSSRC: 0x3852414b Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 19285 Report0SequenceNumberCycles: 1 Report0IAJitter: 0 Report0LSR: 0 Report0DLSR: 62809.7760 [Dec 3 09:55:05] DEBUG[2551] netsock2.c: Splitting '147.27.13.11:19503' into... [Dec 3 09:55:05] DEBUG[2551] netsock2.c: ...host '147.27.13.11' and port '19503'. [Dec 3 09:55:05] DEBUG[2551] netsock2.c: Splitting '147.27.13.13:0' into... [Dec 3 09:55:05] DEBUG[2551] netsock2.c: ...host '147.27.13.13' and port '0'. [Dec 3 09:55:05] DEBUG[22561][C-000005b2] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 3 09:55:05] DEBUG[22561][C-000005b2] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Dec 3 09:55:05] DEBUG[22561][C-000005b2] netsock2.c: Splitting 'tuc-emg03.voip.tuc.local' into... [Dec 3 09:55:05] DEBUG[22561][C-000005b2] netsock2.c: ...host 'tuc-emg03.voip.tuc.local' and port ''. [Dec 3 09:55:05] DEBUG[22561][C-000005b2] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Dec 3 09:55:05] DEBUG[22561][C-000005b2] acl.c: Attached to given IP address [Dec 3 09:55:05] DEBUG[2561] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Channel: SIP/emg03emg01-000010dc ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 7456 CallerIDName: ConnectedLineNum: 2821087130 ConnectedLineName: 2821087130 Language: en AccountCode: Context: DialIn Exten: Priority: 1 Uniqueid: 1449128350.4316 Linkedid: 1449128350.4314 To: 147.27.13.13:0 From: 147.27.13.11:16749 RTT: 0.0000 SSRC: 0x3852414b PT: 200(SR) ReportCount: 1 SentNTP: 1449129305.17534829867008 SentRTP: 7640000 SentPackets: 47750 SentOctets: 7640000 Report0SourceSSRC: 0x19b0e661 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 62740 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 0 Report0DLSR: 62809.8000 [Dec 3 09:55:05] DEBUG[2551] netsock2.c: Splitting '147.27.13.11:16749' into... [Dec 3 09:55:05] DEBUG[2551] netsock2.c: ...host '147.27.13.11' and port '16749'. [Dec 3 09:55:05] DEBUG[2551] netsock2.c: Splitting '147.27.13.13:0' into... [Dec 3 09:55:05] DEBUG[2551] netsock2.c: ...host '147.27.13.13' and port '0'. [Dec 3 09:55:09] DEBUG[23596] threadpool.c: Worker thread idle timeout reached. Dying. [Dec 3 09:55:09] DEBUG[2503] threadpool.c: Destroying worker thread 1780 [Dec 3 09:55:10] DEBUG[2532] chan_sip.c: Allocating new SIP dialog for 583104df033e28fb47999a0e5637321c@147.27.13.13:5060 - OPTIONS (No RTP) [Dec 3 09:55:10] DEBUG[2532] acl.c: For destination '147.27.13.12', our source address is '147.27.13.13'. [Dec 3 09:55:10] DEBUG[2532] chan_sip.c: Setting AST_TRANSPORT_UDP with address 147.27.13.13:5060 [Dec 3 09:55:10] DEBUG[2532] chan_sip.c: SIP call-id changed from '583104df033e28fb47999a0e5637321c@147.27.13.13:5060' to '2938af0f1669350f2311ac192b0f7f84@147.27.13.13:5060' [Dec 3 09:55:10] DEBUG[2532] chan_sip.c: Initializing initreq for method OPTIONS - callid 2938af0f1669350f2311ac192b0f7f84@147.27.13.13:5060 [Dec 3 09:55:10] DEBUG[2532] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 147.27.13.12:5060 [Dec 3 09:55:10] DEBUG[2532] chan_sip.c: = Looking for Call ID: 2938af0f1669350f2311ac192b0f7f84@147.27.13.13:5060 (Checking To) --From tag as528bfbce --To-tag as68cc4162 [Dec 3 09:55:10] DEBUG[2532] chan_sip.c: Stopping retransmission on '2938af0f1669350f2311ac192b0f7f84@147.27.13.13:5060' of Request 102: Match Found [Dec 3 09:55:10] DEBUG[2532] chan_sip.c: Destroying SIP dialog 2938af0f1669350f2311ac192b0f7f84@147.27.13.13:5060 [Dec 3 09:55:10] DEBUG[2532] chan_sip.c: = Looking for Call ID: 64e6d4e603b7334030c7586958a1e7a2@147.27.13.12:5060 (Checking From) --From tag as23505b3d --To-tag [Dec 3 09:55:10] DEBUG[2532] acl.c: For destination '147.27.13.12', our source address is '147.27.13.13'. [Dec 3 09:55:10] DEBUG[2532] chan_sip.c: Setting AST_TRANSPORT_UDP with address 147.27.13.13:5060 [Dec 3 09:55:10] DEBUG[2532] netsock2.c: Splitting '147.27.13.12:5060' into... [Dec 3 09:55:10] DEBUG[2532] netsock2.c: ...host '147.27.13.12' and port '5060'. [Dec 3 09:55:10] DEBUG[2532] chan_sip.c: Allocating new SIP dialog for 64e6d4e603b7334030c7586958a1e7a2@147.27.13.12:5060 - OPTIONS (No RTP) [Dec 3 09:55:10] DEBUG[2532] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Dec 3 09:55:10] DEBUG[2532] netsock2.c: Splitting '147.27.13.13' into... [Dec 3 09:55:10] DEBUG[2532] netsock2.c: ...host '147.27.13.13' and port ''. [Dec 3 09:55:10] DEBUG[2532] netsock2.c: Splitting '147.27.13.12' into... [Dec 3 09:55:10] DEBUG[2532] netsock2.c: ...host '147.27.13.12' and port ''. [Dec 3 09:55:10] DEBUG[2532] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM extensions WHERE exten = ? AND priority = ? AND context = ? [Dec 3 09:55:10] DEBUG[2532] res_config_odbc.c: Parameter 1 ('exten') = 's' [Dec 3 09:55:10] DEBUG[2532] res_config_odbc.c: Parameter 2 ('priority') = '1' [Dec 3 09:55:10] DEBUG[2532] res_config_odbc.c: Parameter 3 ('context') = 'Restrict' [Dec 3 09:55:10] DEBUG[2532] res_odbc.c: odbc_release_obj2(0x315e758) called (obj->txf = (nil)) [Dec 3 09:55:10] DEBUG[2532] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM extensions WHERE exten LIKE ? AND priority = ? AND context = ? ORDER BY exten [Dec 3 09:55:10] DEBUG[2532] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Dec 3 09:55:10] DEBUG[2532] res_config_odbc.c: Parameter 2 ('priority') = '1' [Dec 3 09:55:10] DEBUG[2532] res_config_odbc.c: Parameter 3 ('context') = 'Restrict' [Dec 3 09:55:10] DEBUG[2532] res_odbc.c: odbc_release_obj2(0x315e758) called (obj->txf = (nil)) [Dec 3 09:55:10] DEBUG[2532] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM extensions WHERE exten = ? AND priority = ? AND context = ? [Dec 3 09:55:10] DEBUG[2532] res_config_odbc.c: Parameter 1 ('exten') = 's' [Dec 3 09:55:10] DEBUG[2532] res_config_odbc.c: Parameter 2 ('priority') = '1' [Dec 3 09:55:10] DEBUG[2532] res_config_odbc.c: Parameter 3 ('context') = 'Restrict' [Dec 3 09:55:10] DEBUG[2532] res_odbc.c: odbc_release_obj2(0x315e758) called (obj->txf = (nil)) [Dec 3 09:55:10] DEBUG[2532] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM extensions WHERE exten LIKE ? AND priority = ? AND context = ? ORDER BY exten [Dec 3 09:55:10] DEBUG[2532] res_config_odbc.c: Parameter 1 ('exten LIKE') = '\_%' [Dec 3 09:55:10] DEBUG[2532] res_config_odbc.c: Parameter 2 ('priority') = '1' [Dec 3 09:55:10] DEBUG[2532] res_config_odbc.c: Parameter 3 ('context') = 'Restrict' [Dec 3 09:55:10] DEBUG[2532] res_odbc.c: odbc_release_obj2(0x315e758) called (obj->txf = (nil)) [Dec 3 09:55:10] DEBUG[2532] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 147.27.13.12:5060 [Dec 3 09:55:10] DEBUG[22560][C-000005b2] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 3 09:55:10] DEBUG[22560][C-000005b2] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Dec 3 09:55:10] DEBUG[22560][C-000005b2] netsock2.c: Splitting 'tuc-emg03.voip.tuc.local' into... [Dec 3 09:55:10] DEBUG[22560][C-000005b2] netsock2.c: ...host 'tuc-emg03.voip.tuc.local' and port ''. [Dec 3 09:55:10] DEBUG[22560][C-000005b2] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Dec 3 09:55:10] DEBUG[22560][C-000005b2] acl.c: Attached to given IP address [Dec 3 09:55:10] DEBUG[2561] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Channel: SIP/emg03emg01-000010da ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 2821087130 CallerIDName: 2821087130 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: DefaultPlan Exten: 7456 Priority: 2 Uniqueid: 1449128350.4314 Linkedid: 1449128350.4314 To: 147.27.13.13:0 From: 147.27.13.11:19503 RTT: 0.0000 SSRC: 0x19b0e661 PT: 200(SR) ReportCount: 1 SentNTP: 1449129310.17538621276160 SentRTP: 7640160 SentPackets: 47751 SentOctets: 7640160 Report0SourceSSRC: 0x3852414b Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 19535 Report0SequenceNumberCycles: 1 Report0IAJitter: 0 Report0LSR: 0 Report0DLSR: 62814.7750 [Dec 3 09:55:10] DEBUG[2551] netsock2.c: Splitting '147.27.13.11:19503' into... [Dec 3 09:55:10] DEBUG[2551] netsock2.c: ...host '147.27.13.11' and port '19503'. [Dec 3 09:55:10] DEBUG[2551] netsock2.c: Splitting '147.27.13.13:0' into... [Dec 3 09:55:10] DEBUG[2551] netsock2.c: ...host '147.27.13.13' and port '0'. [Dec 3 09:55:10] DEBUG[22561][C-000005b2] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Dec 3 09:55:10] DEBUG[22561][C-000005b2] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Dec 3 09:55:10] DEBUG[22561][C-000005b2] netsock2.c: Splitting 'tuc-emg03.voip.tuc.local' into... [Dec 3 09:55:10] DEBUG[22561][C-000005b2] netsock2.c: ...host 'tuc-emg03.voip.tuc.local' and port ''. [Dec 3 09:55:10] DEBUG[22561][C-000005b2] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Dec 3 09:55:10] DEBUG[22561][C-000005b2] acl.c: Attached to given IP address [Dec 3 09:55:10] DEBUG[2561] manager.c: Examining AMI event: Event: RTCPReceived Privilege: reporting,all Channel: SIP/emg03emg01-000010dc ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 7456 CallerIDName: ConnectedLineNum: 2821087130 ConnectedLineName: 2821087130 Language: en AccountCode: Context: DialIn Exten: Priority: 1 Uniqueid: 1449128350.4316 Linkedid: 1449128350.4314 To: 147.27.13.13:0 From: 147.27.13.11:16749 RTT: 0.0000 SSRC: 0x3852414b PT: 200(SR) ReportCount: 1 SentNTP: 1449129310.17534919102464 SentRTP: 7680000 SentPackets: 48000 SentOctets: 7680000 Report0SourceSSRC: 0x19b0e661 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 62990 Report0SequenceNumberCycles: 0 Report0IAJitter: 0 Report0LSR: 0 Report0DLSR: 62814.8000 [Dec 3 09:55:10] DEBUG[2551] netsock2.c: Splitting '147.27.13.11:16749' into... [Dec 3 09:55:10] DEBUG[2551] netsock2.c: ...host '147.27.13.11' and port '16749'. [Dec 3 09:55:10] DEBUG[2551] netsock2.c: Splitting '147.27.13.13:0' into... [Dec 3 09:55:10] DEBUG[2551] netsock2.c: ...host '147.27.13.13' and port '0'.