[Aug 1 10:11:11] DEBUG[17073] sig_pri.c: prioffset: 1 mastertrunkgroup: 0 logicalspan: 0 result: 1 [Aug 1 10:11:11] DEBUG[17073] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Aug 1 10:11:11] DEBUG[17073] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Aug 1 10:11:11] DEBUG[17073] dsp.c: Setup v21 detector, block_size=160 [Aug 1 10:11:11] VERBOSE[17073] sig_pri.c: -- Accepting call from '502503' to '59' on channel 0/1, span 2 [Aug 1 10:11:11] DEBUG[17073] chan_dahdi.c: Enabled echo cancellation on channel 4 [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for DAHDI - i2/502503 [Aug 1 10:11:11] DEBUG[17050] devicestate.c: Changing state for DAHDI/i2/502503 - state 2 (In use) [Aug 1 10:11:11] DEBUG[17050] devicestate.c: device 'DAHDI/i2/502503' state '2' [Aug 1 10:11:11] DEBUG[17092] app_queue.c: Device 'DAHDI/i2/502503' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [59@from-isdn:1] Set("DAHDI/i2/502503-3ce", "FAXOPT(t38gateway)=yes") in new stack [Aug 1 10:11:11] DEBUG[13789] res_fax.c: channel 'DAHDI/i2/502503-3ce' setting FAXOPT(t38gateway) to 'yes' [Aug 1 10:11:11] DEBUG[13789] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Aug 1 10:11:11] DEBUG[13789] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Aug 1 10:11:11] DEBUG[13789] dsp.c: Setup v21 detector, block_size=160 [Aug 1 10:11:11] DEBUG[13789] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Aug 1 10:11:11] DEBUG[13789] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Aug 1 10:11:11] DEBUG[13789] dsp.c: Setup v21 detector, block_size=160 [Aug 1 10:11:11] DEBUG[13789] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Aug 1 10:11:11] DEBUG[13789] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Aug 1 10:11:11] DEBUG[13789] dsp.c: Setup v21 detector, block_size=160 [Aug 1 10:11:11] DEBUG[13789] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Aug 1 10:11:11] DEBUG[13789] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Aug 1 10:11:11] DEBUG[13789] dsp.c: Setup v21 detector, block_size=160 [Aug 1 10:11:11] DEBUG[13789] res_fax.c: Reserving a FAX session from 'Spandsp FAX Driver'. [Aug 1 10:11:11] DEBUG[13789] res_fax.c: Selected FAX technology module (Spandsp FAX Driver) does not support reserving sessions. [Aug 1 10:11:11] DEBUG[13789] res_fax.c: Attached T.38 gateway to channel DAHDI/i2/502503-3ce. [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'EXTEN' is '59' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Goto' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [59@from-isdn:2] Goto("DAHDI/i2/502503-3ce", "from-pstn,59,1") in new stack [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Goto (from-pstn,59,1) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'EXTEN' is '59' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [59@from-pstn:1] Set("DAHDI/i2/502503-3ce", "__FROM_DID=59") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '502503' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'ExecIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [59@from-pstn:2] ExecIf("DAHDI/i2/502503-3ce", "1 ?Set(CALLERID(name)=502503)") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is 'allowed' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [59@from-pstn:3] Set("DAHDI/i2/502503-3ce", "__CALLINGPRES_SV=allowed") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [59@from-pstn:4] Set("DAHDI/i2/502503-3ce", "CALLERPRES()=allowed_not_screened") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Goto' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [59@from-pstn:5] Goto("DAHDI/i2/502503-3ce", "from-did-direct,867,1") in new stack [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Goto (from-did-direct,867,1) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'ExecIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [867@from-did-direct:1] ExecIf("DAHDI/i2/502503-3ce", "0?Set(__RINGTIMER=0)") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Macro' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [867@from-did-direct:2] Macro("DAHDI/i2/502503-3ce", "exten-vm,novm,867,0,0,0") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Macro' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-exten-vm:1] Macro("DAHDI/i2/502503-3ce", "user-callerid,") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'AMPUSER' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '502503' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'AMPUSER' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '502503' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-user-callerid:1] Set("DAHDI/i2/502503-3ce", "AMPUSER=502503") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'CHANNEL' is 'DAHDI/i2/502503-3ce' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'AMPUSERCIDNAME' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("DAHDI/i2/502503-3ce", "0?report") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Not taking any branch [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'REALCALLERIDNUM' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '502503' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'ExecIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("DAHDI/i2/502503-3ce", "1?Set(REALCALLERIDNUM=502503)") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: ExecIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'REALCALLERIDNUM:1:2' (from 'REALCALLERIDNUM:1:2}" = ""' len 19) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'REALCALLERIDNUM' is '502503' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '502503' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'REALCALLERIDNUM' is '502503' [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key '502503/user' in family 'DEVICE' [Aug 1 10:11:11] DEBUG[13789] func_db.c: DB: DEVICE/502503/user not found in database. [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-user-callerid:4] Set("DAHDI/i2/502503-3ce", "AMPUSER=") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'AMPUSER' is '' [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key '/cidname' in family 'AMPUSER' [Aug 1 10:11:11] DEBUG[13789] func_db.c: DB: AMPUSER//cidname not found in database. [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-user-callerid:5] Set("DAHDI/i2/502503-3ce", "AMPUSERCIDNAME=") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'AMPUSERCIDNAME' is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("DAHDI/i2/502503-3ce", "1?report") in new stack [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Goto (macro-user-callerid,s,11) [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG1' is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG1' is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-user-callerid:11] GotoIf("DAHDI/i2/502503-3ce", "0?continue") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Not taking any branch [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'TTL' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'TTL' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '-1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '64' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-user-callerid:12] Set("DAHDI/i2/502503-3ce", "__TTL=64") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'TTL' is '64' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-user-callerid:13] GotoIf("DAHDI/i2/502503-3ce", "1?continue") in new stack [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Goto (macro-user-callerid,s,24) [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '502503' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-user-callerid:24] Set("DAHDI/i2/502503-3ce", "CALLERID(number)=502503") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '502503' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-user-callerid:25] Set("DAHDI/i2/502503-3ce", "CALLERID(name)=502503") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'CHANNEL(language)' (from 'CHANNEL(language)}' len 17) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is 'en' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is 'en' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-user-callerid:26] Set("DAHDI/i2/502503-3ce", "CHANNEL(language)=en") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Macro [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-exten-vm:2] Set("DAHDI/i2/502503-3ce", "RingGroupMethod=none") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG2' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-exten-vm:3] Set("DAHDI/i2/502503-3ce", "__EXTTOCALL=867") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG2' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-exten-vm:4] Set("DAHDI/i2/502503-3ce", "__PICKUPMARK=867") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG1' is 'novm' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'EXTTOCALL' is '867' [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key '867' in family 'CFU' [Aug 1 10:11:11] DEBUG[13789] func_db.c: DB: CFU/867 not found in database. [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'EXTTOCALL' is '867' [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key '867' in family 'CFB' [Aug 1 10:11:11] DEBUG[13789] func_db.c: DB: CFB/867 not found in database. [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG3' is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG4' is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG5' is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'RINGTIMER' is '90' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '""' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-exten-vm:5] Set("DAHDI/i2/502503-3ce", "RT=""") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'EXTTOCALL' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Macro' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-exten-vm:6] Macro("DAHDI/i2/502503-3ce", "record-enable,867,IN") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'BLINDTRANSFER' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-record-enable:1] GotoIf("DAHDI/i2/502503-3ce", "1?check") in new stack [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Goto (macro-record-enable,s,4) [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG1' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'ExecIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-record-enable:4] ExecIf("DAHDI/i2/502503-3ce", "0?MacroExit()") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: ExecIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'ARG1' (from 'ARG1}"=""' len 4) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG1' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG2' is 'IN' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-record-enable:5] GotoIf("DAHDI/i2/502503-3ce", "0?Group:OUT") in new stack [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Goto (macro-record-enable,s,15) [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG2' is 'IN' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-record-enable:15] GotoIf("DAHDI/i2/502503-3ce", "1?IN") in new stack [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Goto (macro-record-enable,s,20) [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG1' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'DB(AMPUSER/867/recording)' (from 'DB(AMPUSER/867/recording)}' len 25) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is 'out=Adhoc|in=Adhoc' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is 'in=Adhoc' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'AMPUSER' is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'DB(AMPUSER//recording)' (from 'DB(AMPUSER//recording)}' len 22) [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key '/recording' in family 'AMPUSER' [Aug 1 10:11:11] DEBUG[13789] func_db.c: DB: AMPUSER//recording not found in database. [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'ExecIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-record-enable:20] ExecIf("DAHDI/i2/502503-3ce", "1?MacroExit()") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Macro [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'RT' is '""' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DIAL_OPTIONS' is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'EXTTOCALL' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Macro' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-exten-vm:7] Macro("DAHDI/i2/502503-3ce", "dial-one,"",,867") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG3' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:1] Set("DAHDI/i2/502503-3ce", "DEXTEN=867") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:2] Set("DAHDI/i2/502503-3ce", "DIALSTATUS_CW=") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'FROM_DID' is '59' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'SCREEN' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key '867/screen' in family 'AMPUSER' [Aug 1 10:11:11] DEBUG[13789] func_db.c: DB: AMPUSER/867/screen not found in database. [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GosubIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:3] GosubIf("DAHDI/i2/502503-3ce", "0?screen,1") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GosubIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'FROM_DID' (from 'FROM_DID}"!="" & "${SCREEN}"="" & "${DB(AMPUSER/${DEXTEN}/screen)}"!=""' len 8) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'FROM_DID' is '59' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'SCREEN' (from 'SCREEN}"="" & "${DB(AMPUSER/${DEXTEN}/screen)}"!=""' len 6) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'SCREEN' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'DB(AMPUSER/${DEXTEN}/screen)' (from 'DB(AMPUSER/${DEXTEN}/screen)}"!=""' len 28) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'DEXTEN' (from 'DEXTEN}/screen)' len 6) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key '867/screen' in family 'AMPUSER' [Aug 1 10:11:11] DEBUG[13789] func_db.c: DB: AMPUSER/867/screen not found in database. [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key '867' in family 'CF' [Aug 1 10:11:11] DEBUG[13789] func_db.c: DB: CF/867 not found in database. [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GosubIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:4] GosubIf("DAHDI/i2/502503-3ce", "0?cf,1") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GosubIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'DB(CF/${DEXTEN})' (from 'DB(CF/${DEXTEN})}"!=""' len 16) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'DEXTEN' (from 'DEXTEN})' len 6) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key '867' in family 'CF' [Aug 1 10:11:11] DEBUG[13789] func_db.c: DB: CF/867 not found in database. [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key '867' in family 'DND' [Aug 1 10:11:11] DEBUG[13789] func_db.c: DB: DND/867 not found in database. [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:5] GotoIf("DAHDI/i2/502503-3ce", "1?skip1") in new stack [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Goto (macro-dial-one,s,8) [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:8] GotoIf("DAHDI/i2/502503-3ce", "0?nodial") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Not taking any branch [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:9] GotoIf("DAHDI/i2/502503-3ce", "0?continue") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Not taking any branch [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'CWIGNORE' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key '867' in family 'CW' [Aug 1 10:11:11] DEBUG[13789] func_db.c: DB: CW/867 not found in database. [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:10] Set("DAHDI/i2/502503-3ce", "EXTHASCW=") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'EXTHASCW' is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key '867' in family 'CFB' [Aug 1 10:11:11] DEBUG[13789] func_db.c: DB: CFB/867 not found in database. [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key '867' in family 'CFU' [Aug 1 10:11:11] DEBUG[13789] func_db.c: DB: CFU/867 not found in database. [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:11] GotoIf("DAHDI/i2/502503-3ce", "1?next1:cwinusebusy") in new stack [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Goto (macro-dial-one,s,12) [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key '867' in family 'CFU' [Aug 1 10:11:11] DEBUG[13789] func_db.c: DB: CFU/867 not found in database. [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] devicestate.c: Checking if I can find provider for "Custom" - number: DND867 [Aug 1 10:11:11] DEBUG[13789] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key 'DND867' in family 'CustomDevstate' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is 'NOT_INUSE' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] devicestate.c: Checking if I can find provider for "Custom" - number: DND867 [Aug 1 10:11:11] DEBUG[13789] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key 'DND867' in family 'CustomDevstate' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is 'NOT_INUSE' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:12] GotoIf("DAHDI/i2/502503-3ce", "0?docfu:skip3") in new stack [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Goto (macro-dial-one,s,16) [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'EXTHASCW' is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key '867' in family 'CFB' [Aug 1 10:11:11] DEBUG[13789] func_db.c: DB: CFB/867 not found in database. [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:16] GotoIf("DAHDI/i2/502503-3ce", "1?next2:continue") in new stack [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Goto (macro-dial-one,s,17) [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] devicestate.c: Checking if I can find provider for "Custom" - number: DND867 [Aug 1 10:11:11] DEBUG[13789] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key 'DND867' in family 'CustomDevstate' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is 'NOT_INUSE' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] devicestate.c: Checking if I can find provider for "Custom" - number: DND867 [Aug 1 10:11:11] DEBUG[13789] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key 'DND867' in family 'CustomDevstate' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is 'NOT_INUSE' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] devicestate.c: Checking if I can find provider for "Custom" - number: DND867 [Aug 1 10:11:11] DEBUG[13789] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:11] DEBUG[13789] db.c: Unable to find key 'DND867' in family 'CustomDevstate' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is 'NOT_INUSE' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:17] GotoIf("DAHDI/i2/502503-3ce", "1?continue") in new stack [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Goto (macro-dial-one,s,25) [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:25] GotoIf("DAHDI/i2/502503-3ce", "0?nodial") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Not taking any branch [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GosubIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:26] GosubIf("DAHDI/i2/502503-3ce", "1?dstring,1:dlocal,1") in new stack [Aug 1 10:11:11] DEBUG[13789] app_stack.c: Channel DAHDI/i2/502503-3ce has no datastore, so we're allocating one. [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GosubIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'DEXTEN:-1' (from 'DEXTEN:-1}"!="#"' len 9) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Incrementing gosub_level [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [dstring@macro-dial-one:1] Set("DAHDI/i2/502503-3ce", "DSTRING=") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [dstring@macro-dial-one:2] Set("DAHDI/i2/502503-3ce", "DEVICES=867") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEVICES' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'ExecIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [dstring@macro-dial-one:3] ExecIf("DAHDI/i2/502503-3ce", "0?Return()") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: ExecIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'DEVICES' (from 'DEVICES}"=""' len 7) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEVICES' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEVICES' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEVICES' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'ExecIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [dstring@macro-dial-one:4] ExecIf("DAHDI/i2/502503-3ce", "0?Set(DEVICES=67)") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: ExecIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'DEVICES:0:1' (from 'DEVICES:0:1}"="&"' len 11) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEVICES' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'DEVICES:1' (from 'DEVICES:1})' len 9) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEVICES' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'DEVICES' (from 'DEVICES}' len 7) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEVICES' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [dstring@macro-dial-one:5] Set("DAHDI/i2/502503-3ce", "LOOPCNT=1") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [dstring@macro-dial-one:6] Set("DAHDI/i2/502503-3ce", "ITER=1") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ITER' is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'DEVICES' (from 'DEVICES}' len 7) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEVICES' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is 'SIP/867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [dstring@macro-dial-one:7] Set("DAHDI/i2/502503-3ce", "THISDIAL=SIP/867") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ASTCHANDAHDI' is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GosubIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [dstring@macro-dial-one:8] GosubIf("DAHDI/i2/502503-3ce", "1?zap2dahdi,1") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GosubIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'ASTCHANDAHDI' (from 'ASTCHANDAHDI}" != ""' len 12) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ASTCHANDAHDI' is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Incrementing gosub_level [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'THISDIAL' is 'SIP/867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'ExecIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [zap2dahdi@macro-dial-one:1] ExecIf("DAHDI/i2/502503-3ce", "0?Return()") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: ExecIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'THISDIAL' (from 'THISDIAL}" = ""' len 8) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'THISDIAL' is 'SIP/867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [zap2dahdi@macro-dial-one:2] Set("DAHDI/i2/502503-3ce", "NEWDIAL=") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'THISDIAL' (from 'THISDIAL}' len 8) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'THISDIAL' is 'SIP/867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [zap2dahdi@macro-dial-one:3] Set("DAHDI/i2/502503-3ce", "LOOPCNT2=1") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [zap2dahdi@macro-dial-one:4] Set("DAHDI/i2/502503-3ce", "ITER2=1") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ITER2' is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'THISDIAL' (from 'THISDIAL}' len 8) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'THISDIAL' is 'SIP/867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is 'SIP/867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [zap2dahdi@macro-dial-one:5] Set("DAHDI/i2/502503-3ce", "THISPART2=SIP/867") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'THISPART2' is 'SIP/867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'THISPART2' is 'SIP/867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'ExecIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [zap2dahdi@macro-dial-one:6] ExecIf("DAHDI/i2/502503-3ce", "0?Set(THISPART2=DAHDI/867)") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: ExecIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'THISPART2:0:3' (from 'THISPART2:0:3}" = "ZAP"' len 13) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'THISPART2' is 'SIP/867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'THISPART2:3' (from 'THISPART2:3})' len 11) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'THISPART2' is 'SIP/867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'NEWDIAL' is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'THISPART2' is 'SIP/867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [zap2dahdi@macro-dial-one:7] Set("DAHDI/i2/502503-3ce", "NEWDIAL=SIP/867&") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ITER2' is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '2' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [zap2dahdi@macro-dial-one:8] Set("DAHDI/i2/502503-3ce", "ITER2=2") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ITER2' is '2' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'LOOPCNT2' is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [zap2dahdi@macro-dial-one:9] GotoIf("DAHDI/i2/502503-3ce", "0?begin2") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Not taking any branch [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'NEWDIAL' is 'SIP/867&' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '8' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '7' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'NEWDIAL' is 'SIP/867&' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [zap2dahdi@macro-dial-one:10] Set("DAHDI/i2/502503-3ce", "THISDIAL=SIP/867") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Return' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [zap2dahdi@macro-dial-one:11] Return("DAHDI/i2/502503-3ce", "") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Return [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Decrementing gosub_level [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DSTRING' is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'THISDIAL' is 'SIP/867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [dstring@macro-dial-one:9] Set("DAHDI/i2/502503-3ce", "DSTRING=SIP/867&") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ITER' is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '2' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [dstring@macro-dial-one:10] Set("DAHDI/i2/502503-3ce", "ITER=2") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ITER' is '2' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'LOOPCNT' is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [dstring@macro-dial-one:11] GotoIf("DAHDI/i2/502503-3ce", "0?begin") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Not taking any branch [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DSTRING' is 'SIP/867&' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '8' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '7' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DSTRING' is 'SIP/867&' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [dstring@macro-dial-one:12] Set("DAHDI/i2/502503-3ce", "DSTRING=SIP/867") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Return' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [dstring@macro-dial-one:13] Return("DAHDI/i2/502503-3ce", "") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Return [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Decrementing gosub_level [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DSTRING' is 'SIP/867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '7' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:27] GotoIf("DAHDI/i2/502503-3ce", "0?nodial") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Not taking any branch [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DEXTEN' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:28] GotoIf("DAHDI/i2/502503-3ce", "1?skiptrace") in new stack [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Goto (macro-dial-one,s,30) [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'NODEST' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG2' is '' [Aug 1 10:11:11] DEBUG[13789] func_strings.c: FUNCTION REGEX ((M[(]auto-blkvm[)]))() [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG2' is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG2' is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:30] Set("DAHDI/i2/502503-3ce", "D_OPTIONS=") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ALERT_INFO' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ALERT_INFO' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'ExecIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:31] ExecIf("DAHDI/i2/502503-3ce", "0?SIPAddHeader(Alert-Info: )") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: ExecIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'ALERT_INFO' (from 'ALERT_INFO}"!=""' len 10) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ALERT_INFO' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'ALERT_INFO' (from 'ALERT_INFO})' len 10) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ALERT_INFO' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'SIPADDHEADER' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'SIPADDHEADER' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'ExecIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:32] ExecIf("DAHDI/i2/502503-3ce", "0?SIPAddHeader()") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: ExecIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'SIPADDHEADER' (from 'SIPADDHEADER}"!=""' len 12) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'SIPADDHEADER' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'SIPADDHEADER' (from 'SIPADDHEADER})' len 12) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'SIPADDHEADER' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'MOHCLASS' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'MOHCLASS' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'ExecIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:33] ExecIf("DAHDI/i2/502503-3ce", "0?Set(CHANNEL(musicclass)=)") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: ExecIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'MOHCLASS' (from 'MOHCLASS}"!=""' len 8) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'MOHCLASS' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'MOHCLASS' (from 'MOHCLASS})' len 8) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'MOHCLASS' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'QUEUEWAIT' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GosubIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:34] GosubIf("DAHDI/i2/502503-3ce", "0?qwait,1") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GosubIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Evaluating 'QUEUEWAIT' (from 'QUEUEWAIT}"!=""' len 9) [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'QUEUEWAIT' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'CWIGNORE' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:35] Set("DAHDI/i2/502503-3ce", "__CWIGNORE=") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:36] Set("DAHDI/i2/502503-3ce", "__KEEPCID=TRUE") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'USEGOTO' is NULL [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:37] GotoIf("DAHDI/i2/502503-3ce", "0?usegoto,1") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Not taking any branch [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'EXTTOCALL' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is 'FAX Titkarsag' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Expression result is '0' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:38] GotoIf("DAHDI/i2/502503-3ce", "0?godial") in new stack [Aug 1 10:11:11] DEBUG[13789] pbx.c: Not taking any branch [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'EXTTOCALL' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Function result is 'FAX Titkarsag' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:39] Set("DAHDI/i2/502503-3ce", "CONNECTEDLINE(name,i)=FAX Titkarsag") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'EXTTOCALL' is '867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:40] Set("DAHDI/i2/502503-3ce", "CONNECTEDLINE(num)=867") in new stack [Aug 1 10:11:11] DEBUG[13789] chan_dahdi.c: Requested indication 22 on channel DAHDI/i2/502503-3ce [Aug 1 10:11:11] DEBUG[13789] sig_pri.c: Received AST_CONTROL_CONNECTED_LINE on DAHDI/i2/502503-3ce [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'D_OPTIONS' is '' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Set' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:41] Set("DAHDI/i2/502503-3ce", "D_OPTIONS=I") in new stack [Aug 1 10:11:11] DEBUG[13789] app_macro.c: Executed application: Set [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'DSTRING' is 'SIP/867' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'ARG1' is '""' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Result of 'D_OPTIONS' is 'I' [Aug 1 10:11:11] DEBUG[13789] pbx.c: Launching 'Dial' [Aug 1 10:11:11] VERBOSE[13789] pbx.c: -- Executing [s@macro-dial-one:42] Dial("DAHDI/i2/502503-3ce", "SIP/867,"",I") in new stack [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw) [Aug 1 10:11:11] VERBOSE[13789] netsock.c: == Using UDPTL TOS bits 184 [Aug 1 10:11:11] VERBOSE[13789] netsock.c: == Using UDPTL CoS mark 5 [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: Allocating new SIP dialog for 3122699868d600e8198ed6152032ed80@127.0.1.1:0 - INVITE (No RTP) [Aug 1 10:11:11] DEBUG[13789] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb60236c8' [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: Allocated port 15552 for RTP instance '0xb60236c8' [Aug 1 10:11:11] DEBUG[13789] rtp_engine.c: RTP instance '0xb60236c8' is setup and ready to go [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb60236c8' [Aug 1 10:11:11] VERBOSE[13789] netsock2.c: == Using SIP RTP TOS bits 184 [Aug 1 10:11:11] VERBOSE[13789] netsock2.c: == Using SIP RTP CoS mark 5 [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: Setting NAT on RTP to Off [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: Setting NAT on UDPTL to Off [Aug 1 10:11:11] DEBUG[13789] acl.c: For destination '10.199.253.249', our source address is '10.199.0.1'. [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: *** Our native formats are 0x8 (alaw) [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: *** Joint capabilities are 0x8 (alaw) [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: *** Our capabilities are 0x8 (alaw) [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw) [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: This channel will not be able to handle video. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable DIALEDTIME. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable ANSWEREDTIME. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable DIALEDPEERNAME. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable DIALEDPEERNUMBER. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable DIALSTATUS. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable MACRO_DEPTH. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable D_OPTIONS. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable DB_RESULT. [Aug 1 10:11:11] DEBUG[13789] channel.c: Copying hard-transferable variable KEEPCID. [Aug 1 10:11:11] DEBUG[13789] channel.c: Copying hard-transferable variable CWIGNORE. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable GOSUB_RETVAL. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable DSTRING. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable ITER. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable THISDIAL. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable ITER2. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable NEWDIAL. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable THISPART2. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable LOOPCNT2. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable LOOPCNT. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable DEVICES. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable EXTHASCW. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable DIALSTATUS_CW. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable DEXTEN. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable ARG3. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable ARG2. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable ARG1. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable MACRO_PRIORITY. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable MACRO_CONTEXT. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable MACRO_EXTEN. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable RT. [Aug 1 10:11:11] DEBUG[13789] channel.c: Copying hard-transferable variable PICKUPMARK. [Aug 1 10:11:11] DEBUG[13789] channel.c: Copying hard-transferable variable EXTTOCALL. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable RingGroupMethod. [Aug 1 10:11:11] DEBUG[13789] channel.c: Copying hard-transferable variable TTL. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable AMPUSERCIDNAME. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable AMPUSER. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable REALCALLERIDNUM. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable ARG5. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable ARG4. [Aug 1 10:11:11] DEBUG[13789] channel.c: Copying hard-transferable variable CALLINGPRES_SV. [Aug 1 10:11:11] DEBUG[13789] channel.c: Copying hard-transferable variable FROM_DID. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable FAXPAGES. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable FAXSTATUSSTRING. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable FAXERROR. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable FAXSTATUS. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable CALLEDTON. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable PRIREDIRECTREASON. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable ANI2. [Aug 1 10:11:11] DEBUG[13789] channel.c: Not copying variable TRANSFERCAPABILITY. [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: Outgoing Call for 867 [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: Updating call counter for outgoing call [Aug 1 10:11:11] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for SIP - 867 [Aug 1 10:11:11] DEBUG[17050] chan_sip.c: Checking device state for peer 867 [Aug 1 10:11:11] DEBUG[17050] devicestate.c: Changing state for SIP/867 - state 6 (Ringing) [Aug 1 10:11:11] DEBUG[17050] devicestate.c: device 'SIP/867' state '6' [Aug 1 10:11:11] DEBUG[17092] app_queue.c: Device 'SIP/867' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Aug 1 10:11:11] DEBUG[17051] devicestate.c: Checking if I can find provider for "Custom" - number: DND867 [Aug 1 10:11:11] DEBUG[17051] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:11] DEBUG[17051] db.c: Unable to find key 'DND867' in family 'CustomDevstate' [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: False Text flag: False [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: ** Our prefcodec: 0x8 (alaw) [Aug 1 10:11:11] DEBUG[17051] app_queue.c: Extension '867@ext-local' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: -- Done with adding codecs to SDP [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: Initializing initreq for method INVITE - callid 1796ae7910a60e8e2f66c2d367e9dee9@10.199.0.1:5060 [Aug 1 10:11:11] DEBUG[13789] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 10.199.253.249:5061 [Aug 1 10:11:11] VERBOSE[13789] app_dial.c: -- Called SIP/867 [Aug 1 10:11:11] VERBOSE[13789] app_dial.c: -- Connected line update to DAHDI/i2/502503-3ce prevented. [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[17078] chan_sip.c: = Looking for Call ID: 1796ae7910a60e8e2f66c2d367e9dee9@10.199.0.1:5060 (Checking To) --From tag as720b2ee6 --To-tag [Aug 1 10:11:11] DEBUG[17078] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '1796ae7910a60e8e2f66c2d367e9dee9@10.199.0.1:5060' Request 102: Found [Aug 1 10:11:11] DEBUG[17078] chan_sip.c: SIP response 100 to standard invite [Aug 1 10:11:11] DEBUG[17078] chan_sip.c: = Looking for Call ID: 1796ae7910a60e8e2f66c2d367e9dee9@10.199.0.1:5060 (Checking To) --From tag as720b2ee6 --To-tag 6213e0932bd558cai1 [Aug 1 10:11:11] DEBUG[17078] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '1796ae7910a60e8e2f66c2d367e9dee9@10.199.0.1:5060' Request 102: Found [Aug 1 10:11:11] DEBUG[17078] chan_sip.c: SIP response 180 to standard invite [Aug 1 10:11:11] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for SIP - 867 [Aug 1 10:11:11] DEBUG[17050] chan_sip.c: Checking device state for peer 867 [Aug 1 10:11:11] DEBUG[17050] devicestate.c: Changing state for SIP/867 - state 6 (Ringing) [Aug 1 10:11:11] DEBUG[17050] devicestate.c: device 'SIP/867' state '6' [Aug 1 10:11:11] VERBOSE[13789] app_dial.c: -- SIP/867-00000b7b is ringing [Aug 1 10:11:11] DEBUG[13789] chan_dahdi.c: Requested indication 3 on channel DAHDI/i2/502503-3ce [Aug 1 10:11:11] DEBUG[13789] sig_pri.c: prioffset: 1 mastertrunkgroup: 0 logicalspan: 0 result: 1 [Aug 1 10:11:11] DEBUG[17092] app_queue.c: Device 'SIP/867' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Aug 1 10:11:11] DEBUG[17051] devicestate.c: Checking if I can find provider for "Custom" - number: DND867 [Aug 1 10:11:11] DEBUG[17051] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:11] DEBUG[17051] db.c: Unable to find key 'DND867' in family 'CustomDevstate' [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[17078] chan_sip.c: = Looking for Call ID: f0772e9a-90014a6d@10.199.254.249 (Checking From) --From tag 4617a50557a3cefdo0 --To-tag [Aug 1 10:11:11] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:11] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.249:5060 [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:11] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: = Looking for Call ID: 5baf57ce-985a0f00@10.199.254.2 (Checking From) --From tag 56cefd94af6e7238o0 --To-tag [Aug 1 10:11:12] DEBUG[17078] acl.c: For destination '10.199.254.2', our source address is '10.199.0.1'. [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 5baf57ce-985a0f00@10.199.254.2 - REGISTER (No RTP) [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 1 10:11:12] DEBUG[17078] netsock2.c: Splitting '10.199.254.2:5060' into... [Aug 1 10:11:12] DEBUG[17078] netsock2.c: ...host '10.199.254.2' and port '5060'. [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.199.254.2:5060 [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: = Looking for Call ID: 5baf57ce-985a0f00@10.199.254.2 (Checking From) --From tag 56cefd94af6e7238o0 --To-tag [Aug 1 10:11:12] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:12] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:12] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:12] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 1 10:11:12] DEBUG[17078] netsock2.c: Splitting '10.199.254.2:5060' into... [Aug 1 10:11:12] DEBUG[17078] netsock2.c: ...host '10.199.254.2' and port '5060'. [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 68e3d1a351c70a1b6c420fc048274f39@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:12] DEBUG[17078] acl.c: For destination '10.199.254.2', our source address is '10.199.0.1'. [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 27fd2d093bc595a71778aa8a392124c9@10.199.0.1:5060 [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.254.2:5060 [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.2:5060 [Aug 1 10:11:12] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for SIP - 878 [Aug 1 10:11:12] DEBUG[17050] chan_sip.c: Checking device state for peer 878 [Aug 1 10:11:12] DEBUG[17050] devicestate.c: Changing state for SIP/878 - state 1 (Not in use) [Aug 1 10:11:12] DEBUG[17050] devicestate.c: device 'SIP/878' state '1' [Aug 1 10:11:12] DEBUG[17092] app_queue.c: Device 'SIP/878' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 1 10:11:12] DEBUG[17051] devicestate.c: Checking if I can find provider for "Custom" - number: DND878 [Aug 1 10:11:12] DEBUG[17051] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:12] DEBUG[17051] db.c: Unable to find key 'DND878' in family 'CustomDevstate' [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: = Looking for Call ID: 27fd2d093bc595a71778aa8a392124c9@10.199.0.1:5060 (Checking To) --From tag as303b8840 --To-tag 537b35c4341c17c8i0 [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: Stopping retransmission on '27fd2d093bc595a71778aa8a392124c9@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: Destroying SIP dialog 27fd2d093bc595a71778aa8a392124c9@10.199.0.1:5060 [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: = Looking for Call ID: 2f5e687a-f1405d23@10.199.251.253 (Checking From) --From tag 3d8f436e57c21ebfo0 --To-tag [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:12] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.251.253:5060 [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:12] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[17078] chan_sip.c: Auto destroying SIP dialog 'a95d0ab7-85655122@10.199.250.253' [Aug 1 10:11:13] DEBUG[17078] chan_sip.c: Destroying SIP dialog a95d0ab7-85655122@10.199.250.253 [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[17077] chan_dahdi.c: Monitor doohicky got event No more alarm on channel 10 [Aug 1 10:11:13] NOTICE[17077] chan_dahdi.c: Alarm cleared on channel 10 [Aug 1 10:11:13] DEBUG[17077] chan_dahdi.c: Monitor doohicky got event No more alarm on channel 11 [Aug 1 10:11:13] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for DAHDI - I4/congestion [Aug 1 10:11:13] NOTICE[17077] chan_dahdi.c: Alarm cleared on channel 11 [Aug 1 10:11:13] DEBUG[17050] devicestate.c: Changing state for DAHDI/I4/congestion - state 1 (Not in use) [Aug 1 10:11:13] DEBUG[17050] devicestate.c: device 'DAHDI/I4/congestion' state '1' [Aug 1 10:11:13] NOTICE[17075] chan_dahdi.c: PRI got event: No more alarm (5) on D-channel of span 4 [Aug 1 10:11:13] DEBUG[17092] app_queue.c: Device 'DAHDI/I4/congestion' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[17078] chan_sip.c: = Looking for Call ID: c893311a-63912ab2@10.199.252.252 (Checking From) --From tag 5d33797a7a867dd2o0 --To-tag [Aug 1 10:11:13] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:13] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.252.252:5060 [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[17078] chan_sip.c: = Looking for Call ID: a2674c1d-dcd9ba2d@10.199.254.252 (Checking From) --From tag fa93e4719420cc95 --To-tag [Aug 1 10:11:13] DEBUG[17078] acl.c: For destination '10.199.254.252', our source address is '10.199.0.1'. [Aug 1 10:11:13] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:13] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for a2674c1d-dcd9ba2d@10.199.254.252 - SUBSCRIBE (No RTP) [Aug 1 10:11:13] DEBUG[17078] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Aug 1 10:11:13] DEBUG[17078] netsock2.c: Splitting '10.199.254.252:5060' into... [Aug 1 10:11:13] DEBUG[17078] netsock2.c: ...host '10.199.254.252' and port '5060'. [Aug 1 10:11:13] DEBUG[17078] chan_sip.c: build_route: Contact hop: "89" [Aug 1 10:11:13] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.199.254.252:5060 [Aug 1 10:11:13] DEBUG[17078] chan_sip.c: = Looking for Call ID: a2674c1d-dcd9ba2d@10.199.254.252 (Checking From) --From tag fa93e4719420cc95 --To-tag [Aug 1 10:11:13] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:13] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:13] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:13] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:13] DEBUG[17078] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Aug 1 10:11:13] DEBUG[17078] netsock2.c: Splitting '10.199.254.252:5060' into... [Aug 1 10:11:13] DEBUG[17078] netsock2.c: ...host '10.199.254.252' and port '5060'. [Aug 1 10:11:13] DEBUG[17078] chan_sip.c: build_route: Retaining previous route: [Aug 1 10:11:13] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 10.199.254.252:5060 [Aug 1 10:11:13] DEBUG[17078] chan_sip.c: Destroying SIP dialog a2674c1d-dcd9ba2d@10.199.254.252 [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:13] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[17078] chan_sip.c: = Looking for Call ID: 82ff0d12-cd5a3ccc@10.199.251.255 (Checking From) --From tag 3654e91abdfad064o0 --To-tag [Aug 1 10:11:14] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:14] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.251.255:5060 [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] NOTICE[17075] chan_dahdi.c: PRI got event: HDLC Abort (6) on D-channel of span 4 [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[17078] chan_sip.c: Auto destroying SIP dialog 'b3cbe77c-1770132a@10.199.254.251' [Aug 1 10:11:14] DEBUG[17078] chan_sip.c: Destroying SIP dialog b3cbe77c-1770132a@10.199.254.251 [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:14] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: = Looking for Call ID: 498df378-a90719e7@10.199.253.251 (Checking From) --From tag 6abc3064e37e21ebo0 --To-tag [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.253.251:5060 [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: = Looking for Call ID: 54022244-c32e1548@10.199.254.2 (Checking From) --From tag 56cefd94af6e7238o0 --To-tag [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.2:5060 [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: = Looking for Call ID: 21321976-86e9fba6@10.199.250.253 (Checking From) --From tag 3486b936bfb7dee6o0 --To-tag [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.250.253:5060 [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: = Looking for Call ID: bf848b91-79833907@10.199.249.255 (Checking From) --From tag da82d10c6e03b9c7o0 --To-tag [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.249.255:5060 [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: = Looking for Call ID: f181ca83-33afdfc8@10.199.254.252 (Checking From) --From tag 3f202dd187b212b5 --To-tag [Aug 1 10:11:15] DEBUG[17078] acl.c: For destination '10.199.254.252', our source address is '10.199.0.1'. [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for f181ca83-33afdfc8@10.199.254.252 - SUBSCRIBE (No RTP) [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Aug 1 10:11:15] DEBUG[17078] netsock2.c: Splitting '10.199.254.252:5060' into... [Aug 1 10:11:15] DEBUG[17078] netsock2.c: ...host '10.199.254.252' and port '5060'. [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: build_route: Contact hop: "89" [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.199.254.252:5060 [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: = Looking for Call ID: f181ca83-33afdfc8@10.199.254.252 (Checking From) --From tag 3f202dd187b212b5 --To-tag [Aug 1 10:11:15] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:15] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:15] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:15] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Aug 1 10:11:15] DEBUG[17078] netsock2.c: Splitting '10.199.254.252:5060' into... [Aug 1 10:11:15] DEBUG[17078] netsock2.c: ...host '10.199.254.252' and port '5060'. [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: build_route: Retaining previous route: [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 10.199.254.252:5060 [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Destroying SIP dialog f181ca83-33afdfc8@10.199.254.252 [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: No remote address on RTP instance '0xb60236c8' so dropping frame [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Auto destroying SIP dialog '45bf573d-a158feb2@10.199.252.252' [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Destroying SIP dialog 45bf573d-a158feb2@10.199.252.252 [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: = Looking for Call ID: 1796ae7910a60e8e2f66c2d367e9dee9@10.199.0.1:5060 (Checking To) --From tag as720b2ee6 --To-tag 6213e0932bd558cai1 [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Acked pending invite 102 [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Stopping retransmission on '1796ae7910a60e8e2f66c2d367e9dee9@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: SIP response 200 to standard invite [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Processing session-level SDP o=- 181028290 181028290 IN IP4 10.199.253.249... UNSUPPORTED. [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Aug 1 10:11:15] DEBUG[17078] netsock2.c: Splitting '10.199.253.249' into... [Aug 1 10:11:15] DEBUG[17078] netsock2.c: ...host '10.199.253.249' and port ''. [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Processing session-level SDP c=IN IP4 10.199.253.249... OK. [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Aug 1 10:11:15] DEBUG[17078] rtp_engine.c: Setting payload 8 based on m type on 0xb61b9d5c [Aug 1 10:11:15] DEBUG[17078] rtp_engine.c: Setting payload 101 based on m type on 0xb61b9d5c [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Aug 1 10:11:15] DEBUG[17078] rtp_engine.c: Unsetting payload 100 on 0xb61b9d5c [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:100 NSE/8000... UNSUPPORTED. [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Processing media-level (audio) SDP a=fmtp:100 192-193... UNSUPPORTED. [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Processing media-level (audio) SDP a=ptime:30... OK. [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Aug 1 10:11:15] DEBUG[17078] rtp_engine.c: Incorporating payload 8 on 0xb61b9d5c [Aug 1 10:11:15] DEBUG[17078] rtp_engine.c: Incorporating payload 101 on 0xb61b9d5c [Aug 1 10:11:15] DEBUG[17078] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb60236c8' [Aug 1 10:11:15] DEBUG[17078] rtp_engine.c: Copying payload 8 from 0xb61b9d5c to 0xb6023874 [Aug 1 10:11:15] DEBUG[17078] rtp_engine.c: Copying payload 101 from 0xb61b9d5c to 0xb6023874 [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: We're settling with these formats: 0x8 (alaw) [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: We have an owner, now see if we need to change this call [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Updating call counter for outgoing call [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: build_route: Contact hop: FAXTitkarsag [Aug 1 10:11:15] DEBUG[17078] netsock2.c: Splitting '10.199.253.249:5061' into... [Aug 1 10:11:15] DEBUG[17078] netsock2.c: ...host '10.199.253.249' and port '5061'. [Aug 1 10:11:15] DEBUG[17078] netsock2.c: Splitting '10.199.253.249:5061' into... [Aug 1 10:11:15] DEBUG[17078] netsock2.c: ...host '10.199.253.249' and port '5061'. [Aug 1 10:11:15] DEBUG[17078] chan_sip.c: Trying to put 'ACK sip:867' onto UDP socket destined for 10.199.253.249:5061 [Aug 1 10:11:15] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for SIP - 867 [Aug 1 10:11:15] DEBUG[17050] chan_sip.c: Checking device state for peer 867 [Aug 1 10:11:15] DEBUG[17050] devicestate.c: Changing state for SIP/867 - state 2 (In use) [Aug 1 10:11:15] DEBUG[17050] devicestate.c: device 'SIP/867' state '2' [Aug 1 10:11:15] VERBOSE[13789] app_dial.c: -- Connected line update to DAHDI/i2/502503-3ce prevented. [Aug 1 10:11:15] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for SIP - 867 [Aug 1 10:11:15] DEBUG[17050] chan_sip.c: Checking device state for peer 867 [Aug 1 10:11:15] DEBUG[17050] devicestate.c: Changing state for SIP/867 - state 2 (In use) [Aug 1 10:11:15] DEBUG[17050] devicestate.c: device 'SIP/867' state '2' [Aug 1 10:11:15] DEBUG[17092] app_queue.c: Device 'SIP/867' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Aug 1 10:11:15] VERBOSE[13789] app_dial.c: -- SIP/867-00000b7b answered DAHDI/i2/502503-3ce [Aug 1 10:11:15] DEBUG[17051] devicestate.c: Checking if I can find provider for "Custom" - number: DND867 [Aug 1 10:11:15] DEBUG[17051] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:15] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for DAHDI - i2/502503 [Aug 1 10:11:15] DEBUG[17051] db.c: Unable to find key 'DND867' in family 'CustomDevstate' [Aug 1 10:11:15] DEBUG[17051] app_queue.c: Extension '867@ext-local' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Aug 1 10:11:15] DEBUG[17050] devicestate.c: Changing state for DAHDI/i2/502503 - state 2 (In use) [Aug 1 10:11:15] DEBUG[17050] devicestate.c: device 'DAHDI/i2/502503' state '2' [Aug 1 10:11:15] DEBUG[17092] app_queue.c: Device 'SIP/867' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Aug 1 10:11:15] DEBUG[13789] chan_dahdi.c: Requested indication -1 on channel DAHDI/i2/502503-3ce [Aug 1 10:11:15] DEBUG[17051] devicestate.c: Checking if I can find provider for "Custom" - number: DND867 [Aug 1 10:11:15] DEBUG[17051] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:15] DEBUG[13789] features.c: bridge answer set, chan answer set [Aug 1 10:11:15] DEBUG[17051] db.c: Unable to find key 'DND867' in family 'CustomDevstate' [Aug 1 10:11:15] DEBUG[13789] features.c: Removing dialed interfaces datastore on SIP/867-00000b7b since we're bridging [Aug 1 10:11:15] DEBUG[13789] channel.c: Set channel DAHDI/i2/502503-3ce to read format slin [Aug 1 10:11:15] DEBUG[13789] channel.c: Set channel DAHDI/i2/502503-3ce to write format slin [Aug 1 10:11:15] DEBUG[17092] app_queue.c: Device 'DAHDI/i2/502503' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Aug 1 10:11:15] DEBUG[13789] channel.c: Set channel SIP/867-00000b7b to read format slin [Aug 1 10:11:15] DEBUG[13789] channel.c: Set channel SIP/867-00000b7b to write format slin [Aug 1 10:11:15] DEBUG[13789] chan_dahdi.c: Requested indication 20 on channel DAHDI/i2/502503-3ce [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: Setting the marker bit due to a source update [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: Ooh, format changed from unknown to alaw [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: Created smoother: format: alaw ms: 20 len: 160 [Aug 1 10:11:15] DEBUG[13789] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0xb60236c8' [Aug 1 10:11:16] DEBUG[17078] chan_sip.c: Auto destroying SIP dialog '5eda872f-5c153f93@10.199.253.251' [Aug 1 10:11:16] DEBUG[17078] chan_sip.c: Destroying SIP dialog 5eda872f-5c153f93@10.199.253.251 [Aug 1 10:11:16] DEBUG[17078] chan_sip.c: Auto destroying SIP dialog '3d0738a-71b74678@10.199.252.254' [Aug 1 10:11:16] DEBUG[17078] chan_sip.c: Destroying SIP dialog 3d0738a-71b74678@10.199.252.254 [Aug 1 10:11:16] DEBUG[17078] chan_sip.c: = Looking for Call ID: e5514ba9-b833d08f@10.199.249.254 (Checking From) --From tag d2dafc81117e1597o0 --To-tag [Aug 1 10:11:16] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:16] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.249.254:5060 [Aug 1 10:11:16] DEBUG[17078] chan_sip.c: Auto destroying SIP dialog '5ccfd041-1f09394d@10.199.252.249' [Aug 1 10:11:16] DEBUG[17078] chan_sip.c: Destroying SIP dialog 5ccfd041-1f09394d@10.199.252.249 [Aug 1 10:11:17] DEBUG[17077] chan_dahdi.c: Monitor doohicky got event Alarm on channel 10 [Aug 1 10:11:17] WARNING[17077] chan_dahdi.c: Detected alarm on channel 10: Red Alarm [Aug 1 10:11:17] DEBUG[17077] chan_dahdi.c: Monitor doohicky got event Alarm on channel 11 [Aug 1 10:11:17] WARNING[17077] chan_dahdi.c: Detected alarm on channel 11: Red Alarm [Aug 1 10:11:17] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for DAHDI - I4/congestion [Aug 1 10:11:17] DEBUG[17050] devicestate.c: Changing state for DAHDI/I4/congestion - state 5 (Unavailable) [Aug 1 10:11:17] DEBUG[17050] devicestate.c: device 'DAHDI/I4/congestion' state '5' [Aug 1 10:11:17] NOTICE[17075] chan_dahdi.c: PRI got event: Alarm (4) on D-channel of span 4 [Aug 1 10:11:17] DEBUG[17092] app_queue.c: Device 'DAHDI/I4/congestion' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [Aug 1 10:11:17] DEBUG[17078] chan_sip.c: = Looking for Call ID: ea99862-f6d8aa06@10.199.251.251 (Checking From) --From tag b406303263387476o0 --To-tag [Aug 1 10:11:17] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:17] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.251.251:5060 [Aug 1 10:11:17] DEBUG[13789] dsp.c: 1100 Hz done detected [Aug 1 10:11:17] DEBUG[13789] chan_dahdi.c: End DTMF digit: 0x66 'f' on DAHDI/i2/502503-3ce [Aug 1 10:11:17] DEBUG[13789] chan_dahdi.c: Disabling FAX tone detection on DAHDI/i2/502503-3ce after tone received [Aug 1 10:11:17] NOTICE[13789] chan_dahdi.c: Fax detected, but no fax extension [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: = Looking for Call ID: 1796ae7910a60e8e2f66c2d367e9dee9@10.199.0.1:5060 (Checking From) --From tag 6213e0932bd558cai1 --To-tag as720b2ee6 [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Aug 1 10:11:18] DEBUG[17078] netsock2.c: Splitting '10.199.253.249:5061' into... [Aug 1 10:11:18] DEBUG[17078] netsock2.c: ...host '10.199.253.249' and port '5061'. [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Processing session-level SDP o=- 181028952 181028952 IN IP4 10.199.253.249... UNSUPPORTED. [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Aug 1 10:11:18] DEBUG[17078] netsock2.c: Splitting '10.199.253.249' into... [Aug 1 10:11:18] DEBUG[17078] netsock2.c: ...host '10.199.253.249' and port ''. [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Processing session-level SDP c=IN IP4 10.199.253.249... OK. [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: FaxVersion: 0 [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Processing media-level (image) SDP a=T38FaxVersion:0... OK. [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: T38MaxBitRate: 14400 [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Processing media-level (image) SDP a=T38MaxBitRate:14400... OK. [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: RateManagement: transferredTCF [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Processing media-level (image) SDP a=T38FaxRateManagement:transferredTCF... OK. [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: MaxBufferSize:200 [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Processing media-level (image) SDP a=T38FaxMaxBuffer:200... OK. [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Overriding T38FaxMaxDatagram '200' with '400' [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: FaxMaxDatagram: 400 [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Processing media-level (image) SDP a=T38FaxMaxDatagram:200... OK. [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: UDP EC: t38UDPRedundancy [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Processing media-level (image) SDP a=T38FaxUdpEC:t38UDPRedundancy... OK. [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: T38 state changed to 2 on channel SIP/867-00000b7b [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Have T.38 but no audio, accepting offer anyway [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: SIP/867-00000b7b: This call is UP.... [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.199.253.249:5061 [Aug 1 10:11:18] DEBUG[13789] res_fax.c: SIP/867-00000b7b is attempting to negotiate T.38 but DAHDI/i2/502503-3ce does not support it [Aug 1 10:11:18] DEBUG[13789] res_fax.c: starting T.38 gateway for T.38 channel SIP/867-00000b7b and G.711 channel DAHDI/i2/502503-3ce [Aug 1 10:11:18] DEBUG[13789] res_fax.c: Requesting a new FAX session from 'Spandsp FAX Driver'. [Aug 1 10:11:18] DEBUG[13789] res_fax.c: channel 'DAHDI/i2/502503-3ce' using FAX session '1' [Aug 1 10:11:18] DEBUG[13789] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Aug 1 10:11:18] DEBUG[13789] chan_dahdi.c: Requested indication 20 on channel DAHDI/i2/502503-3ce [Aug 1 10:11:18] DEBUG[13789] chan_sip.c: T38 state changed to 3 on channel SIP/867-00000b7b [Aug 1 10:11:18] DEBUG[13789] chan_sip.c: Done building SDP. Settling with this capability: 0x0 (nothing) [Aug 1 10:11:18] DEBUG[13789] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.253.249:5061 [Aug 1 10:11:18] DEBUG[13789] chan_dahdi.c: Requested indication 24 on channel DAHDI/i2/502503-3ce [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: = Looking for Call ID: 1796ae7910a60e8e2f66c2d367e9dee9@10.199.0.1:5060 (Checking From) --From tag 6213e0932bd558cai1 --To-tag as720b2ee6 [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Stopping retransmission on '1796ae7910a60e8e2f66c2d367e9dee9@10.199.0.1:5060' of Response 101: Match Found [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: = Looking for Call ID: 82a1b8a4-b87c40d8@10.199.254.7 (Checking From) --From tag 5bd6d6cf626c40a8o0 --To-tag [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.7:5060 [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: = Looking for Call ID: add7ab47-ab0afab@10.199.251.254 (Checking From) --From tag 874c8a17a8fcdf1bo0 --To-tag [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.251.254:5060 [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Auto destroying SIP dialog 'cc6a8dca-a39f130@10.199.252.255' [Aug 1 10:11:18] DEBUG[17078] chan_sip.c: Destroying SIP dialog cc6a8dca-a39f130@10.199.252.255 [Aug 1 10:11:20] DEBUG[17078] chan_sip.c: = Looking for Call ID: 69e5b89-356e8fb@10.199.253.248 (Checking From) --From tag bba8dbf1b8423b3o0 --To-tag [Aug 1 10:11:20] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:20] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.253.248:5060 [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: = Looking for Call ID: 46a24636-640ce1ee@10.199.254.252 (Checking From) --From tag 842d00e1cf0cdae5 --To-tag [Aug 1 10:11:21] DEBUG[17078] acl.c: For destination '10.199.254.252', our source address is '10.199.0.1'. [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 46a24636-640ce1ee@10.199.254.252 - SUBSCRIBE (No RTP) [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Aug 1 10:11:21] DEBUG[17078] netsock2.c: Splitting '10.199.254.252:5060' into... [Aug 1 10:11:21] DEBUG[17078] netsock2.c: ...host '10.199.254.252' and port '5060'. [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: build_route: Contact hop: "89" [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.199.254.252:5060 [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: = Looking for Call ID: 46a24636-640ce1ee@10.199.254.252 (Checking From) --From tag 842d00e1cf0cdae5 --To-tag [Aug 1 10:11:21] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:21] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:21] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:21] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Aug 1 10:11:21] DEBUG[17078] netsock2.c: Splitting '10.199.254.252:5060' into... [Aug 1 10:11:21] DEBUG[17078] netsock2.c: ...host '10.199.254.252' and port '5060'. [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: build_route: Retaining previous route: [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 10.199.254.252:5060 [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: Destroying SIP dialog 46a24636-640ce1ee@10.199.254.252 [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: = Looking for Call ID: d33c6755-bb95713e@10.199.254.245 (Checking From) --From tag 70e79b49f0b8addao0 --To-tag [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.245:5060 [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: = Looking for Call ID: 328c1ea4-18250ac1@10.199.254.7 (Checking From) --From tag 5bd6d6cf626c40a8o0 --To-tag [Aug 1 10:11:21] DEBUG[17078] acl.c: For destination '10.199.254.7', our source address is '10.199.0.1'. [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 328c1ea4-18250ac1@10.199.254.7 - REGISTER (No RTP) [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 1 10:11:21] DEBUG[17078] netsock2.c: Splitting '10.199.254.7:5060' into... [Aug 1 10:11:21] DEBUG[17078] netsock2.c: ...host '10.199.254.7' and port '5060'. [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.199.254.7:5060 [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: = Looking for Call ID: 328c1ea4-18250ac1@10.199.254.7 (Checking From) --From tag 5bd6d6cf626c40a8o0 --To-tag [Aug 1 10:11:21] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:21] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:21] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:21] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 1 10:11:21] DEBUG[17078] netsock2.c: Splitting '10.199.254.7:5060' into... [Aug 1 10:11:21] DEBUG[17078] netsock2.c: ...host '10.199.254.7' and port '5060'. [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 2227b1f16c70552c48b061e81347fa3e@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:21] DEBUG[17078] acl.c: For destination '10.199.254.7', our source address is '10.199.0.1'. [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 4bf913491432ff74101f841a751dc8e9@10.199.0.1:5060 [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.254.7:5060 [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.7:5060 [Aug 1 10:11:21] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for SIP - 884 [Aug 1 10:11:21] DEBUG[17050] chan_sip.c: Checking device state for peer 884 [Aug 1 10:11:21] DEBUG[17050] devicestate.c: Changing state for SIP/884 - state 1 (Not in use) [Aug 1 10:11:21] DEBUG[17050] devicestate.c: device 'SIP/884' state '1' [Aug 1 10:11:21] DEBUG[17092] app_queue.c: Device 'SIP/884' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 1 10:11:21] DEBUG[17051] devicestate.c: Checking if I can find provider for "Custom" - number: DND884 [Aug 1 10:11:21] DEBUG[17051] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:21] DEBUG[17051] db.c: Unable to find key 'DND884' in family 'CustomDevstate' [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: = Looking for Call ID: 4bf913491432ff74101f841a751dc8e9@10.199.0.1:5060 (Checking To) --From tag as6e98cfdb --To-tag 9597231b7bb980cci0 [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: Stopping retransmission on '4bf913491432ff74101f841a751dc8e9@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:21] DEBUG[17078] chan_sip.c: Destroying SIP dialog 4bf913491432ff74101f841a751dc8e9@10.199.0.1:5060 [Aug 1 10:11:22] DEBUG[17078] chan_sip.c: = Looking for Call ID: d95fc224-3fce725@10.199.254.252 (Checking From) --From tag 57b4474185174805 --To-tag [Aug 1 10:11:22] DEBUG[17078] acl.c: For destination '10.199.254.252', our source address is '10.199.0.1'. [Aug 1 10:11:22] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:22] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for d95fc224-3fce725@10.199.254.252 - SUBSCRIBE (No RTP) [Aug 1 10:11:22] DEBUG[17078] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Aug 1 10:11:22] DEBUG[17078] netsock2.c: Splitting '10.199.254.252:5060' into... [Aug 1 10:11:22] DEBUG[17078] netsock2.c: ...host '10.199.254.252' and port '5060'. [Aug 1 10:11:22] DEBUG[17078] chan_sip.c: build_route: Contact hop: "89" [Aug 1 10:11:22] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.199.254.252:5060 [Aug 1 10:11:22] DEBUG[17078] chan_sip.c: = Looking for Call ID: d95fc224-3fce725@10.199.254.252 (Checking From) --From tag 57b4474185174805 --To-tag [Aug 1 10:11:22] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:22] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:22] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:22] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:22] DEBUG[17078] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Aug 1 10:11:22] DEBUG[17078] netsock2.c: Splitting '10.199.254.252:5060' into... [Aug 1 10:11:22] DEBUG[17078] netsock2.c: ...host '10.199.254.252' and port '5060'. [Aug 1 10:11:22] DEBUG[17078] chan_sip.c: build_route: Retaining previous route: [Aug 1 10:11:22] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 10.199.254.252:5060 [Aug 1 10:11:22] DEBUG[17078] chan_sip.c: Destroying SIP dialog d95fc224-3fce725@10.199.254.252 [Aug 1 10:11:22] DEBUG[17078] chan_sip.c: = Looking for Call ID: 5379a4a1-6aa2b085@10.199.253.252 (Checking From) --From tag 90193971edd3a1f5o0 --To-tag [Aug 1 10:11:22] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:22] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.253.252:5060 [Aug 1 10:11:23] DEBUG[17078] chan_sip.c: = Looking for Call ID: d165bdfa-ae250352@10.199.252.252 (Checking From) --From tag cb595c3a177bfa12o1 --To-tag [Aug 1 10:11:23] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:23] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.252.252:5061 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 1d0cd3ec38e8b6837d06ef4612d206fe@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:24] DEBUG[17078] acl.c: For destination '10.199.253.250', our source address is '10.199.0.1'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 58e313fc70e2dff930972e9d75c8c1b9@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.253.250:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 075d17bf1e7dc1bb4fbf31f247135f47@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:24] DEBUG[17078] acl.c: For destination '10.199.251.253', our source address is '10.199.0.1'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 2d46cb124c03dd686c638a6a2a4dc648@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.251.253:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 5d4843aa343cbab02317c62551c1d875@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:24] DEBUG[17078] acl.c: For destination '10.199.253.247', our source address is '10.199.0.1'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 6ff8269556eac5826cd39fd82f4ea805@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.253.247:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 1bbf4f4f13769a1c07adc4ea29eacb37@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:24] DEBUG[17078] acl.c: For destination '10.199.253.255', our source address is '10.199.0.1'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 162d6dc5141f37ca7e69e2e223339cb3@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.253.255:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: = Looking for Call ID: 6ff8269556eac5826cd39fd82f4ea805@10.199.0.1:5060 (Checking To) --From tag as343225aa --To-tag a71ee5c8c3fa4e9di0 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Stopping retransmission on '6ff8269556eac5826cd39fd82f4ea805@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 193de8c77ec7557f24b4c00357162959@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:24] DEBUG[17078] acl.c: For destination '10.199.252.251', our source address is '10.199.0.1'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 617941c70cd961b674dba3a773646452@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.252.251:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Destroying SIP dialog 6ff8269556eac5826cd39fd82f4ea805@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: = Looking for Call ID: 58e313fc70e2dff930972e9d75c8c1b9@10.199.0.1:5060 (Checking To) --From tag as1452950e --To-tag b74131c78fb0d784i0 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Stopping retransmission on '58e313fc70e2dff930972e9d75c8c1b9@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 2b85463951b65d055c3acb58766f8e03@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:24] DEBUG[17078] acl.c: For destination '10.199.254.250', our source address is '10.199.0.1'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 468b866e1430e40d67a91ed055a8d8ad@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.254.250:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 4f4500f1105ab24656459a6f6b770adb@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:24] DEBUG[17078] acl.c: For destination '10.199.254.1', our source address is '10.199.0.1'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 458efe4828e4609468aa4e6336213dc1@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.254.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Destroying SIP dialog 58e313fc70e2dff930972e9d75c8c1b9@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: = Looking for Call ID: 2d46cb124c03dd686c638a6a2a4dc648@10.199.0.1:5060 (Checking To) --From tag as78409309 --To-tag 9650d195ab620ec3i0 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Stopping retransmission on '2d46cb124c03dd686c638a6a2a4dc648@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Destroying SIP dialog 2d46cb124c03dd686c638a6a2a4dc648@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 595b41b074a9b89018e7ac88049b4049@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:24] DEBUG[17078] acl.c: For destination '10.199.253.248', our source address is '10.199.0.1'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 35195dca012490f77df816624abe791b@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.253.248:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 40dc17df00ff2d922abb377250118312@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:24] DEBUG[17078] acl.c: For destination '10.199.254.9', our source address is '10.199.0.1'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 20660ebc1de8c57754f38b3641c2bcbd@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.254.9:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: = Looking for Call ID: 162d6dc5141f37ca7e69e2e223339cb3@10.199.0.1:5060 (Checking To) --From tag as28ca5568 --To-tag c5de70d37027c3cdi0 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Stopping retransmission on '162d6dc5141f37ca7e69e2e223339cb3@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Destroying SIP dialog 162d6dc5141f37ca7e69e2e223339cb3@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: = Looking for Call ID: 468b866e1430e40d67a91ed055a8d8ad@10.199.0.1:5060 (Checking To) --From tag as12cff77e --To-tag b4955b2158163d46i0 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Stopping retransmission on '468b866e1430e40d67a91ed055a8d8ad@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Destroying SIP dialog 468b866e1430e40d67a91ed055a8d8ad@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: = Looking for Call ID: 617941c70cd961b674dba3a773646452@10.199.0.1:5060 (Checking To) --From tag as403652a2 --To-tag 251b2aecc2442d21i0 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Stopping retransmission on '617941c70cd961b674dba3a773646452@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Destroying SIP dialog 617941c70cd961b674dba3a773646452@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: = Looking for Call ID: 458efe4828e4609468aa4e6336213dc1@10.199.0.1:5060 (Checking To) --From tag as3c4daa69 --To-tag 9956b07378b388f1i0 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Stopping retransmission on '458efe4828e4609468aa4e6336213dc1@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Destroying SIP dialog 458efe4828e4609468aa4e6336213dc1@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: = Looking for Call ID: 35195dca012490f77df816624abe791b@10.199.0.1:5060 (Checking To) --From tag as3abf8b95 --To-tag 230a9749fe91e03bi0 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Stopping retransmission on '35195dca012490f77df816624abe791b@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Destroying SIP dialog 35195dca012490f77df816624abe791b@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: = Looking for Call ID: 20660ebc1de8c57754f38b3641c2bcbd@10.199.0.1:5060 (Checking To) --From tag as409ce552 --To-tag 57339b7c9a0bf2dfi0 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Stopping retransmission on '20660ebc1de8c57754f38b3641c2bcbd@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Destroying SIP dialog 20660ebc1de8c57754f38b3641c2bcbd@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 64a5b835630f61af40f2960c728ac785@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:24] DEBUG[17078] acl.c: For destination '10.199.0.81', our source address is '10.199.0.1'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 111bb3d10186d39d43b3180246e39a0f@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.0.81:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: = Looking for Call ID: adbf6d8e-c1b2f43d@10.199.253.247 (Checking From) --From tag 985b73cc60e57869o0 --To-tag [Aug 1 10:11:24] DEBUG[17078] acl.c: For destination '10.199.253.247', our source address is '10.199.0.1'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for adbf6d8e-c1b2f43d@10.199.253.247 - REGISTER (No RTP) [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 1 10:11:24] DEBUG[17078] netsock2.c: Splitting '10.199.253.247:5060' into... [Aug 1 10:11:24] DEBUG[17078] netsock2.c: ...host '10.199.253.247' and port '5060'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.199.253.247:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: = Looking for Call ID: adbf6d8e-c1b2f43d@10.199.253.247 (Checking From) --From tag 985b73cc60e57869o0 --To-tag [Aug 1 10:11:24] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:24] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:24] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:24] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 1 10:11:24] DEBUG[17078] netsock2.c: Splitting '10.199.253.247:5060' into... [Aug 1 10:11:24] DEBUG[17078] netsock2.c: ...host '10.199.253.247' and port '5060'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Store REGISTER's Contact header for call routing. [Aug 1 10:11:24] DEBUG[17078] netsock2.c: Splitting '10.199.253.247:5060' into... [Aug 1 10:11:24] DEBUG[17078] netsock2.c: ...host '10.199.253.247' and port '5060'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 52209c7e3d15765563124643752f4911@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:24] DEBUG[17078] acl.c: For destination '10.199.253.247', our source address is '10.199.0.1'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 40fc2b4668830aa77ace172901b73665@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.253.247:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.253.247:5060 [Aug 1 10:11:24] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for SIP - 837 [Aug 1 10:11:24] DEBUG[17050] chan_sip.c: Checking device state for peer 837 [Aug 1 10:11:24] DEBUG[17050] devicestate.c: Changing state for SIP/837 - state 1 (Not in use) [Aug 1 10:11:24] DEBUG[17050] devicestate.c: device 'SIP/837' state '1' [Aug 1 10:11:24] DEBUG[17092] app_queue.c: Device 'SIP/837' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 1 10:11:24] DEBUG[17051] devicestate.c: Checking if I can find provider for "Custom" - number: DND837 [Aug 1 10:11:24] DEBUG[17051] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:24] DEBUG[17051] db.c: Unable to find key 'DND837' in family 'CustomDevstate' [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: = Looking for Call ID: 40fc2b4668830aa77ace172901b73665@10.199.0.1:5060 (Checking To) --From tag as22995952 --To-tag a71ee5c8c3fa4e9di0 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Stopping retransmission on '40fc2b4668830aa77ace172901b73665@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Destroying SIP dialog 40fc2b4668830aa77ace172901b73665@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 6e862085788e74a060c4208e7db338df@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:24] DEBUG[17078] acl.c: For destination '10.199.254.0', our source address is '10.199.0.1'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 2f93c5ad6172e45623bcd7ed304fb5b8@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.254.0:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: = Looking for Call ID: 2f93c5ad6172e45623bcd7ed304fb5b8@10.199.0.1:5060 (Checking To) --From tag as5e3fab9e --To-tag ec43abf57dd5f761i0 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Stopping retransmission on '2f93c5ad6172e45623bcd7ed304fb5b8@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Destroying SIP dialog 2f93c5ad6172e45623bcd7ed304fb5b8@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 451ecf75488c56a03b5ea8db1e76ad87@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:24] DEBUG[17078] acl.c: For destination '10.199.0.81', our source address is '10.199.0.1'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 612a882d7755cd63259ae29f6dd61f2b@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.0.81:5062 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: = Looking for Call ID: 111bb3d10186d39d43b3180246e39a0f@10.199.0.1:5060 (Checking To) --From tag as1a3c8c2f --To-tag 08ea9f70 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Stopping retransmission on '111bb3d10186d39d43b3180246e39a0f@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Destroying SIP dialog 111bb3d10186d39d43b3180246e39a0f@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Auto destroying SIP dialog 'b7b16ad5-72383ff6@10.199.254.245' [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Destroying SIP dialog b7b16ad5-72383ff6@10.199.254.245 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: = Looking for Call ID: 612a882d7755cd63259ae29f6dd61f2b@10.199.0.1:5060 (Checking To) --From tag as7b719aa5 --To-tag 638976a2 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Stopping retransmission on '612a882d7755cd63259ae29f6dd61f2b@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Destroying SIP dialog 612a882d7755cd63259ae29f6dd61f2b@10.199.0.1:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 25bbccd83243d2a842267c8250881fe0@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:24] DEBUG[17078] acl.c: For destination '109.69.119.16', our source address is '192.168.1.200'. [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.1.200:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 69920bd0387d4cd76eec73cf09cea067@192.168.1.200:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 109.69.119.16:5060 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: = Looking for Call ID: 69920bd0387d4cd76eec73cf09cea067@192.168.1.200:5060 (Checking To) --From tag as3bac1b3a --To-tag f11cc33e4c3e69d0eea5e87b80848bfd.f3f0 [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Stopping retransmission on '69920bd0387d4cd76eec73cf09cea067@192.168.1.200:5060' of Request 102: Match Found [Aug 1 10:11:24] DEBUG[17078] chan_sip.c: Destroying SIP dialog 69920bd0387d4cd76eec73cf09cea067@192.168.1.200:5060 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 2a037e01487bc00c73b7759a42a43674@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:25] DEBUG[17078] acl.c: For destination '10.199.254.255', our source address is '10.199.0.1'. [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 7acc023d2cdf5868706126e2527488b5@10.199.0.1:5060 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.254.255:5060 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 7d446b0062c3275302ea51de75c05d15@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:25] DEBUG[17078] acl.c: For destination '10.199.251.254', our source address is '10.199.0.1'. [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 70b79da91738793379ce313858a97f4d@10.199.0.1:5060 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.251.254:5060 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: = Looking for Call ID: 7acc023d2cdf5868706126e2527488b5@10.199.0.1:5060 (Checking To) --From tag as0c45ab94 --To-tag cee5da9d69855c84i0 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Stopping retransmission on '7acc023d2cdf5868706126e2527488b5@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Destroying SIP dialog 7acc023d2cdf5868706126e2527488b5@10.199.0.1:5060 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: = Looking for Call ID: 70b79da91738793379ce313858a97f4d@10.199.0.1:5060 (Checking To) --From tag as65bb2e0f --To-tag 92672c7f0a48e2bi0 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Stopping retransmission on '70b79da91738793379ce313858a97f4d@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Destroying SIP dialog 70b79da91738793379ce313858a97f4d@10.199.0.1:5060 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: = Looking for Call ID: 67ded6c2-d64d8e1a@10.199.254.250 (Checking From) --From tag 8e87b965f22bd3d2o0 --To-tag [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.250:5060 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: = Looking for Call ID: a0f9c329-8a19a784@10.199.254.3 (Checking From) --From tag fbc23b856ed62ad8o0 --To-tag [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.3:5060 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: = Looking for Call ID: 34118faf-62d5d2ca@10.199.253.254 (Checking From) --From tag cec7bf0b6a280b1eo0 --To-tag [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.253.254:5060 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 6f5e17045b715fde72d14e986ca57f96@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:25] DEBUG[17078] acl.c: For destination '10.199.252.250', our source address is '10.199.0.1'. [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 65e57a1b4cc30a4c107b3e730c880011@10.199.0.1:5060 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.252.250:5060 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: = Looking for Call ID: 65e57a1b4cc30a4c107b3e730c880011@10.199.0.1:5060 (Checking To) --From tag as5317f181 --To-tag 254582674437bf65i0 [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Stopping retransmission on '65e57a1b4cc30a4c107b3e730c880011@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:25] DEBUG[17078] chan_sip.c: Destroying SIP dialog 65e57a1b4cc30a4c107b3e730c880011@10.199.0.1:5060 [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: = Looking for Call ID: 7bc5c072-16e428b4@10.199.254.255 (Checking From) --From tag 3ed9ebc9a0b69d48o0 --To-tag [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.255:5060 [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: = Looking for Call ID: 40743d76-41ee2bd5@10.199.254.0 (Checking From) --From tag 9b5442e515eccd31o0 --To-tag [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.0:5060 [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: = Looking for Call ID: 3722f441-7230a6e8@10.199.254.254 (Checking From) --From tag 670dd78d31fc3c0co0 --To-tag [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.254:5060 [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: = Looking for Call ID: d44ace13-15c5078d@10.199.253.255 (Checking From) --From tag aeb0fd1b2cd96425o0 --To-tag [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.253.255:5060 [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 1bebbdfc3a9f45656665634868a7f943@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:26] DEBUG[17078] acl.c: For destination '10.199.249.255', our source address is '10.199.0.1'. [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 6e02883b4372924149cf22db1af754f9@10.199.0.1:5060 [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.249.255:5060 [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: = Looking for Call ID: 6e02883b4372924149cf22db1af754f9@10.199.0.1:5060 (Checking To) --From tag as29426d92 --To-tag 1965b230c137aaf3i0 [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Stopping retransmission on '6e02883b4372924149cf22db1af754f9@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Destroying SIP dialog 6e02883b4372924149cf22db1af754f9@10.199.0.1:5060 [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: = Looking for Call ID: 8da0ca43-be33c87a@10.199.254.253 (Checking From) --From tag 469e1a5f979b570eo0 --To-tag [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.253:5060 [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: = Looking for Call ID: 9375a868-28016958@10.199.253.250 (Checking From) --From tag 48aca4eb4ea55eb0o0 --To-tag [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.253.250:5060 [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 57c9421b643c221a12a2f6ac341d7479@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:26] DEBUG[17078] acl.c: For destination '10.199.251.252', our source address is '10.199.0.1'. [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 2bfaa8c431bd8875364561183eafb859@10.199.0.1:5060 [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.251.252:5060 [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: = Looking for Call ID: 2bfaa8c431bd8875364561183eafb859@10.199.0.1:5060 (Checking To) --From tag as71e7d072 --To-tag 2c02300658b6fa3i0 [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Stopping retransmission on '2bfaa8c431bd8875364561183eafb859@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:26] DEBUG[17078] chan_sip.c: Destroying SIP dialog 2bfaa8c431bd8875364561183eafb859@10.199.0.1:5060 [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 4661c6462b5173d120b199386931c84d@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:27] DEBUG[17078] acl.c: For destination '10.199.253.254', our source address is '10.199.0.1'. [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 13ed23897014cb0429e85e6b6dd5474b@10.199.0.1:5060 [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.253.254:5060 [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: = Looking for Call ID: 13ed23897014cb0429e85e6b6dd5474b@10.199.0.1:5060 (Checking To) --From tag as26871ea9 --To-tag 92973b4f77d31baai0 [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: Stopping retransmission on '13ed23897014cb0429e85e6b6dd5474b@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: Destroying SIP dialog 13ed23897014cb0429e85e6b6dd5474b@10.199.0.1:5060 [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: = Looking for Call ID: fe44ea93-fe7d9aaf@10.199.253.253 (Checking From) --From tag 131eae2e351bb3cfo0 --To-tag [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.253.253:5060 [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: = Looking for Call ID: 75cff3a8-4efd8891@10.199.252.252 (Checking From) --From tag 6d41af3a40f7c320 --To-tag [Aug 1 10:11:27] DEBUG[17078] acl.c: For destination '10.199.252.252', our source address is '10.199.0.1'. [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 75cff3a8-4efd8891@10.199.252.252 - SUBSCRIBE (No RTP) [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Aug 1 10:11:27] DEBUG[17078] netsock2.c: Splitting '10.199.252.252:5060' into... [Aug 1 10:11:27] DEBUG[17078] netsock2.c: ...host '10.199.252.252' and port '5060'. [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: build_route: Contact hop: "49" [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.199.252.252:5060 [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: = Looking for Call ID: 75cff3a8-4efd8891@10.199.252.252 (Checking From) --From tag 6d41af3a40f7c320 --To-tag [Aug 1 10:11:27] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:27] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:27] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:27] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Aug 1 10:11:27] DEBUG[17078] netsock2.c: Splitting '10.199.252.252:5060' into... [Aug 1 10:11:27] DEBUG[17078] netsock2.c: ...host '10.199.252.252' and port '5060'. [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: build_route: Retaining previous route: [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 10.199.252.252:5060 [Aug 1 10:11:27] DEBUG[17078] chan_sip.c: Destroying SIP dialog 75cff3a8-4efd8891@10.199.252.252 [Aug 1 10:11:28] DEBUG[17078] chan_sip.c: = Looking for Call ID: f80b7f1-e82dfc04@10.199.254.5 (Checking From) --From tag 13c03c7d952b60e8o0 --To-tag [Aug 1 10:11:28] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:28] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.5:5060 [Aug 1 10:11:28] DEBUG[17078] chan_sip.c: = Looking for Call ID: 760a7c56-5e41f622@10.199.254.251 (Checking From) --From tag 930f6d46946039f2o0 --To-tag [Aug 1 10:11:28] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:28] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.251:5060 [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: = Looking for Call ID: 65562e07-7249fa30@10.199.252.252 (Checking From) --From tag 13e8bc1216645c28 --To-tag [Aug 1 10:11:29] DEBUG[17078] acl.c: For destination '10.199.252.252', our source address is '10.199.0.1'. [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 65562e07-7249fa30@10.199.252.252 - SUBSCRIBE (No RTP) [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Aug 1 10:11:29] DEBUG[17078] netsock2.c: Splitting '10.199.252.252:5060' into... [Aug 1 10:11:29] DEBUG[17078] netsock2.c: ...host '10.199.252.252' and port '5060'. [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: build_route: Contact hop: "49" [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.199.252.252:5060 [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: = Looking for Call ID: 65562e07-7249fa30@10.199.252.252 (Checking From) --From tag 13e8bc1216645c28 --To-tag [Aug 1 10:11:29] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:29] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:29] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:29] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Aug 1 10:11:29] DEBUG[17078] netsock2.c: Splitting '10.199.252.252:5060' into... [Aug 1 10:11:29] DEBUG[17078] netsock2.c: ...host '10.199.252.252' and port '5060'. [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: build_route: Retaining previous route: [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 10.199.252.252:5060 [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: Destroying SIP dialog 65562e07-7249fa30@10.199.252.252 [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: = Looking for Call ID: e884a81c-a74d4d35@10.199.252.250 (Checking From) --From tag 3dcb767fe2609a2do0 --To-tag [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.252.250:5060 [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: = Looking for Call ID: 87b93c0b-ec40a428@10.199.252.252 (Checking From) --From tag fbd8d72222f47c58 --To-tag [Aug 1 10:11:29] DEBUG[17078] acl.c: For destination '10.199.252.252', our source address is '10.199.0.1'. [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 87b93c0b-ec40a428@10.199.252.252 - SUBSCRIBE (No RTP) [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Aug 1 10:11:29] DEBUG[17078] netsock2.c: Splitting '10.199.252.252:5060' into... [Aug 1 10:11:29] DEBUG[17078] netsock2.c: ...host '10.199.252.252' and port '5060'. [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: build_route: Contact hop: "49" [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.199.252.252:5060 [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: = Looking for Call ID: 87b93c0b-ec40a428@10.199.252.252 (Checking From) --From tag fbd8d72222f47c58 --To-tag [Aug 1 10:11:29] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:29] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:29] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:29] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Aug 1 10:11:29] DEBUG[17078] netsock2.c: Splitting '10.199.252.252:5060' into... [Aug 1 10:11:29] DEBUG[17078] netsock2.c: ...host '10.199.252.252' and port '5060'. [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: build_route: Retaining previous route: [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 10.199.252.252:5060 [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: Destroying SIP dialog 87b93c0b-ec40a428@10.199.252.252 [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 7aeabc8b60e852971f09dc636b519145@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:29] DEBUG[17078] acl.c: For destination '10.199.254.3', our source address is '10.199.0.1'. [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 56a1f7894233d050001c8147500050c3@10.199.0.1:5060 [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.254.3:5060 [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: = Looking for Call ID: 56a1f7894233d050001c8147500050c3@10.199.0.1:5060 (Checking To) --From tag as0bcfeda7 --To-tag 984f86c972c5b864i0 [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: Stopping retransmission on '56a1f7894233d050001c8147500050c3@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:29] DEBUG[17078] chan_sip.c: Destroying SIP dialog 56a1f7894233d050001c8147500050c3@10.199.0.1:5060 [Aug 1 10:11:30] DEBUG[17078] chan_sip.c: Auto destroying SIP dialog '5c151705-db750146@10.199.254.253' [Aug 1 10:11:30] DEBUG[17078] chan_sip.c: Destroying SIP dialog 5c151705-db750146@10.199.254.253 [Aug 1 10:11:30] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 2db4e4b6463b844c3b56970e7e73f419@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:30] DEBUG[17078] acl.c: For destination '10.199.253.253', our source address is '10.199.0.1'. [Aug 1 10:11:30] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:30] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 00a65afb59fb30df6c35916111108477@10.199.0.1:5060 [Aug 1 10:11:30] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.253.253:5060 [Aug 1 10:11:30] DEBUG[17078] chan_sip.c: = Looking for Call ID: 00a65afb59fb30df6c35916111108477@10.199.0.1:5060 (Checking To) --From tag as36fce7b1 --To-tag bff598dace6be913i0 [Aug 1 10:11:30] DEBUG[17078] chan_sip.c: Stopping retransmission on '00a65afb59fb30df6c35916111108477@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:30] DEBUG[17078] chan_sip.c: Destroying SIP dialog 00a65afb59fb30df6c35916111108477@10.199.0.1:5060 [Aug 1 10:11:30] DEBUG[17078] chan_sip.c: Auto destroying SIP dialog 'fe8ad4f-9c604f80@10.199.254.5' [Aug 1 10:11:30] DEBUG[17078] chan_sip.c: Destroying SIP dialog fe8ad4f-9c604f80@10.199.254.5 [Aug 1 10:11:30] DEBUG[17078] chan_sip.c: Auto destroying SIP dialog '51c70ff3-1e32ad3a@10.199.254.252' [Aug 1 10:11:30] DEBUG[17078] chan_sip.c: Destroying SIP dialog 51c70ff3-1e32ad3a@10.199.254.252 [Aug 1 10:11:31] DEBUG[17078] chan_sip.c: = Looking for Call ID: 81f46ef4-94f87217@10.199.251.253 (Checking From) --From tag 3d8f436e57c21ebfo0 --To-tag [Aug 1 10:11:31] DEBUG[17078] acl.c: For destination '10.199.251.253', our source address is '10.199.0.1'. [Aug 1 10:11:31] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:31] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 81f46ef4-94f87217@10.199.251.253 - REGISTER (No RTP) [Aug 1 10:11:31] DEBUG[17078] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 1 10:11:31] DEBUG[17078] netsock2.c: Splitting '10.199.251.253:5060' into... [Aug 1 10:11:31] DEBUG[17078] netsock2.c: ...host '10.199.251.253' and port '5060'. [Aug 1 10:11:31] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.199.251.253:5060 [Aug 1 10:11:31] DEBUG[17077] chan_dahdi.c: Monitor doohicky got event No more alarm on channel 7 [Aug 1 10:11:31] NOTICE[17077] chan_dahdi.c: Alarm cleared on channel 7 [Aug 1 10:11:31] DEBUG[17077] chan_dahdi.c: Monitor doohicky got event No more alarm on channel 8 [Aug 1 10:11:31] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for DAHDI - I3/congestion [Aug 1 10:11:31] NOTICE[17077] chan_dahdi.c: Alarm cleared on channel 8 [Aug 1 10:11:31] DEBUG[17050] devicestate.c: Changing state for DAHDI/I3/congestion - state 1 (Not in use) [Aug 1 10:11:31] DEBUG[17050] devicestate.c: device 'DAHDI/I3/congestion' state '1' [Aug 1 10:11:31] DEBUG[17092] app_queue.c: Device 'DAHDI/I3/congestion' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 1 10:11:31] NOTICE[17074] chan_dahdi.c: PRI got event: No more alarm (5) on D-channel of span 3 [Aug 1 10:11:31] DEBUG[17078] chan_sip.c: = Looking for Call ID: 81f46ef4-94f87217@10.199.251.253 (Checking From) --From tag 3d8f436e57c21ebfo0 --To-tag [Aug 1 10:11:31] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:31] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:31] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:31] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:31] DEBUG[17078] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 1 10:11:31] DEBUG[17078] netsock2.c: Splitting '10.199.251.253:5060' into... [Aug 1 10:11:31] DEBUG[17078] netsock2.c: ...host '10.199.251.253' and port '5060'. [Aug 1 10:11:31] DEBUG[17078] chan_sip.c: Store REGISTER's Contact header for call routing. [Aug 1 10:11:31] DEBUG[17078] netsock2.c: Splitting '10.199.251.253:5060' into... [Aug 1 10:11:31] DEBUG[17078] netsock2.c: ...host '10.199.251.253' and port '5060'. [Aug 1 10:11:31] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 2724b7a24d2f80037ee851d746b68ddd@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:31] DEBUG[17078] acl.c: For destination '10.199.251.253', our source address is '10.199.0.1'. [Aug 1 10:11:31] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:31] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 42bcb66269dcc5495d8f684260d03432@10.199.0.1:5060 [Aug 1 10:11:31] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.251.253:5060 [Aug 1 10:11:31] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.251.253:5060 [Aug 1 10:11:31] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for SIP - 835 [Aug 1 10:11:31] DEBUG[17050] chan_sip.c: Checking device state for peer 835 [Aug 1 10:11:31] DEBUG[17050] devicestate.c: Changing state for SIP/835 - state 1 (Not in use) [Aug 1 10:11:31] DEBUG[17050] devicestate.c: device 'SIP/835' state '1' [Aug 1 10:11:31] DEBUG[17092] app_queue.c: Device 'SIP/835' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 1 10:11:31] DEBUG[17051] devicestate.c: Checking if I can find provider for "Custom" - number: DND835 [Aug 1 10:11:31] DEBUG[17051] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:31] DEBUG[17051] db.c: Unable to find key 'DND835' in family 'CustomDevstate' [Aug 1 10:11:31] DEBUG[17078] chan_sip.c: = Looking for Call ID: 42bcb66269dcc5495d8f684260d03432@10.199.0.1:5060 (Checking To) --From tag as32bbce16 --To-tag 9650d195ab620ec3i0 [Aug 1 10:11:31] DEBUG[17078] chan_sip.c: Stopping retransmission on '42bcb66269dcc5495d8f684260d03432@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:31] DEBUG[17078] chan_sip.c: Destroying SIP dialog 42bcb66269dcc5495d8f684260d03432@10.199.0.1:5060 [Aug 1 10:11:32] NOTICE[17074] chan_dahdi.c: PRI got event: HDLC Abort (6) on D-channel of span 3 [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 44461a034028d4476b94720671b83ff9@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:32] DEBUG[17078] acl.c: For destination '10.199.249.254', our source address is '10.199.0.1'. [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 481227d871aca39e2bef28d02a0e066e@10.199.0.1:5060 [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.249.254:5060 [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: = Looking for Call ID: 481227d871aca39e2bef28d02a0e066e@10.199.0.1:5060 (Checking To) --From tag as12abed5d --To-tag fb09ee49bf428e6fi0 [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: Stopping retransmission on '481227d871aca39e2bef28d02a0e066e@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: Destroying SIP dialog 481227d871aca39e2bef28d02a0e066e@10.199.0.1:5060 [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: = Looking for Call ID: f9a026fd-ff88718c@10.199.254.9 (Checking From) --From tag b1134ad81042ab33o0 --To-tag [Aug 1 10:11:32] DEBUG[17078] acl.c: For destination '10.199.254.9', our source address is '10.199.0.1'. [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for f9a026fd-ff88718c@10.199.254.9 - REGISTER (No RTP) [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 1 10:11:32] DEBUG[17078] netsock2.c: Splitting '10.199.254.9:5060' into... [Aug 1 10:11:32] DEBUG[17078] netsock2.c: ...host '10.199.254.9' and port '5060'. [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.199.254.9:5060 [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: = Looking for Call ID: f9a026fd-ff88718c@10.199.254.9 (Checking From) --From tag b1134ad81042ab33o0 --To-tag [Aug 1 10:11:32] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:32] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:32] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:32] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 1 10:11:32] DEBUG[17078] netsock2.c: Splitting '10.199.254.9:5060' into... [Aug 1 10:11:32] DEBUG[17078] netsock2.c: ...host '10.199.254.9' and port '5060'. [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: Store REGISTER's Contact header for call routing. [Aug 1 10:11:32] DEBUG[17078] netsock2.c: Splitting '10.199.254.9:5060' into... [Aug 1 10:11:32] DEBUG[17078] netsock2.c: ...host '10.199.254.9' and port '5060'. [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 1db4a4c921d50c5c3ccf34311aa99d79@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:32] DEBUG[17078] acl.c: For destination '10.199.254.9', our source address is '10.199.0.1'. [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 59214688686b519408ed33a32f00d030@10.199.0.1:5060 [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.254.9:5060 [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.9:5060 [Aug 1 10:11:32] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for SIP - 862 [Aug 1 10:11:32] DEBUG[17050] chan_sip.c: Checking device state for peer 862 [Aug 1 10:11:32] DEBUG[17050] devicestate.c: Changing state for SIP/862 - state 1 (Not in use) [Aug 1 10:11:32] DEBUG[17050] devicestate.c: device 'SIP/862' state '1' [Aug 1 10:11:32] DEBUG[17092] app_queue.c: Device 'SIP/862' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 1 10:11:32] DEBUG[17051] devicestate.c: Checking if I can find provider for "Custom" - number: DND862 [Aug 1 10:11:32] DEBUG[17051] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:32] DEBUG[17051] db.c: Unable to find key 'DND862' in family 'CustomDevstate' [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: = Looking for Call ID: 59214688686b519408ed33a32f00d030@10.199.0.1:5060 (Checking To) --From tag as6f4b51bc --To-tag 57339b7c9a0bf2dfi0 [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: Stopping retransmission on '59214688686b519408ed33a32f00d030@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:32] DEBUG[17078] chan_sip.c: Destroying SIP dialog 59214688686b519408ed33a32f00d030@10.199.0.1:5060 [Aug 1 10:11:33] DEBUG[17078] chan_sip.c: = Looking for Call ID: e5fb6419-50e2fc81@10.199.253.247 (Checking From) --From tag 985b73cc60e57869o0 --To-tag [Aug 1 10:11:33] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:33] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.253.247:5060 [Aug 1 10:11:33] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 7e6c00aa53edfa833e204f552f0241c2@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:33] DEBUG[17078] acl.c: For destination '10.199.254.4', our source address is '10.199.0.1'. [Aug 1 10:11:33] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:33] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 708b72a62202bdb11e30e08543978a6d@10.199.0.1:5060 [Aug 1 10:11:33] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.254.4:5060 [Aug 1 10:11:33] DEBUG[17078] chan_sip.c: = Looking for Call ID: 708b72a62202bdb11e30e08543978a6d@10.199.0.1:5060 (Checking To) --From tag as350ec09c --To-tag 1f5b872893d71f1di0 [Aug 1 10:11:33] DEBUG[17078] chan_sip.c: Stopping retransmission on '708b72a62202bdb11e30e08543978a6d@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:33] DEBUG[17078] chan_sip.c: Destroying SIP dialog 708b72a62202bdb11e30e08543978a6d@10.199.0.1:5060 [Aug 1 10:11:33] DEBUG[17078] chan_sip.c: = Looking for Call ID: f8d480e7-ec90d0eb@10.199.253.249 (Checking From) --From tag 4ac87c7759ba8a9bo0 --To-tag [Aug 1 10:11:33] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:33] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.253.249:5060 [Aug 1 10:11:33] DEBUG[17078] chan_sip.c: = Looking for Call ID: da2f20b7-79ca335b@10.199.253.249 (Checking From) --From tag ad5e8d9742a6abfbo1 --To-tag [Aug 1 10:11:33] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:33] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.253.249:5061 [Aug 1 10:11:34] DEBUG[17078] chan_sip.c: = Looking for Call ID: 9739106-2ce85d6c@10.199.252.252 (Checking From) --From tag 851c9dca12af25d0 --To-tag [Aug 1 10:11:34] DEBUG[17078] acl.c: For destination '10.199.252.252', our source address is '10.199.0.1'. [Aug 1 10:11:34] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:34] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 9739106-2ce85d6c@10.199.252.252 - SUBSCRIBE (No RTP) [Aug 1 10:11:34] DEBUG[17078] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Aug 1 10:11:34] DEBUG[17078] netsock2.c: Splitting '10.199.252.252:5060' into... [Aug 1 10:11:34] DEBUG[17078] netsock2.c: ...host '10.199.252.252' and port '5060'. [Aug 1 10:11:34] DEBUG[17078] chan_sip.c: build_route: Contact hop: "49" [Aug 1 10:11:34] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.199.252.252:5060 [Aug 1 10:11:34] DEBUG[17078] chan_sip.c: = Looking for Call ID: 9739106-2ce85d6c@10.199.252.252 (Checking From) --From tag 851c9dca12af25d0 --To-tag [Aug 1 10:11:34] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:34] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:34] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:34] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:34] DEBUG[17078] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Aug 1 10:11:34] DEBUG[17078] netsock2.c: Splitting '10.199.252.252:5060' into... [Aug 1 10:11:34] DEBUG[17078] netsock2.c: ...host '10.199.252.252' and port '5060'. [Aug 1 10:11:34] DEBUG[17078] chan_sip.c: build_route: Retaining previous route: [Aug 1 10:11:34] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 404' onto UDP socket destined for 10.199.252.252:5060 [Aug 1 10:11:34] DEBUG[17078] chan_sip.c: Destroying SIP dialog 9739106-2ce85d6c@10.199.252.252 [Aug 1 10:11:34] NOTICE[17074] chan_dahdi.c: PRI got event: Alarm (4) on D-channel of span 3 [Aug 1 10:11:34] DEBUG[17077] chan_dahdi.c: Monitor doohicky got event Alarm on channel 7 [Aug 1 10:11:34] WARNING[17077] chan_dahdi.c: Detected alarm on channel 7: Red Alarm [Aug 1 10:11:34] DEBUG[17077] chan_dahdi.c: Monitor doohicky got event Alarm on channel 8 [Aug 1 10:11:34] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for DAHDI - I3/congestion [Aug 1 10:11:34] WARNING[17077] chan_dahdi.c: Detected alarm on channel 8: Red Alarm [Aug 1 10:11:34] DEBUG[17050] devicestate.c: Changing state for DAHDI/I3/congestion - state 5 (Unavailable) [Aug 1 10:11:34] DEBUG[17050] devicestate.c: device 'DAHDI/I3/congestion' state '5' [Aug 1 10:11:34] DEBUG[17092] app_queue.c: Device 'DAHDI/I3/congestion' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [Aug 1 10:11:35] DEBUG[17078] chan_sip.c: = Looking for Call ID: 9801860-e9cf9c3@10.199.251.252 (Checking From) --From tag b09a535c7fa19af7o0 --To-tag [Aug 1 10:11:35] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:35] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.251.252:5060 [Aug 1 10:11:35] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 255c69c025cafb596344515507a7d73c@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:35] DEBUG[17078] acl.c: For destination '10.199.251.255', our source address is '10.199.0.1'. [Aug 1 10:11:35] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:35] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 6e93f03b2f0eb3600729835b67150efc@10.199.0.1:5060 [Aug 1 10:11:35] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.251.255:5060 [Aug 1 10:11:35] DEBUG[17078] chan_sip.c: = Looking for Call ID: 6e93f03b2f0eb3600729835b67150efc@10.199.0.1:5060 (Checking To) --From tag as4af1d80b --To-tag 235927d246e8e10ci0 [Aug 1 10:11:35] DEBUG[17078] chan_sip.c: Stopping retransmission on '6e93f03b2f0eb3600729835b67150efc@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:35] DEBUG[17078] chan_sip.c: Destroying SIP dialog 6e93f03b2f0eb3600729835b67150efc@10.199.0.1:5060 [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: = Looking for Call ID: 2a2deeed-145bcaa1@10.199.254.0 (Checking From) --From tag 9b5442e515eccd31o0 --To-tag [Aug 1 10:11:36] DEBUG[17078] acl.c: For destination '10.199.254.0', our source address is '10.199.0.1'. [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 2a2deeed-145bcaa1@10.199.254.0 - REGISTER (No RTP) [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 1 10:11:36] DEBUG[17078] netsock2.c: Splitting '10.199.254.0:5060' into... [Aug 1 10:11:36] DEBUG[17078] netsock2.c: ...host '10.199.254.0' and port '5060'. [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.199.254.0:5060 [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: = Looking for Call ID: 2a2deeed-145bcaa1@10.199.254.0 (Checking From) --From tag 9b5442e515eccd31o0 --To-tag [Aug 1 10:11:36] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:36] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:36] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:36] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 1 10:11:36] DEBUG[17078] netsock2.c: Splitting '10.199.254.0:5060' into... [Aug 1 10:11:36] DEBUG[17078] netsock2.c: ...host '10.199.254.0' and port '5060'. [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 6f864d323acbd6936050f93725223b01@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:36] DEBUG[17078] acl.c: For destination '10.199.254.0', our source address is '10.199.0.1'. [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 1b16a9d37fd1c1dd72be8c7276fa205f@10.199.0.1:5060 [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.254.0:5060 [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.0:5060 [Aug 1 10:11:36] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for SIP - 880 [Aug 1 10:11:36] DEBUG[17050] chan_sip.c: Checking device state for peer 880 [Aug 1 10:11:36] DEBUG[17050] devicestate.c: Changing state for SIP/880 - state 1 (Not in use) [Aug 1 10:11:36] DEBUG[17050] devicestate.c: device 'SIP/880' state '1' [Aug 1 10:11:36] DEBUG[17092] app_queue.c: Device 'SIP/880' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 1 10:11:36] DEBUG[17051] devicestate.c: Checking if I can find provider for "Custom" - number: DND880 [Aug 1 10:11:36] DEBUG[17051] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:36] DEBUG[17051] db.c: Unable to find key 'DND880' in family 'CustomDevstate' [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: = Looking for Call ID: 1b16a9d37fd1c1dd72be8c7276fa205f@10.199.0.1:5060 (Checking To) --From tag as55aa01ac --To-tag ec43abf57dd5f761i0 [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Stopping retransmission on '1b16a9d37fd1c1dd72be8c7276fa205f@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Destroying SIP dialog 1b16a9d37fd1c1dd72be8c7276fa205f@10.199.0.1:5060 [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 795f171b2c09893a4f07ca9571c785e2@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:36] DEBUG[17078] acl.c: For destination '10.199.251.251', our source address is '10.199.0.1'. [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 31de7d6e19d3c212361ab7653faeb6c6@10.199.0.1:5060 [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.251.251:5060 [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: = Looking for Call ID: 31de7d6e19d3c212361ab7653faeb6c6@10.199.0.1:5060 (Checking To) --From tag as758c9da4 --To-tag 11b6f7e2a5ed086i0 [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Stopping retransmission on '31de7d6e19d3c212361ab7653faeb6c6@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Destroying SIP dialog 31de7d6e19d3c212361ab7653faeb6c6@10.199.0.1:5060 [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 4a5321ce3a328732379e50ee78a9fbdf@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:36] DEBUG[17078] acl.c: For destination '10.199.254.254', our source address is '10.199.0.1'. [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 48c05dd119246c5f53c99a7d458c033c@10.199.0.1:5060 [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.254.254:5060 [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: = Looking for Call ID: 48c05dd119246c5f53c99a7d458c033c@10.199.0.1:5060 (Checking To) --From tag as099ebc1b --To-tag 536d8a61f2ea0748i0 [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Stopping retransmission on '48c05dd119246c5f53c99a7d458c033c@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:36] DEBUG[17078] chan_sip.c: Destroying SIP dialog 48c05dd119246c5f53c99a7d458c033c@10.199.0.1:5060 [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 109a37f32ba3e4bd35424e00255d0c81@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:37] DEBUG[17078] acl.c: For destination '10.199.252.252', our source address is '10.199.0.1'. [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 7ae000c60ee67b7a4e7e8e1668d2b670@10.199.0.1:5060 [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.252.252:5061 [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: = Looking for Call ID: 7ae000c60ee67b7a4e7e8e1668d2b670@10.199.0.1:5060 (Checking To) --From tag as78123269 --To-tag 36ab855a451ae372i1 [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Stopping retransmission on '7ae000c60ee67b7a4e7e8e1668d2b670@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Destroying SIP dialog 7ae000c60ee67b7a4e7e8e1668d2b670@10.199.0.1:5060 [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 14ed963761ee57a446136846168bb0be@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:37] DEBUG[17078] acl.c: For destination '10.199.253.252', our source address is '10.199.0.1'. [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 743f7483237099540bf349cd6cd4a5b2@10.199.0.1:5060 [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.253.252:5060 [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: = Looking for Call ID: 743f7483237099540bf349cd6cd4a5b2@10.199.0.1:5060 (Checking To) --From tag as72e19124 --To-tag 87a0fc2113173f05i0 [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Stopping retransmission on '743f7483237099540bf349cd6cd4a5b2@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Destroying SIP dialog 743f7483237099540bf349cd6cd4a5b2@10.199.0.1:5060 [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 0a1a683c4f41de21462e1d3141b0a43b@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:37] DEBUG[17078] acl.c: For destination '10.199.254.249', our source address is '10.199.0.1'. [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 34a2b4cd48226c4b1c78d9cc3d78c6cd@10.199.0.1:5060 [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.254.249:5060 [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: = Looking for Call ID: 34a2b4cd48226c4b1c78d9cc3d78c6cd@10.199.0.1:5060 (Checking To) --From tag as37dd413a --To-tag dad443a59d1ec0ddi0 [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Stopping retransmission on '34a2b4cd48226c4b1c78d9cc3d78c6cd@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Destroying SIP dialog 34a2b4cd48226c4b1c78d9cc3d78c6cd@10.199.0.1:5060 [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: = Looking for Call ID: 56048fb1-f8d60721@10.199.252.251 (Checking From) --From tag b8e58871ef5b6561o0 --To-tag [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:37] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.252.251:5060 [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: = Looking for Call ID: 1715acc8-879a35fd@10.199.254.4 (Checking From) --From tag eb70dfac8f7c0069o0 --To-tag [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.4:5060 [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: = Looking for Call ID: aa074275-3c34ee6@10.199.254.252 (Checking From) --From tag bb596af986d1a032o0 --To-tag [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.252:5060 [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: = Looking for Call ID: 7d94ea33-a7149a31@10.199.254.1 (Checking From) --From tag 57b15a8b891f25b9o0 --To-tag [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.1:5060 [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: = Looking for Call ID: 6362bdda-6d904f2@10.199.252.252 (Checking From) --From tag 5df80afad76f1a52o2 --To-tag [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.252.252:5062 [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 732c7e5e2e5fe12d1534a41b094a0f16@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:38] DEBUG[17078] acl.c: For destination '10.199.254.248', our source address is '10.199.0.1'. [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 1a81f0721c16d64f439e527f60468de8@10.199.0.1:5060 [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.254.248:5060 [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: = Looking for Call ID: 1a81f0721c16d64f439e527f60468de8@10.199.0.1:5060 (Checking To) --From tag as69e58b5e --To-tag f15a1a2a4988d537i0 [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: Stopping retransmission on '1a81f0721c16d64f439e527f60468de8@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:38] DEBUG[17078] chan_sip.c: Destroying SIP dialog 1a81f0721c16d64f439e527f60468de8@10.199.0.1:5060 [Aug 1 10:11:39] DEBUG[17078] chan_sip.c: = Looking for Call ID: 2c7996be-edc362d8@10.199.252.254 (Checking From) --From tag 548a3809e2c8ba08o0 --To-tag [Aug 1 10:11:39] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:39] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.252.254:5060 [Aug 1 10:11:39] DEBUG[17078] chan_sip.c: Auto destroying SIP dialog '462d4ab4-69cf4944@10.199.254.10' [Aug 1 10:11:39] DEBUG[17078] chan_sip.c: Destroying SIP dialog 462d4ab4-69cf4944@10.199.254.10 [Aug 1 10:11:39] DEBUG[17078] chan_sip.c: Auto destroying SIP dialog 'd0588fa9-85353f0b@10.199.253.249' [Aug 1 10:11:39] DEBUG[17078] chan_sip.c: Destroying SIP dialog d0588fa9-85353f0b@10.199.253.249 [Aug 1 10:11:39] DEBUG[17078] chan_sip.c: Auto destroying SIP dialog 'e5536ec3-bd4d5ab9@10.199.253.249' [Aug 1 10:11:39] DEBUG[17078] chan_sip.c: Destroying SIP dialog e5536ec3-bd4d5ab9@10.199.253.249 [Aug 1 10:11:39] DEBUG[17078] chan_sip.c: = Looking for Call ID: 82328dc-68f2c4ff@10.199.254.9 (Checking From) --From tag b1134ad81042ab33o0 --To-tag [Aug 1 10:11:39] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:39] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.9:5060 [Aug 1 10:11:39] DEBUG[17078] chan_sip.c: = Looking for Call ID: 3815aaca-8ac17d17@10.199.254.248 (Checking From) --From tag 26e80d8e99a2d923o0 --To-tag [Aug 1 10:11:39] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:39] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.248:5060 [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: = Looking for Call ID: dc87307e-39c8e11@10.199.253.255 (Checking From) --From tag aeb0fd1b2cd96425o0 --To-tag [Aug 1 10:11:40] DEBUG[17078] acl.c: For destination '10.199.253.255', our source address is '10.199.0.1'. [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for dc87307e-39c8e11@10.199.253.255 - REGISTER (No RTP) [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 1 10:11:40] DEBUG[17078] netsock2.c: Splitting '10.199.253.255:5060' into... [Aug 1 10:11:40] DEBUG[17078] netsock2.c: ...host '10.199.253.255' and port '5060'. [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.199.253.255:5060 [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: = Looking for Call ID: dc87307e-39c8e11@10.199.253.255 (Checking From) --From tag aeb0fd1b2cd96425o0 --To-tag [Aug 1 10:11:40] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:40] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:40] DEBUG[17078] netsock2.c: Splitting '10.199.0.1' into... [Aug 1 10:11:40] DEBUG[17078] netsock2.c: ...host '10.199.0.1' and port ''. [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 1 10:11:40] DEBUG[17078] netsock2.c: Splitting '10.199.253.255:5060' into... [Aug 1 10:11:40] DEBUG[17078] netsock2.c: ...host '10.199.253.255' and port '5060'. [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: Store REGISTER's Contact header for call routing. [Aug 1 10:11:40] DEBUG[17078] netsock2.c: Splitting '10.199.253.255:5060' into... [Aug 1 10:11:40] DEBUG[17078] netsock2.c: ...host '10.199.253.255' and port '5060'. [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 0db117b4407675680cdcd0eb515266dc@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:40] DEBUG[17078] acl.c: For destination '10.199.253.255', our source address is '10.199.0.1'. [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 170a68734ec60b4d6e6f5b242531f14c@10.199.0.1:5060 [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.253.255:5060 [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.253.255:5060 [Aug 1 10:11:40] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for SIP - 839 [Aug 1 10:11:40] DEBUG[17050] chan_sip.c: Checking device state for peer 839 [Aug 1 10:11:40] DEBUG[17050] devicestate.c: Changing state for SIP/839 - state 1 (Not in use) [Aug 1 10:11:40] DEBUG[17050] devicestate.c: device 'SIP/839' state '1' [Aug 1 10:11:40] DEBUG[17092] app_queue.c: Device 'SIP/839' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 1 10:11:40] DEBUG[17051] devicestate.c: Checking if I can find provider for "Custom" - number: DND839 [Aug 1 10:11:40] DEBUG[17051] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:40] DEBUG[17051] db.c: Unable to find key 'DND839' in family 'CustomDevstate' [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: = Looking for Call ID: 170a68734ec60b4d6e6f5b242531f14c@10.199.0.1:5060 (Checking To) --From tag as560faa95 --To-tag c5de70d37027c3cdi0 [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: Stopping retransmission on '170a68734ec60b4d6e6f5b242531f14c@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: Destroying SIP dialog 170a68734ec60b4d6e6f5b242531f14c@10.199.0.1:5060 [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: = Looking for Call ID: 47016381-c5b2c204@10.199.254.10 (Checking From) --From tag 49b31cfd82a1f6b8o0 --To-tag [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.254.10:5060 [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: = Looking for Call ID: 6570105e-7f599971@10.199.252.249 (Checking From) --From tag 1de8f91a94f967e5o0 --To-tag [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:40] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.252.249:5060 [Aug 1 10:11:41] DEBUG[17078] chan_sip.c: Allocating new SIP dialog for 0e9c55a827c9458b48fff02a7ea27a0a@127.0.1.1:0 - OPTIONS (No RTP) [Aug 1 10:11:41] DEBUG[17078] acl.c: For destination '10.199.250.253', our source address is '10.199.0.1'. [Aug 1 10:11:41] DEBUG[17078] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.199.0.1:5060 [Aug 1 10:11:41] DEBUG[17078] chan_sip.c: Initializing initreq for method OPTIONS - callid 7c9ec5fa3c20574909969be1204a9f05@10.199.0.1:5060 [Aug 1 10:11:41] DEBUG[17078] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.199.250.253:5060 [Aug 1 10:11:41] DEBUG[17078] chan_sip.c: = Looking for Call ID: 7c9ec5fa3c20574909969be1204a9f05@10.199.0.1:5060 (Checking To) --From tag as0485cbb5 --To-tag 4154376f050d9a6i0 [Aug 1 10:11:41] DEBUG[17078] chan_sip.c: Stopping retransmission on '7c9ec5fa3c20574909969be1204a9f05@10.199.0.1:5060' of Request 102: Match Found [Aug 1 10:11:41] DEBUG[17078] chan_sip.c: Destroying SIP dialog 7c9ec5fa3c20574909969be1204a9f05@10.199.0.1:5060 [Aug 1 10:11:41] DEBUG[17078] chan_sip.c: = Looking for Call ID: 1796ae7910a60e8e2f66c2d367e9dee9@10.199.0.1:5060 (Checking From) --From tag 6213e0932bd558cai1 --To-tag as720b2ee6 [Aug 1 10:11:41] DEBUG[17078] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Aug 1 10:11:41] DEBUG[17078] netsock2.c: Splitting '10.199.253.249:5061' into... [Aug 1 10:11:41] DEBUG[17078] netsock2.c: ...host '10.199.253.249' and port '5061'. [Aug 1 10:11:41] DEBUG[17078] chan_sip.c: Setting SIP_ALREADYGONE on dialog 1796ae7910a60e8e2f66c2d367e9dee9@10.199.0.1:5060 [Aug 1 10:11:41] DEBUG[17078] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb60236c8' [Aug 1 10:11:41] DEBUG[17078] chan_sip.c: Received bye, issuing owner hangup [Aug 1 10:11:41] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.253.249:5061 [Aug 1 10:11:41] DEBUG[13789] channel.c: Didn't get a frame from channel: SIP/867-00000b7b [Aug 1 10:11:41] DEBUG[13789] chan_dahdi.c: Requested indication 20 on channel DAHDI/i2/502503-3ce [Aug 1 10:11:41] DEBUG[13789] channel.c: Bridge stops bridging channels DAHDI/i2/502503-3ce and SIP/867-00000b7b [Aug 1 10:11:41] DEBUG[13789] pbx.c: Launching 'Macro' [Aug 1 10:11:41] VERBOSE[13789] pbx.c: -- Executing [h@macro-dial-one:1] Macro("DAHDI/i2/502503-3ce", "hangupcall,") in new stack [Aug 1 10:11:41] DEBUG[13789] pbx.c: Result of 'USE_CONFIRMATION' is NULL [Aug 1 10:11:41] DEBUG[13789] pbx.c: Result of 'RINGGROUP_INDEX' is NULL [Aug 1 10:11:41] DEBUG[13789] pbx.c: Result of 'CHANNEL' is 'DAHDI/i2/502503-3ce' [Aug 1 10:11:41] DEBUG[13789] pbx.c: Result of 'UNIQCHAN' is NULL [Aug 1 10:11:41] DEBUG[13789] pbx.c: Expression result is '1' [Aug 1 10:11:41] DEBUG[13789] pbx.c: Launching 'GotoIf' [Aug 1 10:11:41] VERBOSE[13789] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("DAHDI/i2/502503-3ce", "1?theend") in new stack [Aug 1 10:11:41] VERBOSE[13789] pbx.c: -- Goto (macro-hangupcall,s,3) [Aug 1 10:11:41] DEBUG[13789] app_macro.c: Executed application: GotoIf [Aug 1 10:11:41] DEBUG[13789] pbx.c: Launching 'Hangup' [Aug 1 10:11:41] VERBOSE[13789] pbx.c: -- Executing [s@macro-hangupcall:3] Hangup("DAHDI/i2/502503-3ce", "") in new stack [Aug 1 10:11:41] DEBUG[13789] app_macro.c: Spawn extension (macro-hangupcall,s,3) exited non-zero on 'DAHDI/i2/502503-3ce' in macro 'hangupcall' [Aug 1 10:11:41] VERBOSE[13789] app_macro.c: == Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'DAHDI/i2/502503-3ce' in macro 'hangupcall' [Aug 1 10:11:41] DEBUG[13789] features.c: Spawn extension (macro-dial-one,h,1) exited non-zero on 'DAHDI/i2/502503-3ce' [Aug 1 10:11:41] VERBOSE[13789] features.c: == Spawn extension (macro-dial-one, h, 1) exited non-zero on 'DAHDI/i2/502503-3ce' [Aug 1 10:11:41] DEBUG[17078] chan_sip.c: = Looking for Call ID: a9587ee4-73aa24e8@10.199.252.255 (Checking From) --From tag 6722963450ae75d8o0 --To-tag [Aug 1 10:11:41] DEBUG[17078] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [Aug 1 10:11:41] DEBUG[17078] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.199.252.255:5060 [Aug 1 10:11:41] DEBUG[13789] cdr_mysql.c: Inserting a CDR record. [Aug 1 10:11:41] DEBUG[13789] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`calldate`,`clid`,`src`,`dst`,`dcontext`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`) VALUES ('2011-08-01 10:11:11','\"502503\" <502503>','502503','867','from-did-direct','DAHDI/i2/502503-3ce','SIP/867-00000b7b','Dial','SIP/867,\"\",I','30','26','ANSWERED','3','1312186271.4002') [Aug 1 10:11:41] DEBUG[13789] channel.c: Hanging up channel 'SIP/867-00000b7b' [Aug 1 10:11:41] DEBUG[13789] chan_sip.c: Hangup call SIP/867-00000b7b, SIP callid 1796ae7910a60e8e2f66c2d367e9dee9@10.199.0.1:5060 [Aug 1 10:11:41] DEBUG[13789] chan_sip.c: Updating call counter for outgoing call [Aug 1 10:11:41] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for SIP - 867 [Aug 1 10:11:41] DEBUG[17050] chan_sip.c: Checking device state for peer 867 [Aug 1 10:11:41] DEBUG[17050] devicestate.c: Changing state for SIP/867 - state 1 (Not in use) [Aug 1 10:11:41] DEBUG[17050] devicestate.c: device 'SIP/867' state '1' [Aug 1 10:11:41] DEBUG[13789] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb60236c8' [Aug 1 10:11:41] DEBUG[17092] app_queue.c: Device 'SIP/867' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 1 10:11:41] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for SIP - 867 [Aug 1 10:11:41] DEBUG[17050] chan_sip.c: Checking device state for peer 867 [Aug 1 10:11:41] DEBUG[17050] devicestate.c: Changing state for SIP/867 - state 1 (Not in use) [Aug 1 10:11:41] DEBUG[17050] devicestate.c: device 'SIP/867' state '1' [Aug 1 10:11:41] DEBUG[13789] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Aug 1 10:11:41] DEBUG[13789] app_macro.c: Spawn extension (macro-dial-one,s,42) exited non-zero on 'DAHDI/i2/502503-3ce' in macro 'dial-one' [Aug 1 10:11:41] VERBOSE[13789] app_macro.c: == Spawn extension (macro-dial-one, s, 42) exited non-zero on 'DAHDI/i2/502503-3ce' in macro 'dial-one' [Aug 1 10:11:41] DEBUG[13789] app_macro.c: Spawn extension (macro-exten-vm,s,7) exited non-zero on 'DAHDI/i2/502503-3ce' in macro 'exten-vm' [Aug 1 10:11:41] VERBOSE[13789] app_macro.c: == Spawn extension (macro-exten-vm, s, 7) exited non-zero on 'DAHDI/i2/502503-3ce' in macro 'exten-vm' [Aug 1 10:11:41] DEBUG[13789] pbx.c: Spawn extension (from-did-direct,867,2) exited non-zero on 'DAHDI/i2/502503-3ce' [Aug 1 10:11:41] VERBOSE[13789] pbx.c: == Spawn extension (from-did-direct, 867, 2) exited non-zero on 'DAHDI/i2/502503-3ce' [Aug 1 10:11:41] DEBUG[13789] channel.c: Soft-Hanging up channel 'DAHDI/i2/502503-3ce' [Aug 1 10:11:41] DEBUG[13789] channel.c: Set channel DAHDI/i2/502503-3ce to read format alaw [Aug 1 10:11:41] DEBUG[13789] channel.c: Hanging up channel 'DAHDI/i2/502503-3ce' [Aug 1 10:11:41] DEBUG[13789] chan_dahdi.c: dahdi_hangup(DAHDI/i2/502503-3ce) [Aug 1 10:11:41] DEBUG[13789] chan_dahdi.c: Set option AUDIO MODE, value: ON(1) on DAHDI/i2/502503-3ce [Aug 1 10:11:41] DEBUG[13789] sig_pri.c: sig_pri_hangup 4 [Aug 1 10:11:41] DEBUG[13789] sig_pri.c: Not yet hungup... Calling hangup once with icause, and clearing call [Aug 1 10:11:41] DEBUG[13789] chan_dahdi.c: Disabled echo cancellation on channel 4 [Aug 1 10:11:41] DEBUG[17092] app_queue.c: Device 'SIP/867' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 1 10:11:41] DEBUG[13789] chan_dahdi.c: Set option TDD MODE, value: OFF(0) on DAHDI/i2/502503-3ce [Aug 1 10:11:41] DEBUG[13789] chan_dahdi.c: Updated conferencing on 4, with 0 conference users [Aug 1 10:11:41] DEBUG[13789] chan_dahdi.c: Set option AUDIO MODE, value: OFF(0) on DAHDI/i2/502503-3ce [Aug 1 10:11:41] VERBOSE[13789] chan_dahdi.c: -- Hungup 'DAHDI/i2/502503-3ce' [Aug 1 10:11:41] DEBUG[17050] devicestate.c: No provider found, checking channel drivers for DAHDI - i2/502503 [Aug 1 10:11:41] DEBUG[17050] devicestate.c: Changing state for DAHDI/i2/502503 - state 0 (Unknown) [Aug 1 10:11:41] DEBUG[17050] devicestate.c: device 'DAHDI/i2/502503' state '0' [Aug 1 10:11:41] DEBUG[17092] app_queue.c: Device 'DAHDI/i2/502503' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Aug 1 10:11:41] DEBUG[17051] devicestate.c: Checking if I can find provider for "Custom" - number: DND867 [Aug 1 10:11:41] DEBUG[17051] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:41] DEBUG[17051] db.c: Unable to find key 'DND867' in family 'CustomDevstate' [Aug 1 10:11:41] DEBUG[17051] app_queue.c: Extension '867@ext-local' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 1 10:11:41] DEBUG[17051] devicestate.c: Checking if I can find provider for "Custom" - number: DND867 [Aug 1 10:11:41] DEBUG[17051] devicestate.c: Checking provider Custom with Custom [Aug 1 10:11:41] DEBUG[17051] db.c: Unable to find key 'DND867' in family 'CustomDevstate'